[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

693–700

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

82

Looks like it's not used.

lib/sanitizer_common/sanitizer_mac.cc

403

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

690

Use InternalScopedString instead of InternalScopedBuffer<char>.

lib/sanitizer_common/sanitizer_common.h

52

Rename to "kErrorMessageBufferSize".

662

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

50–51

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

lib/sanitizer_common/sanitizer_posix.cc

126

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

690

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

320

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

lib/asan/asan_report.cc

 #include "sanitizer_common/sanitizer_symbolizer.h"
 
 namespace __asan {
 
 // -------------------- User-specified callbacks ----------------- {{{1
 static void (*error_report_callback)(const char*);
 static char *error_message_buffer = nullptr;
 static uptr error_message_buffer_pos = 0;
-static uptr error_message_buffer_size = 0;
 static BlockingMutex error_message_buf_mutex(LINKER_INITIALIZED);
 
 struct ReportData {
   uptr pc;
   uptr sp;
   uptr bp;
   uptr addr;
   bool is_write;
   uptr access_size;
   const char *description;
 };
 
 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(kErrorMessageBufferSize, __func__);
     error_message_buffer_pos = 0;
   }
   uptr length = internal_strlen(buffer);
-  CHECK_GE(error_message_buffer_size, error_message_buffer_pos);
-  uptr remaining = error_message_buffer_size - error_message_buffer_pos;
+  RAW_CHECK(kErrorMessageBufferSize >= error_message_buffer_pos);
+  uptr remaining = kErrorMessageBufferSize - error_message_buffer_pos;
   internal_strncpy(error_message_buffer + error_message_buffer_pos,
                    buffer, remaining);
-  error_message_buffer[error_message_buffer_size - 1] = '\0';
+  error_message_buffer[kErrorMessageBufferSize - 1] = '\0';
   // FIXME: reallocate the buffer instead of truncating the message.
   error_message_buffer_pos += Min(remaining, length);
 }
 
 // ---------------------- Decorator ------------------------------ {{{1
 class Decorator: public __sanitizer::SanitizerCommonDecorator {
  public:
   Decorator() : SanitizerCommonDecorator() { }
public:
   ~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(kErrorMessageBufferSize);
     {
       BlockingMutexLock l(&error_message_buf_mutex);
-      LogFullErrorReport(error_message_buffer);
+      internal_memcpy(buffer_copy.data(),
+                      error_message_buffer, kErrorMessageBufferSize);
+    }
+
+    // Remove color sequences since logs cannot print them.
+    RemoveANSIEscapeSequencesFromString(buffer_copy.data());
+
+    LogFullErrorReport(buffer_copy.data());
 
-      if (error_report_callback) {
-        error_report_callback(error_message_buffer);
-      }
+      error_report_callback(buffer_copy.data());
     }
     CommonSanitizerReportMutex.Unlock();
     reporting_thread_tid_ = kInvalidTid;
     lock_.Unlock();
     if (halt_on_error_) {
       Report("ABORTING\n");
       Die();
     }

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
 
+static const uptr kErrorMessageBufferSize = 1 << 16;
+
 // 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) {

 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);

 bool TemplateMatch(const char *templ, const char *str);
 
 // 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);
+                                      const char *mmap_type, error_t err,
+                                      bool raw_report = false);
+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);
 
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_KITKAT = 19,
   ANDROID_LOLLIPOP_MR1 = 22,
   ANDROID_POST_LOLLIPOP = 23
 };
 
 void WriteToSyslog(const char *buffer);
 
 #if SANITIZER_MAC
-void LogFullErrorReport(const char *error_message_buffer);
+void LogFullErrorReport(const char *buffer);
 #else
-INLINE void LogFullErrorReport(const char *error_message_buffer) {}
+INLINE void LogFullErrorReport(const 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) {
+                                      const char *mmap_type, error_t err,
+                                      bool raw_report) {
   static int recursion_count;
-  if (recursion_count) {
+  if (raw_report || recursion_count) {
+    // If raw report is requested or we went into recursion, just die.
     // 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);
 #ifndef SANITIZER_GO
   DumpProcessMap();
 #endif

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(const char *msg) {
+  InternalScopedString msg_copy(kErrorMessageBufferSize);
+  msg_copy.append("%s", msg);
+  char *p = msg_copy.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_mac.cc

 //===-- sanitizer_mac.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 various sanitizers' runtime libraries and
 // implements OSX-specific functions.
 //===----------------------------------------------------------------------===//
 
 #include "sanitizer_platform.h"
 #if SANITIZER_MAC
+#include "sanitizer_mac.h"
 
 // Use 64-bit inodes in file operations. ASan does not support OS X 10.5, so
 // the clients will most certainly use 64-bit ones as well.
 #ifndef _DARWIN_USE_64_BIT_INODE
 #define _DARWIN_USE_64_BIT_INODE 1
 #endif
 #include <stdio.h>
 
 #include "sanitizer_common.h"
 #include "sanitizer_flags.h"
 #include "sanitizer_internal_defs.h"
 #include "sanitizer_libc.h"
-#include "sanitizer_mac.h"
 #include "sanitizer_placement_new.h"
 #include "sanitizer_platform_limits_posix.h"
 #include "sanitizer_procmaps.h"
 
 #if !SANITIZER_IOS
 #include <crt_externs.h>  // for _NSGetEnviron
 #else
 extern char **environ;

 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) {
   // Log with os_trace. This will make it into the crash log.
 #if SANITIZER_OS_TRACE
   if (GetMacosVersion() >= MACOS_VERSION_YOSEMITE) {
     // 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)

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))
-    ReportMmapFailureAndDie(size, mem_type, "allocate", reserrno);
+    ReportMmapFailureAndDie(size, mem_type, "allocate", reserrno, raw_report);
   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)) {
     Report("ERROR: %s failed to deallocate 0x%zx (%zd) bytes at address %p\n",
            SanitizerToolName, size, size, addr);
     CHECK("unable to unmap" && 0);
   }

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)
-    ReportMmapFailureAndDie(size, mem_type, "allocate", GetLastError());
+    ReportMmapFailureAndDie(size, mem_type, "allocate",
+                            GetLastError(), raw_report);
   return rv;
 }
 
 void UnmapOrDie(void *addr, uptr size) {
   if (!size || !addr)
     return;
 
   if (VirtualFree(addr, size, MEM_DECOMMIT) == 0) {