[tracing] Flush trace when test hits a DCHECK

Register a log message handler in BrowserTestBase if --enable-tracing is
passed and flush the trace when encountering a fatal message.

R=eseckler@chromium.org,skyostil@chromium.org,nasko@chromium.org
BUG=1157954

Change-Id: Ic28b108e9b15a38e4f2c94a4a713583b98fa1998
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2595384
Commit-Queue: Alexander Timin <altimin@chromium.org>
Reviewed-by: Gabriel Charette <gab@chromium.org>
Reviewed-by: Eric Seckler <eseckler@chromium.org>
Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
Reviewed-by: Nasko Oskov <nasko@chromium.org>
Cr-Commit-Position: refs/heads/master@{#841452}

base/threading/thread_restrictions.h

@@ -150,13 +150,14 @@ class BrowserShutdownProfileDumper;
 class BrowserTestBase;
 class CategorizedWorkerPool;
 class DesktopCaptureDevice;
+class EmergencyTraceFinalisationCoordinator;
 class InProcessUtilityThread;
 class NestedMessagePumpAndroid;
 class NetworkServiceInstancePrivate;
 class PepperPrintSettingsManagerImpl;
+class RTCVideoDecoder;
 class RenderProcessHostImpl;
 class RenderWidgetHostViewMac;
-class RTCVideoDecoder;
 class SandboxHostLinux;
 class ScopedAllowWaitForDebugURL;
 class ServiceWorkerContextClient;
@@ -530,6 +531,7 @@ class BASE_EXPORT ScopedAllowBaseSyncPrimitivesOutsideBlockingScope {
   friend class cc::TileTaskManagerImpl;
   friend class content::CategorizedWorkerPool;
   friend class content::DesktopCaptureDevice;
+  friend class content::EmergencyTraceFinalisationCoordinator;
   friend class content::InProcessUtilityThread;
   friend class content::RTCVideoDecoder;
   friend class content::SandboxHostLinux;

content/browser/tracing/startup_tracing_browsertest.cc

@@ -5,6 +5,7 @@
 #include "base/files/file_util.h"
 #include "base/json/json_reader.h"
 #include "base/run_loop.h"
+#include "base/test/bind.h"
 #include "base/test/scoped_feature_list.h"
 #include "base/test/test_timeouts.h"
 #include "base/threading/thread_restrictions.h"
@@ -246,13 +247,13 @@ class StartupTracingTest
                                        GetOutputTypeAsString());
   }
 
