[ubsan] Respect log_to_syslog=1 on Darwin

[vsk]

Summary

This patch adds support for logging ubsan errors to syslog on Darwin.

I turned off color encoding in this patch because the macOS log viewer doesn't know what to do with the color codes, and just displays a mess.

[zaks.anna]

lib/sanitizer_common/sanitizer_common_libcdep.cc

41 ↗

(On Diff #71975)

Doesn't this strip coloring from all outputs whenever log_to_system is set? I think what we want is not to show the coloring only in syslog and in the CrashLogs on the mac.

Please, see
https://reviews.llvm.org/D15396
(and it's predecessor http://reviews.llvm.org/D13452)

[vsk]

Thanks for your comments. I can think of two ways to preserve color output while writing to syslog --

lib/sanitizer_common/sanitizer_common_libcdep.cc

41 ↗

(On Diff #71975)

Should I modify LogMessageOnPrintf on Mac platforms so that it prints to syslog when common_flags()->abort_on_error isn't set? The shared printf code should take care of removing color codes. However, this might trigger extra logging on mac.

Or, should I just introduce Mac-specific logic to remove color codes in the PrintToLog function introduced by this patch?

[zaks.anna]

Or, should I just introduce Mac-specific logic to remove color codes in the PrintToLog function introduced by this patch?

1. Do you want to log UBSan errors into CrashLog? If so, how will you accomplish that?
2. I've tried adding the logging into every Printf, but it does not work for ASan and TSan, see the following comment in r253688. This may or may not apply to UBSan. Another smaller concern is that using different logging strategies is not consistent.

" 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.

"

Should I modify LogMessageOnPrintf on Mac platforms so that it prints to syslog when common_flags()->abort_on_error isn't set?

This might not work because of the problem described above.

What we do instead is record all the info into a buffer that will be used for CrashReporting and log that to syslog before the process ends.

[vsk]

In D24781#548200, @zaks.anna wrote:

Or, should I just introduce Mac-specific logic to remove color codes in the PrintToLog function introduced by this patch?

1. Do you want to log UBSan errors into CrashLog? If so, how will you accomplish that?

No, I don't have plans to do this. The typical workflow with ubsan is to continue after an error/warning is reported. In trap or abort mode, it's easier to run the instrumented program with a debugger than to rely on crashlog.

2. I've tried adding the logging into every Printf, but it does not work for ASan and TSan, see the following comment in r253688. This may or may not apply to UBSan. Another smaller concern is that using different logging strategies is not consistent.

" 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.

"

I don't think the same issue affects ubsan because it doesn't have a thread registry lock. Asan (and presumably also tsan) grabs a thread registry lock when preparing error reports. So as long as asl_log does not launch another copy of the instrumented process and triggers more UB by jumping into its main(), we will avoid double-locking scenarios with ubsan.

Should I modify LogMessageOnPrintf on Mac platforms so that it prints to syslog when common_flags()->abort_on_error isn't set?

This might not work because of the problem described above.

What we do instead is record all the info into a buffer that will be used for CrashReporting and log that to syslog before the process ends.

I see your point that having different logging strategies is strange, but I think there are advantages to logging errors to syslog directly instead of doing it at exit. For one, we're not limited by the fixed-size crashlog buffer. Secondly, we can extract errors from long-running apps or daemons without having to shut them down. In some situations (e.g Xcode UI Tests), instrumented apps are killed with SIGTERM and their atexit() handlers never run..

[zaks.anna]

No, I don't have plans to do this. The typical workflow with ubsan is to continue after an error/warning is
reported. In trap or abort mode, it's easier to run the instrumented program with a debugger than to rely
on crashlog.

Are you sure that UBSan workflow should be different from TSan workflow? In my mind they are the same.

I see your point that having different logging strategies is strange, but I think there are advantages to
logging errors to syslog directly instead of doing it at exit.

Yes, this is the main downslide.

For one, we're not limited by the fixed-size
crashlog buffer. Secondly, we can extract errors from long-running apps or daemons without having to
shut them down. In some situations (e.g Xcode UI Tests), instrumented apps are killed with SIGTERM
and their atexit() handlers never run..

What would be the user workflow for the Xcode UI Tests? (Syslog is not a great communication channel in that case.)

[vsk]

Are you sure that UBSan workflow should be different from TSan workflow? In my mind they are the same.

Yes, they should be different. Ubsan's ability to log before exit time isn't constrained, so there's no reason to take the same approach. Logging early is more convenient, has fewer restrictions, and is less surprising.

However, not logging to the syslog at the same time we log to the console is surprising.

For one, we're not limited by the fixed-size
crashlog buffer. Secondly, we can extract errors from long-running apps or daemons without having to
shut them down. In some situations (e.g Xcode UI Tests), instrumented apps are killed with SIGTERM
and their atexit() handlers never run..

What would be the user workflow for the Xcode UI Tests? (Syslog is not a great communication channel in that case.)

Sorry, that was a bad example. In that scenario we'd use the same mechanism TSan has for reporting issues to Xcode through lldb.

There are other scenarios where we'd have to go through launchctl, or some other daemon management tool just to get UB reports to show up in the syslog. I'd rather avoid that.

[zaks.anna]

What I was trying to say is that you need CrashReport logging since it will be what users expect based on other tools (ASan and TSan) and will be important in workflows that do not include lldb, such as Xcode Test integration when running without the debugger.

[vsk]

In D24781#548353, @zaks.anna wrote:

What I was trying to say is that you need CrashReport logging since it will be what users expect based on other tools (ASan and TSan) and will be important in workflows that do not include lldb, such as Xcode Test integration when running without the debugger.

Ah, right, I see why this is needed now. Actually, it already works. Running with UBSAN_OPTIONS="halt_on_error=1" prints a report to the terminal, emits a *.crash file with a copy of the report, and then aborts. This is handled by LogMessageOnPrintf.

It sounds like I can't update LogMessageOnPrintf to log when abort_on_error isn't set, because it could trigger double-locking situations in the other sanitizers. So, would it be OK to pursue the other option: "introduce Mac-specific logic to remove color codes in the PrintToLog function introduced by this patch"?

[zaks.anna]

When abort_on_error is set, you should make sure you do not log twice.

Sounds good to me. @eugenis (or someone else from the sanitizers community) should review this as well.

[vsk]

Teach LogMessageOnPrintf to only write to syslog on Darwin if there is no danger of dead-locking. This is a little cleaner than introducing separate logging functions for ubsan. We also avoid stripping out color codes from the string passed to Printf twice, unnecessarily.

I tested this with a multi-threaded program with both asan+ubsan turned on. I verified that we get syslog output from ubsan but not asan, and that there are no deadlocks:

// Test:
//
//   $ clang++ -std=c++11 -g -O0 -fsanitize=address,integer -fsanitize-recover=address,integer Buggy.cc -o /tmp/Buggy
//   $ export ASAN_OPTIONS="abort_on_error=0:halt_on_error=0:log_to_syslog=1"
//   $ export UBSAN_OPTIONS=$ASAN_OPTIONS
//   $ /tmp/Buggy

#include <thread>
#include <vector>

void Buggy() {
  for (unsigned I = 0; I < 10; ++I) {
    int *x = new int[4];
    x[0] = x[8] + 1000; //< ASAN: out-of-bounds
    x[0] <<= 30; //< UBSAN: invalid shift
  }
}

int main() {
  std::vector<std::thread> Threads;
  for (unsigned I = 0; I < 10; ++I)
    Threads.emplace_back(Buggy);
  for (unsigned I = 0; I < 10; ++I)
    Threads[I].join();
  return 0;
}

I also ran check-sanitizer and check-{a,t,ub}san.

[zaks.anna]

lib/sanitizer_common/sanitizer_mac.cc

505

The expected behavior is that we do log to syslog for ASan and TSan when log_to_syslog is set.

[vsk]

This patch is looking more complicated than it needs to be. Since asl_log has been obsoleted by os_log, I think it'd be better to focus on moving to the new API than adding something messy like "DarwinLogInit".

lib/sanitizer_common/sanitizer_mac.cc

505

Ah, yikes! is_log_threadsafe or some equivalent should only have been checked if we're not in the LogFullErrorReport path.

lib/sanitizer_common/sanitizer_common.h

   ANDROID_KITKAT = 19,
   ANDROID_LOLLIPOP_MR1 = 22,
   ANDROID_POST_LOLLIPOP = 23
 };
 
 void WriteToSyslog(const char *buffer);
 
 #if SANITIZER_MAC
+void DarwinLogInit(bool IsLogThreadsafe);
 void LogFullErrorReport(const char *buffer);
 #else
+INLINE void DarwinLogInit(bool IsLogThreadsafe) {}
 INLINE void LogFullErrorReport(const char *buffer) {}
 #endif
 
 #if SANITIZER_LINUX || SANITIZER_MAC
 void WriteOneLineToSyslog(const char *s);
 void LogMessageOnPrintf(const char *str);
 #else
 INLINE void WriteOneLineToSyslog(const char *s) {}

lib/sanitizer_common/sanitizer_mac.cc

bool IsHandledDeadlySignal(int signum) {
   if ((SANITIZER_WATCHOS || SANITIZER_TVOS) && !(SANITIZER_IOSSIM))
     // Handling fatal signals on watchOS and tvOS devices is disallowed.
     return false;
   if (common_flags()->handle_abort && signum == SIGABRT)
     return true;
   return (signum == SIGSEGV || signum == SIGBUS) && common_flags()->handle_segv;
 }
 
+#ifndef SANITIZER_GO
+uint32_t is_log_threadsafe = 0;
+#endif
+
+// The logging on OS X may call pthread_create so we need the threading
+// environment to be fully initialized.
+//
+// NOTE: It isn't safe to write to the syslog while holding a thread registry
+// lock. 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. Only set
+// IsLogThreadsafe to true if this deadlock scenario has been ruled out.
+//
+// If multiple sanitizers are enabled, it's safe to set IsLogThreadsafe=true
+// in one runtime and not in the others. That's because no single thread will
+// double-lock a thread-registry lock while preparing a report.
+void DarwinLogInit(bool IsLogThreadsafe) {
+#ifndef SANITIZER_GO
+  atomic_store(reinterpret_cast<atomic_uint32_t *>(&is_log_threadsafe),
+               uint32_t(IsLogThreadsafe), memory_order_release);
+#endif
+}
+
 MacosVersion cached_macos_version = MACOS_VERSION_UNINITIALIZED;
 
 MacosVersion GetMacosVersionInternal() {
   int mib[2] = { CTL_KERN, KERN_OSRELEASE };
   char version[100];
   uptr len = 0, maxlen = sizeof(version) / sizeof(version[0]);
   for (uptr i = 0; i < maxlen; i++) version[i] = '\0';
   // Get the version length.

 
 void WriteOneLineToSyslog(const char *s) {
 #ifndef SANITIZER_GO
   syslog_lock.CheckLocked();
   asl_log(nullptr, nullptr, ASL_LEVEL_ERR, "%s", s);
 #endif
 }
 
+void WriteToSyslogIfPossible(const char *str) {
+#ifndef SANITIZER_GO
+  // We can't write to syslog if it's disabled.
+  if (!common_flags()->log_to_syslog)
+    return;
+
+  // We also can't do the write if there's a danger of double-locking a thread
+  // registry lock. See this discussion: https://reviews.llvm.org/D24781
+  if (!atomic_load(reinterpret_cast<atomic_uint32_t *>(&is_log_threadsafe),
+                   memory_order_acquire))
+    return;
+
+  BlockingMutexLock l(&syslog_lock);
+  WriteToSyslog(str);
+#endif
+}
+
 void LogMessageOnPrintf(const char *str) {
-  // Log all printf output to CrashLog.
-  if (common_flags()->abort_on_error)
+  // If the program is about to crash, *just* copy the report into CrashLog.
+  if (common_flags()->abort_on_error) {
     CRAppendCrashLogMessage(str);
+    return;
+  }
+
+  WriteToSyslogIfPossible(str);
 }
 
 void LogFullErrorReport(const char *buffer) {
 #ifndef SANITIZER_GO
   // 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.
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);
+  WriteToSyslogIfPossible(buffer);
 
   // The report is added to CrashLog as part of logging all of Printf output.
 #endif
 }
 
 SignalContext::WriteFlag SignalContext::GetWriteFlag(void *context) {
 #if defined(__x86_64__) || defined(__i386__)
   ucontext_t *ucontext = static_cast<ucontext_t*>(context);

lib/ubsan/ubsan_init.cc

 }
 
 static void CommonStandaloneInit() {
   SanitizerToolName = "UndefinedBehaviorSanitizer";
   InitializeFlags();
   CacheBinaryName();
   __sanitizer_set_report_path(common_flags()->log_path);
   AndroidLogInit();
+  // Set up logging on Darwin. There is no thread-registry lock in ubsan, so
+  // the logging routine may safely create a thread whenever it needs to.
+  DarwinLogInit(/*IsLogThreadsafe=*/true);
   InitializeCoverage(common_flags()->coverage, common_flags()->coverage_dir);
   CommonInit();
   ubsan_mode = UBSAN_MODE_STANDALONE;
 }
 
 void __ubsan::InitAsStandalone() {
   if (SANITIZER_CAN_USE_PREINIT_ARRAY) {
     CHECK_EQ(UBSAN_MODE_UNKNOWN, ubsan_mode);

test/ubsan/TestCases/Misc/log-path_test.cc

 // RUN: %env_ubsan_opts=log_path='"%t.log"' %run %t -4 2> %t.out
 // RUN: FileCheck %s --check-prefix=CHECK-ERROR < %t.log.*
 
 // Run w/o errors should not produce any log.
 // RUN: rm -f %t.log.*
 // RUN: %env_ubsan_opts=log_path='"%t.log"'  %run %t 4
 // RUN: not cat %t.log.*
 
+// We should print out a report even if we're logging to syslog.
+// RUN: %env_ubsan_opts=log_to_syslog=1 %run %t -4 2> %t.out
+// RUN: FileCheck %s --check-prefix=CHECK-ERROR < %t.out
+
 // FIXME: log_path is not supported on Windows yet.
 // XFAIL: win32
 
 #include <stdio.h>
 #include <stdlib.h>
 int main(int argc, char *argv[]) {
   double a = atof(argv[1]);
   unsigned int ai = (unsigned int) a;
   printf("%f %u\n", a, ai);
   return 0;
 }
 
 // CHECK-ERROR: runtime error: value -4 is outside the range of representable values of type 'unsigned int'