From 72f38c18d7a51953e3708bcb4d36d519395cfc4b Mon Sep 17 00:00:00 2001 From: Anna Zaks Date: Tue, 27 Oct 2015 20:13:01 +0000 Subject: [PATCH] [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 git-svn-id: https://llvm.org/svn/llvm-project/compiler-rt/trunk@251447 91177308-0d34-0410-b5e6-96231b3b80d8 --- lib/asan/asan_report.cc | 40 ++++++++++-------- 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 | 22 ++++++++++ lib/sanitizer_common/sanitizer_flags.inc | 2 +- .../sanitizer_linux_libcdep.cc | 24 ++--------- lib/sanitizer_common/sanitizer_mac.cc | 41 +++++++++++++++++++ lib/sanitizer_common/sanitizer_printf.cc | 2 +- .../tests/sanitizer_common_test.cc | 24 +++++++++++ test/asan/lit.cfg | 2 + test/ubsan/lit.common.cfg | 1 + 12 files changed, 171 insertions(+), 43 deletions(-) diff --git a/lib/asan/asan_report.cc b/lib/asan/asan_report.cc index 957ac14e..5c266b65 100644 --- a/lib/asan/asan_report.cc +++ b/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 @@ -664,8 +670,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); + } } Report("ABORTING\n"); Die(); @@ -1061,13 +1072,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/lib/asan/tests/asan_test_main.cc b/lib/asan/tests/asan_test_main.cc index 5958cb8a..cdaf801d 100644 --- a/lib/asan/tests/asan_test_main.cc +++ b/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/lib/sanitizer_common/sanitizer_common.cc b/lib/sanitizer_common/sanitizer_common.cc index 2fb88688..db734d62 100644 --- a/lib/sanitizer_common/sanitizer_common.cc +++ b/lib/sanitizer_common/sanitizer_common.cc @@ -295,6 +295,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/lib/sanitizer_common/sanitizer_common.h b/lib/sanitizer_common/sanitizer_common.h index bfd0d6e1..63c772bc 100644 --- a/lib/sanitizer_common/sanitizer_common.h +++ b/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/lib/sanitizer_common/sanitizer_common_libcdep.cc b/lib/sanitizer_common/sanitizer_common_libcdep.cc index 1b65bced..865f0d58 100644 --- a/lib/sanitizer_common/sanitizer_common_libcdep.cc +++ b/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" @@ -116,6 +117,27 @@ 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. // Start the background thread if one of the rss limits is given. diff --git a/lib/sanitizer_common/sanitizer_flags.inc b/lib/sanitizer_common/sanitizer_flags.inc index e742d854..3b685db5 100644 --- a/lib/sanitizer_common/sanitizer_flags.inc +++ b/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/lib/sanitizer_common/sanitizer_linux_libcdep.cc b/lib/sanitizer_common/sanitizer_linux_libcdep.cc index 97c65676..cf58f04a 100644 --- a/lib/sanitizer_common/sanitizer_linux_libcdep.cc +++ b/lib/sanitizer_common/sanitizer_linux_libcdep.cc @@ -548,16 +548,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 @@ -565,24 +565,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/lib/sanitizer_common/sanitizer_mac.cc b/lib/sanitizer_common/sanitizer_mac.cc index 3151cf8b..951a48a7 100644 --- a/lib/sanitizer_common/sanitizer_mac.cc +++ b/lib/sanitizer_common/sanitizer_mac.cc @@ -36,12 +36,14 @@ extern char **environ; #endif +#include #include #include #include #include #include #include +#include #include #include #include @@ -371,6 +373,45 @@ uptr GetRSS() { return info.resident_size; } +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 (GetMacosVersion() >= MACOS_VERSION_MAVERICKS) { + // 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."); + } + + // 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 *internal_start_thread(void (*func)(void *arg), void *arg) { return 0; } void internal_join_thread(void *th) { } diff --git a/lib/sanitizer_common/sanitizer_printf.cc b/lib/sanitizer_common/sanitizer_printf.cc index 5f4725ec..2794e667 100644 --- a/lib/sanitizer_common/sanitizer_printf.cc +++ b/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/lib/sanitizer_common/tests/sanitizer_common_test.cc b/lib/sanitizer_common/tests/sanitizer_common_test.cc index c1bb797d..6fc308ad 100644 --- a/lib/sanitizer_common/tests/sanitizer_common_test.cc +++ b/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/test/asan/lit.cfg b/test/asan/lit.cfg index fd99f669..83554709 100644 --- a/test/asan/lit.cfg +++ b/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/test/ubsan/lit.common.cfg b/test/ubsan/lit.common.cfg index 8e844066..e5086298 100644 --- a/test/ubsan/lit.common.cfg +++ b/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