Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Conversation

danliew-apple
Copy link

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 445b810)

…ing 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 445b810)
@danliew-apple
Copy link
Author

@swift-ci please test

@danliew-apple
Copy link
Author

@swift-ci Please test OS X platform

@danliew-apple
Copy link
Author

We're hitting a network outage: https://forums.swift.org/t/unexpected-outage-on-ci-swift-org-3-26/34838

@danliew-apple
Copy link
Author

@swift-ci Please test OS X platform

@danliew-apple
Copy link
Author

Hmm well the tests ran this time but the new fails.

FAIL: AddressSanitizer-x86_64-darwin :: TestCases/Darwin/duplicate_os_log_reports.cpp (4613 of 56513)
******************** TEST 'AddressSanitizer-x86_64-darwin :: TestCases/Darwin/duplicate_os_log_reports.cpp' FAILED ********************
Script:
--
: 'RUN: at line 4';      /Users/buildnode/jenkins/workspace/apple-llvm-project-pr-macos/llvm-project/build/./bin/clang  --driver-mode=g++ -fsanitize=address -mno-omit-leaf-frame-pointer -fno-omit-frame-pointer -fno-optimize-sibling-calls -gline-tables-only  -arch x86_64 -stdlib=libc++ -mmacosx-version-min=10.10 -isysroot /Applications/Xcode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX10.15.sdk  -shared-libasan -fsanitize-recover=address /Users/buildnode/jenkins/workspace/apple-llvm-project-pr-macos/llvm-project/compiler-rt/test/asan/TestCases/Darwin/duplicate_os_log_reports.cpp -o /Users/buildnode/jenkins/workspace/apple-llvm-project-pr-macos/llvm-project/build/projects/compiler-rt/test/asan/X86_64DarwinConfig/TestCases/Darwin/Output/duplicate_os_log_reports.cpp.tmp
: 'RUN: at line 5';   { env ASAN_OPTIONS=abort_on_error=0:log_to_syslog=0:detect_leaks=1:halt_on_error=0,log_to_syslog=1  /Users/buildnode/jenkins/workspace/apple-llvm-project-pr-macos/llvm-project/build/projects/compiler-rt/test/asan/X86_64DarwinConfig/TestCases/Darwin/Output/duplicate_os_log_reports.cpp.tmp > /Users/buildnode/jenkins/workspace/apple-llvm-project-pr-macos/llvm-project/build/projects/compiler-rt/test/asan/X86_64DarwinConfig/TestCases/Darwin/Output/duplicate_os_log_reports.cpp.tmp.process_output.txt 2>&1 & }  ; export TEST_PID=$! ; wait ${TEST_PID}
: 'RUN: at line 9';   FileCheck /Users/buildnode/jenkins/workspace/apple-llvm-project-pr-macos/llvm-project/compiler-rt/test/asan/TestCases/Darwin/duplicate_os_log_reports.cpp --check-prefixes CHECK,CHECK-PROC -input-file=/Users/buildnode/jenkins/workspace/apple-llvm-project-pr-macos/llvm-project/build/projects/compiler-rt/test/asan/X86_64DarwinConfig/TestCases/Darwin/Output/duplicate_os_log_reports.cpp.tmp.process_output.txt
: 'RUN: at line 13';   log show --debug --last 2m  --predicate "processID == ${TEST_PID}" --style syslog > /Users/buildnode/jenkins/workspace/apple-llvm-project-pr-macos/llvm-project/build/projects/compiler-rt/test/asan/X86_64DarwinConfig/TestCases/Darwin/Output/duplicate_os_log_reports.cpp.tmp.process_syslog_output.txt
: 'RUN: at line 14';   FileCheck /Users/buildnode/jenkins/workspace/apple-llvm-project-pr-macos/llvm-project/compiler-rt/test/asan/TestCases/Darwin/duplicate_os_log_reports.cpp -input-file=/Users/buildnode/jenkins/workspace/apple-llvm-project-pr-macos/llvm-project/build/projects/compiler-rt/test/asan/X86_64DarwinConfig/TestCases/Darwin/Output/duplicate_os_log_reports.cpp.tmp.process_syslog_output.txt
--
Exit Code: 77

Command Output (stderr):
--
log: Could not open local log store: Operation not permitted

--

@shahmishal Any idea why its not possible to query the local logs on the bot?

@danliew-apple
Copy link
Author

Hmm actually I guess it's because the bot user is unprivileged.

I've put up a fix to disable running the test if log show doesn't on llvm.org (https://reviews.llvm.org/D76899). I'll cherry-pick it here once it's approved.

…queried.

Summary:
Follow up fix to 445b810. The `log show` command only works for
privileged users so run a quick test of the command during lit config to
see if the command works and only add the `darwin_log_cmd` feature if
this is the case.

Unfortunately this means the `asan/TestCases/Darwin/duplicate_os_log_reports.cpp`
test and any other tests in the future that use this feature won't run
for unprivileged users which is likely the case in CI.

rdar://problem/55986279

Reviewers: kubamracek, yln, dcoughlin

Subscribers: Charusso, #sanitizers, llvm-commits

Tags: #sanitizers

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

(cherry picked from commit 853a1e6)
@danliew-apple
Copy link
Author

@swift-ci Please test OS X platform

@danliew-apple danliew-apple merged commit 7533999 into swiftlang:apple/stable/20200108 Mar 27, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants