Add logging of where a sequence/thread was bound when a failure occurs

Use SequenceChecker::EnableStackLogging() to enable this logging.

When DCHECK() fails for a ThreadChecker or SequenceChecker, if the error
is not at the site of checking, it takes a great amount of knowledge and
persistence to figure out where the erroroneous thread/sequence-
attachment occurred. This is especially fun for a WeakPtr, which if
checked on the wrong thread becomes bound to the thread. Then if the
WeakPtrFactory is invalidated later, it's difficult to determine why it
believes it is on the wrong thread.

This adds a copy of the StackTrace in SequenceChecker and ThreadChecker
that is set whenever they are bound to a thread/sequence. Then on
failure the DCHECK() callers will get back a copy of the StackTrace and
include it in the log message. WeakPtr calls the SequenceChecker
manually instead of using the macros, since it has an additional
condition so we also add the StackTrace to the message there.

The StackTrace logging slows things down a bit, enough that we'd slow
bots down without good reason, so the logging is optional. You may use
SequenceChecker::EnableStackLogging() to enable this logging, or the
equivalent alias ThreadChecker::EnableStackLogging().

Example output with stack logging enabled:

[890744:1:1201/174351.878197:FATAL:weak_ptr.cc(23)] Check failed:
sequence_checker_.CalledOnValidSequence(&bound_at) || HasOneRef().
WeakPtrs must be invalidated on the same sequenced thread as where they
are bound. This was bound at:
#0 0x7fd813c8d369 base::debug::CollectStackTrace()
#1 0x7fd813b94103 base::debug::StackTrace::StackTrace()
#2 0x7fd813c70aef base::ThreadCheckerImpl::ThreadCheckerImpl()
#3 0x7fd813c02155 base::SequenceCheckerImpl::CalledOnValidSequence()
#4 0x7fd813ba4f55 base::ScopedValidateSequenceChecker::ScopedValidateSequenceChecker()
#5 0x7fd813bbfa4f base::internal::WeakReference::IsValid()
#6 0x7fd80acd0f36 blink::FrameWidgetInputHandlerImpl::FrameWidgetInputHandlerImpl()
[...]
Check failed at:
#0 0x7fd813c8d369 base::debug::CollectStackTrace()
#1 0x7fd813b94103 base::debug::StackTrace::StackTrace()
#2 0x7fd813bb3c53 logging::LogMessage::~LogMessage()
#3 0x7fd813bb45ae logging::LogMessage::~LogMessage()
#4 0x7fd813bbf91c base::internal::WeakReference::Flag::Invalidate()
#5 0x7fd813bbfc8c base::internal::WeakReferenceOwner::Invalidate()
#6 0x7fd80ca6eda7 blink::WebFrameWidgetImpl::Close()
#7 0x7fd80ff22359 content::RenderWidget::Close()
#8 0x7fd80ff21eff content::RenderWidget::CloseForFrame()
[...]

[email protected]

