[asan] Fix the deadlocks introduced by "On OS X, log reports to syslog and os_trace" commit

[zaks.anna]

Summary

[asan] On OS X, log reports to syslog and os_trace, has been reverted in r252076 due to deadlocks on earlier versions of OS X. Alexey has also noticed deadlocks in some corner cases on Linux. This patch, if applied on top of the logging patch (http://reviews.llvm.org/D13452), addresses the known deadlock issues.

(This also proactively removes the color escape sequences from the error report buffer since we have to copy the buffer anyway.)

More background:

Alexey Samsonov <[e-mail]>:
While I'm not exactly sure what caused these issues on Mac buildbot, I've also observed several self-deadlocks caused by this change.
Essentially, they are caused by AppendToErrorMessageBuffer function, which now takes a lock, but can be re-entrant:

• AppendToErrorMessageBuffer is called and takes a lock
• AppendToErrorMessageBuffer tries to allocate error message buffer and calls MmapOrDie()
• MmapOrDie() fails, because memory limit is exceeded, and calls Report() to report that
• Report calls AppendToErrorMessageBuffer, which attempts to take a lock, and hangs.

The same will happen if CHECK() call in AppendToErrorMessageBuffer fails. Sadly, I can't suggest a good solution for that: probably
you just need to try harder to make sure the function will never be called recursively: use RAW_CHECK instead of CHECK and
call (some variation of) MmapOrDieQuietly(), which will just call RawWrite()+Die() on failure.

Anna:
I suspect the issue with the earlier versions of OS X is that logging the error report results in ASan calling Printf under high verbosity level (and Printf calls AppendToErrorMessageBuffer). We hold the lock that is guarding error_message_buf when reporting inside ScopedInErrorReport. We can work around that issue by copying the buffer under the lock but releasing it before calling the logging routines.

[samsonov]

lib/asan/asan_report.cc

679–681

Hm, I would actually prefer InternalScopedString here to avoid using internal allocator that late (and use the same mmap we use for error_message_buffer).

lib/sanitizer_common/sanitizer_common.h

80

Looks like it's not used.

lib/sanitizer_common/sanitizer_mac.cc

384

Wouldn't we die earlier if it's null? If it can be null, we probably don't need to invoke error_report_callback either.

[zaks.anna]

Addressing Alexey's review. Switching to use InternalScopedBuffer lead to a bit more refactoring. For example, I've also switched to InternalScopedBuffer in WriteToSyslog since that copy happens late as well.

[zaks.anna]

Alexey,

Could you look at this?

Thanks!
Anna.

[zaks.anna]

Change WriteToSyslog to make it's own copy of the message since it destroys the buffer.

[kubamracek]

LGTM with a few nits.

lib/asan/asan_report.cc

676

Use InternalScopedString instead of InternalScopedBuffer<char>.

lib/sanitizer_common/sanitizer_common.h

52

Rename to "kErrorMessageBufferSize".

659

Do we need to pass InternalScopedBuffer/InternalScopedString? Can we keep it as const char *?

[samsonov]

Sorry for the delay in review! =/

lib/asan/asan_report.cc

52

Do you actually need this variable at all, now that you have a constant?

lib/sanitizer_common/sanitizer_posix.cc

125

This function is now called in several more places. You might want to just add extra argument (raw_report) to ReportMmapFailureAndDie to reduce code duplication.

[zaks.anna]

lib/asan/asan_report.cc

676

It's a buffer because we treat it as a buffer later on. For example, RemoveANSIEscapeSequencesFromString modifies it in place and modifies the raw data. (If it were a string, its length would get invalidated.)

[zaks.anna]

Addressed all outstanding suggestions.

[samsonov]

LGTM with a nit. Thanks!

lib/sanitizer_common/sanitizer_common.h

318

You can remove this function from the header, and make it static in .cc file (if not inline it).

lib/asan/asan_report.cc

 };
 
 static bool report_happened = false;
 static ReportData report_data = {};
 
 void AppendToErrorMessageBuffer(const char *buffer) {
   BlockingMutexLock l(&error_message_buf_mutex);
   if (!error_message_buffer) {
     error_message_buffer_size = 1 << 16;
     error_message_buffer =
-      (char*)MmapOrDie(error_message_buffer_size, __func__);
+      (char*)MmapOrDieQuietly(error_message_buffer_size, __func__);
     error_message_buffer_pos = 0;
   }
   uptr length = internal_strlen(buffer);
-  CHECK_GE(error_message_buffer_size, error_message_buffer_pos);
+  RAW_CHECK(error_message_buffer_size >= error_message_buffer_pos);
   uptr remaining = error_message_buffer_size - error_message_buffer_pos;
   internal_strncpy(error_message_buffer + error_message_buffer_pos,
                    buffer, remaining);
   error_message_buffer[error_message_buffer_size - 1] = '\0';
   // FIXME: reallocate the buffer instead of truncating the message.
   error_message_buffer_pos += Min(remaining, length);
 }
 
