Skip to content

Commit 445b810

Browse files
committed
[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
1 parent 3dceb6d commit 445b810

File tree

3 files changed

+75
-0
lines changed

3 files changed

+75
-0
lines changed

compiler-rt/lib/asan/asan_report.cpp

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -160,6 +160,9 @@ class ScopedInErrorReport {
160160
BlockingMutexLock l(&error_message_buf_mutex);
161161
internal_memcpy(buffer_copy.data(),
162162
error_message_buffer, kErrorMessageBufferSize);
163+
// Clear error_message_buffer so that if we find other errors
164+
// we don't re-log this error.
165+
error_message_buffer_pos = 0;
163166
}
164167

165168
LogFullErrorReport(buffer_copy.data());
Lines changed: 68 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,68 @@
1+
// UNSUPPORTED: ios
2+
// REQUIRES: shell
3+
// REQUIRES: darwin_log_cmd
4+
// RUN: %clangxx_asan -fsanitize-recover=address %s -o %t
5+
// RUN: { %env_asan_opts=halt_on_error=0,log_to_syslog=1 %run %t > %t.process_output.txt 2>&1 & } \
6+
// RUN: ; export TEST_PID=$! ; wait ${TEST_PID}
7+
8+
// Check process output.
9+
// RUN: FileCheck %s --check-prefixes CHECK,CHECK-PROC -input-file=%t.process_output.txt
10+
11+
// Check syslog output. We filter recent system logs based on PID to avoid
12+
// getting the logs of previous test runs.
13+
// RUN: log show --debug --last 2m --predicate "processID == ${TEST_PID}" --style syslog > %t.process_syslog_output.txt
14+
// RUN: FileCheck %s -input-file=%t.process_syslog_output.txt
15+
#include <cassert>
16+
#include <cstdio>
17+
#include <sanitizer/asan_interface.h>
18+
19+
const int kBufferSize = 512;
20+
char *buffer;
21+
22+
// `readZero` and `readOne` exist so that we can distinguish the two
23+
// error reports based on the symbolized stacktrace.
24+
void readZero() {
25+
assert(__asan_address_is_poisoned(buffer));
26+
char c = buffer[0];
27+
printf("Read %c\n", c);
28+
}
29+
30+
void readOne() {
31+
assert(__asan_address_is_poisoned(buffer + 1));
32+
char c = buffer[1];
33+
printf("Read %c\n", c);
34+
}
35+
36+
int main() {
37+
buffer = static_cast<char *>(malloc(kBufferSize));
38+
assert(buffer);
39+
// Deliberately poison `buffer` so that we have a deterministic way
40+
// triggering two ASan reports in a row in the no halt_on_error mode (e.g. Two
41+
// heap-use-after free in a row might not be deterministic).
42+
__asan_poison_memory_region(buffer, kBufferSize);
43+
44+
// This sequence of ASan reports are designed to catch an old bug in the way
45+
// ASan's internal syslog buffer was handled after reporting an issue.
46+
// Previously in the no halt_on_error mode the internal buffer wasn't cleared
47+
// after reporting an issue. When another issue was encountered everything
48+
// that was already in the buffer would be written to the syslog again
49+
// leading to duplicate reports in the syslog.
50+
51+
// First bad access.
52+
// CHECK: use-after-poison
53+
// CHECK-NEXT: READ of size 1
54+
// CHECK-NEXT: #0 0x{{[0-9a-f]+}} in readZero
55+
// CHECK: SUMMARY: {{.*}} use-after-poison {{.*}} in readZero
56+
readZero();
57+
58+
// Second bad access.
59+
// CHECK: use-after-poison
60+
// CHECK-NEXT: READ of size 1
61+
// CHECK-NEXT: #0 0x{{[0-9a-f]+}} in readOne
62+
// CHECK: SUMMARY: {{.*}} use-after-poison {{.*}} in readOne
63+
readOne();
64+
65+
// CHECK-PROC: DONE
66+
printf("DONE\n");
67+
return 0;
68+
}

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

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -533,6 +533,10 @@ def is_windows_lto_supported():
533533
# much slower. Let's override this and run lit tests with 'abort_on_error=0'.
534534
config.default_sanitizer_opts += ['abort_on_error=0']
535535
config.default_sanitizer_opts += ['log_to_syslog=0']
536+
if lit.util.which('log'):
537+
config.available_features.add('darwin_log_cmd')
538+
else:
539+
lit_config.warning('log command not found. Some tests will be skipped.')
536540
elif config.android:
537541
config.default_sanitizer_opts += ['abort_on_error=0']
538542

0 commit comments

Comments
 (0)