[base] Support an additional log message in ScopedRunLoopTimeout.

Allow an optional RepeatingCallback<std::string()> to be supplied to
ScopedRunLoopTimeout, to provide an additional message string in case of
timeout.

Update base::test::TaskEnvironment to have DescribeAllPendingTasks'
output appending to the timeout message.

Bug: 1021777
Change-Id: I32ff686924aea50cc56b6f103696bdbde7e8d8fd
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2062984
Auto-Submit: Wez <wez@chromium.org>
Reviewed-by: Gabriel Charette <gab@chromium.org>
Commit-Queue: Gabriel Charette <gab@chromium.org>
Commit-Queue: Wez <wez@chromium.org>
Cr-Commit-Position: refs/heads/master@{#742679}

base/test/scoped_run_loop_timeout.cc

@@ -5,7 +5,9 @@
 #include "base/test/scoped_run_loop_timeout.h"
 
 #include "base/bind.h"
+#include "base/bind_helpers.h"
 #include "base/location.h"
+#include "base/strings/strcat.h"
 #include "base/time/time.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
@@ -13,38 +15,56 @@ namespace base {
 namespace test {
 
 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.";
+  if (get_log)
+    StrAppend(&message, {"\n", get_log.Run()});
+  return message;
 }
 
+}  // namespace
+
 ScopedRunLoopTimeout::ScopedRunLoopTimeout(const Location& from_here,
                                            TimeDelta timeout)
+    : ScopedRunLoopTimeout(from_here, timeout, NullCallback()) {}
+
+ScopedRunLoopTimeout::~ScopedRunLoopTimeout() {
+  RunLoop::SetTimeoutForCurrentThread(nested_timeout_);
+}
+
+ScopedRunLoopTimeout::ScopedRunLoopTimeout(
+    const Location& from_here,
+    TimeDelta timeout,
+    RepeatingCallback<std::string()> on_timeout_log)
     : nested_timeout_(RunLoop::GetTimeoutForCurrentThread()) {
   DCHECK_GT(timeout, TimeDelta());
   run_timeout_.timeout = timeout;
 
   if (g_add_gtest_failure_on_timeout) {
-    run_timeout_.on_timeout = base::BindRepeating(
-        [](const Location& from_here) {
+    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())
-              << "RunLoop::Run() timed out.";
+              << TimeoutMessage(on_timeout_log);
         },
-        from_here);
+        from_here, std::move(on_timeout_log));
   } else {
-    run_timeout_.on_timeout = base::BindRepeating(
-        [](const Location& from_here) {
+    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(),
-                              "RunLoop::Run() timed out.");
+                              message.data());
         },
-        from_here);
+        from_here, std::move(on_timeout_log));
   }
 
   RunLoop::SetTimeoutForCurrentThread(&run_timeout_);
 }
 
-ScopedRunLoopTimeout::~ScopedRunLoopTimeout() {
-  RunLoop::SetTimeoutForCurrentThread(nested_timeout_);
-}
-
 // static
 bool ScopedRunLoopTimeout::ExistsForCurrentThread() {
   return RunLoop::GetTimeoutForCurrentThread() != nullptr;

base/test/scoped_run_loop_timeout.h

@@ -5,6 +5,9 @@
 #ifndef BASE_TEST_SCOPED_RUN_LOOP_TIMEOUT_H_
 #define BASE_TEST_SCOPED_RUN_LOOP_TIMEOUT_H_
 
+#include <string>
+
+#include "base/callback.h"
 #include "base/location.h"
 #include "base/run_loop.h"
 #include "base/time/time.h"
@@ -58,6 +61,12 @@ class ScopedRunLoopTimeout {
   ScopedRunLoopTimeout(const Location& 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,
+                       TimeDelta timeout,
+                       RepeatingCallback<std::string()> on_timeout_log);
+
   ScopedRunLoopTimeout(const ScopedRunLoopTimeout&) = delete;
   ScopedRunLoopTimeout& operator=(const ScopedRunLoopTimeout&) = delete;
 

base/test/scoped_run_loop_timeout_unittest.cc

@@ -61,5 +61,19 @@ TEST(ScopedRunLoopTimeoutTest, RunTasksUntilTimeout) {
   EXPECT_FATAL_FAILURE(static_loop.Run(), "Run() timed out.");
 }
 
+TEST(ScopedRunLoopTimeoutTest, OnTimeoutLog) {
+  TaskEnvironment task_environment;
+  RunLoop run_loop;
+
+  static constexpr auto kArbitraryTimeout = TimeDelta::FromMilliseconds(10);
+  ScopedRunLoopTimeout run_timeout(
+      FROM_HERE, kArbitraryTimeout,
+      BindRepeating([]() -> std::string { return "I like kittens!"; }));
+
+  // 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!");
+}
+
 }  // namespace test
 }  // namespace base

base/test/task_environment.cc

@@ -382,11 +382,15 @@ TaskEnvironment::TaskEnvironment(
           std::make_unique<internal::ScopedLazyTaskRunnerListForTesting>()),
       // TODO(https://crbug.com/922098): Enable Run() timeouts even for
       // instances created with TimeSource::MOCK_TIME.
-      run_loop_timeout_(mock_time_domain_
-                            ? nullptr
-                            : std::make_unique<ScopedRunLoopTimeout>(
-                                  FROM_HERE,
-                                  TestTimeouts::action_timeout())) {
+      run_loop_timeout_(
+          mock_time_domain_
+              ? nullptr
+              : std::make_unique<ScopedRunLoopTimeout>(
+                    FROM_HERE,
+                    TestTimeouts::action_timeout(),
+                    BindRepeating(&sequence_manager::SequenceManager::
+                                      DescribeAllPendingTasks,
+                                  Unretained(sequence_manager_.get())))) {
   CHECK(!base::ThreadTaskRunnerHandle::IsSet());
   // If |subclass_creates_default_taskrunner| is true then initialization is
   // deferred until DeferredInitFromSubclass().