From 2ce9f9447c9503534a75315d058fb50f07a01c45 Mon Sep 17 00:00:00 2001 From: Anna Zaks Date: Fri, 20 Nov 2015 18:41:44 +0000 Subject: [PATCH] Reapply: [asan] On OS X, log reports to syslog and os_trace When ASan currently detects a bug, by default it will only print out the text of the report to stderr. This patch changes this behavior and writes the full text of the report to syslog before we terminate the process. It also calls os_trace (Activity Tracing available on OS X and iOS) with a message saying that the report is available in syslog. This is useful, because this message will be shown in the crash log. For this to work, the patch makes sure we store the full report into error_message_buffer unconditionally, and it also strips out ANSI escape sequences from the report (they are used when producing colored reports). I've initially tried to log to syslog during printing, which is done on Android right now. The advantage is that if we crash during error reporting or the produced error does not go through ScopedInErrorReport, we would still get a (partial) message in the syslog. However, that solution is very problematic on OS X. One issue is that the logging routine uses GCD, which may spawn a new thread on its behalf. In many cases, the reporting logic locks threadRegistry, which leads to deadlocks. Reviewed at http://reviews.llvm.org/D13452 (In addition, add sanitizer_common_libcdep.cc to buildgo.sh to avoid build failures on Linux.) llvm-svn: 253688 --- compiler-rt/lib/asan/asan_report.cc | 40 ++++++++------- compiler-rt/lib/asan/tests/asan_test_main.cc | 3 +- .../lib/sanitizer_common/sanitizer_common.cc | 34 +++++++++++++ .../lib/sanitizer_common/sanitizer_common.h | 19 ++++++- .../sanitizer_common_libcdep.cc | 27 +++++++++- .../sanitizer_common_nolibc.cc | 4 +- .../lib/sanitizer_common/sanitizer_flags.inc | 2 +- .../sanitizer_linux_libcdep.cc | 24 ++------- .../lib/sanitizer_common/sanitizer_mac.cc | 49 +++++++++++++++++++ .../lib/sanitizer_common/sanitizer_printf.cc | 2 +- .../tests/sanitizer_common_test.cc | 24 +++++++++ compiler-rt/lib/tsan/go/buildgo.sh | 1 + compiler-rt/test/asan/lit.cfg | 2 + compiler-rt/test/ubsan/lit.common.cfg | 1 + 14 files changed, 186 insertions(+), 46 deletions(-) diff --git a/compiler-rt/lib/asan/asan_report.cc b/compiler-rt/lib/asan/asan_report.cc index fae84041a3a6..365ad61ff1f0 100644 --- a/compiler-rt/lib/asan/asan_report.cc +++ b/compiler-rt/lib/asan/asan_report.cc @@ -31,6 +31,7 @@ static void (*error_report_callback)(const char*); static char *error_message_buffer = nullptr; static uptr error_message_buffer_pos = 0; static uptr error_message_buffer_size = 0; +static BlockingMutex error_message_buf_mutex(LINKER_INITIALIZED); struct ReportData { uptr pc; @@ -46,16 +47,21 @@ static bool report_happened = false; static ReportData report_data = {}; void AppendToErrorMessageBuffer(const char *buffer) { - if (error_message_buffer) { - uptr length = internal_strlen(buffer); - CHECK_GE(error_message_buffer_size, error_message_buffer_pos); - uptr remaining = error_message_buffer_size - error_message_buffer_pos; - internal_strncpy(error_message_buffer + error_message_buffer_pos, - buffer, remaining); - error_message_buffer[error_message_buffer_size - 1] = '\0'; - // FIXME: reallocate the buffer instead of truncating the message. - error_message_buffer_pos += Min(remaining, length); + BlockingMutexLock l(&error_message_buf_mutex); + if (!error_message_buffer) { + error_message_buffer_size = 1 << 16; + error_message_buffer = + (char*)MmapOrDie(error_message_buffer_size, __func__); + error_message_buffer_pos = 0; } + uptr length = internal_strlen(buffer); + CHECK_GE(error_message_buffer_size, error_message_buffer_pos); + uptr remaining = error_message_buffer_size - error_message_buffer_pos; + internal_strncpy(error_message_buffer + error_message_buffer_pos, + buffer, remaining); + error_message_buffer[error_message_buffer_size - 1] = '\0'; + // FIXME: reallocate the buffer instead of truncating the message. + error_message_buffer_pos += Min(remaining, length); } // ---------------------- Decorator ------------------------------ {{{1 @@ -680,8 +686,13 @@ class ScopedInErrorReport { // Print memory stats. if (flags()->print_stats) __asan_print_accumulated_stats(); - if (error_report_callback) { - error_report_callback(error_message_buffer); + { + BlockingMutexLock l(&error_message_buf_mutex); + LogFullErrorReport(error_message_buffer); + + if (error_report_callback) { + error_report_callback(error_message_buffer); + } } CommonSanitizerReportMutex.Unlock(); reporting_thread_tid_ = kInvalidTid; @@ -1112,13 +1123,8 @@ void __asan_report_error(uptr pc, uptr bp, uptr sp, uptr addr, int is_write, } void NOINLINE __asan_set_error_report_callback(void (*callback)(const char*)) { + BlockingMutexLock l(&error_message_buf_mutex); error_report_callback = callback; - if (callback) { - error_message_buffer_size = 1 << 16; - error_message_buffer = - (char*)MmapOrDie(error_message_buffer_size, __func__); - error_message_buffer_pos = 0; - } } void __asan_describe_address(uptr addr) { diff --git a/compiler-rt/lib/asan/tests/asan_test_main.cc b/compiler-rt/lib/asan/tests/asan_test_main.cc index 5958cb8a065f..cdaf801d914b 100644 --- a/compiler-rt/lib/asan/tests/asan_test_main.cc +++ b/compiler-rt/lib/asan/tests/asan_test_main.cc @@ -19,7 +19,8 @@ extern "C" const char* __asan_default_options() { #if SANITIZER_MAC // 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'. - return "symbolize=false:abort_on_error=0"; + // Also, make sure we do not overwhelm the syslog while testing. + return "symbolize=false:abort_on_error=0:log_to_syslog=0"; #else return "symbolize=false"; #endif diff --git a/compiler-rt/lib/sanitizer_common/sanitizer_common.cc b/compiler-rt/lib/sanitizer_common/sanitizer_common.cc index 40edf499ddc9..4697f229f205 100644 --- a/compiler-rt/lib/sanitizer_common/sanitizer_common.cc +++ b/compiler-rt/lib/sanitizer_common/sanitizer_common.cc @@ -297,6 +297,40 @@ void ReportErrorSummary(const char *error_type, const AddressInfo &info) { } #endif +// Removes the ANSI escape sequences from the input string (in-place). +void RemoveANSIEscapeSequencesFromString(char *str) { + if (!str) + return; + + // We are going to remove the escape sequences in place. + char *s = str; + char *z = str; + while (*s != '\0') { + CHECK_GE(s, z); + // Skip over ANSI escape sequences with pointer 's'. + if (*s == '\033' && *(s + 1) == '[') { + s = internal_strchrnul(s, 'm'); + if (*s == '\0') { + break; + } + s++; + continue; + } + // 's' now points at a character we want to keep. Copy over the buffer + // content if the escape sequence has been perviously skipped andadvance + // both pointers. + if (s != z) + *z = *s; + + // If we have not seen an escape sequence, just advance both pointers. + z++; + s++; + } + + // Null terminate the string. + *z = '\0'; +} + void LoadedModule::set(const char *module_name, uptr base_address) { clear(); full_name_ = internal_strdup(module_name); diff --git a/compiler-rt/lib/sanitizer_common/sanitizer_common.h b/compiler-rt/lib/sanitizer_common/sanitizer_common.h index 43cd2d0e8c3d..8c2770b3d46d 100644 --- a/compiler-rt/lib/sanitizer_common/sanitizer_common.h +++ b/compiler-rt/lib/sanitizer_common/sanitizer_common.h @@ -162,6 +162,7 @@ void SetLowLevelAllocateCallback(LowLevelAllocateCallback callback); // IO void RawWrite(const char *buffer); bool ColorizeReports(); +void RemoveANSIEscapeSequencesFromString(char *buffer); void Printf(const char *format, ...); void Report(const char *format, ...); void SetPrintfAndReportCallback(void (*callback)(const char *)); @@ -648,13 +649,27 @@ enum AndroidApiLevel { ANDROID_POST_LOLLIPOP = 23 }; +void WriteToSyslog(const char *buffer); + +#if SANITIZER_MAC +void LogFullErrorReport(const char *error_message_buffer); +#else +INLINE void LogFullErrorReport(const char *error_message_buffer) {} +#endif + +#if SANITIZER_LINUX || SANITIZER_MAC +void WriteOneLineToSyslog(const char *s); +#else +INLINE void WriteOneLineToSyslog(const char *s) {} +#endif + #if SANITIZER_LINUX // Initialize Android logging. Any writes before this are silently lost. void AndroidLogInit(); -void WriteToSyslog(const char *buffer); +bool ShouldLogAfterPrintf(); #else INLINE void AndroidLogInit() {} -INLINE void WriteToSyslog(const char *buffer) {} +INLINE bool ShouldLogAfterPrintf() { return false; } #endif #if SANITIZER_ANDROID diff --git a/compiler-rt/lib/sanitizer_common/sanitizer_common_libcdep.cc b/compiler-rt/lib/sanitizer_common/sanitizer_common_libcdep.cc index 1b65bced75d5..9095002aa621 100644 --- a/compiler-rt/lib/sanitizer_common/sanitizer_common_libcdep.cc +++ b/compiler-rt/lib/sanitizer_common/sanitizer_common_libcdep.cc @@ -12,6 +12,7 @@ //===----------------------------------------------------------------------===// #include "sanitizer_common.h" +#include "sanitizer_allocator_internal.h" #include "sanitizer_flags.h" #include "sanitizer_stackdepot.h" #include "sanitizer_stacktrace.h" @@ -46,6 +47,7 @@ void SetSandboxingCallback(void (*f)()) { } void ReportErrorSummary(const char *error_type, StackTrace *stack) { +#if !SANITIZER_GO if (!common_flags()->print_summary) return; if (stack->size == 0) { @@ -58,6 +60,7 @@ void ReportErrorSummary(const char *error_type, StackTrace *stack) { SymbolizedStack *frame = Symbolizer::GetOrInit()->SymbolizePC(pc); ReportErrorSummary(error_type, frame->info); frame->ClearAll(); +#endif } static void (*SoftRssLimitExceededCallback)(bool exceeded); @@ -116,8 +119,30 @@ void BackgroundThread(void *arg) { } } +void WriteToSyslog(const char *buffer) { + char *copy = internal_strdup(buffer); + char *p = copy; + char *q; + + // Remove color sequences since syslogs cannot print them. + RemoveANSIEscapeSequencesFromString(copy); + + // Print one line at a time. + // syslog, at least on Android, has an implicit message length limit. + do { + q = internal_strchr(p, '\n'); + if (q) + *q = '\0'; + WriteOneLineToSyslog(p); + if (q) + p = q + 1; + } while (q); + InternalFree(copy); +} + void MaybeStartBackgroudThread() { -#if SANITIZER_LINUX // Need to implement/test on other platforms. +#if SANITIZER_LINUX && \ + !SANITIZER_GO // Need to implement/test on other platforms. // Start the background thread if one of the rss limits is given. if (!common_flags()->hard_rss_limit_mb && !common_flags()->soft_rss_limit_mb) return; diff --git a/compiler-rt/lib/sanitizer_common/sanitizer_common_nolibc.cc b/compiler-rt/lib/sanitizer_common/sanitizer_common_nolibc.cc index 65d1e37f62ef..89c17e0797ef 100644 --- a/compiler-rt/lib/sanitizer_common/sanitizer_common_nolibc.cc +++ b/compiler-rt/lib/sanitizer_common/sanitizer_common_nolibc.cc @@ -18,9 +18,9 @@ namespace __sanitizer { #if SANITIZER_LINUX -void WriteToSyslog(const char *buffer) {} +bool ShouldLogAfterPrintf() { return false; } #endif - +void WriteToSyslog(const char *buffer) {} void Abort() { internal__exit(1); } } // namespace __sanitizer diff --git a/compiler-rt/lib/sanitizer_common/sanitizer_flags.inc b/compiler-rt/lib/sanitizer_common/sanitizer_flags.inc index e742d8546639..3b685db5a567 100644 --- a/compiler-rt/lib/sanitizer_common/sanitizer_flags.inc +++ b/compiler-rt/lib/sanitizer_common/sanitizer_flags.inc @@ -56,7 +56,7 @@ COMMON_FLAG( "Mention name of executable when reporting error and " "append executable name to logs (as in \"log_path.exe_name.pid\").") COMMON_FLAG( - bool, log_to_syslog, SANITIZER_ANDROID, + bool, log_to_syslog, SANITIZER_ANDROID || SANITIZER_MAC, "Write all sanitizer output to syslog in addition to other means of " "logging.") COMMON_FLAG( diff --git a/compiler-rt/lib/sanitizer_common/sanitizer_linux_libcdep.cc b/compiler-rt/lib/sanitizer_common/sanitizer_linux_libcdep.cc index 8c12f81a72d7..0bb66c9d634e 100644 --- a/compiler-rt/lib/sanitizer_common/sanitizer_linux_libcdep.cc +++ b/compiler-rt/lib/sanitizer_common/sanitizer_linux_libcdep.cc @@ -524,16 +524,16 @@ void AndroidLogInit() { atomic_store(&android_log_initialized, 1, memory_order_release); } -static bool IsSyslogAvailable() { +bool ShouldLogAfterPrintf() { return atomic_load(&android_log_initialized, memory_order_acquire); } #else void AndroidLogInit() {} -static bool IsSyslogAvailable() { return true; } +bool ShouldLogAfterPrintf() { return true; } #endif // SANITIZER_ANDROID -static void WriteOneLineToSyslog(const char *s) { +void WriteOneLineToSyslog(const char *s) { #if SANITIZER_ANDROID &&__ANDROID_API__ < 21 __android_log_write(ANDROID_LOG_INFO, NULL, s); #else @@ -541,24 +541,6 @@ static void WriteOneLineToSyslog(const char *s) { #endif } -void WriteToSyslog(const char *buffer) { - if (!IsSyslogAvailable()) - return; - char *copy = internal_strdup(buffer); - char *p = copy; - char *q; - // syslog, at least on Android, has an implicit message length limit. - // Print one line at a time. - do { - q = internal_strchr(p, '\n'); - if (q) - *q = '\0'; - WriteOneLineToSyslog(p); - if (q) - p = q + 1; - } while (q); - InternalFree(copy); -} #endif // SANITIZER_LINUX } // namespace __sanitizer diff --git a/compiler-rt/lib/sanitizer_common/sanitizer_mac.cc b/compiler-rt/lib/sanitizer_common/sanitizer_mac.cc index 11d27e864c26..08bb882c221c 100644 --- a/compiler-rt/lib/sanitizer_common/sanitizer_mac.cc +++ b/compiler-rt/lib/sanitizer_common/sanitizer_mac.cc @@ -36,6 +36,14 @@ extern char **environ; #endif +#if defined(__has_include) && __has_include() +#define SANITIZER_OS_TRACE 1 +#include +#else +#define SANITIZER_OS_TRACE 0 +#endif + +#include #include #include #include @@ -406,6 +414,47 @@ void *internal_start_thread(void(*func)(void *arg), void *arg) { void internal_join_thread(void *th) { pthread_join((pthread_t)th, 0); } +static BlockingMutex syslog_lock(LINKER_INITIALIZED); + +void WriteOneLineToSyslog(const char *s) { + syslog_lock.CheckLocked(); + asl_log(nullptr, nullptr, ASL_LEVEL_ERR, "%s", s); +} + +void LogFullErrorReport(const char *buffer) { + // Log with os_trace. This will make it into the crash log. +#if SANITIZER_OS_TRACE + if (GetMacosVersion() >= MACOS_VERSION_YOSEMITE) { + // os_trace requires the message (format parameter) to be a string literal. + if (internal_strncmp(SanitizerToolName, "AddressSanitizer", + sizeof("AddressSanitizer") - 1) == 0) + os_trace("Address Sanitizer reported a failure."); + else if (internal_strncmp(SanitizerToolName, "UndefinedBehaviorSanitizer", + sizeof("UndefinedBehaviorSanitizer") - 1) == 0) + os_trace("Undefined Behavior Sanitizer reported a failure."); + else if (internal_strncmp(SanitizerToolName, "ThreadSanitizer", + sizeof("ThreadSanitizer") - 1) == 0) + os_trace("Thread Sanitizer reported a failure."); + else + os_trace("Sanitizer tool reported a failure."); + + if (common_flags()->log_to_syslog) + os_trace("Consult syslog for more information."); + } +#endif + + // Log to syslog. + // The logging on OS X may call pthread_create so we need the threading + // environment to be fully initialized. Also, this should never be called when + // holding the thread registry lock since that may result in a deadlock. If + // the reporting thread holds the thread registry mutex, and asl_log waits + // for GCD to dispatch a new thread, the process will deadlock, because the + // pthread_create wrapper needs to acquire the lock as well. + BlockingMutexLock l(&syslog_lock); + if (common_flags()->log_to_syslog) + WriteToSyslog(buffer); +} + void GetPcSpBp(void *context, uptr *pc, uptr *sp, uptr *bp) { ucontext_t *ucontext = (ucontext_t*)context; # if defined(__aarch64__) diff --git a/compiler-rt/lib/sanitizer_common/sanitizer_printf.cc b/compiler-rt/lib/sanitizer_common/sanitizer_printf.cc index 5f4725ec1d2c..2794e667e697 100644 --- a/compiler-rt/lib/sanitizer_common/sanitizer_printf.cc +++ b/compiler-rt/lib/sanitizer_common/sanitizer_printf.cc @@ -278,7 +278,7 @@ static void SharedPrintfCode(bool append_pid, const char *format, # undef CHECK_NEEDED_LENGTH } RawWrite(buffer); - if (common_flags()->log_to_syslog) + if (common_flags()->log_to_syslog && ShouldLogAfterPrintf()) WriteToSyslog(buffer); CallPrintfAndReportCallback(buffer); // If we had mapped any memory, clean up. diff --git a/compiler-rt/lib/sanitizer_common/tests/sanitizer_common_test.cc b/compiler-rt/lib/sanitizer_common/tests/sanitizer_common_test.cc index c1bb797db203..6fc308ad14d4 100644 --- a/compiler-rt/lib/sanitizer_common/tests/sanitizer_common_test.cc +++ b/compiler-rt/lib/sanitizer_common/tests/sanitizer_common_test.cc @@ -208,6 +208,30 @@ TEST(SanitizerCommon, StripPathPrefix) { EXPECT_STREQ("file.h", StripPathPrefix("/usr/lib/./file.h", "/usr/lib/")); } +TEST(SanitizerCommon, RemoveANSIEscapeSequencesFromString) { + RemoveANSIEscapeSequencesFromString(nullptr); + const char *buffs[22] = { + "Default", "Default", + "\033[95mLight magenta", "Light magenta", + "\033[30mBlack\033[32mGreen\033[90mGray", "BlackGreenGray", + "\033[106mLight cyan \033[107mWhite ", "Light cyan White ", + "\033[31mHello\033[0m World", "Hello World", + "\033[38;5;82mHello \033[38;5;198mWorld", "Hello World", + "123[653456789012", "123[653456789012", + "Normal \033[5mBlink \033[25mNormal", "Normal Blink Normal", + "\033[106m\033[107m", "", + "", "", + " ", " ", + }; + + for (size_t i = 0; i < ARRAY_SIZE(buffs); i+=2) { + char *buffer_copy = internal_strdup(buffs[i]); + RemoveANSIEscapeSequencesFromString(buffer_copy); + EXPECT_STREQ(buffer_copy, buffs[i+1]); + InternalFree(buffer_copy); + } +} + TEST(SanitizerCommon, InternalScopedString) { InternalScopedString str(10); EXPECT_EQ(0U, str.length()); diff --git a/compiler-rt/lib/tsan/go/buildgo.sh b/compiler-rt/lib/tsan/go/buildgo.sh index f31b7dad53e8..fdbd4056959c 100755 --- a/compiler-rt/lib/tsan/go/buildgo.sh +++ b/compiler-rt/lib/tsan/go/buildgo.sh @@ -20,6 +20,7 @@ SRCS=" ../rtl/tsan_sync.cc ../../sanitizer_common/sanitizer_allocator.cc ../../sanitizer_common/sanitizer_common.cc + ../../sanitizer_common/sanitizer_common_libcdep.cc ../../sanitizer_common/sanitizer_deadlock_detector2.cc ../../sanitizer_common/sanitizer_flag_parser.cc ../../sanitizer_common/sanitizer_flags.cc diff --git a/compiler-rt/test/asan/lit.cfg b/compiler-rt/test/asan/lit.cfg index fd99f669961a..835547090a17 100644 --- a/compiler-rt/test/asan/lit.cfg +++ b/compiler-rt/test/asan/lit.cfg @@ -34,7 +34,9 @@ default_asan_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'. + # Also, make sure we do not overwhelm the syslog while testing. default_asan_opts = 'abort_on_error=0' + default_asan_opts += ':log_to_syslog=0' if default_asan_opts: config.environment['ASAN_OPTIONS'] = default_asan_opts default_asan_opts += ':' diff --git a/compiler-rt/test/ubsan/lit.common.cfg b/compiler-rt/test/ubsan/lit.common.cfg index 8e8440666424..e50862983d62 100644 --- a/compiler-rt/test/ubsan/lit.common.cfg +++ b/compiler-rt/test/ubsan/lit.common.cfg @@ -42,6 +42,7 @@ 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'. default_ubsan_opts += ['abort_on_error=0'] + default_ubsan_opts += ['log_to_syslog=0'] default_ubsan_opts_str = ':'.join(default_ubsan_opts) if default_ubsan_opts_str: config.environment['UBSAN_OPTIONS'] = default_ubsan_opts_str