[tsan] Mark "responsible frames" in stack traces to show which frame contains the race

[kubamracek]

Summary

For reports that involve interceptors (e.g. races against free() or memcpy races), TSan displays reports like this:

==================
WARNING: ThreadSanitizer: data race (pid=67781)
  Write of size 1 at 0x7b0400000045 by thread T2:
    #0 memcpy (libclang_rt.tsan_osx_dynamic.dylib)
    #1 Thread2(void*) (testapp)

  Previous write of size 1 at 0x7b0400000045 by thread T1:
    #0 memcpy (libclang_rt.tsan_osx_dynamic.dylib)
    #1 Thread1(void*) (testapp)

  Location is heap block of size 10 at 0x7b0400000040 allocated by main thread:
    #0 operator new[] ...
  ...
==================

The idea of this patch is to signify which frame is responsible for the bug. Usually, we'd assume that the topmost frame contains the problem that TSan is complaining about, but that's not true in the example above, where memcpy is being called in a racy way. This patch turns the report into:

==================
WARNING: ThreadSanitizer: data race (pid=67781)
  Write of size 1 at 0x7b0400000045 by thread T2:
    #0 memcpy (libclang_rt.tsan_osx_dynamic.dylib)
  * #1 Thread2(void*) (testapp)

  Previous write of size 1 at 0x7b0400000045 by thread T1:
    #0 memcpy (libclang_rt.tsan_osx_dynamic.dylib)
  * #1 Thread1(void*) (testapp)

  Issue is caused by frames marked with "*".

  Location is heap block of size 10 at 0x7b0400000040 allocated by main thread:
    #0 operator new[] ...
  ...
==================

This applies to races on interceptors (memcpy, memcmp, strcpy, ...), races against free, external races (via __tsan_external_read/__tsan_external_write API), and mutex issues like double unlock (where the top frame is the pthread_mutex API and not the caller of it).

[dvyukov]

I am not completely follow motivation for this. Is it meant for user? Or for any automated tools?
For automated tools we already have SUMMARY line. User must be proficient enough to understand what happens. And in the end this is not specific to libc, and the guilty frame is not necessary the one just above libc. Consider a race in std::vector, it's probably not std::vector code that is guilty. And this extends just to any library, consider you have race in libfoo, but it's actually your code that misuses libfoo. We don't have enough info to provide precise signal. What we provide here is a weak, potentially incorrect signal.

lib/sanitizer_common/sanitizer_stacktrace_libcdep.cc

for (uptr i = 0; i < size && trace[i]; i++) {
     uptr pc = GetPreviousInstructionPc(trace[i]);
     SymbolizedStack *frames = Symbolizer::GetOrInit()->SymbolizePC(pc);
     CHECK(frames);
     for (SymbolizedStack *cur = frames; cur; cur = cur->next) {
       frame_desc.clear();
       RenderFrame(&frame_desc, common_flags()->stack_trace_format, frame_num++,
                   cur->info, common_flags()->symbolize_vs_style,
                   common_flags()->strip_path_prefix);
-      Printf("%s\n", frame_desc.data());
+      Printf("    %s\n", frame_desc.data());
       if (dedup_frames-- > 0) {
         if (dedup_token.length())
           dedup_token.append("--");
         dedup_token.append(cur->info.function);
       }
     }
     frames->ClearAll();
   }

lib/sanitizer_common/sanitizer_stacktrace_printer.cc

static const char *StripFunctionName(const char *function, const char *prefix) {
   if (!function) return nullptr;
   if (!prefix) return function;
   uptr prefix_len = internal_strlen(prefix);
   if (0 == internal_strncmp(function, prefix, prefix_len))
     return function + prefix_len;
   return function;
 }
 