Change-Id: Id89c12eaedfba9788b3cd2624447c6a1616f0afa
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2568446
Commit-Queue: danakj <[email protected]>
Reviewed-by: Gabriel Charette <[email protected]>
Reviewed-by: Nico Weber <[email protected]>
Cr-Commit-Position: refs/heads/master@{#847805}

base/BUILD.gn

@@ -1694,6 +1694,7 @@ component("base") {
   if (is_nacl) {
     # Explicitly include the linux file.
     sources += [
+      "debug/stack_trace_nacl.cc",
       "files/file_path_watcher_stub.cc",
       "process/process_metrics_nacl.cc",
       "process/process_stubs.cc",

base/debug/stack_trace_nacl.cc

@@ -0,0 +1,35 @@
+// Copyright 2020 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "base/debug/stack_trace.h"
+
+namespace base {
+namespace debug {
+
+StackTrace::StackTrace() = default;
+StackTrace::StackTrace(size_t count) : StackTrace() {}
+StackTrace::StackTrace(const void* const* trace, size_t count) : StackTrace() {}
+
+const void* const* StackTrace::Addresses(size_t* count) const {
+  return nullptr;
+}
+
+void StackTrace::Print() const {}
+
+void StackTrace::OutputToStream(std::ostream* os) const {}
+
+std::string StackTrace::ToString() const {
+  return "";
+}
+
+std::string StackTrace::ToStringWithPrefix(const char* prefix_string) const {
+  return "";
+}
+
+std::ostream& operator<<(std::ostream& os, const StackTrace& s) {
+  return os;
+}
+
+}  // namespace debug
+}  // namespace base

base/memory/weak_ptr.cc

@@ -4,6 +4,10 @@
 
 #include "base/memory/weak_ptr.h"
 
+#if DCHECK_IS_ON()
+#include "base/debug/stack_trace.h"
+#endif
+
 namespace base {
 namespace internal {
 
@@ -18,8 +22,12 @@ void WeakReference::Flag::Invalidate() {
   // The flag being invalidated with a single ref implies that there are no
   // weak pointers in existence. Allow deletion on other thread in this case.
 #if DCHECK_IS_ON()
-  DCHECK(sequence_checker_.CalledOnValidSequence() || HasOneRef())
-      << "WeakPtrs must be invalidated on the same sequenced thread.";
+  std::unique_ptr<debug::StackTrace> bound_at;
+  DCHECK(sequence_checker_.CalledOnValidSequence(&bound_at) || HasOneRef())
+      << "WeakPtrs must be invalidated on the same sequenced thread as where "
+      << "they are bound.\n"
+      << (bound_at ? "This was bound at:\n" + bound_at->ToString() : "")
+      << "Check failed at:";
 #endif
   invalidated_.Set();
 }

base/sequence_checker.h

@@ -10,6 +10,10 @@
 #include "base/strings/string_piece.h"
 #include "build/build_config.h"
 
+#if DCHECK_IS_ON()
+#include "base/debug/stack_trace.h"
+#endif
+
 // SequenceChecker is a helper class used to help verify that some methods of a
 // class are called sequentially (for thread-safety). It supports thread safety
 // annotations (see base/thread_annotations.h).
@@ -22,6 +26,12 @@
 // ThreadChecker should only be used for classes that are truly thread-affine
 // (use thread-local-storage or a third-party API that does).
 //
+// Debugging:
+//   If SequenceChecker::EnableStackLogging() is called beforehand, then when
+//   SequenceChecker fails, in addition to crashing with a stack trace of where
+//   the violation occurred, it will also dump a stack trace of where the
+//   checker was bound to a sequence.
+//
 // Usage:
 //   class MyClass {
 //    public:
@@ -93,6 +103,8 @@ namespace base {
 class THREAD_ANNOTATION_ATTRIBUTE__(capability("context"))
     SequenceCheckerDoNothing {
  public:
+  static void EnableStackLogging() {}
+
   SequenceCheckerDoNothing() = default;
 
   // Moving between matching sequences is allowed to help classes with
@@ -103,7 +115,9 @@ class THREAD_ANNOTATION_ATTRIBUTE__(capability("context"))
   SequenceCheckerDoNothing(const SequenceCheckerDoNothing&) = delete;
   SequenceCheckerDoNothing& operator=(const SequenceCheckerDoNothing&) = delete;
 
-  bool CalledOnValidSequence() const WARN_UNUSED_RESULT { return true; }
+  bool CalledOnValidSequence(void* = nullptr) const WARN_UNUSED_RESULT {
+    return true;
+  }
   void DetachFromSequence() {}
 };
 
@@ -113,23 +127,32 @@ using SequenceChecker = SequenceCheckerImpl;
 using SequenceChecker = SequenceCheckerDoNothing;
 #endif  // DCHECK_IS_ON()
 
+#if DCHECK_IS_ON()
 class SCOPED_LOCKABLE ScopedValidateSequenceChecker {
  public:
   explicit ScopedValidateSequenceChecker(const SequenceChecker& checker)
       EXCLUSIVE_LOCK_FUNCTION(checker) {
-    DCHECK(checker.CalledOnValidSequence());
+    std::unique_ptr<debug::StackTrace> bound_at;
+    DCHECK(checker.CalledOnValidSequence(&bound_at))
+        << (bound_at ? "\nWas attached to sequence at:\n" + bound_at->ToString()
+                     : "");
   }
 
   explicit ScopedValidateSequenceChecker(const SequenceChecker& checker,
                                          const StringPiece& msg)
       EXCLUSIVE_LOCK_FUNCTION(checker) {
-    DCHECK(checker.CalledOnValidSequence()) << msg;
+    std::unique_ptr<debug::StackTrace> bound_at;
+    DCHECK(checker.CalledOnValidSequence(&bound_at))
+        << msg
+        << (bound_at ? "\nWas attached to sequence at:\n" + bound_at->ToString()
+                     : "");
   }
 
   ~ScopedValidateSequenceChecker() UNLOCK_FUNCTION() {}
 
  private:
 };
+#endif
 
 }  // namespace base
 

base/sequence_checker_impl.cc

@@ -7,37 +7,50 @@
 #include <utility>
 
 #include "base/check.h"
+#include "base/debug/stack_trace.h"
 #include "base/memory/ptr_util.h"
 #include "base/sequence_token.h"
+#include "base/threading/thread_checker.h"
 #include "base/threading/thread_checker_impl.h"
 #include "base/threading/thread_local_storage.h"
 
 namespace base {
 
+// static
+void SequenceCheckerImpl::EnableStackLogging() {
+  ThreadChecker::EnableStackLogging();
+}
+
 class SequenceCheckerImpl::Core {
  public:
   Core() : sequence_token_(SequenceToken::GetForCurrentThread()) {}
 
   ~Core() = default;
 
-  bool CalledOnValidSequence() const {
+  bool CalledOnValidSequence(
+      std::unique_ptr<debug::StackTrace>* out_bound_at) const {
     // SequenceToken::GetForCurrentThread() accesses thread-local storage.
     // During destruction the state of thread-local storage is not guaranteed to
     // be in a consistent state. Further, task-runner only installs the
     // SequenceToken when running a task. For this reason, |sequence_token_| is
     // not checked during thread destruction.
     if (!SequenceCheckerImpl::HasThreadLocalStorageBeenDestroyed() &&
         sequence_token_.IsValid()) {
-      return sequence_token_ == SequenceToken::GetForCurrentThread();
+      if (sequence_token_ != SequenceToken::GetForCurrentThread()) {
+        if (out_bound_at)
+          *out_bound_at = thread_checker_.GetBoundAt();
+        return false;
+      }
+      return true;
     }
 
     // SequenceChecker behaves as a ThreadChecker when it is not bound to a
     // valid sequence token.
-    return thread_checker_.CalledOnValidThread();
+    return thread_checker_.CalledOnValidThread(out_bound_at);
   }
 
  private:
-  SequenceToken sequence_token_;
+  SequenceToken sequence_token_{SequenceToken::GetForCurrentThread()};
 
   // Used when |sequence_token_| is invalid, or during thread destruction.
   ThreadCheckerImpl thread_checker_;
@@ -73,11 +86,12 @@ SequenceCheckerImpl& SequenceCheckerImpl::operator=(
   return *this;
 }
 
-bool SequenceCheckerImpl::CalledOnValidSequence() const {
+bool SequenceCheckerImpl::CalledOnValidSequence(
+    std::unique_ptr<debug::StackTrace>* bound_at) const {
   AutoLock auto_lock(lock_);
   if (!core_)
     core_ = std::make_unique<Core>();
-  return core_->CalledOnValidSequence();
+  return core_->CalledOnValidSequence(bound_at);
 }
 
 void SequenceCheckerImpl::DetachFromSequence() {

base/sequence_checker_impl.h

@@ -12,6 +12,9 @@
 #include "base/thread_annotations.h"
 
 namespace base {
+namespace debug {
+class StackTrace;
+}
 
 // Real implementation of SequenceChecker for use in debug mode or for temporary
 // use in release mode (e.g. to CHECK on a threading issue seen only in the
@@ -24,6 +27,8 @@ namespace base {
 class THREAD_ANNOTATION_ATTRIBUTE__(capability("context"))
     BASE_EXPORT SequenceCheckerImpl {
  public:
+  static void EnableStackLogging();
+
   SequenceCheckerImpl();
 
   // Allow move construct/assign. This must be called on |other|'s associated
@@ -40,7 +45,13 @@ class THREAD_ANNOTATION_ATTRIBUTE__(capability("context"))
 
   // Returns true if called in sequence with previous calls to this method and
   // the constructor.
-  bool CalledOnValidSequence() const WARN_UNUSED_RESULT;
+  // On returning false, if logging is enabled with EnableStackLogging() and
+  // `out_bound_at` is not null, this method allocates a StackTrace and returns
+  // it in the out-parameter, storing inside it the stack from where the failing
+  // SequenceChecker was bound to its sequence. Otherwise, out_bound_at is left
+  // untouched.
+  bool CalledOnValidSequence(std::unique_ptr<debug::StackTrace>* out_bound_at =
+                                 nullptr) const WARN_UNUSED_RESULT;
 
   // Unbinds the checker from the currently associated sequence. The checker
   // will be re-bound on the next call to CalledOnValidSequence().

base/sequence_checker_unittest.cc

@@ -270,6 +270,7 @@ class SequenceCheckerOwner {
 // Verifies SequenceCheckerImpl::CalledOnValidSequence() returns true if called
 // during thread destruction.
 TEST(SequenceCheckerTest, CalledOnValidSequenceFromThreadDestruction) {
+  SequenceChecker::EnableStackLogging();
   ThreadLocalOwnedPointer<SequenceCheckerOwner> thread_local_owner;
   {
     test::TaskEnvironment task_environment;

base/threading/thread_checker.h

@@ -11,6 +11,10 @@
 #include "base/thread_annotations.h"
 #include "base/threading/thread_checker_impl.h"
 
+#if DCHECK_IS_ON()
+#include "base/debug/stack_trace.h"
+#endif
+
 // ThreadChecker is a helper class used to help verify that some methods of a
 // class are called from the same thread (for thread-affinity).  It supports
 // thread safety annotations (see base/thread_annotations.h).
@@ -34,6 +38,12 @@
 // SequencedTaskRunner for ease of scheduling as well as minimizes side-effects
 // if that change is made.
 //
+// Debugging:
+//   If ThreadChecker::EnableStackLogging() is called beforehand, then when
+//   ThreadChecker fails, in addition to crashing with a stack trace of where
+//   the violation occurred, it will also dump a stack trace of where the
+//   checker was bound to a thread.
+//
 // Usage:
 //   class MyClass {
 //    public:
@@ -98,14 +108,19 @@ namespace base {
 // order to support thread_annotations.h.
 class LOCKABLE ThreadCheckerDoNothing {
  public:
+  static void EnableStackLogging() {}
+
   ThreadCheckerDoNothing() = default;
 
   // Moving between matching threads is allowed to help classes with
   // ThreadCheckers that want a default move-construct/assign.
   ThreadCheckerDoNothing(ThreadCheckerDoNothing&& other) = default;
   ThreadCheckerDoNothing& operator=(ThreadCheckerDoNothing&& other) = default;
 
-  bool CalledOnValidThread() const WARN_UNUSED_RESULT { return true; }
+  bool CalledOnValidThread(std::unique_ptr<void*> = nullptr) const
+      WARN_UNUSED_RESULT {
+    return true;
+  }
   void DetachFromThread() {}
 
  private:
@@ -124,24 +139,33 @@ class ThreadChecker : public ThreadCheckerDoNothing {
 };
 #endif  // DCHECK_IS_ON()
 
+#if DCHECK_IS_ON()
 class SCOPED_LOCKABLE ScopedValidateThreadChecker {
  public:
   explicit ScopedValidateThreadChecker(const ThreadChecker& checker)
       EXCLUSIVE_LOCK_FUNCTION(checker) {
-    DCHECK(checker.CalledOnValidThread());
+    std::unique_ptr<debug::StackTrace> bound_at;
+    DCHECK(checker.CalledOnValidThread(&bound_at))
+        << (bound_at ? "\nWas attached to thread at:\n" + bound_at->ToString()
+                     : "");
   }
 
   explicit ScopedValidateThreadChecker(const ThreadChecker& checker,
                                        const StringPiece& msg)
       EXCLUSIVE_LOCK_FUNCTION(checker) {
-    DCHECK(checker.CalledOnValidThread()) << msg;
+    std::unique_ptr<debug::StackTrace> bound_at;
+    DCHECK(checker.CalledOnValidThread(&bound_at))
+        << msg
+        << (bound_at ? "\nWas attached to thread at:\n" + bound_at->ToString()
+                     : "");
   }
 
   ~ScopedValidateThreadChecker() UNLOCK_FUNCTION() {}
 
  private:
   DISALLOW_COPY_AND_ASSIGN(ScopedValidateThreadChecker);
 };
+#endif
 
 }  // namespace base