Add process name to Asan logfile name and report message

[ygribov]

Summary

Currently when we set log_path in ASAN_OPTIONS, Asan runtime appends process ID to name to distinguish log files for different processes. This patch adds process name to log name. This is handy for inspection of Asan logs of fully sanitized system runs (for common Linux distributions this would be hundreds of logs). I've also added process name to Asan error report. Currently it prints just process ID so to identify the actual process one needs to manually scan the stacktrace (which is not always available) and check the PC of top-most frame.

[eugenis]

A test?

lib/asan/asan_rtl.cc

566 ↗

(On Diff #14710)

Why do you need this?

lib/sanitizer_common/sanitizer_common.cc

261

This is wrong. W/o some kind of synchronization on the read path it would not prevent, for example, prefetching of proc_self_exe_cache_str before checking proc_self_exe_cache_initialized.

You need release store and acquire load.

lib/sanitizer_common/sanitizer_linux.cc

699

This should be changed to reading the first chunk of /proc/self/cmdline. It is normally the same as /exe, but on Android it would return the "nice name" of an application if it has one.

This is probably out of the scope of this CL.

[ygribov]

lib/asan/asan_rtl.cc

566 ↗

(On Diff #14710)

Sorry, forgot to remove this.

lib/sanitizer_common/sanitizer_common.cc

261

Doesn't mutex take care of that?

[eugenis]

lib/sanitizer_common/sanitizer_common.cc

261

No, this is double-checked locking.
http://www.aristeia.com/Papers/DDJ_Jul_Aug_2004_revised.pdf

[emaste]

lib/sanitizer_common/sanitizer_linux.cc

696–700

Not part of this CL but just noticed while reviewing: it looks like this comment and error message was missed in the SANITIZER_FREEBSD work. This should either be moved into the individual #if cases above or made into a generic error ("WARNING: reading executable name failed with errno %d")

[ygribov]

Addressed reviewers' comments.

[ygribov]

lib/sanitizer_common/sanitizer_common.cc

259

Ok, these should be removed.

[ygribov]

Updated tests and removed the now redundant code.

[ygribov]

Ping?

[eugenis]

LGTM

lib/sanitizer_common/sanitizer_common.cc

272

There is Max() definition in sanitizer_common.

lib/sanitizer_common/sanitizer_common.h

181

You've got 2 overloads of ReadBinayName that do very different things.
Rename to GetBinaryName?

[ygribov]

lib/sanitizer_common/sanitizer_common.cc

272

Ah, ok, I looked at min/max in tsan_defs.h and thought that it's ok to reinvent adhoc max.

lib/sanitizer_common/sanitizer_common.h

181

Good point.

[ygribov]

Updated based on Eugene's comments.

[emaste]

The ReadBinaryName change wrt my FreeBSD comment LGTM.

[ygribov]

Evgeny, is anything else needed here?

[ygribov]

Ping.

[eugenis]

LGTM
Sorry for the delay

[samsonov]

Please fix a couple of things below.

Thanks for working on this!

lib/sanitizer_common/sanitizer_common.cc

250

This should be proc_self_exe_cache_lock(LINKER_INITIALIZED);

268

I think we already have it: StripModuleName().
You may need to fix its implementation.

[ygribov]

Updated based on recent review.

[samsonov]

LGTM with one last nit. Feel free to commit after fixing it.

lib/sanitizer_common/sanitizer_mac.cc

323

Shouldn't you return 0 in this case? (if we decide to keep "uptr" as return value of ReadBinaryName, we never use it anywhere)

lib/sanitizer_common/sanitizer_win.cc

534

ditto

[ygribov]

Perhaps it's time to ask for a commit access...

lib/sanitizer_common/sanitizer_mac.cc

323

Looks like you are right, readlink does not include the terminating 0 into the return value. Not sure about FreeBSD though.

[samsonov]

Sure, please email Chris (http://llvm.org/docs/DeveloperPolicy.html#obtaining-commit-access). Feel free to CC me and/or Kostya.

[emaste]

lib/sanitizer_common/sanitizer_common.cc

250–252

should probably be binary_name_cache_str or similar instead so the name is appropriate on all OSes.

[ygribov]

Landed in r221896.

[ygribov]

Guys, I had to revert the commit because it caused warnings in compiler-rt when compiled with clang:

/home/ygribov/src/compiler-rt-master/lib/sanitizer_common/sanitizer_common.cc:230:22: warning: declaration requires a global constructor [-Wglobal-constructors]
static BlockingMutex binary_name_cache_lock(LINKER_INITIALIZED);
                     ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

It looks like LINKER_INITIALIZED trick isn't working after all - a global (empty) ctor is generated anyways. Any ideas on how to fix this? I could e.g. replace this global with array of uptrs and the reinterpret_cast them to BlockingMutex. This could be wrapped in a macro to hide all the ugliness.

[ygribov]

Something like this seems to work

+#define DEFINE_LINKER_INITIALIZED_OBJECT(type, name) \
+  static uptr __ ## name ## _bytes [(sizeof(type) + sizeof(u64) - 1) / sizeof(u64)]; \
+  static type & name = reinterpret_cast<type &>(__ ## name ## _bytes[0]);
...
-static BlockingMutex binary_name_cache_lock(LINKER_INITIALIZED);
+DEFINE_LINKER_INITIALIZED_OBJECT(BlockingMutex, binary_name_cache_lock);
 static char binary_name_cache_str[kMaxPathLength];
 static bool binary_name_cache_initialized = false;

Does this approach make sense?

[kcc]

Yea. For historical reasons we do allow LINKER_INITIALIZED in asan, but not in tsan and not in sanitizer_common.
It probably makes sense to remove all instances of LINKER_INITIALIZED in asan too
Your suggestion with DEFINE_LINKER_INITIALIZED_OBJECT makes sense, go for it. (as a separate CL, preferably)
Thanks!

[samsonov]

In D5724#35, @ygribov wrote:

Something like this seems to work

+#define DEFINE_LINKER_INITIALIZED_OBJECT(type, name) \
+  static uptr __ ## name ## _bytes [(sizeof(type) + sizeof(u64) - 1) / sizeof(u64)]; \
+  static type & name = reinterpret_cast<type &>(__ ## name ## _bytes[0]);
...
-static BlockingMutex binary_name_cache_lock(LINKER_INITIALIZED);
+DEFINE_LINKER_INITIALIZED_OBJECT(BlockingMutex, binary_name_cache_lock);
 static char binary_name_cache_str[kMaxPathLength];
 static bool binary_name_cache_initialized = false;

Does this approach make sense?

Can we enforce the correct alignment of the array of uptr's?

[ygribov]

Can we enforce the correct alignment of the array of uptr's?

Yeah, I just went for u64 because I thought it'd force largest alignment on a platform. But this indeed wouldn't handle user-aligned types properly. Perhaps I should just use array of chars with ALIGNED(alignof(type)).

lib/asan/asan_report.cc

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 += remaining > length ? length : remaining;
+    error_message_buffer_pos += Min(remaining, length);
   }
 }
 
 // ---------------------- Decorator ------------------------------ {{{1
 class Decorator: public __sanitizer::SanitizerCommonDecorator {
  public:
   Decorator() : SanitizerCommonDecorator() { }
   const char *Access()     { return Blue(); }

lib/msan/msan_interceptors.cc

INTERCEPTOR(SSIZE_T, recvfrom, int fd, void *buf, SIZE_T len, int flags,
   ENSURE_MSAN_INITED();
   SIZE_T srcaddr_sz;
   if (srcaddr) srcaddr_sz = *addrlen;
   SSIZE_T res = REAL(recvfrom)(fd, buf, len, flags, srcaddr, addrlen);
   if (res > 0) {
     __msan_unpoison(buf, res);
     if (srcaddr) {
       SIZE_T sz = *addrlen;
-      __msan_unpoison(srcaddr, (sz < srcaddr_sz) ? sz : srcaddr_sz);
+      __msan_unpoison(srcaddr, Min(sz, srcaddr_sz));
     }
   }
   return res;
 }
 
 INTERCEPTOR(void *, calloc, SIZE_T nmemb, SIZE_T size) {
   if (CallocShouldReturnNullDueToOverflow(size, nmemb))
     return AllocatorReturnNull();

lib/sanitizer_common/sanitizer_common.h

 const char *StripPathPrefix(const char *filepath,
                             const char *strip_file_prefix);
 void PrintSourceLocation(InternalScopedString *buffer, const char *file,
                          int line, int column);
 void PrintModuleAndOffset(InternalScopedString *buffer,
                           const char *module, uptr offset);
 
 // OS
+uptr ReadBinaryName(/*out*/char *buf, uptr buf_len);
+const char *GetBinaryName();
+void CacheBinaryName();
+const char *BaseName(const char *name);
 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

void IncreaseTotalMmap(uptr size) {
   }
 }
 
 void DecreaseTotalMmap(uptr size) {
   if (!common_flags()->mmap_limit_mb) return;
   atomic_fetch_sub(&g_total_mmaped, size, memory_order_relaxed);
 }
 
+static BlockingMutex proc_self_exe_cache_lock;
+static char proc_self_exe_cache_str[kMaxPathLength];
+static bool proc_self_exe_cache_initialized = false;
+
+const char *GetBinaryName() {
+  BlockingMutexLock l(&proc_self_exe_cache_lock);
+  if (!proc_self_exe_cache_initialized) {
+    ReadBinaryName(proc_self_exe_cache_str, sizeof(proc_self_exe_cache_str));
+    proc_self_exe_cache_initialized = true;
+  }
+  return proc_self_exe_cache_str;
+}
+
+void CacheBinaryName() {
+  // Call once to make sure that proc_self_exe_cache_str is initialized
+  GetBinaryName();
+}
+
+const char *BaseName(const char *name) {
+  const char *base1 = internal_strrchr(name, '/'),
+    *base2 = internal_strrchr(name, '\\');
+  if (base1 || base2)
+    return Max(base1, base2) + 1;
+  return name;
+}
+
 }  // namespace __sanitizer
 
 using namespace __sanitizer;  // NOLINT
 
 extern "C" {
 void __sanitizer_set_report_path(const char *path) {
   if (!path)
     return;

lib/sanitizer_common/sanitizer_flags.cc

void ParseCommonFlagsFromString(CommonFlags *f, const char *str) {
   ParseFlag(str, &f->fast_unwind_on_malloc, "fast_unwind_on_malloc",
       "If available, use the fast frame-pointer-based unwinder on "
       "malloc/free.");
   ParseFlag(str, &f->handle_ioctl, "handle_ioctl",
       "Intercept and handle ioctl requests.");
   ParseFlag(str, &f->malloc_context_size, "malloc_context_size",
       "Max number of stack frames kept for each allocation/deallocation.");
   ParseFlag(str, &f->log_path, "log_path",
-      "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\".");
   ParseFlag(str, &f->verbosity, "verbosity",
       "Verbosity level (0 - silent, 1 - a bit of output, 2+ - more output).");
   ParseFlag(str, &f->detect_leaks, "detect_leaks",
       "Enable memory leak detection.");
   ParseFlag(str, &f->leak_check_at_exit, "leak_check_at_exit",
       "Invoke leak checking in an atexit handler. Has no effect if "
       "detect_leaks=false, or if __lsan_do_leak_check() is called before the "
       "handler has a chance to run.");

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);
   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

MacosVersion result =
       static_cast<MacosVersion>(atomic_load(cache, memory_order_acquire));
   if (result == MACOS_VERSION_UNINITIALIZED) {
     result = GetMacosVersionInternal();
     atomic_store(cache, result, memory_order_release);
   }
   return result;
 }
 
+uptr ReadBinaryName(/*out*/char *buf, uptr buf_len) {
+  // FIXME: Actually implement this function.
+  CHECK_GT(buf_len, 0);
+  buf[0] = 0;
+  return 1;
+}
+
 }  // namespace __sanitizer
 
 #endif  // SANITIZER_MAC

lib/sanitizer_common/sanitizer_posix.cc

while (true) {
     beg = end + 1;
   }
   return 0;
 }
 
 void MaybeOpenReportFile() {
   if (!log_to_file) return;
   uptr pid = internal_getpid();
+  const char *pname = BaseName(GetBinaryName());
   // If in tracer, use the parent's file.
   if (pid == stoptheworld_tracer_pid)
     pid = stoptheworld_tracer_ppid;
   if (report_fd_pid == pid) return;
   InternalScopedBuffer<char> report_path_full(4096);
   internal_snprintf(report_path_full.data(), report_path_full.size(),
-                    "%s.%zu", report_path_prefix, pid);
+                    "%s.%s.%zu", report_path_prefix, pname, pid);
   uptr openrv = OpenFile(report_path_full.data(), true);
   if (internal_iserror(openrv)) {
     report_fd = kStderrFd;
     log_to_file = false;
     Report("ERROR: Can't open file: %s\n", report_path_full.data());
     Die();
   }
   if (report_fd != kInvalidFd) {

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 = BaseName(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) {

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() {
-#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);

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 1;
+}
+
 }  // namespace __sanitizer
 
 #endif  // _WIN32

test/asan/TestCases/log-path_test.cc

 // FIXME: https://code.google.com/p/address-sanitizer/issues/detail?id=316
 // XFAIL: android
 //
 // RUN: %clangxx_asan  %s -o %t
 
 // Regular run.
 // RUN: not %run %t 2> %t.out
 // RUN: FileCheck %s --check-prefix=CHECK-ERROR < %t.out
 
 // 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.*
+// RUN: FileCheck %s --check-prefix=CHECK-ERROR < %t.log.log-path_test.cc*
 
 // Invalid log_path.
 // RUN: env ASAN_OPTIONS=log_path=/INVALID not %run %t 2> %t.out
 // RUN: FileCheck %s --check-prefix=CHECK-INVALID < %t.out
 
 // Too long log_path.
 // RUN: env ASAN_OPTIONS=log_path=`for((i=0;i<10000;i++)); do echo -n $i; done` \
 // RUN:   not %run %t 2> %t.out
 // RUN: FileCheck %s --check-prefix=CHECK-LONG < %t.out
 
 // Run w/o errors should not produce any log.
 // RUN: rm -f %t.log.*
 // RUN: env ASAN_OPTIONS=log_path=%t.log  %run %t ARG ARG ARG
-// RUN: not cat %t.log.*
+// RUN: not cat %t.log.log-path_test.cc*
 
 // FIXME: log_path is not supported on Windows yet.
 // XFAIL: win32
 
 #include <stdlib.h>
 #include <string.h>
 int main(int argc, char **argv) {
   if (argc > 2) return 0;

test/asan/TestCases/log_path_fork_test.cc.disabled

 // RUN: %clangxx_asan  %s -o %t
 // RUN: rm -f %t.log.*
 // Set verbosity to 1 so that the log files are opened prior to fork().
 // RUN: env ASAN_OPTIONS="log_path=%t.log verbosity=1" not %run %t 2> %t.out
-// RUN: for f in %t.log.* ; do FileCheck %s < $f; done
+// RUN: for f in %t.log.log_path_fork_test.cc* ; do FileCheck %s < $f; done
 // RUN: [ `ls %t.log.* | wc -l` == 2 ]
 
 #include <stdlib.h>
 #include <string.h>
 #include <unistd.h>
 
 int main(int argc, char **argv) {
   void *x = malloc(10);