[ASan] Add process basename to log name and error message to simplify analysis of sanitized systems logs.

[ygribov]

Summary

Resurrection of accidentally closed http://reviews.llvm.org/D7172

[ygribov]

Ping.

[kcc]

sorry for delay...

lib/sanitizer_common/sanitizer_common.cc

58

What's "pname"? Can this be more descriptive?
Also, if this does not change over time, we should just precompute it at start up

299

does binary name change over time?
If not, we should compute it at start up w/o any mutexes

lib/sanitizer_common/sanitizer_linux.cc

709

I am lost here. What's being changed?

lib/sanitizer_common/sanitizer_printf.cc

257

So, now everyone will have the module name in their logs by default?
Not good. Make it an option.

test/asan/lit.cfg

135

I think this is an overkill. Just make the tests require linux/Freebsd

[ygribov]

lib/sanitizer_common/sanitizer_common.cc

58

Ok.

299

does binary name change over time?

You can mess with process name at least on some platforms. I'm not sure /proc/self/exe can be changed though.

If not, we should compute it at start up w/o any mutexes

You mean initialize it in _asan_init, _msan_init, etc.? Ok.

lib/sanitizer_common/sanitizer_linux.cc

709

I removed the redundant 4.

lib/sanitizer_common/sanitizer_printf.cc

257

I could but is there a good reason not to make this default (besides legacy scripts)?

[kcc]

You mean initialize it in _asan_init, _msan_init, etc.? Ok.

Yes, create something like InitializeBinaryName() and GetBinaryName(), GetWhateverElseName() in sanitizer_common and call it in tool init routines.

I could but is there a good reason not to make this default (besides legacy scripts)?

legacy scripts is a good reason by itself, but more importantly, you are the first to request this in 4 years,
which means that most users don't need it. If they don't need it, extra bloat in the report will be a distraction.
If we see that the feature is useful we can always set the flag on by default.

[ygribov]

but more importantly, you are the first to request this in 4 years,

That's probably because not many people sanitize full distributions.

[ygribov]

Fixed based on Kostya's feedback.

[kcc]

lib/asan/asan_rtl.cc

311 ↗