public:
   NORETURN ~ScopedInErrorReport() {
     // Make sure the current thread is announced.
     DescribeThread(GetCurrentThread());
     // We may want to grab this lock again when printing stats.
     asanThreadRegistry().Unlock();
     // Print memory stats.
     if (flags()->print_stats)
       __asan_print_accumulated_stats();
+
+    // Copy the message buffer so that we could start logging without holding a
+    // lock that gets aquired during printing.
+    InternalScopedBuffer<char> buffer_copy(error_message_buffer_size);
     {
       BlockingMutexLock l(&error_message_buf_mutex);
-      LogFullErrorReport(error_message_buffer);
+      internal_memcpy(buffer_copy.data(),
+                      error_message_buffer, error_message_buffer_size);
+    }
+
+    // Remove color sequences since logs cannot print them.
+    RemoveANSIEscapeSequencesFromString(buffer_copy.data());
+
+    LogFullErrorReport(&buffer_copy);
 
-      if (error_report_callback) {
-        error_report_callback(error_message_buffer);
-      }
+      error_report_callback(buffer_copy.data());
     }
     Report("ABORTING\n");
     Die();
   }
 };
 
 void ReportStackOverflow(const SignalContext &sig) {
   ScopedInErrorReport in_report;

lib/sanitizer_common/sanitizer_common.h

 
 const uptr kMaxPathLength = 4096;
 
 // 16K loaded modules should be enough for everyone.
 static const uptr kMaxNumberOfModules = 1 << 14;
 
 const uptr kMaxThreadStackSize = 1 << 30;  // 1Gb
 
 // Denotes fake PC values that come from JIT/JAVA/etc.
 // For such PC values __tsan_symbolize_external() will be called.
 const u64 kExternalPCBit = 1ULL << 60;
 
 extern const char *SanitizerToolName;  // Can be changed by the tool.
 
 extern atomic_uint32_t current_verbosity;
 INLINE void SetVerbosity(int verbosity) {
   atomic_store(&current_verbosity, verbosity, memory_order_relaxed);

 uptr GetTid();
 uptr GetThreadSelf();
 void GetThreadStackTopAndBottom(bool at_initialization, uptr *stack_top,
                                 uptr *stack_bottom);
 void GetThreadStackAndTls(bool main, uptr *stk_addr, uptr *stk_size,
                           uptr *tls_addr, uptr *tls_size);
 
 // Memory management
-void *MmapOrDie(uptr size, const char *mem_type);
+void *MmapOrDie(uptr size, const char *mem_type, bool raw_report = false);
+INLINE void *MmapOrDieQuietly(uptr size, const char *mem_type) {
+  return MmapOrDie(size, mem_type, /*raw_report*/ true);
+}
 void UnmapOrDie(void *addr, uptr size);
 void *MmapFixedNoReserve(uptr fixed_addr, uptr size,
                          const char *name = nullptr);
 void *MmapNoReserveOrDie(uptr size, const char *mem_type);
 void *MmapFixedOrDie(uptr fixed_addr, uptr size);
 void *MmapNoAccess(uptr fixed_addr, uptr size, const char *name = nullptr);
 // Map aligned chunk of address space; size and alignment are powers of two.
 void *MmapAlignedOrDie(uptr size, uptr alignment, const char *mem_type);

 
 // Exit
 void NORETURN Abort();
 void NORETURN Die();
 void NORETURN
 CheckFailed(const char *file, int line, const char *cond, u64 v1, u64 v2);
 void NORETURN ReportMmapFailureAndDie(uptr size, const char *mem_type,
                                       const char *mmap_type, error_t err);
+void NORETURN RawReportMmapFailureAndDie();
 
 // Set the name of the current thread to 'name', return true on succees.
 // The name may be truncated to a system-dependent limit.
 bool SanitizerSetThreadName(const char *name);
 // Get the name of the current thread (no more than max_len bytes),
 // return true on succees. name should have space for at least max_len+1 bytes.
 bool SanitizerGetThreadName(char *name, int max_len);
 
 // Specific tools may override behavior of "Die" and "CheckFailed" functions
INLINE uptr RoundUpToPowerOfTwo(uptr size) {
 
   uptr up = MostSignificantSetBitIndex(size);
   CHECK(size < (1ULL << (up + 1)));
   CHECK(size > (1ULL << up));
   return 1ULL << (up + 1);
 }
 
 INLINE uptr RoundUpTo(uptr size, uptr boundary) {
-  CHECK(IsPowerOfTwo(boundary));
+  RAW_CHECK(IsPowerOfTwo(boundary));
   return (size + boundary - 1) & ~(boundary - 1);
 }
 
 INLINE uptr RoundDownTo(uptr x, uptr boundary) {
   return x & ~(boundary - 1);
 }
 
 INLINE bool IsAligned(uptr a, uptr alignment) {

 
 enum AndroidApiLevel {
   ANDROID_NOT_ANDROID = 0,
   ANDROID_KITKAT = 19,
   ANDROID_LOLLIPOP_MR1 = 22,
   ANDROID_POST_LOLLIPOP = 23
 };
 
-void WriteToSyslog(const char *buffer);
+void WriteToSyslog(InternalScopedBuffer<char> *buffer);
 
 #if SANITIZER_MAC
-void LogFullErrorReport(const char *error_message_buffer);
+void LogFullErrorReport(InternalScopedBuffer<char> *buffer);
 #else
-INLINE void LogFullErrorReport(const char *error_message_buffer) {}
+INLINE void LogFullErrorReport(InternalScopedBuffer<char> *buffer) {}
 #endif
 
 #if SANITIZER_LINUX || SANITIZER_MAC
 void WriteOneLineToSyslog(const char *s);
 #else
 INLINE void WriteOneLineToSyslog(const char *s) {}
 #endif
 

lib/sanitizer_common/sanitizer_common.cc

void NORETURN CheckFailed(const char *file, int line, const char *cond,
   if (CheckFailedCallback) {
     CheckFailedCallback(file, line, cond, v1, v2);
   }
   Report("Sanitizer CHECK failed: %s:%d %s (%lld, %lld)\n", file, line, cond,
                                                             v1, v2);
   Die();
 }
 
+void NORETURN RawReportMmapFailureAndDie() {
+  RawWrite("ERROR: Failed to mmap\n");
+  Die();
+}
+
 void NORETURN ReportMmapFailureAndDie(uptr size, const char *mem_type,
                                       const char *mmap_type, error_t err) {
   static int recursion_count;
   if (recursion_count) {
     // The Report() and CHECK calls below may call mmap recursively and fail.
     // If we went into recursion, just die.
-    RawWrite("ERROR: Failed to mmap\n");
-    Die();
+    RawReportMmapFailureAndDie();
   }
   recursion_count++;
   Report("ERROR: %s failed to "
          "%s 0x%zx (%zd) bytes of %s (error code: %d)\n",
          SanitizerToolName, mmap_type, size, size, mem_type, err);
   DumpProcessMap();
   UNREACHABLE("unable to mmap");
 }

lib/sanitizer_common/sanitizer_common_libcdep.cc

 //===-- sanitizer_common_libcdep.cc ---------------------------------------===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 //
 // This file is shared between AddressSanitizer and ThreadSanitizer
 // run-time libraries.
 //===----------------------------------------------------------------------===//
 
 #include "sanitizer_common.h"
-#include "sanitizer_allocator_internal.h"
 #include "sanitizer_flags.h"
 #include "sanitizer_stackdepot.h"
 #include "sanitizer_stacktrace.h"
 #include "sanitizer_symbolizer.h"
 
 #if SANITIZER_POSIX
 #include "sanitizer_posix.h"
 #endif
if (soft_rss_limit_mb) {
         reached_soft_rss_limit = false;
         if (SoftRssLimitExceededCallback)
           SoftRssLimitExceededCallback(false);
       }
     }
   }
 }
 
