[asan] On OS X, log reports to syslog and os_trace

When ASan currently detects a bug, by default it will only print out the text
of the report to stderr. This patch changes this behavior and writes the full
text of the report to syslog before we terminate the process. It also calls
os_trace (Activity Tracing available on OS X and iOS) with a message saying
that the report is available in syslog. This is useful, because this message
will be shown in the crash log.

For this to work, the patch makes sure we store the full report into
error_message_buffer unconditionally, and it also strips out ANSI escape
sequences from the report (they are used when producing colored reports).

I've initially tried to log to syslog during printing, which is done on Android
right now. The advantage is that if we crash during error reporting or the
produced error does not go through ScopedInErrorReport, we would still get a
(partial) message in the syslog. However, that solution is very problematic on
OS X. One issue is that the logging routine uses GCD, which may spawn a new
thread on its behalf. In many cases, the reporting logic locks threadRegistry,
which leads to deadlocks.

Reviewed at http://reviews.llvm.org/D13452

git-svn-id: https://llvm.org/svn/llvm-project/compiler-rt/trunk@251447 91177308-0d34-0410-b5e6-96231b3b80d8

lib/asan/asan_report.cc

@@ -31,6 +31,7 @@ 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;
@@ -46,16 +47,21 @@ static bool report_happened = false;
 static ReportData report_data = {};
 
 void AppendToErrorMessageBuffer(const char *buffer) {
-  if (error_message_buffer) {
-    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;
-    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);
+  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__);
+    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;
+  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);
 }
 
 // ---------------------- Decorator ------------------------------ {{{1
