[ASan] Fix issue where system log buffer was not cleared after reporting an issue.

[delcypher]

Summary

When ASan reports an issue the contents of the system log buffer
(error_message_buffer) get flushed to the system log (via
LogFullErrorReport()). After this happens the buffer is not cleared
but this is usually fine because the process usually exits soon after
reporting the issue.

However, when ASan runs in halt_on_error=0 mode execution continues
without clearing the buffer. This leads to problems if more ASan
issues are found and reported.

1. Duplicate ASan reports in the system log. The Nth (start counting from 1)

ASan report will be duplicated (M - N) times in the system log if M is the
number of ASan issues reported.

2. Lost ASan reports. Given a sufficient

number of reports the buffer will fill up and consequently cannot be appended
to. This means reports can be lost.

The fix here is to reset error_message_buffer_pos to 0 which
effectively clears the system log buffer.

A test case is included but unfortunately it is Darwin specific because
querying the system log is an OS specific activity.

rdar://problem/55986279

[vitalybuka]

compiler-rt/lib/asan/asan_report.cpp

58

static?
or maybe just avoid a function

162–165

I guess it should be reset here just after internal_memcpy under the same lock

[delcypher]

compiler-rt/lib/asan/asan_report.cpp

58

The reason I made this a function is because I intend to refactor the logging support out of ASan into sanitizer_common so that UBSan has syslog support. However putting the logic inside a function at this stage is probably premature. I'll remove it.

162–165

That sounds reasonable. I placed my code later because there was already a block conditional on halt_on_error_. However what you suggested sounds better because it avoids any races where something writes to the buffer after it gets released here and where I added my code to clear the buffer.

[delcypher]

Address review feedback

[delcypher]

@vitalybuka Thanks for the initial review. I've tried to address your comments. Please let me know if there's anything else you'd like to change.

[vitalybuka]

compiler-rt/lib/asan/asan_report.cpp

163

why do we need to check halt_on_error_?
we copied all info line above, we need nothing there in any case

[delcypher]

compiler-rt/lib/asan/asan_report.cpp

163

Clearing the buffer is only needed when halt_on_error_ is false. However the process will soon die when halt_on_error_ is true so there probably isn't any harm is clearing the buffer unconditionally. I'll update the patch.

[delcypher]

Clear error_message_buffer unconditionally.

compiler-rt/lib/asan/asan_report.cpp