-static const char kDefaultFormat[] = "    #%n %p %F %L";
+static const char kDefaultFormat[] = "#%n %p %F %L";
 
 void RenderFrame(InternalScopedString *buffer, const char *format, int frame_no,
                  const AddressInfo &info, bool vs_style,
                  const char *strip_path_prefix, const char *strip_func_prefix) {
   if (0 == internal_strcmp(format, "DEFAULT"))
     format = kDefaultFormat;
   for (const char *p = format; *p != '\0'; p++) {
     if (*p != '%') {

lib/tsan/rtl/tsan_flags.cc

SetCommonFlagsDefaults();
     if (SANITIZER_GO) {
       // Does not work as expected for Go: runtime handles SIGABRT and crashes.
       cf.abort_on_error = false;
       // Go does not have mutexes.
     } else {
       cf.detect_deadlocks = true;
     }
     cf.print_suppressions = false;
-    cf.stack_trace_format = "    #%n %f %S %M";
+    cf.stack_trace_format = "#%n %f %S %M";
     cf.exitcode = 66;
     cf.intercept_tls_get_addr = true;
     OverrideCommonFlags(cf);
   }
 
   f->SetDefaults();
 
   FlagParser parser;

lib/tsan/rtl/tsan_report.h

enum ReportType {
   ReportTypeSignalUnsafe,
   ReportTypeErrnoInSignal,
   ReportTypeDeadlock
 };
 
 struct ReportStack {
   SymbolizedStack *frames;
   bool suppressable;
+  SymbolizedStack *responsible_frame;
   static ReportStack *New();
 
  private:
   ReportStack();
 };
 
 struct ReportMopMutex {
   u64 id;

 
  private:
   ReportDesc(const ReportDesc&);
   void operator = (const ReportDesc&);
 };
 
 // Format and output the report to the console/log. No additional logic.
 void PrintReport(const ReportDesc *rep);
-void PrintStack(const ReportStack *stack);
+void PrintStack(const ReportStack *ent, bool mark_frames = false);
 
 }  // namespace __tsan
 
 #endif  // TSAN_REPORT_H

lib/tsan/rtl/tsan_report.cc

 #include "tsan_platform.h"
 #include "tsan_rtl.h"
 #include "sanitizer_common/sanitizer_placement_new.h"
 #include "sanitizer_common/sanitizer_report_decorator.h"
 #include "sanitizer_common/sanitizer_stacktrace_printer.h"
 
 namespace __tsan {
 
-ReportStack::ReportStack() : frames(nullptr), suppressable(false) {}
+ReportStack::ReportStack()
+    : frames(nullptr), suppressable(false), responsible_frame(0) {}
 
 ReportStack *ReportStack::New() {
   void *mem = internal_alloc(MBlockReportStack, sizeof(ReportStack));
   return new(mem) ReportStack();
 }
 
 ReportLocation::ReportLocation(ReportLocationType type)
     : type(type), global(), heap_chunk_start(0), heap_chunk_size(0), tid(0),

 }
 
 #if SANITIZER_MAC
 static const char *const kInterposedFunctionPrefix = "wrap_";
 #else
 static const char *const kInterposedFunctionPrefix = "__interceptor_";
 #endif
 
-void PrintStack(const ReportStack *ent) {
+void PrintStack(const ReportStack *ent, bool mark_frames) {
   if (ent == 0 || ent->frames == 0) {
     Printf("    [failed to restore the stack]\n\n");
     return;
   }
   SymbolizedStack *frame = ent->frames;
   for (int i = 0; frame && frame->info.address; frame = frame->next, i++) {
     InternalScopedString res(2 * GetPageSizeCached());
     RenderFrame(&res, common_flags()->stack_trace_format, i, frame->info,
                 common_flags()->symbolize_vs_style,
                 common_flags()->strip_path_prefix, kInterposedFunctionPrefix);
-    Printf("%s\n", res.data());
+    const char *star_or_space =
+        (mark_frames && frame == ent->responsible_frame) ? "*" : " ";
+    Printf("  %s %s\n", star_or_space, res.data());
   }
   Printf("\n");
 }
 
 static void PrintMutexSet(Vector<ReportMopMutex> const& mset) {
   for (uptr i = 0; i < mset.Size(); i++) {
     if (i == 0)
       Printf(" (mutexes:");
return atomic ? (first ? (write ? "Atomic write" : "Atomic read")
                 : (write ? "Previous write" : "Previous read"));
 }
 
 static const char *ExternalMopDesc(bool first, bool write) {
   return first ? (write ? "Mutating" : "Read-only")
                : (write ? "Previous mutating" : "Previous read-only");
 }
 
-static void PrintMop(const ReportMop *mop, bool first) {
+static void PrintMop(const ReportMop *mop, bool mark_frames, bool first) {
   Decorator d;
   char thrbuf[kThreadBufSize];
   Printf("%s", d.Access());
   const char *object_type = GetObjectTypeFromTag(mop->external_tag);
   if (!object_type) {
     Printf("  %s of size %d at %p by %s",
            MopDesc(first, mop->write, mop->atomic), mop->size,
            (void *)mop->addr, thread_name(thrbuf, mop->tid));
   } else {
     Printf("  %s access of object %s at %p by %s",
            ExternalMopDesc(first, mop->write), object_type,
            (void *)mop->addr, thread_name(thrbuf, mop->tid));
   }
   PrintMutexSet(mop->mset);
   Printf(":\n");
   Printf("%s", d.EndAccess());
-  PrintStack(mop->stack);
+  PrintStack(mop->stack, mark_frames);
 }
 
 static void PrintLocation(const ReportLocation *loc) {
   Decorator d;
   char thrbuf[kThreadBufSize];
   bool print_stack = false;
   Printf("%s", d.Location());
   if (loc->type == ReportLocationGlobal) {
if (file != 0 &&
        internal_strstr(file, "sanitizer_common_interceptors.inc") ||
        internal_strstr(file, "tsan_interface_")))
     return true;
   if (module != 0 && (internal_strstr(module, "libclang_rt.tsan_")))
     return true;
   return false;
 }
 
-static SymbolizedStack *SkipTsanInternalFrames(SymbolizedStack *frames) {
-  while (FrameIsInternal(frames) && frames->next)
-    frames = frames->next;
-  return frames;
+static bool FillResponsibleFrame(ReportStack *stack, ReportType typ) {
+  if (stack) {
+    SymbolizedStack *frame = stack->frames;
+    while (FrameIsInternal(frame) && frame->next) frame = frame->next;
+    if (typ == ReportTypeExternalRace && frame->next) frame = frame->next;
+    if (stack) {
+      stack->responsible_frame = frame;
+      return stack->responsible_frame != stack->frames;
+    }
+  }
+  return false;
 }
 
 void PrintReport(const ReportDesc *rep) {
   Decorator d;
   Printf("==================\n");
   const char *rep_typ_str = ReportTypeString(rep->typ);
   Printf("%s", d.Warning());
   Printf("WARNING: ThreadSanitizer: %s (pid=%d)\n", rep_typ_str,
          (int)internal_getpid());
   Printf("%s", d.EndWarning());
 
+  bool should_mark_frame = false;
+  for (uptr i = 0; i < rep->mops.Size(); i++)
+    should_mark_frame |= FillResponsibleFrame(rep->mops[i]->stack, rep->typ);
+  for (uptr i = 0; i < rep->stacks.Size(); i++)
+    should_mark_frame |= FillResponsibleFrame(rep->stacks[i], rep->typ);
+  for (uptr i = 0; i < rep->threads.Size(); i++)
+    should_mark_frame |= FillResponsibleFrame(rep->threads[i]->stack, rep->typ);
+  for (uptr i = 0; i < rep->locs.Size(); i++)
+    should_mark_frame |= FillResponsibleFrame(rep->locs[i]->stack, rep->typ);
+
   if (rep->typ == ReportTypeDeadlock) {
     char thrbuf[kThreadBufSize];
     Printf("  Cycle in lock order graph: ");
     for (uptr i = 0; i < rep->mutexes.Size(); i++)
       PrintMutexShortWithAddress(rep->mutexes[i], " => ");
     PrintMutexShort(rep->mutexes[0], "\n\n");
     CHECK_GT(rep->mutexes.Size(), 0U);
     CHECK_EQ(rep->mutexes.Size() * (flags()->second_deadlock_stack ? 2 : 1),
for (uptr i = 0; i < rep->mutexes.Size(); i++) {
           Printf("    Hint: use TSAN_OPTIONS=second_deadlock_stack=1 "
                  "to get more informative warning message\n\n");
       }
     }
   } else {
     for (uptr i = 0; i < rep->stacks.Size(); i++) {
       if (i)
         Printf("  and:\n");
-      PrintStack(rep->stacks[i]);
+      PrintStack(rep->stacks[i], should_mark_frame);
     }
   }
 
   for (uptr i = 0; i < rep->mops.Size(); i++)
-    PrintMop(rep->mops[i], i == 0);
+    PrintMop(rep->mops[i], should_mark_frame, i == 0);
+
+  if (should_mark_frame) {
+    Printf("  Issue is caused by frames marked with \"*\".\n\n");
+  }
 
   if (rep->sleep)
     PrintSleep(rep->sleep);
 
   for (uptr i = 0; i < rep->locs.Size(); i++)
     PrintLocation(rep->locs[i]);
 
   if (rep->typ != ReportTypeDeadlock) {
     for (uptr i = 0; i < rep->mutexes.Size(); i++)
       PrintMutex(rep->mutexes[i]);
   }
 
   for (uptr i = 0; i < rep->threads.Size(); i++)
     PrintThread(rep->threads[i]);
 
   if (rep->typ == ReportTypeThreadLeak && rep->count > 1)
     Printf("  And %d more similar thread leaks.\n\n", rep->count - 1);
 
   if (ReportStack *stack = ChooseSummaryStack(rep)) {
-    if (SymbolizedStack *frame = SkipTsanInternalFrames(stack->frames))
+    SymbolizedStack *frame = stack->responsible_frame ?: stack->frames;
+    if (frame)
       ReportErrorSummary(rep_typ_str, frame->info);
   }
 
   if (common_flags()->print_module_map == 2) PrintModuleMap();
 
   Printf("==================\n");
 }
 
 #else  // #if !SANITIZER_GO
 
 const int kMainThreadId = 1;
 
-void PrintStack(const ReportStack *ent) {
+void PrintStack(const ReportStack *ent, bool mark_frames) {
   if (ent == 0 || ent->frames == 0) {
     Printf("  [failed to restore the stack]\n");
     return;
   }
   SymbolizedStack *frame = ent->frames;
   for (int i = 0; frame; frame = frame->next, i++) {
     const AddressInfo &info = frame->info;
     Printf("  %s()\n      %s:%d +0x%zx\n", info.function,

test/tsan/Darwin/external.cc

 #if defined(USE_TSAN_CALLBACKS)
   callback_write(ref, __builtin_return_address(0), tag);
 #endif
   ref->_another = val;
 }
 
 #else  // defined(SHARED_LIB)
 
+void UserCodeRead(MyObjectRef ref) {
+  ObjectRead(ref);
+}
+
+void UserCodeWrite(MyObjectRef ref, long val) {
+  ObjectWrite(ref, val);
+}
+
+void UserCodeWriteAnother(MyObjectRef ref, long val) {
+  ObjectWriteAnother(ref, val);
+}
+
 int main(int argc, char *argv[]) {
   InitializeLibrary();
   
   {
     MyObjectRef ref = ObjectCreate();
-    std::thread t1([ref]{ ObjectRead(ref); });
-    std::thread t2([ref]{ ObjectRead(ref); });
+    std::thread t1([ref]{ UserCodeRead(ref); });
+    std::thread t2([ref]{ UserCodeRead(ref); });
     t1.join();
     t2.join();
   }
   
   // CHECK-NOT: WARNING: ThreadSanitizer
   
   fprintf(stderr, "RR test done\n");
   // CHECK: RR test done
   
   {
     MyObjectRef ref = ObjectCreate();
-    std::thread t1([ref]{ ObjectRead(ref); });
-    std::thread t2([ref]{ ObjectWrite(ref, 66); });
+    std::thread t1([ref]{ UserCodeRead(ref); });
+    std::thread t2([ref]{ UserCodeWrite(ref, 66); });
     t1.join();
     t2.join();
   }
   
   // TEST1: WARNING: ThreadSanitizer: data race
   // TEST1: {{Write|Read}} of size 8 at
   // TEST1: Previous {{write|read}} of size 8 at
   // TEST1: Location is heap block of size 16 at
   
   // TEST2-NOT: WARNING: ThreadSanitizer
   
   // TEST3: WARNING: ThreadSanitizer: race on a library object
   // TEST3: {{Mutating|read-only}} access of object MyLibrary::MyObject at
-  // TEST3: {{ObjectWrite|ObjectRead}}
+  // TEST3: * #1 {{UserCodeWrite|UserCodeRead}}
   // TEST3: Previous {{mutating|read-only}} access of object MyLibrary::MyObject at
-  // TEST3: {{ObjectWrite|ObjectRead}}
+  // TEST3: * #1 {{UserCodeWrite|UserCodeRead}}
+  // TEST3: Issue is caused by frames marked with "*".
   // TEST3: Location is MyLibrary::MyObject object of size 16 at
   // TEST3: {{ObjectCreate}}
   
   fprintf(stderr, "RW test done\n");
   // CHECK: RW test done
   
   {
     MyObjectRef ref = ObjectCreate();
-    std::thread t1([ref]{ ObjectWrite(ref, 76); });
-    std::thread t2([ref]{ ObjectWriteAnother(ref, 77); });
+    std::thread t1([ref]{ UserCodeWrite(ref, 76); });
+    std::thread t2([ref]{ UserCodeWriteAnother(ref, 77); });
     t1.join();
     t2.join();
   }
   
   // TEST1-NOT: WARNING: ThreadSanitizer: data race
   
   // TEST2-NOT: WARNING: ThreadSanitizer
   
   // TEST3: WARNING: ThreadSanitizer: race on a library object
   // TEST3: Mutating access of object MyLibrary::MyObject at
-  // TEST3: {{ObjectWrite|ObjectWriteAnother}}
+  // TEST3: * #1 {{UserCodeWrite|UserCodeWriteAnother}}
   // TEST3: Previous mutating access of object MyLibrary::MyObject at
-  // TEST3: {{ObjectWrite|ObjectWriteAnother}}
+  // TEST3: * #1 {{UserCodeWrite|UserCodeWriteAnother}}
+  // TEST3: Issue is caused by frames marked with "*".
   // TEST3: Location is MyLibrary::MyObject object of size 16 at
   // TEST3: {{ObjectCreate}}
   
   fprintf(stderr, "WW test done\n");
   // CHECK: WW test done
 }
 
 #endif  // defined(SHARED_LIB)

test/tsan/free_race.c

int main() {
   Thread2(0);
   pthread_join(t, NULL);
   pthread_mutex_destroy(&mtx);
   return 0;
 }
 
 // CHECK-NOZUPP: WARNING: ThreadSanitizer: heap-use-after-free
 // CHECK-NOZUPP:   Write of size 4 at {{.*}} by main thread{{.*}}:
-// CHECK-NOZUPP:     #0 Thread2
+// CHECK-NOZUPP:   * #0 Thread2
 // CHECK-NOZUPP:     #1 main
 // CHECK-NOZUPP:   Previous write of size 8 at {{.*}} by thread T1{{.*}}:
 // CHECK-NOZUPP:     #0 free
-// CHECK-NOZUPP:     #{{(1|2)}} Thread1
+// CHECK-NOZUPP:   * #{{(1|2)}} Thread1
+// CHECK-NOZUPP:   Issue is caused by frames marked with "*".
 // CHECK-NOZUPP: SUMMARY: ThreadSanitizer: heap-use-after-free{{.*}}Thread2
 // CHECK-SUPP:   ThreadSanitizer: Matched 1 suppressions
 // CHECK-SUPP:    1 race:^Thread2$

test/tsan/memcmp_race.cc

int main() {
   pthread_join(t[1], NULL);
   return 0;
 }
 
 // CHECK: addr=[[ADDR:0x[0-9,a-f]+]]
 // CHECK: WARNING: ThreadSanitizer: data race
 // CHECK:   Write of size 1 at [[ADDR]] by thread T2:
 // CHECK:     #0 {{(memcpy|memmove)}}
-// CHECK:     #1 Thread2
+// CHECK:   * #1 Thread2
 // CHECK:   Previous read of size 1 at [[ADDR]] by thread T1:
 // CHECK:     #0 memcmp
-// CHECK:     #1 Thread1
+// CHECK:   * #1 Thread1
+// CHECK:   Issue is caused by frames marked with "*".

test/tsan/memcpy_race.cc

int main() {
   pthread_join(t[1], NULL);
   return 0;
 }
 
 // CHECK: addr=[[ADDR:0x[0-9,a-f]+]]
 // CHECK: WARNING: ThreadSanitizer: data race
 // CHECK:   Write of size 1 at [[ADDR]] by thread T2:
 // CHECK:     #0 {{(memcpy|memmove)}}
-// CHECK:     #1 Thread2
+// CHECK:   * #1 Thread2
 // CHECK:   Previous write of size 1 at [[ADDR]] by thread T1:
 // CHECK:     #0 {{(memcpy|memmove)}}
-// CHECK:     #1 Thread1
+// CHECK:   * #1 Thread1
+// CHECK:   Issue is caused by frames marked with "*".

test/tsan/mutex_destroy_locked.cc

 // RUN: %clangxx_tsan -O1 %s -o %t && %deflake %run %t | FileCheck %s
 #include <pthread.h>
 #include <unistd.h>
 
 int main() {
   pthread_mutex_t m;
   pthread_mutex_init(&m, 0);
   pthread_mutex_lock(&m);
   pthread_mutex_destroy(&m);
   return 0;
 }
 
 // CHECK: WARNING: ThreadSanitizer: destroy of a locked mutex
 // CHECK:     #0 pthread_mutex_destroy
-// CHECK:     #1 main
+// CHECK:   * #1 main
 // CHECK:   and:
 // CHECK:     #0 pthread_mutex_lock
-// CHECK:     #1 main
+// CHECK:   * #1 main
+// CHECK:   Issue is caused by frames marked with "*".
 // CHECK:   Mutex {{.*}} created at:
 // CHECK:     #0 pthread_mutex_init
 // CHECK:     #1 main
 // CHECK: SUMMARY: ThreadSanitizer: destroy of a locked mutex{{.*}}main