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

[kubamracek]

Summary

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

[filcab]

lib/asan/asan_report.cc

708

Is this error_message_buffer_size == 0 something we should reasonably expect?

[kubamracek]

Is this error_message_buffer_size == 0 something we should reasonably expect?

Not really. At this point, something was definitely already written to the message buffer. Removed the check.

[kcc]

lib/asan/asan_report.cc

631

OMG, no.
Instead of removing the ANSI escapes can't we just not emit them?

707

Please move large ifdef-ed chunks of code into separate functions

[zaks.anna]

lib/asan/asan_report.cc

631

We want the colored report to be printed but store the color-less report in the syslog. The buffer we get here, 'error_message_buffer', is exactly what gets printed. So simply using a different decorator would not work, unless we want to generate the report twice..

[kcc]

lib/asan/asan_report.cc

631

So, you say that a user is going to let asan print the output to screen (not to file!!!)
and will still need to have the sys log entry?

Well, ok...

Please write a unit test for it (probably in sanitizer_common_test.cc)

[kcc]

also, consider moving all of the mac-specific code to sanitizer_mac.cc

[samsonov]

lib/asan/asan_report.cc

53

Is this function called under some mutex? Can we check for that?

721

So, does it mean that error_report_callback is invoked with ANSI escape sequences? Maybe, we don't need them there either?

[zaks.anna]

So, does it mean that error_report_callback is invoked with ANSI escape sequences? Maybe, we don't need
them there either?

Yes and I don't think it would be easy to change. Here is my understanding of how this works. The users of Printf decide how everything should be decorated. Sometimes the messages are added to a temporary buffer with the ANSI escape sequences already in place even before calling Printf.
Ex:
static void DescribeAccessToHeapChunk(AsanChunkView chunk, uptr addr,

                                    uptr access_size) {
sptr offset;
Decorator d;
InternalScopedString str(4096);
str.append("%s", d.Location());
str.append("%s", d.Location());
if (chunk.AddrIsAtLeft(addr, access_size, &offset)) {
  str.append("%p is located %zd bytes to the left of", (void *)addr, offset);
...
str.append("%s", d.EndLocation());
Printf("%s", str.data());

}
The error_report_callback callback is called at the last step in the implementation of SharedPrintfCode; we are passed the same buffer and have no control over the decoration at that point:

RawWrite(buffer);
if (common_flags()->log_to_syslog)
  WriteToSyslog(buffer);
CallPrintfAndReportCallback(buffer);

Interesting.. looks like logging to syslog for Android is done directly right there on every Printf and the logging is done with ANSI in place...

If we log there, everything not only "error reports", will be logged.
Also, should we consider logging line by line, syslog does not work well with new line characters?

[kcc]

Interesting.. looks like logging to syslog for Android is done directly right there on every Printf and the logging is done with ANSI in place...

I don't think that we ever print error messages on android to the screen,
i.e. the ANSI colors are disabled and not printed at all

[glider]

lib/asan/asan_report.cc

631

We can store the report in a linked list of strings with ANSI characters emitted to separate strings and marked somehow. Then we can easily reconstruct the report without markup.

[kcc]

lib/asan/asan_report.cc

631

OMG, no!

[filcab]

I was looking at this and… Shouldn't something like this be in sanitizer_common, and then all the sanitizers could use it?
It seems to me that our method of reporting errors is different from sanitizer to sanitizer, and changes like this would need to be done again for other sanitizers, which doesn't seem very nice.

[kcc]

In D11981#226987, @filcab wrote:

I was looking at this and… Shouldn't something like this be in sanitizer_common, and then all the sanitizers could use it?
It seems to me that our method of reporting errors is different from sanitizer to sanitizer, and changes like this would need to be done again for other sanitizers, which doesn't seem very nice.

Yes, as I've also mentioned above we should move most of this Mac-specific code to sanitizer_mac.cc (which is in sanitizer_common).

[kubamracek]

Superseded by http://reviews.llvm.org/D13452, closing.

lib/asan/asan_report.cc

 #include "asan_stack.h"
 #include "asan_thread.h"
 #include "sanitizer_common/sanitizer_common.h"
 #include "sanitizer_common/sanitizer_flags.h"
 #include "sanitizer_common/sanitizer_report_decorator.h"
 #include "sanitizer_common/sanitizer_stackdepot.h"
 #include "sanitizer_common/sanitizer_symbolizer.h"
 
+#if SANITIZER_MAC
+# include <asl.h>
+# include <os/trace.h>
+#endif
+
 namespace __asan {
 
 // -------------------- User-specified callbacks ----------------- {{{1
 static void (*error_report_callback)(const char*);
 static char *error_message_buffer = 0;
 static uptr error_message_buffer_pos = 0;
 static uptr error_message_buffer_size = 0;
 
 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) {
-  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);
-  }
-}
+  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;
+  }
+
 
 // ---------------------- Decorator ------------------------------ {{{1
 class Decorator: public __sanitizer::SanitizerCommonDecorator {
  public:
   Decorator() : SanitizerCommonDecorator() { }
   const char *Access()     { return Blue(); }
   const char *EndAccess()  { return Default(); }
   const char *Location()   { return Green(); }
if (flags()->print_full_thread_history) {
     AsanThreadContext *parent_context =
         GetThreadContextByTidLocked(context->parent_tid);
     DescribeThread(parent_context);
   }
 }
 
 // -------------------- Different kinds of reports ----------------- {{{1
 
+// 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') {
+    // Skip ANSI escape sequences.
+    if (*s == '\033' && *(s + 1) == '[') {
+      while (*s != 'm' && *s != '\0') {
+        s++;
+      }
+      if (*s == '\0') {
+        break;
+      }
+    // Copy over the buffer content.
+    } else if (s != z) {
+      CHECK_GT(s, z);
+      *z = *s;
+      z++;
+    }
+    s++;
+  }
+
+  // Null terminate the string.
+  *z = '\0';
+}
+
 // Use ScopedInErrorReport to run common actions just before and
 // immediately after printing error report.
 class ScopedInErrorReport {
  public:
   explicit ScopedInErrorReport(ReportData *report = nullptr) {
     static atomic_uint32_t num_calls;
     static u32 reporting_thread_tid;
     if (atomic_fetch_add(&num_calls, 1, memory_order_relaxed) != 0) {
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();
+
+#if SANITIZER_MAC
+    RemoveANSIEscapeSequencesFromString(error_message_buffer);
+
+    // Log the full message to syslog.
+    asl_log(nullptr, nullptr, ASL_LEVEL_ERR, "%s", error_message_buffer);
+
+    // Log with os_trace. This will make it into the crash log.
+    if (&_os_trace_with_buffer != nullptr) {
+      os_trace("AddressSanitizer reported a failure. "
+               "Consult syslog for more information.");
+    }
+#endif
+
     if (error_report_callback) {
       error_report_callback(error_message_buffer);
     }
     Report("ABORTING\n");
     Die();
   }
 };
 
 void ReportStackOverflow(const SignalContext &sig) {
   ScopedInErrorReport in_report;
void __asan_report_error(uptr pc, uptr bp, uptr sp, uptr addr, int is_write,
 
   DescribeAddress(addr, access_size, bug_descr);
   ReportErrorSummary(bug_descr, &stack);
   PrintShadowMemoryForAddress(addr);
 }
 
 void NOINLINE __asan_set_error_report_callback(void (*callback)(const char*)) {
   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) {
   // Thread registry must be locked while we're describing an address.
   asanThreadRegistry().Lock();
   DescribeAddress(addr, 1, "");
   asanThreadRegistry().Unlock();
 }