[compiler-rt] 445b810 - [ASan] Fix issue where system log buffer was not cleared after reporting an issue.

[Dan Liew via llvm-commits]

Author: Dan Liew
Date: 2020-03-26T10:56:17-07:00
New Revision: 445b810fbd4f1dad71fbdf96ba1c3b947417b884

URL: https://github.com/llvm/llvm-project/commit/445b810fbd4f1dad71fbdf96ba1c3b947417b884
DIFF: https://github.com/llvm/llvm-project/commit/445b810fbd4f1dad71fbdf96ba1c3b947417b884.diff

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

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

Reviewers: kubamracek, yln, vitalybuka, kcc, filcab

Subscribers: #sanitizers, llvm-commits

Tags: #sanitizers

Differential Revision: https://reviews.llvm.org/D76749

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

Modified: 
    compiler-rt/lib/asan/asan_report.cpp
    compiler-rt/test/lit.common.cfg.py

Removed: 
    


################################################################################
diff  --git a/compiler-rt/lib/asan/asan_report.cpp b/compiler-rt/lib/asan/asan_report.cpp
index 2e6ce436d030..99e8678aa785 100644
--- a/compiler-rt/lib/asan/asan_report.cpp
+++ b/compiler-rt/lib/asan/asan_report.cpp
@@ -160,6 +160,9 @@ class ScopedInErrorReport {
       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());

diff  --git a/compiler-rt/test/asan/TestCases/Darwin/duplicate_os_log_reports.cpp b/compiler-rt/test/asan/TestCases/Darwin/duplicate_os_log_reports.cpp
new file mode 100644
index 000000000000..5f923d22a9a4
--- /dev/null
+++ b/compiler-rt/test/asan/TestCases/Darwin/duplicate_os_log_reports.cpp
@@ -0,0 +1,68 @@
+// 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;
+}

diff  --git a/compiler-rt/test/lit.common.cfg.py b/compiler-rt/test/lit.common.cfg.py
index 3b1ea53fb8d9..d7def93d82ce 100644
--- a/compiler-rt/test/lit.common.cfg.py
+++ b/compiler-rt/test/lit.common.cfg.py
@@ -533,6 +533,10 @@ def is_windows_lto_supported():
   # 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']