(On Diff #20738)

empty line?

314 ↗

(On Diff #20738)

do you really need to call this twice?

lib/sanitizer_common/sanitizer_common.cc

310

So why do you still need the Mutex if you are calling this only once at init time?
Just add an asssertion that you've never initialized this before.
Then you also don't need binary_name_cache_initialized, you can use binary_name_cache_str[0],
which in turn could be function-scope because no one else needs it.

lib/sanitizer_common/sanitizer_symbolizer_posix_libcdep.cc

648–649

So, do we still need this here?

test/asan/TestCases/verbose-log-path_test.cc

10

maybe just put it inside test/asan/TestCases/Linux?

17

this test could be smaller, e.g.
int glob[10];
int main(int argc, char **argv) {

return glob[argc * 10];

}

[ygribov]

lib/asan/asan_rtl.cc

314 ↗

(On Diff #20738)

Yes, just like AsanCheckIncompatibleRT is called twice in two types of initializers that we have (__asan_init and AsanInitializer). But - I should move it to AsanInitializer::AsanInitializer().

lib/sanitizer_common/sanitizer_common.cc

310

I thought about that but I decided to keep CacheBinaryName more generic so that it could be used in other contexts besides pure program startup. I could remove this if you think it's unnecessary.

lib/sanitizer_common/sanitizer_symbolizer_posix_libcdep.cc

648–649

I don't know the whole sandboxing thing well enough so I kept it.

test/asan/TestCases/verbose-log-path_test.cc

10

Well, it's absolutely trivial to support on other platforms so I thought it makes sense to simply xfail.

17

That's a blind copy-paste of similar log_path test without log_exe_name.

[kcc]

lib/sanitizer_common/sanitizer_common.cc

310

Yes, I'd prefer to simplify it and make sure it crashes if called twice, or while other threads are running (or at least after the init is done)

lib/sanitizer_common/sanitizer_symbolizer_posix_libcdep.cc

648–649

This should be safe, especially if the tests pass :)
Also, if you ensure that CacheBinaryName asserts on the 2-nd call, this call site will stop working.

test/asan/TestCases/verbose-log-path_test.cc

17

Sure. Please make this one simpler.

[kcc]

adding one more reviewer in a time zone more suitable for you.

[ygribov]

Updated based on previous review. Unfortunately I was unable to prohibit against multiple calls to CheckBinaryName because both UBSan and ASan call it.

[kcc]

lib/sanitizer_common/sanitizer_common.cc

296

initialize to nullptr, so that if we forget to call CacheBinaryName we instantly crash

309

This will not catch a situation where someone calls CacheBinaryName() twice, which should be illegal.
Instead, do a hard check that this is the first call.

313

You can probably implement this thing w/o an extra static bool, just use binary_basename_cache_str

[ygribov]

lib/sanitizer_common/sanitizer_common.cc

296

Yeah, I thought about this. But note that even though we call CacheBinaryName very early, some code has to execute before it. And I'd prefer this code to print something at least to stderr instead of crashing.

309

Unfortunately we do have situations where double call is needed e.g. when app is both A- and UB-sanitized.

313

Right.

[kcc]

lib/sanitizer_common/sanitizer_common.cc

296

Sure, use CHECK_NE(foo, nullptr)

309

I believe the recent refactoring by Alexey allows to solve this.
Really, if we allow double call but do not allow lazy initialization later on we are asking for trouble.

[ygribov]

lib/sanitizer_common/sanitizer_common.cc

296

Sorry, I still don't understand - how do you propose to handle failing CHECKs in e.g. InitializeFlags (which is called before CacheBinaryName has a chance to set binary_basename_cache_str)? If we CHECK_NE(binary_basename_cache_str, nullptr) we'll abort without reporting the real error.

[kcc]

lib/sanitizer_common/sanitizer_common.cc

296

Can you then read the binary name earlier?
Or don't use check and rely on SEGV handler to show you stack trace if binary_basename_cache_str is nullptr.
Or tolerate the binary name biign null?

[ygribov]

lib/sanitizer_common/sanitizer_common.cc

309

Could you be more specific? I can see that ASan and UBSan have been changed to have isolated copies of some core structures (e.g. suppressions). But error reporting (e.g. report_file or log_path) are still shared across all sanitizers with mutexes being used to serialize accesses.

[kcc]

lib/sanitizer_common/sanitizer_common.cc

309

Alexey actually tells that this part will be ready later this week.
The idea is that something like ubsan_common_init() will be called from asan_init() if ubsan and asan are bundled and
from ubsan_init() if ubsan runs separately.
In this case, we can call CacheBinaryName in ubsan_init and in __asan_init.
This way it will be ensured that CacheBinaryName is executed strictly once, and we'll be able to add the CHECK to prevent from calling it for the second time.
Can you wait a few more days before Alexey lands his patch?

[ygribov]

Sure, thanks for the update. Could you guys make sure that this works properly with dynamic A- and UB-runtimes in GCC (which have separate sanitizer_commons)?

[kcc]

In D7333#141772, @ygribov wrote:

Sure, thanks for the update. Could you guys make sure that this works properly with dynamic A- and UB-runtimes in GCC (which have separate sanitizer_commons)?

OMG. I'll let Alexey speak here, but if I were him I would not support this mode.
What we should have is

• separate UBSan run-time
• bundled ASan+UBSan run-time

Having two sanitizers co-exist in the same process w/o properly knowing about each other is beyond of what we can reasonably maintain.

[ygribov]

This comment was removed by ygribov.

[ygribov]

I accidentally commited wrong commit. Will fix with next version of the patch.

[ygribov]

Updated after recent ASan-UBSan refactoring. Addressed Kostya's remarks.

[ygribov]

Ping.

[kcc]

I am on long leave. Alexey/Sergey, please review.

[ygribov]

Ping.

[samsonov]

Once again, sorry for delay :-/
I will look into it shortly.

[samsonov]

Looks mostly good. I'd rather land this in three changes: (1) refactor Asan dynamic initialization (2) move CacheBinaryName to sanitizer_common and call it early (3) implement log_exe_name.

lib/asan/asan_linux.cc

116 ↗

(On Diff #23491)

just if (!ASAN_DYNAMIC) return;

lib/asan/asan_rtl.cc

372 ↗

(On Diff #23491)

I think that moving these functions to the AsanInitInternal is a positive change, do you think you can land it independently (as a refactoring), before submitting the rest of this patch?

lib/sanitizer_common/sanitizer_common.cc

223–226

That's weird, don't we handle backslash on Windows above?

lib/sanitizer_common/sanitizer_common.h

209

It is already declared below.

lib/sanitizer_common/sanitizer_printf.cc

261

You should probably check that needed_length is not greater than buffer_size here as well.

lib/sanitizer_common/sanitizer_symbolizer_posix_libcdep.cc

649

Note that moving CacheBinaryName() to sanitizer_common (and calling it early during initialization) may also be separated to an independent change, that shouldn't change user-visible behavior.

lib/tsan/rtl/tsan_rtl.cc

309 ↗

(On Diff #23491)

I'd rather do this after setting SanitizerToolName and parsing the flags, as you do in different sanitizers.
Also, what about MSan?

test/asan/TestCases/verbose-log-path_test.cc

2

Consider changing the name of the output executable (%t-verbose-log-path_test-binary)...

7

... and matching against this executable name here.

10

XFAIL: win32,android,darwin

[ygribov]

Once again, sorry for delay :-/

Np, this isn't the most interesting change for sure.

lib/asan/asan_rtl.cc

372 ↗

(On Diff #23491)

Sure.

lib/sanitizer_common/sanitizer_common.cc

223–226

True.

lib/sanitizer_common/sanitizer_printf.cc

261

Good catch, otherwise there may be an overflow.

lib/tsan/rtl/tsan_rtl.cc

309 ↗

(On Diff #23491)

Will do.

test/asan/TestCases/verbose-log-path_test.cc

7

Sorry, not quite clear. What would be the benefit of this?

[samsonov]

test/asan/TestCases/verbose-log-path_test.cc

7

Otherwise you seem to depend on the fact that %t (temporary string generated by lit) contains the source file name (verbose-log-path_test.cc).

[ygribov]

Updated based on previous review + split independent functionality to separate patches.

[samsonov]

lib/sanitizer_common/sanitizer_printf.cc

260

Hm, now this chunk of code is copied three times in the function... Factor it out to a macro, maybe?

[ygribov]

Added a macro to reduce code dup.

[samsonov]

LGTM

lib/sanitizer_common/sanitizer_printf.cc

274

#undef macro here?

lib/sanitizer_common/sanitizer_common.h

 
 // Error report formatting.
 const char *StripPathPrefix(const char *filepath,
                             const char *strip_file_prefix);
 // Strip the directories from the module name.
 const char *StripModuleName(const char *module);
 
 // OS
+uptr ReadBinaryName(/*out*/char *buf, uptr buf_len);
+const char *GetBinaryName();
+void CacheBinaryName();
 void DisableCoreDumperIfNecessary();
 void DumpProcessMap();
 bool FileExists(const char *filename);
 const char *GetEnv(const char *name);
 bool SetEnv(const char *name, const char *value);
 const char *GetPwd();
 char *FindPathToBinary(const char *name);
 u32 GetUid();

lib/sanitizer_common/sanitizer_common.cc

if (fd != kInvalidFd) {
     // do nothing. Otherwise the report file was opened by the parent
     // process, close it now.
     if (fd_pid == pid)
       return;
     else
       internal_close(fd);
   }
 
-  internal_snprintf(full_path, kMaxPathLength, "%s.%zu", path_prefix, pid);
+  const char *pname = StripModuleName(GetBinaryName());
+  internal_snprintf(full_path, kMaxPathLength, "%s.%s.%zu", path_prefix, pname,
+                    pid);
   uptr openrv = OpenFile(full_path, true);
   if (internal_iserror(openrv)) {
     const char *ErrorMsgPrefix = "ERROR: Can't open file: ";
     internal_write(kStderrFd, ErrorMsgPrefix, internal_strlen(ErrorMsgPrefix));
     internal_write(kStderrFd, full_path, internal_strlen(full_path));
     Die();
   }
   fd = openrv;
if (pos[0] == '.' && pos[1] == '/')
     pos += 2;
   return pos;
 }
 
 const char *StripModuleName(const char *module) {
   if (module == 0)
     return 0;
   if (const char *slash_pos = internal_strrchr(module, '/'))
     return slash_pos + 1;
+  else if (const char *backslash_pos = internal_strrchr(module, '\\'))
+    return backslash_pos + 1;
   return module;
 }
 
 void ReportErrorSummary(const char *error_message) {
   if (!common_flags()->print_summary)
     return;
   InternalScopedString buff(kMaxSummaryLength);
   buff.append("SUMMARY: %s: %s", SanitizerToolName, error_message);
   __sanitizer_report_error_summary(buff.data());
void IncreaseTotalMmap(uptr size) {
   RAW_CHECK((total_mmaped >> 20) < common_flags()->mmap_limit_mb);
 }
 
 void DecreaseTotalMmap(uptr size) {
   if (!common_flags()->mmap_limit_mb) return;
   atomic_fetch_sub(&g_total_mmaped, size, memory_order_relaxed);
 }
 
+static BlockingMutex binary_name_cache_lock(LINKER_INITIALIZED);
+static char binary_name_cache_str[kMaxPathLength];
+static bool binary_name_cache_initialized = false;
+
+const char *GetBinaryName() {
+  BlockingMutexLock l(&binary_name_cache_lock);
+  if (!binary_name_cache_initialized) {
+    ReadBinaryName(binary_name_cache_str, sizeof(binary_name_cache_str));
+    binary_name_cache_initialized = true;
+  }
+  return binary_name_cache_str;
+}
+
+void CacheBinaryName() {
+  // Call once to make sure that binary_name_cache_str is initialized
+  GetBinaryName();
+}
+
 }  // namespace __sanitizer
 
 using namespace __sanitizer;  // NOLINT
 
 extern "C" {
 void __sanitizer_set_report_path(const char *path) {
   report_file.SetReportPath(path);
 }
 

lib/sanitizer_common/sanitizer_flags.inc

 COMMON_FLAG(bool, fast_unwind_on_malloc, true,
             "If available, use the fast frame-pointer-based unwinder on "
             "malloc/free.")
 COMMON_FLAG(bool, handle_ioctl, false, "Intercept and handle ioctl requests.")
 COMMON_FLAG(int, malloc_context_size, 1,
             "Max number of stack frames kept for each allocation/deallocation.")
 COMMON_FLAG(
     const char *, log_path, "stderr",
-    "Write logs to \"log_path.pid\". The special values are \"stdout\" and "
-    "\"stderr\". The default is \"stderr\".")
+    "Write logs to \"log_path.pname.pid\". The special values are \"stdout\" "
+    "and \"stderr\". The default is \"stderr\".")
 COMMON_FLAG(
     int, verbosity, 0,
     "Verbosity level (0 - silent, 1 - a bit of output, 2+ - more output).")
 COMMON_FLAG(bool, detect_leaks, true, "Enable memory leak detection.")
 COMMON_FLAG(
     bool, leak_check_at_exit, true,
     "Invoke leak checking in an atexit handler. Has no effect if "
     "detect_leaks=false, or if __lsan_do_leak_check() is called before the "

lib/sanitizer_common/sanitizer_linux.h

 uptr ThreadDescriptorSize();
 uptr ThreadSelf();
 uptr ThreadSelfOffset();
 
 // Matches a library's file name against a base name (stripping path and version
 // information).
 bool LibraryNameIs(const char *full_name, const char *base_name);
 
-// Read the name of the current binary from /proc/self/exe.
-uptr ReadBinaryName(/*out*/char *buf, uptr buf_len);
-// Cache the value of /proc/self/exe.
-void CacheBinaryName();
-
 // Call cb for each region mapped by map.
 void ForEachMappedRegion(link_map *map, void (*cb)(const void *, uptr));
 }  // namespace __sanitizer
 
 #endif  // SANITIZER_FREEBSD || SANITIZER_LINUX
 #endif  // SANITIZER_LINUX_H

lib/sanitizer_common/sanitizer_linux.cc

 uptr GetPageSize() {
 #if SANITIZER_LINUX && (defined(__x86_64__) || defined(__i386__))
   return EXEC_PAGESIZE;
 #else
   return sysconf(_SC_PAGESIZE);  // EXEC_PAGESIZE may not be trustworthy.
 #endif
 }
 
-static char proc_self_exe_cache_str[kMaxPathLength];
-static uptr proc_self_exe_cache_len = 0;
-
 uptr ReadBinaryName(/*out*/char *buf, uptr buf_len) {
-  if (proc_self_exe_cache_len > 0) {
-    // If available, use the cached module name.
-    uptr module_name_len =
-        internal_snprintf(buf, buf_len, "%s", proc_self_exe_cache_str);
-    CHECK_LT(module_name_len, buf_len);
-    return module_name_len;
-  }
 #if SANITIZER_FREEBSD
-  const int Mib[4] = { CTL_KERN, KERN_PROC, KERN_PROC_PATHNAME, -1 };
+  const int Mib[] = { CTL_KERN, KERN_PROC, KERN_PROC_PATHNAME, -1 };
+  const char *default_module_name = "kern.proc.pathname";
   size_t Size = buf_len;
-  bool IsErr = (sysctl(Mib, 4, buf, &Size, NULL, 0) != 0);
+  bool IsErr = (sysctl(Mib, ARRAY_SIZE(Mib), buf, &Size, NULL, 0) != 0);
   int readlink_error = IsErr ? errno : 0;
   uptr module_name_len = Size;
 #else
+  const char *default_module_name = "/proc/self/exe";
   uptr module_name_len = internal_readlink(
-      "/proc/self/exe", buf, buf_len);
+      default_module_name, buf, buf_len);
   int readlink_error;
   bool IsErr = internal_iserror(module_name_len, &readlink_error);
 #endif
   if (IsErr) {
-    // We can't read /proc/self/exe for some reason, assume the name of the
-    // binary is unknown.
-    Report("WARNING: readlink(\"/proc/self/exe\") failed with errno %d, "
+    // We can't read binary name for some reason, assume it's unknown.
+    Report("WARNING: reading executable name failed with errno %d, "
            "some stack frames may not be symbolized\n", readlink_error);
-    module_name_len = internal_snprintf(buf, buf_len, "/proc/self/exe");
+    module_name_len = internal_snprintf(buf, buf_len, default_module_name);
     CHECK_LT(module_name_len, buf_len);
   }
   return module_name_len;
 }
 
-void CacheBinaryName() {
-  if (!proc_self_exe_cache_len) {
-    proc_self_exe_cache_len =
-        ReadBinaryName(proc_self_exe_cache_str, kMaxPathLength);
-  }
-}
-
 // Match full names of the form /path/to/base_name{-,.}*
 bool LibraryNameIs(const char *full_name, const char *base_name) {
   const char *name = full_name;
   // Strip path.
   while (*name != '\0') name++;
   while (name > full_name && *name != '/') name--;
   if (*name == '/') name++;
   uptr base_name_length = internal_strlen(base_name);

lib/sanitizer_common/sanitizer_mac.cc

 
 uptr GetRSS() {
   return 0;
 }
 
 void *internal_start_thread(void (*func)(void *arg), void *arg) { return 0; }
 void internal_join_thread(void *th) { }
 
+uptr ReadBinaryName(/*out*/char *buf, uptr buf_len) {
+  // FIXME: Actually implement this function.
+  CHECK_GT(buf_len, 0);
+  buf[0] = 0;
+  return 0;
+}
+
 }  // namespace __sanitizer
 
 #endif  // SANITIZER_MAC

lib/sanitizer_common/sanitizer_printf.cc

if (use_mmap) {
       va_end(args);
       va_copy(args, args2);
       buffer = (char*)MmapOrDie(kLen, "Report");
       buffer_size = kLen;
     }
     needed_length = 0;
     if (append_pid) {
       int pid = internal_getpid();
-      needed_length += internal_snprintf(buffer, buffer_size, "==%d==", pid);
+      const char *pname = StripModuleName(GetBinaryName());
+      needed_length += internal_snprintf(buffer, buffer_size,
+                                         "==%s %d==", pname, pid);
       if (needed_length >= buffer_size) {
-        // The pid doesn't fit into the current buffer.
+        // Process name + pid do not fit into the current buffer.
         if (!use_mmap)
           continue;
         RAW_CHECK_MSG(needed_length < kLen, "Buffer in Report is too short!\n");
       }
     }
     needed_length += VSNPrintf(buffer + needed_length,
                                buffer_size - needed_length, format, args);
     if (needed_length >= buffer_size) {
       // The message doesn't fit into the current buffer.
       if (!use_mmap)
         continue;
       RAW_CHECK_MSG(needed_length < kLen, "Buffer in Report is too short!\n");
     }
     // If the message fit into the buffer, print it and exit.
     break;
   }
   RawWrite(buffer);
   AndroidLogWrite(buffer);
   CallPrintfAndReportCallback(buffer);
   // If we had mapped any memory, clean up.
   if (buffer != local_buffer)
     UnmapOrDie((void *)buffer, buffer_size);

lib/sanitizer_common/sanitizer_symbolizer_posix_libcdep.cc

if (libbacktrace_symbolizer_ != 0) {
         return demangled;
     }
     if (internal_symbolizer_ != 0)
       return internal_symbolizer_->Demangle(name);
     return DemangleCXXABI(name);
   }
 
   void PrepareForSandboxing() override {
-#if SANITIZER_LINUX && !SANITIZER_ANDROID
     BlockingMutexLock l(&mu_);
-    // Cache /proc/self/exe on Linux.
     CacheBinaryName();
-#endif
   }
 
  private:
   char *SendCommand(bool is_data, const char *module_name, uptr module_offset) {
     mu_.CheckLocked();
     // First, try to use internal symbolizer.
     if (internal_symbolizer_) {
       SymbolizerScope sym_scope(this);
       return internal_symbolizer_->SendCommand(is_data, module_name,

lib/sanitizer_common/sanitizer_win.cc

bool IsDeadlySignal(int signum) {
   return false;
 }
 
 bool IsAccessibleMemoryRange(uptr beg, uptr size) {
   // FIXME: Actually implement this function.
   return true;
 }
 
+uptr ReadBinaryName(/*out*/char *buf, uptr buf_len) {
+  // FIXME: Actually implement this function.
+  CHECK_GT(buf_len, 0);
+  buf[0] = 0;
+  return 0;
+}
+
 }  // namespace __sanitizer
 
 #endif  // _WIN32

test/asan/TestCases/verbose-log-path_test.cc

+// FIXME: https://code.google.com/p/address-sanitizer/issues/detail?id=316
+// XFAIL: android
+//
+// RUN: %clangxx_asan  %s -o %t
+
+// Good log_path.
+// RUN: rm -f %t.log.*
+// RUN: env ASAN_OPTIONS=log_path=%t.log not %run %t 2> %t.out
+// RUN: FileCheck %s --check-prefix=CHECK-ERROR < %t.log.verbose-log-path_test.cc*
+
+// FIXME: log_path is not supported on Windows yet.
+// XFAIL: win32
+//
+// FIXME: only FreeBSD and Linux have verbose log paths.
+// REQUIRES: verbose-log-path
+
+#include <stdlib.h>
+#include <string.h>
+int main(int argc, char **argv) {
+  if (argc > 2) return 0;
+  char *x = (char*)malloc(10);
+  memset(x, 0, 10);
+  int res = x[argc * 10];  // BOOOM
+  free(x);
+  return res;
+}
+// CHECK-ERROR: ERROR: AddressSanitizer

test/asan/lit.cfg

 
 config.available_features.add("asan-" + config.bits + "-bits")
 
 # Allow tests to use REQUIRES=stable-runtime.  For use when you cannot use XFAIL
 # because the test hangs.
 if config.target_arch != 'arm':
   config.available_features.add('stable-runtime')
 
+# Allow tests to use REQUIRES=verbose-log-path.
+if config.host_os in ['FreeBSD', 'Linux']:
+  config.available_features.add('verbose-log-path')
+
 # Turn on leak detection on 64-bit Linux.
 if config.host_os == 'Linux' and config.target_arch == 'x86_64':
   config.available_features.add('leak-detection')
 
 # Set LD_LIBRARY_PATH to pick dynamic runtime up properly.
 push_dynamic_library_lookup_path(config, config.compiler_rt_libdir)
 
 # GCC-ASan uses dynamic runtime by default.