-void WriteToSyslog(const char *buffer) {
-  char *copy = internal_strdup(buffer);
-  char *p = copy;
+void WriteToSyslog(InternalScopedBuffer<char> *buffer) {
+  char *p = buffer->data();
   char *q;
 
   // Remove color sequences since syslogs cannot print them.
-  RemoveANSIEscapeSequencesFromString(copy);
+  RemoveANSIEscapeSequencesFromString(p);
 
   // Print one line at a time.
   // syslog, at least on Android, has an implicit message length limit.
   do {
     q = internal_strchr(p, '\n');
     if (q)
       *q = '\0';
     WriteOneLineToSyslog(p);
     if (q)
       p = q + 1;
   } while (q);
-  InternalFree(copy);
 }
 
 void MaybeStartBackgroudThread() {
 #if SANITIZER_LINUX && \
     !SANITIZER_GO  // Need to implement/test on other platforms.
   // Start the background thread if one of the rss limits is given.
   if (!common_flags()->hard_rss_limit_mb &&
       !common_flags()->soft_rss_limit_mb) return;

lib/sanitizer_common/sanitizer_common_nolibc.cc

 #include "sanitizer_common.h"
 #include "sanitizer_libc.h"
 
 namespace __sanitizer {
 
 #if SANITIZER_LINUX
 bool ShouldLogAfterPrintf() { return false; }
 #endif
-void WriteToSyslog(const char *buffer) {}
+void WriteToSyslog(InternalScopedBuffer<char> *buffer) {}
 void Abort() { internal__exit(1); }
 
 }  // namespace __sanitizer

lib/sanitizer_common/sanitizer_mac.cc

 
 static BlockingMutex syslog_lock(LINKER_INITIALIZED);
 
 void WriteOneLineToSyslog(const char *s) {
   syslog_lock.CheckLocked();
   asl_log(nullptr, nullptr, ASL_LEVEL_ERR, "%s", s);
 }
 
-void LogFullErrorReport(const char *buffer) {
+void LogFullErrorReport(InternalScopedBuffer<char> *buffer) {
   // Log with os_trace. This will make it into the crash log.
   if (GetMacosVersion() >= MACOS_VERSION_MAVERICKS) {
     // os_trace requires the message (format parameter) to be a string literal.
     if (internal_strncmp(SanitizerToolName, "AddressSanitizer",
                          sizeof("AddressSanitizer") - 1) == 0)
       os_trace("Address Sanitizer reported a failure.");
     else if (internal_strncmp(SanitizerToolName, "UndefinedBehaviorSanitizer",
                               sizeof("UndefinedBehaviorSanitizer") - 1) == 0)
       os_trace("Undefined Behavior Sanitizer reported a failure.");

lib/sanitizer_common/sanitizer_posix.cc

#else  // SANITIZER_WORDSIZE == 32
   uptr res = (1ULL << 32) - 1;  // 0xffffffff;
   if (!common_flags()->full_address_space)
     res -= GetKernelAreaSize();
   CHECK_LT(reinterpret_cast<uptr>(&res), res);
   return res;
 #endif  // SANITIZER_WORDSIZE
 }
 
-void *MmapOrDie(uptr size, const char *mem_type) {
+void *MmapOrDie(uptr size, const char *mem_type, bool raw_report) {
   size = RoundUpTo(size, GetPageSizeCached());
   uptr res = internal_mmap(nullptr, size,
                            PROT_READ | PROT_WRITE,
                            MAP_PRIVATE | MAP_ANON, -1, 0);
   int reserrno;
-  if (internal_iserror(res, &reserrno))
+  if (internal_iserror(res, &reserrno)) {
+    if (raw_report)
+      RawReportMmapFailureAndDie();
+    else
       ReportMmapFailureAndDie(size, mem_type, "allocate", reserrno);
+  }
   IncreaseTotalMmap(size);
   return (void *)res;
 }
 
 void UnmapOrDie(void *addr, uptr size) {
   if (!addr || !size) return;
   uptr res = internal_munmap(addr, size);
   if (internal_iserror(res)) {

lib/sanitizer_common/sanitizer_printf.cc

#   define CHECK_NEEDED_LENGTH \
     needed_length += VSNPrintf(buffer + needed_length,
                                buffer_size - needed_length, format, args);
     CHECK_NEEDED_LENGTH
     // If the message fit into the buffer, print it and exit.
     break;
 #   undef CHECK_NEEDED_LENGTH
   }
   RawWrite(buffer);
-  if (common_flags()->log_to_syslog && ShouldLogAfterPrintf())
-    WriteToSyslog(buffer);
+  if (common_flags()->log_to_syslog && ShouldLogAfterPrintf()) {
+    InternalScopedBuffer<char> buffer_copy(buffer_size);
+    internal_memcpy(buffer_copy.data(), buffer, buffer_size);
+    WriteToSyslog(&buffer_copy);
+  }
   CallPrintfAndReportCallback(buffer);
   // If we had mapped any memory, clean up.
   if (buffer != local_buffer)
     UnmapOrDie((void *)buffer, buffer_size);
   va_end(args2);
 }
 
 FORMAT(1, 2)

lib/sanitizer_common/sanitizer_win.cc

void GetThreadStackTopAndBottom(bool at_initialization, uptr *stack_top,
   // FIXME: is it possible for the stack to not be a single allocation?
   // Are these values what ASan expects to get (reserved, not committed;
   // including stack guard page) ?
   *stack_top = (uptr)mbi.BaseAddress + mbi.RegionSize;
   *stack_bottom = (uptr)mbi.AllocationBase;
 }
 #endif  // #if !SANITIZER_GO
 
-void *MmapOrDie(uptr size, const char *mem_type) {
+void *MmapOrDie(uptr size, const char *mem_type, bool raw_report) {
   void *rv = VirtualAlloc(0, size, MEM_RESERVE | MEM_COMMIT, PAGE_READWRITE);
-  if (rv == 0)
+  if (rv == 0) {
+    if (raw_report)
+      RawReportMmapFailureAndDie();
+    else
       ReportMmapFailureAndDie(size, mem_type, "allocate", GetLastError());
+  }
   return rv;
 }
 
 void UnmapOrDie(void *addr, uptr size) {
   if (!size || !addr)
     return;
 
   if (VirtualFree(addr, size, MEM_DECOMMIT) == 0) {