internal_strncpy(error_message_buffer + error_message_buffer_pos,
                    buffer, remaining);
   error_message_buffer[kErrorMessageBufferSize - 1] = '\0';
   // FIXME: reallocate the buffer instead of truncating the message.
   error_message_buffer_pos += Min(remaining, length);
 }
 
 // ---------------------- Helper functions ----------------------- {{{1
 
 void PrintMemoryByte(InternalScopedString *str, const char *before, u8 byte,
                      bool in_shadow, const char *after) {
   Decorator d;
   str->append("%s%s%x%x%s%s", before,
               in_shadow ? d.ShadowByte(byte) : d.MemoryByte(), byte >> 4,
               byte & 15, d.Default(), after);
 }
 
 static void PrintZoneForPointer(uptr ptr, uptr zone_ptr,
~ScopedInErrorReport() {
     if (common_flags()->print_module_map == 2) PrintModuleMap();
 
     // Copy the message buffer so that we could start logging without holding a
     // lock that gets aquired during printing.
     InternalMmapVector<char> buffer_copy(kErrorMessageBufferSize);
     {
       BlockingMutexLock l(&error_message_buf_mutex);
       internal_memcpy(buffer_copy.data(),
                       error_message_buffer, kErrorMessageBufferSize);
+      // Clear error_message_buffer so that if we find other errors
+      // we don't re-log this error.
+      error_message_buffer_pos = 0;
     }
 
     LogFullErrorReport(buffer_copy.data());
 
     if (error_report_callback) {
       error_report_callback(buffer_copy.data());
     }
 

compiler-rt/test/asan/TestCases/Darwin/duplicate_os_log_reports.cpp

+// UNSUPPORTED: ios
+// REQUIRES: shell
+// REQUIRES: darwin_log_cmd
+// RUN: %clangxx_asan -fsanitize-recover=address %s -o %t
+// RUN: { %env_asan_opts=halt_on_error=0,log_to_syslog=1 %run %t > %t.process_output.txt 2>&1 & } \
+// RUN: ; export TEST_PID=$! ; wait ${TEST_PID}
+
+// Check process output.
+// RUN: FileCheck %s --check-prefixes CHECK,CHECK-PROC -input-file=%t.process_output.txt
+
+// Check syslog output. We filter recent system logs based on PID to avoid
+// getting the logs of previous test runs.
+// RUN: log show --debug --last 2m  --predicate "processID == ${TEST_PID}" --style syslog > %t.process_syslog_output.txt
+// RUN: FileCheck %s -input-file=%t.process_syslog_output.txt
+#include <cassert>
+#include <cstdio>
+#include <sanitizer/asan_interface.h>
+
+const int kBufferSize = 512;
+char *buffer;
+
+// `readZero` and `readOne` exist so that we can distinguish the two
+// error reports based on the symbolized stacktrace.
+void readZero() {
+  assert(__asan_address_is_poisoned(buffer));
+  char c = buffer[0];
+  printf("Read %c\n", c);
+}
+
+void readOne() {
+  assert(__asan_address_is_poisoned(buffer + 1));
+  char c = buffer[1];
+  printf("Read %c\n", c);
+}
+
+int main() {
+  buffer = static_cast<char *>(malloc(kBufferSize));
+  assert(buffer);
+  // Deliberately poison `buffer` so that we have a deterministic way
+  // triggering two ASan reports in a row in the no halt_on_error mode (e.g. Two
+  // heap-use-after free in a row might not be deterministic).
+  __asan_poison_memory_region(buffer, kBufferSize);
+
+  // This sequence of ASan reports are designed to catch an old bug in the way
+  // ASan's internal syslog buffer was handled after reporting an issue.
+  // Previously in the no halt_on_error mode the internal buffer wasn't cleared
+  // after reporting an issue. When another issue was encountered everything
+  // that was already in the buffer would be written to the syslog again
+  // leading to duplicate reports in the syslog.
+
+  // First bad access.
+  // CHECK: use-after-poison
+  // CHECK-NEXT: READ of size 1
+  // CHECK-NEXT: #0 0x{{[0-9a-f]+}} in readZero
+  // CHECK: SUMMARY: {{.*}} use-after-poison {{.*}} in readZero
+  readZero();
+
+  // Second bad access.
+  // CHECK: use-after-poison
+  // CHECK-NEXT: READ of size 1
+  // CHECK-NEXT: #0 0x{{[0-9a-f]+}} in readOne
+  // CHECK: SUMMARY: {{.*}} use-after-poison {{.*}} in readOne
+  readOne();
+
+  // CHECK-PROC: DONE
+  printf("DONE\n");
+  return 0;
+}

compiler-rt/test/lit.common.cfg.py

else:
   config.substitutions.append( ("%linux_static_libstdcplusplus", "") )
 
 config.default_sanitizer_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'.
   config.default_sanitizer_opts += ['abort_on_error=0']
   config.default_sanitizer_opts += ['log_to_syslog=0']
+  if lit.util.which('log'):
+    config.available_features.add('darwin_log_cmd')
+  else:
+    lit_config.warning('log command not found. Some tests will be skipped.')
 elif config.android:
   config.default_sanitizer_opts += ['abort_on_error=0']
 
 # Allow tests to use REQUIRES=stable-runtime.  For use when you cannot use XFAIL
 # because the test hangs or fails on one configuration and not the other.
 if config.android or (config.target_arch not in ['arm', 'armhf', 'aarch64']):
   config.available_features.add('stable-runtime')