-  void CheckOutput(base::FilePath path) {
+  static void CheckOutput(base::FilePath path, OutputType output_type) {
     std::string trace;
     base::ScopedAllowBlockingForTesting allow_blocking;
     ASSERT_TRUE(base::ReadFileToString(path, &trace))
         << "Failed to read file " << path;
 
-    if (GetOutputType() == OutputType::kJSON) {
+    if (output_type == OutputType::kJSON) {
       EXPECT_TRUE(base::JSONReader::Read(trace));
     }
 
@@ -312,7 +313,65 @@ IN_PROC_BROWSER_TEST_P(StartupTracingTest, MAYBE_TestEnableTracing) {
 
   Wait();
 
-  CheckOutput(GetExpectedPath());
+  CheckOutput(GetExpectedPath(), GetOutputType());
+}
+
+class EmergencyStopTracingTest : public StartupTracingTest {};
+
+INSTANTIATE_TEST_SUITE_P(
+    All,
+    EmergencyStopTracingTest,
+    testing::Combine(
+        testing::Values(FinishType::kStopExplicitly),
+        testing::Values(OutputType::kJSON, OutputType::kProto),
+        testing::Values(OutputLocation::kDirectoryWithDefaultBasename)));
+
+IN_PROC_BROWSER_TEST_P(EmergencyStopTracingTest, StopOnUIThread) {
+  EXPECT_TRUE(NavigateToURL(shell(), GetTestUrl("", "title1.html")));
+
+  StartupTracingController::EmergencyStop();
+  CheckOutput(GetExpectedPath(), GetOutputType());
+}
+
+IN_PROC_BROWSER_TEST_P(EmergencyStopTracingTest, StopOnThreadPool) {
+  EXPECT_TRUE(NavigateToURL(shell(), GetTestUrl("", "title1.html")));
+
+  auto expected_path = GetExpectedPath();
+  auto output_type = GetOutputType();
+
+  base::RunLoop run_loop;
+
+  base::ThreadPool::PostTask(FROM_HERE, base::BindLambdaForTesting([&]() {
+                               StartupTracingController::EmergencyStop();
+                               CheckOutput(expected_path, output_type);
+                               run_loop.Quit();
+                             }));
+
+  run_loop.Run();
+}
+
+IN_PROC_BROWSER_TEST_P(EmergencyStopTracingTest, StopOnThreadPoolTwice) {
+  EXPECT_TRUE(NavigateToURL(shell(), GetTestUrl("", "title1.html")));
+
+  auto expected_path = GetExpectedPath();
+  auto output_type = GetOutputType();
+
+  base::RunLoop run_loop1;
+  base::RunLoop run_loop2;
+
+  base::ThreadPool::PostTask(FROM_HERE, base::BindLambdaForTesting([&]() {
+                               StartupTracingController::EmergencyStop();
+                               CheckOutput(expected_path, output_type);
+                               run_loop1.Quit();
+                             }));
+  base::ThreadPool::PostTask(FROM_HERE, base::BindLambdaForTesting([&]() {
+                               StartupTracingController::EmergencyStop();
+                               CheckOutput(expected_path, output_type);
+                               run_loop2.Quit();
+                             }));
+
+  run_loop1.Run();
+  run_loop2.Run();
 }
 
 }  // namespace content

content/browser/tracing/startup_tracing_controller.cc

@@ -10,8 +10,11 @@
 #include "base/logging.h"
 #include "base/no_destructor.h"
 #include "base/run_loop.h"
+#include "base/synchronization/waitable_event.h"
 #include "base/task/task_traits.h"
 #include "base/task/thread_pool.h"
+#include "base/thread_annotations.h"
+#include "base/threading/thread_restrictions.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/trace_event/typed_macros.h"
 #include "build/build_config.h"
@@ -31,6 +34,74 @@
 
 namespace content {
 
+// A helper class responsible for coordinating emergency trace finalisation
+// (e.g. when the process is about to be killed), which can be initiated from
+// any thread.
+class EmergencyTraceFinalisationCoordinator {
+ public:
+  static EmergencyTraceFinalisationCoordinator& GetInstance() {
+    static base::NoDestructor<EmergencyTraceFinalisationCoordinator> g_instance;
+    return *g_instance;
+  }
+
+  void OnTracingStarted(scoped_refptr<base::SequencedTaskRunner> task_runner,
+                        base::OnceClosure stop_tracing) {
+    tracing_started_.Set();
+    base::AutoLock lock(lock_);
+    startup_tracing_controller_task_runner_ = std::move(task_runner);
+    stop_tracing_ = std::move(stop_tracing);
+  }
+
+  void OnTracingStopped() { finalisation_.Signal(); }
+
+  // May be called multiple times per session, e.g. if a second thread
+  // encounters a crash after the first.
+  void StopAndBlockUntilStopped() {
+    // If DCHECK fires before tracing has started, there isn't much for us to
+    // do.
+    if (!tracing_started_.IsSet())
+      return;
+
+    base::trace_event::TraceLog::GetInstance()
+        ->SetCurrentThreadBlocksMessageLoop();
+
+    base::OnceClosure stop_tracing;
+    scoped_refptr<base::SequencedTaskRunner> task_runner;
+    {
+      base::AutoLock lock(lock_);
+      task_runner = startup_tracing_controller_task_runner_;
+      stop_tracing = std::move(stop_tracing_);
+    }
+
+    if (task_runner->RunsTasksInCurrentSequence()) {
+      VLOG(0) << "Ignored an emergency tracing stop request from the "
+                 "StartupTracingController sequence";
+      return;
+    }
+
+    if (stop_tracing)
+      task_runner->PostTask(FROM_HERE, std::move(stop_tracing));
+
+    base::ScopedAllowBaseSyncPrimitivesOutsideBlockingScope allow_wait;
+
+    // Wait for the tracing to be finished before processing.
+    // Note that we should wait even if |stop_tracing| is null — if a second
+    // thread hits DCHECK while the first has posted a task and waits for the
+    // trace to be written, the second one should wait as well to avoid crashing
+    // the process.
+    finalisation_.Wait();
+  }
+
+ private:
+  base::WaitableEvent finalisation_;
+  base::AtomicFlag tracing_started_;
+
+  base::Lock lock_;
+  scoped_refptr<base::SequencedTaskRunner>
+      startup_tracing_controller_task_runner_ GUARDED_BY(lock_);
+  base::OnceClosure stop_tracing_ GUARDED_BY(lock_);
+};
+
 class StartupTracingController::BackgroundTracer {
  public:
   enum class WriteMode { kAfterStopping, kStreaming };
@@ -61,23 +132,33 @@ class StartupTracingController::BackgroundTracer {
       tracing_session_->Setup(trace_config);
     }
 
-    tracing_session_->StartBlocking();
+    // |StartBlocking| can take a non-trivial amount of time, so
+    // EmergencyTraceFinalisationController should be set up before it to catch
+    // DCHECKs early.
+    EmergencyTraceFinalisationCoordinator::GetInstance().OnTracingStarted(
+        task_runner_,
+        base::BindOnce(&BackgroundTracer::Stop, weak_ptr_factory_.GetWeakPtr(),
+                       base::nullopt));
+
     tracing_session_->SetOnStopCallback([&]() { OnTracingStopped(); });
+    tracing_session_->StartBlocking();
 
     TRACE_EVENT("startup", "StartupTracingController::Start");
   }
 
-  void Stop(base::FilePath output_file) {
+  void Stop(base::Optional<base::FilePath> output_file) {
     DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
 
     // Tracing might have already been finished due to a timeout.
-    if (state_ == State::kFinished) {
+    if (state_ != State::kTracing) {
       // Note: updating output files is not supported together with
       // timeout-based tracing.
       return;
     }
+    state_ = State::kStopping;
 
-    output_file_ = output_file;
+    if (output_file)
+      output_file_ = output_file.value();
     tracing_session_->StopBlocking();
   }
 
@@ -92,7 +173,9 @@ class StartupTracingController::BackgroundTracer {
     }
 
     DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
-    DCHECK_EQ(state_, State::kTracing);
+    // State will be kStopping if Stop() is called and kTracing if tracing
+    // finishes due to a timeout.
+    DCHECK(state_ == State::kStopping || state_ == State::kTracing);
     if (write_mode_ == WriteMode::kStreaming) {
       // No need to explicitly call ReadTrace as Perfetto has already written
       // the file.
@@ -185,6 +268,7 @@ class StartupTracingController::BackgroundTracer {
     }
 
     VLOG(0) << "Completed startup tracing to " << written_to_file_;
+    EmergencyTraceFinalisationCoordinator::GetInstance().OnTracingStopped();
 
     state_ = State::kFinished;
     std::move(on_tracing_finished_).Run();
@@ -192,6 +276,7 @@ class StartupTracingController::BackgroundTracer {
 
   enum class State {
     kTracing,
+    kStopping,
     kWritingToFile,
     kFinished,
   };
@@ -222,6 +307,8 @@ class StartupTracingController::BackgroundTracer {
   std::unique_ptr<perfetto::TracingSession> tracing_session_;
 
   SEQUENCE_CHECKER(sequence_checker_);
+
+  base::WeakPtrFactory<BackgroundTracer> weak_ptr_factory_{this};
 };
 
 // static
@@ -423,4 +510,16 @@ void StartupTracingController::WaitUntilStopped() {
   run_loop.Run();
 }
 
+// static
+void StartupTracingController::EmergencyStop() {
+  if (GetIOThreadTaskRunner({})->RunsTasksInCurrentSequence()) {
+    VLOG(0) << "Emergency tracing stop request from IO thread is ignored - not "
+               "possible to finalise trace without running tasks on IO thread";
+    return;
+  }
+
+  EmergencyTraceFinalisationCoordinator::GetInstance()
+      .StopAndBlockUntilStopped();
+}
+
 }  // namespace content

content/browser/tracing/startup_tracing_controller.h

@@ -20,6 +20,14 @@ class CONTENT_EXPORT StartupTracingController {
 
   static StartupTracingController& GetInstance();
 
+  // Stop the trace recording, write the trace to disk and block until complete.
+  // Intended to be used in the situation when the browser process is going to
+  // crash (e.g. DCHECK failure) and we want to avoid losing the trace data. Can
+  // be called from any thread.
+  // May not succeed if called from a sequence that is required to be responsive
+  // during trace finalisation.
+  static void EmergencyStop();
+
   void StartIfNeeded();
   void WaitUntilStopped();
 

content/public/test/DEPS

@@ -33,6 +33,7 @@ specific_include_rules = {
   ".*\.(cc|mm)": [
     # Testing utilities can access anything in content/
     "+content",
+    "+components/tracing/common",
     "+gin/v8_initializer.h",
     "+services/network/network_context.h",
     "+third_party/iaccessible2",

content/public/test/browser_test_base.cc

@@ -21,6 +21,7 @@
 #include "base/files/scoped_file.h"
 #include "base/i18n/icu_util.h"
 #include "base/location.h"
+#include "base/logging.h"
 #include "base/macros.h"
 #include "base/rand_util.h"
 #include "base/run_loop.h"
@@ -37,6 +38,7 @@
 #include "base/threading/thread_task_runner_handle.h"
 #include "build/build_config.h"
 #include "build/chromeos_buildflags.h"
+#include "components/tracing/common/tracing_switches.h"
 #include "content/browser/browser_main_loop.h"
 #include "content/browser/browser_thread_impl.h"
 #include "content/browser/network_service_instance_impl.h"
@@ -530,6 +532,22 @@ void BrowserTestBase::SetUp() {
   // test crashes or times out.
   StartupTracingController::GetInstance().SetUsingTemporaryFile(
       StartupTracingController::TempFilePolicy::kWriteDirectly);
+  // Set a logging handler to flush a trace before crashing the test when
+  // hitting a DCHECK / LOG(FATAL).
+  if (base::CommandLine::ForCurrentProcess()->HasSwitch(
+          switches::kEnableTracing)) {
+    DCHECK(!logging::GetLogMessageHandler());
+    logging::SetLogMessageHandler([](int severity, const char* file, int line,
+                                     size_t message_start,
+                                     const std::string& str) {
+      // TODO(crbug.com/1157954): Print the message to the console before
+      // calling this to ensure that the message is still printed if something
+      // goes wrong.
+      if (severity == logging::LOGGING_FATAL)
+        StartupTracingController::EmergencyStop();
+      return false;
+    });
+  }
 
 #if defined(OS_ANDROID)
   // For all other platforms, we call ContentMain for browser tests which goes