From e0481bd3f668cbe349f1d6c14a40dca7bafeca1a Mon Sep 17 00:00:00 2001 From: Dan Liew Date: Tue, 24 Mar 2020 19:39:44 -0700 Subject: [PATCH] [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 (cherry picked from commit 445b810fbd4f1dad71fbdf96ba1c3b947417b884) --- compiler-rt/lib/asan/asan_report.cpp | 3 + .../Darwin/duplicate_os_log_reports.cpp | 68 +++++++++++++++++++ compiler-rt/test/lit.common.cfg.py | 4 ++ 3 files changed, 75 insertions(+) create mode 100644 compiler-rt/test/asan/TestCases/Darwin/duplicate_os_log_reports.cpp diff --git a/compiler-rt/lib/asan/asan_report.cpp b/compiler-rt/lib/asan/asan_report.cpp index 2e6ce436d0306..99e8678aa7857 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 0000000000000..5f923d22a9a41 --- /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 +#include +#include + +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(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 622261535fa2e..6026c604ce496 100644 --- a/compiler-rt/test/lit.common.cfg.py +++ b/compiler-rt/test/lit.common.cfg.py @@ -537,6 +537,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']