Report which RunLoop is timing out in a test.

Tests insert a timeout on RunLoop in order to find slow or flaky tests
but the current error message only reports where the timeout is enabled
and not which RunLoop was currently running. Example:

../../content/public/test/browser_test_base.cc:701: Failure
Failed
RunLoop::Run() timed out.
Stack trace:

We will now include the Location where the RunLoop::Run() call happens
in order to report where the test is actually timing out. The new error
looks like:

../../content/test/content_browser_test_test.cc:341: Failure
Failed
RunLoop::Run() timed out. Timeout set at ../../content/public/test/browser_test_base.cc:701.
Stack trace:

Notably the file and line number where the "Failure" is reported
(in the first line) are where the RunLoop is Run().

R=gab@chromium.org

Bug: 1145280
Change-Id: Ia5e39dbbfb47fd4c9f831cb77889061c4cd3060f
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2518125Reviewed-by: Avi Drissman <avi@chromium.org>
Reviewed-by: Bill Budge <bbudge@chromium.org>
Reviewed-by: Gabriel Charette <gab@chromium.org>
Commit-Queue: danakj <danakj@chromium.org>
Cr-Commit-Position: refs/heads/master@{#845815}

base/run_loop.cc

@@ -19,7 +19,7 @@ namespace base {
 namespace {
 
 ThreadLocalPointer<RunLoop::Delegate>& GetTlsDelegate() {
-  static base::NoDestructor<ThreadLocalPointer<RunLoop::Delegate>> instance;
+  static NoDestructor<ThreadLocalPointer<RunLoop::Delegate>> instance;
   return *instance;
 }
 
@@ -39,9 +39,11 @@ ThreadLocalPointer<const RunLoop::RunLoopTimeout>& RunLoopTimeoutTLS() {
   return *tls;
 }
 
-void OnRunLoopTimeout(RunLoop* run_loop, OnceClosure on_timeout) {
+void OnRunLoopTimeout(RunLoop* run_loop,
+                      const Location& location,
+                      OnceCallback<void(const Location&)> on_timeout) {
   run_loop->Quit();
-  std::move(on_timeout).Run();
+  std::move(on_timeout).Run(location);
 }
 
 }  // namespace
@@ -106,7 +108,7 @@ RunLoop::~RunLoop() {
   DCHECK(!running_);
 }
 
-void RunLoop::Run() {
+void RunLoop::Run(const Location& location) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
 
   if (!BeforeRun())
@@ -118,8 +120,8 @@ void RunLoop::Run() {
   CancelableOnceClosure cancelable_timeout;
   const RunLoopTimeout* run_timeout = GetTimeoutForCurrentThread();
   if (run_timeout) {
-    cancelable_timeout.Reset(
-        BindOnce(&OnRunLoopTimeout, Unretained(this), run_timeout->on_timeout));
+    cancelable_timeout.Reset(BindOnce(&OnRunLoopTimeout, Unretained(this),
+                                      location, run_timeout->on_timeout));
     origin_task_runner_->PostDelayedTask(
         FROM_HERE, cancelable_timeout.callback(), run_timeout->timeout);
   }

base/run_loop.h

@@ -13,6 +13,7 @@
 #include "base/callback.h"
 #include "base/containers/stack.h"
 #include "base/gtest_prod_util.h"
+#include "base/location.h"
 #include "base/memory/ref_counted.h"
 #include "base/memory/weak_ptr.h"
 #include "base/observer_list.h"
@@ -81,7 +82,7 @@ class BASE_EXPORT RunLoop {
 
   // Run the current RunLoop::Delegate. This blocks until Quit is called
   // (directly or by running the RunLoop::QuitClosure).
-  void Run();
+  void Run(const Location& location = Location::Current());
 
   // Run the current RunLoop::Delegate until it doesn't find any tasks or
   // messages in its queue (it goes idle).
@@ -281,7 +282,7 @@ class BASE_EXPORT RunLoop {
     RunLoopTimeout();
     ~RunLoopTimeout();
     TimeDelta timeout;
-    RepeatingClosure on_timeout;
+    RepeatingCallback<void(const Location&)> on_timeout;
   };
 
  private:

base/task/common/task_annotator_unittest.cc

@@ -414,7 +414,8 @@ TEST_F(TaskAnnotatorBacktraceIntegrationTest, SingleThreadedNested) {
   {
     TaskAnnotator::ScopedSetIpcHash scoped_ipc_hash(dummy_ipc_hash2);
     ThreadTaskRunnerHandle::Get()->PostTask(
-        FROM_HERE, BindOnce(&RunLoop::Run, Unretained(&nested_run_loop1)));
+        FROM_HERE,
+        BindOnce(&RunLoop::Run, Unretained(&nested_run_loop1), FROM_HERE));
   }
 
   run_loop.Run();

base/test/scoped_run_loop_timeout.cc

@@ -9,6 +9,7 @@
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/strings/strcat.h"
+#include "base/strings/stringprintf.h"
 #include "base/time/time.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
@@ -19,8 +20,10 @@ namespace {
 
 bool g_add_gtest_failure_on_timeout = false;
 
-std::string TimeoutMessage(const RepeatingCallback<std::string()>& get_log) {
-  std::string message = "RunLoop::Run() timed out.";
+std::string TimeoutMessage(const RepeatingCallback<std::string()>& get_log,
+                           const Location& timeout_enabled_from_here) {
+  std::string message = "RunLoop::Run() timed out. Timeout set at ";
+  message += timeout_enabled_from_here.ToString() + ".";
   if (get_log)
     StrAppend(&message, {"\n", get_log.Run()});
   return message;
@@ -37,7 +40,7 @@ ScopedRunLoopTimeout::~ScopedRunLoopTimeout() {
 }
 
 ScopedRunLoopTimeout::ScopedRunLoopTimeout(
-    const Location& from_here,
+    const Location& timeout_enabled_from_here,
     TimeDelta timeout,
     RepeatingCallback<std::string()> on_timeout_log)
     : nested_timeout_(RunLoop::GetTimeoutForCurrentThread()) {
@@ -46,21 +49,24 @@ ScopedRunLoopTimeout::ScopedRunLoopTimeout(
 
   if (g_add_gtest_failure_on_timeout) {
     run_timeout_.on_timeout = BindRepeating(
-        [](const Location& from_here,
-           RepeatingCallback<std::string()> on_timeout_log) {
-          GTEST_FAIL_AT(from_here.file_name(), from_here.line_number())
-              << TimeoutMessage(on_timeout_log);
+        [](const Location& timeout_enabled_from_here,
+           RepeatingCallback<std::string()> on_timeout_log,
+           const Location& run_from_here) {
+          GTEST_FAIL_AT(run_from_here.file_name(), run_from_here.line_number())
+              << TimeoutMessage(on_timeout_log, timeout_enabled_from_here);
         },
-        from_here, std::move(on_timeout_log));
+        timeout_enabled_from_here, std::move(on_timeout_log));
   } else {
     run_timeout_.on_timeout = BindRepeating(
-        [](const Location& from_here,
-           RepeatingCallback<std::string()> on_timeout_log) {
-          std::string message = TimeoutMessage(on_timeout_log);
-          logging::LogMessage(from_here.file_name(), from_here.line_number(),
-                              message.data());
+        [](const Location& timeout_enabled_from_here,
+           RepeatingCallback<std::string()> on_timeout_log,
+           const Location& run_from_here) {
+          std::string message =
+              TimeoutMessage(on_timeout_log, timeout_enabled_from_here);
+          logging::LogMessage(run_from_here.file_name(),
+                              run_from_here.line_number(), message.data());
         },
-        from_here, std::move(on_timeout_log));
+        timeout_enabled_from_here, std::move(on_timeout_log));
   }
 
   RunLoop::SetTimeoutForCurrentThread(&run_timeout_);

base/test/scoped_run_loop_timeout.h

@@ -58,12 +58,13 @@ FORWARD_DECLARE_TEST(TaskEnvironmentTest, SetsDefaultRunTimeout);
 
 class ScopedRunLoopTimeout {
  public:
-  ScopedRunLoopTimeout(const Location& from_here, TimeDelta timeout);
+  ScopedRunLoopTimeout(const Location& timeout_enabled_from_here,
+                       TimeDelta timeout);
   ~ScopedRunLoopTimeout();
 
   // Invokes |on_timeout_log| if |timeout| expires, and appends it to the
   // logged error message.
-  ScopedRunLoopTimeout(const Location& from_here,
+  ScopedRunLoopTimeout(const Location& timeout_enabled_from_here,
                        TimeDelta timeout,
                        RepeatingCallback<std::string()> on_timeout_log);
 

base/test/scoped_run_loop_timeout_unittest.cc

@@ -72,7 +72,11 @@ TEST(ScopedRunLoopTimeoutTest, OnTimeoutLog) {
 
   // EXPECT_FATAL_FAILURE() can only reference globals and statics.
   static RunLoop& static_loop = run_loop;
-  EXPECT_FATAL_FAILURE(static_loop.Run(), "Run() timed out.\nI like kittens!");
+  EXPECT_FATAL_FAILURE(
+      static_loop.Run(),
+      "Run() timed out. Timeout set at "
+      "TestBody@../../base/test/scoped_run_loop_timeout_unittest.cc:70.\n"
+      "I like kittens!");
 }
 
 }  // namespace test

base/test/task_environment_unittest.cc

@@ -880,8 +880,12 @@ TEST_F(TaskEnvironmentTest, SetsDefaultRunTimeout) {
     if (!debug::BeingDebugged()) {
       EXPECT_LT(run_timeout->timeout, TestTimeouts::test_launcher_timeout());
     }
-    static const RepeatingClosure& static_on_timeout = run_timeout->on_timeout;
-    EXPECT_FATAL_FAILURE(static_on_timeout.Run(), "RunLoop::Run() timed out");
+    static auto& static_on_timeout_cb = run_timeout->on_timeout;
+    EXPECT_FATAL_FAILURE(
+        static_on_timeout_cb.Run(FROM_HERE),
+        "RunLoop::Run() timed out. Timeout set at "
+        // We don't test the line number but it would be present.
+        "TaskEnvironment@../../base/test/task_environment.cc:");
   }
 
   EXPECT_EQ(ScopedRunLoopTimeout::GetTimeoutForCurrentThread(),

content/test/content_browser_test_test.cc

@@ -353,9 +353,12 @@ IN_PROC_BROWSER_TEST_F(ContentBrowserTest, RunTimeoutInstalled) {
   EXPECT_TRUE(run_timeout);
   EXPECT_LT(run_timeout->timeout, TestTimeouts::test_launcher_timeout());
 
-  static const base::RepeatingClosure& static_on_timeout =
-      run_timeout->on_timeout;
-  EXPECT_FATAL_FAILURE(static_on_timeout.Run(), "RunLoop::Run() timed out");
+  static auto& static_on_timeout_cb = run_timeout->on_timeout;
+  EXPECT_FATAL_FAILURE(static_on_timeout_cb.Run(FROM_HERE),
+                       "RunLoop::Run() timed out. Timeout set at "
+                       // We don't test the line number but it would be present.
+                       "ProxyRunTestOnMainThreadLoop@../../content/public/test/"
+                       "browser_test_base.cc:");
 }
 
 }  // namespace content

ppapi/proxy/ppb_message_loop_proxy.cc

@@ -114,8 +114,8 @@ int32_t MessageLoopResource::Run() {
   run_loop_ = &run_loop;
 
   nested_invocations_++;
-  CallWhileUnlocked(
-      base::BindOnce(&base::RunLoop::Run, base::Unretained(run_loop_)));
+  CallWhileUnlocked(base::BindOnce(&base::RunLoop::Run,
+                                   base::Unretained(run_loop_), FROM_HERE));
   nested_invocations_--;
 
   run_loop_ = previous_run_loop;