@@ -664,8 +670,13 @@ class ScopedInErrorReport {
     // Print memory stats.
     if (flags()->print_stats)
       __asan_print_accumulated_stats();
-    if (error_report_callback) {
-      error_report_callback(error_message_buffer);
+    {
+      BlockingMutexLock l(&error_message_buf_mutex);
+      LogFullErrorReport(error_message_buffer);
+
+      if (error_report_callback) {
+        error_report_callback(error_message_buffer);
+      }
     }
     Report("ABORTING\n");
     Die();
@@ -1061,13 +1072,8 @@ void __asan_report_error(uptr pc, uptr bp, uptr sp, uptr addr, int is_write,
 }
 
 void NOINLINE __asan_set_error_report_callback(void (*callback)(const char*)) {
+  BlockingMutexLock l(&error_message_buf_mutex);
   error_report_callback = callback;
-  if (callback) {
-    error_message_buffer_size = 1 << 16;
-    error_message_buffer =
-        (char*)MmapOrDie(error_message_buffer_size, __func__);
-    error_message_buffer_pos = 0;
-  }
 }
 
 void __asan_describe_address(uptr addr) {

lib/asan/tests/asan_test_main.cc

@@ -19,7 +19,8 @@ extern "C" const char* __asan_default_options() {
 #if SANITIZER_MAC
   // On Darwin, we default to `abort_on_error=1`, which would make tests run
   // much slower. Let's override this and run lit tests with 'abort_on_error=0'.
-  return "symbolize=false:abort_on_error=0";
+  // Also, make sure we do not overwhelm the syslog while testing.
+  return "symbolize=false:abort_on_error=0:log_to_syslog=0";
 #else
   return "symbolize=false";
 #endif

lib/sanitizer_common/sanitizer_common.cc

@@ -295,6 +295,40 @@ void ReportErrorSummary(const char *error_type, const AddressInfo &info) {
 }
 #endif
 
+// Removes the ANSI escape sequences from the input string (in-place).
+void RemoveANSIEscapeSequencesFromString(char *str) {
+  if (!str)
+    return;
+
+  // We are going to remove the escape sequences in place.
+  char *s = str;
+  char *z = str;
+  while (*s != '\0') {
+    CHECK_GE(s, z);
+    // Skip over ANSI escape sequences with pointer 's'.
+    if (*s == '\033' && *(s + 1) == '[') {
+      s = internal_strchrnul(s, 'm');
+      if (*s == '\0') {
+        break;
+      }
+      s++;
+      continue;
+    }
+    // 's' now points at a character we want to keep. Copy over the buffer
+    // content if the escape sequence has been perviously skipped andadvance
+    // both pointers.
+    if (s != z)
+      *z = *s;
+
+    // If we have not seen an escape sequence, just advance both pointers.
+    z++;
+    s++;
+  }
+
+  // Null terminate the string.
+  *z = '\0';
+}
+
 void LoadedModule::set(const char *module_name, uptr base_address) {
   clear();
   full_name_ = internal_strdup(module_name);

lib/sanitizer_common/sanitizer_common.h

@@ -162,6 +162,7 @@ void SetLowLevelAllocateCallback(LowLevelAllocateCallback callback);
 // IO
 void RawWrite(const char *buffer);
 bool ColorizeReports();
+void RemoveANSIEscapeSequencesFromString(char *buffer);
 void Printf(const char *format, ...);
 void Report(const char *format, ...);
 void SetPrintfAndReportCallback(void (*callback)(const char *));
@@ -648,13 +649,27 @@ enum AndroidApiLevel {
   ANDROID_POST_LOLLIPOP = 23
 };
 
+void WriteToSyslog(const char *buffer);
+
+#if SANITIZER_MAC
+void LogFullErrorReport(const char *error_message_buffer);
+#else
+INLINE void LogFullErrorReport(const char *error_message_buffer) {}
+#endif
+
+#if SANITIZER_LINUX || SANITIZER_MAC
+void WriteOneLineToSyslog(const char *s);
+#else
+INLINE void WriteOneLineToSyslog(const char *s) {}
+#endif
+
 #if SANITIZER_LINUX
 // Initialize Android logging. Any writes before this are silently lost.
 void AndroidLogInit();
-void WriteToSyslog(const char *buffer);
+bool ShouldLogAfterPrintf();
 #else
 INLINE void AndroidLogInit() {}
-INLINE void WriteToSyslog(const char *buffer) {}
+INLINE bool ShouldLogAfterPrintf() { return false; }
 #endif
 
 #if SANITIZER_ANDROID

lib/sanitizer_common/sanitizer_common_libcdep.cc

@@ -12,6 +12,7 @@
 //===----------------------------------------------------------------------===//
 
 #include "sanitizer_common.h"
+#include "sanitizer_allocator_internal.h"
 #include "sanitizer_flags.h"
 #include "sanitizer_stackdepot.h"
 #include "sanitizer_stacktrace.h"
@@ -116,6 +117,27 @@ void BackgroundThread(void *arg) {
   }
 }
 
+void WriteToSyslog(const char *buffer) {
+  char *copy = internal_strdup(buffer);
+  char *p = copy;
+  char *q;
+
+  // Remove color sequences since syslogs cannot print them.
+  RemoveANSIEscapeSequencesFromString(copy);
+
+  // 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  // Need to implement/test on other platforms.
   // Start the background thread if one of the rss limits is given.

lib/sanitizer_common/sanitizer_flags.inc

@@ -56,7 +56,7 @@ COMMON_FLAG(
     "Mention name of executable when reporting error and "
     "append executable name to logs (as in \"log_path.exe_name.pid\").")
 COMMON_FLAG(
-    bool, log_to_syslog, SANITIZER_ANDROID,
+    bool, log_to_syslog, SANITIZER_ANDROID || SANITIZER_MAC,
     "Write all sanitizer output to syslog in addition to other means of "
     "logging.")
 COMMON_FLAG(

lib/sanitizer_common/sanitizer_linux_libcdep.cc

@@ -548,16 +548,16 @@ void AndroidLogInit() {
   atomic_store(&android_log_initialized, 1, memory_order_release);
 }
 
-static bool IsSyslogAvailable() {
+bool ShouldLogAfterPrintf() {
   return atomic_load(&android_log_initialized, memory_order_acquire);
 }
 #else
 void AndroidLogInit() {}
 
-static bool IsSyslogAvailable() { return true; }
+bool ShouldLogAfterPrintf() { return true; }
 #endif  // SANITIZER_ANDROID
 
-static void WriteOneLineToSyslog(const char *s) {
+void WriteOneLineToSyslog(const char *s) {
 #if SANITIZER_ANDROID &&__ANDROID_API__ < 21
   __android_log_write(ANDROID_LOG_INFO, NULL, s);
 #else
@@ -565,24 +565,6 @@ static void WriteOneLineToSyslog(const char *s) {
 #endif
 }
 
-void WriteToSyslog(const char *buffer) {
-  if (!IsSyslogAvailable())
-    return;
-  char *copy = internal_strdup(buffer);
-  char *p = copy;
-  char *q;
-  // syslog, at least on Android, has an implicit message length limit.
-  // Print one line at a time.
-  do {
-    q = internal_strchr(p, '\n');
-    if (q)
-      *q = '\0';
-    WriteOneLineToSyslog(p);
-    if (q)
-      p = q + 1;
-  } while (q);
-  InternalFree(copy);
-}
 #endif // SANITIZER_LINUX
 
 } // namespace __sanitizer

lib/sanitizer_common/sanitizer_mac.cc

@@ -36,12 +36,14 @@
 extern char **environ;
 #endif
 
+#include <asl.h>
 #include <errno.h>
 #include <fcntl.h>
 #include <libkern/OSAtomic.h>
 #include <mach-o/dyld.h>
 #include <mach/mach.h>
 #include <mach/vm_statistics.h>
+#include <os/trace.h>
 #include <pthread.h>
 #include <sched.h>
 #include <signal.h>
@@ -371,6 +373,45 @@ uptr GetRSS() {
   return info.resident_size;
 }
 
+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 (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.");
+    else if (internal_strncmp(SanitizerToolName, "ThreadSanitizer",
+                              sizeof("ThreadSanitizer") - 1) == 0)
+      os_trace("Thread Sanitizer reported a failure.");
+    else
+      os_trace("Sanitizer tool reported a failure.");
+
+    if (common_flags()->log_to_syslog)
+      os_trace("Consult syslog for more information.");
+  }
+
+  // Log to syslog.
+  // The logging on OS X may call pthread_create so we need the threading
+  // environment to be fully initialized. Also, this should never be called when
+  // holding the thread registry lock since that may result in a deadlock. If
+  // the reporting thread holds the thread registry mutex, and asl_log waits
+  // for GCD to dispatch a new thread, the process will deadlock, because the
+  // pthread_create wrapper needs to acquire the lock as well.
+  BlockingMutexLock l(&syslog_lock);
+  if (common_flags()->log_to_syslog)
+    WriteToSyslog(buffer);
+}
+
 void *internal_start_thread(void (*func)(void *arg), void *arg) { return 0; }
 void internal_join_thread(void *th) { }
 

lib/sanitizer_common/sanitizer_printf.cc

@@ -278,7 +278,7 @@ static void SharedPrintfCode(bool append_pid, const char *format,
 #   undef CHECK_NEEDED_LENGTH
   }
   RawWrite(buffer);
-  if (common_flags()->log_to_syslog)
+  if (common_flags()->log_to_syslog && ShouldLogAfterPrintf())
     WriteToSyslog(buffer);
   CallPrintfAndReportCallback(buffer);
   // If we had mapped any memory, clean up.

lib/sanitizer_common/tests/sanitizer_common_test.cc

@@ -208,6 +208,30 @@ TEST(SanitizerCommon, StripPathPrefix) {
   EXPECT_STREQ("file.h", StripPathPrefix("/usr/lib/./file.h", "/usr/lib/"));
 }
 
+TEST(SanitizerCommon, RemoveANSIEscapeSequencesFromString) {
+  RemoveANSIEscapeSequencesFromString(nullptr);
+  const char *buffs[22] = {
+    "Default",                                "Default",
+    "\033[95mLight magenta",                  "Light magenta",
+    "\033[30mBlack\033[32mGreen\033[90mGray", "BlackGreenGray",
+    "\033[106mLight cyan \033[107mWhite ",    "Light cyan White ",
+    "\033[31mHello\033[0m World",             "Hello World",
+    "\033[38;5;82mHello \033[38;5;198mWorld", "Hello World",
+    "123[653456789012",                       "123[653456789012",
+    "Normal \033[5mBlink \033[25mNormal",     "Normal Blink Normal",
+    "\033[106m\033[107m",                     "",
+    "",                                       "",
+    " ",                                      " ",
+  };
+
+  for (size_t i = 0; i < ARRAY_SIZE(buffs); i+=2) {
+    char *buffer_copy = internal_strdup(buffs[i]);
+    RemoveANSIEscapeSequencesFromString(buffer_copy);
+    EXPECT_STREQ(buffer_copy, buffs[i+1]);
+    InternalFree(buffer_copy);
+  }
+}
+
 TEST(SanitizerCommon, InternalScopedString) {
   InternalScopedString str(10);
   EXPECT_EQ(0U, str.length());

test/asan/lit.cfg

@@ -34,7 +34,9 @@ default_asan_opts = ''
 if config.host_os == 'Darwin':
   # On Darwin, we default to `abort_on_error=1`, which would make tests run
   # much slower. Let's override this and run lit tests with 'abort_on_error=0'.
+  # Also, make sure we do not overwhelm the syslog while testing.
   default_asan_opts = 'abort_on_error=0'
+  default_asan_opts += ':log_to_syslog=0'
 if default_asan_opts:
   config.environment['ASAN_OPTIONS'] = default_asan_opts
   default_asan_opts += ':'

test/ubsan/lit.common.cfg

@@ -42,6 +42,7 @@ if config.host_os == 'Darwin':
   # On Darwin, we default to `abort_on_error=1`, which would make tests run
   # much slower. Let's override this and run lit tests with 'abort_on_error=0'.
   default_ubsan_opts += ['abort_on_error=0']
+  default_ubsan_opts += ['log_to_syslog=0']
 default_ubsan_opts_str = ':'.join(default_ubsan_opts)
 if default_ubsan_opts_str:
   config.environment['UBSAN_OPTIONS'] = default_ubsan_opts_str