Fix for crash in event log when using scenario tests.

Scenario tests runs all its activities on task queues. This is not
allowed by the default event log writer, causing a DCHECK failure.
This CL makes it possible to stop the event asynchronously,
thereby avoiding the need for the DCHECK.

Bug: webrtc:10365
Change-Id: I1206982b29fd609ac85b4ce30ae9291cbec52041
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/136685
Reviewed-by: Stefan Holmer <stefan@webrtc.org>
Reviewed-by: Björn Terelius <terelius@webrtc.org>
Commit-Queue: Sebastian Jansson <srte@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#28027}

api/rtc_event_log/rtc_event_log.h

@@ -54,6 +54,15 @@ class RtcEventLog {
   // which it would be permissible to read and/or modify it.
   virtual void StopLogging() = 0;
 
+  // Stops logging to file and calls |callback| when the file has been closed.
+  // Note that it is not safe to call any other members, including the
+  // destructor, until the callback has been called.
+  // TODO(srte): Remove default implementation when it's safe to do so.
+  virtual void StopLogging(std::function<void()> callback) {
+    StopLogging();
+    callback();
+  }
+
   // Log an RTC event (the type of event is determined by the subclass).
   virtual void Log(std::unique_ptr<RtcEvent> event) = 0;
 };

logging/rtc_event_log/rtc_event_log_impl.cc

@@ -82,6 +82,7 @@ RtcEventLogImpl::RtcEventLogImpl(RtcEventLog::EncodingType encoding_type,
       num_config_events_written_(0),
       last_output_ms_(rtc::TimeMillis()),
       output_scheduled_(false),
+      logging_state_started_(false),
       task_queue_(
           absl::make_unique<rtc::TaskQueue>(task_queue_factory->CreateTaskQueue(
               "rtc_event_log",
@@ -89,6 +90,7 @@ RtcEventLogImpl::RtcEventLogImpl(RtcEventLog::EncodingType encoding_type,
 
 RtcEventLogImpl::~RtcEventLogImpl() {
   // If we're logging to the output, this will stop that. Blocking function.
+  if (logging_state_started_)
     StopLogging();
 
   // We want to block on any executing task by invoking ~TaskQueue() before
@@ -125,6 +127,9 @@ bool RtcEventLogImpl::StartLogging(std::unique_ptr<RtcEventLogOutput> output,
     LogEventsFromMemoryToOutput();
   };
 
+  RTC_DCHECK_RUN_ON(&logging_state_checker_);
+  logging_state_started_ = true;
+
   task_queue_->PostTask(
       absl::make_unique<ResourceOwningTask<RtcEventLogOutput>>(
           std::move(output), start));
@@ -136,17 +141,7 @@ void RtcEventLogImpl::StopLogging() {
   RTC_LOG(LS_INFO) << "Stopping WebRTC event log.";
 
   rtc::Event output_stopped;
-
-  // Binding to |this| is safe because |this| outlives the |task_queue_|.
-  task_queue_->PostTask([this, &output_stopped]() {
-    RTC_DCHECK_RUN_ON(task_queue_.get());
-    if (event_output_) {
-      RTC_DCHECK(event_output_->IsActive());
-      LogEventsFromMemoryToOutput();
-    }
-    StopLoggingInternal();
-    output_stopped.Set();
-  });
+  StopLogging([&output_stopped]() { output_stopped.Set(); });
 
   // By making sure StopLogging() is not executed on a task queue,
   // we ensure it's not running on a thread that is shared with |task_queue_|,
@@ -158,6 +153,20 @@ void RtcEventLogImpl::StopLogging() {
   RTC_LOG(LS_INFO) << "WebRTC event log successfully stopped.";
 }
 
+void RtcEventLogImpl::StopLogging(std::function<void()> callback) {
+  RTC_DCHECK_RUN_ON(&logging_state_checker_);
+  logging_state_started_ = false;
+  task_queue_->PostTask([this, callback] {
+    RTC_DCHECK_RUN_ON(task_queue_.get());
+    if (event_output_) {
+      RTC_DCHECK(event_output_->IsActive());
+      LogEventsFromMemoryToOutput();
+    }
+    StopLoggingInternal();
+    callback();
+  });
+}
+
 void RtcEventLogImpl::Log(std::unique_ptr<RtcEvent> event) {
   RTC_CHECK(event);
 

logging/rtc_event_log/rtc_event_log_impl.h

@@ -43,6 +43,7 @@ class RtcEventLogImpl final : public RtcEventLog {
   bool StartLogging(std::unique_ptr<RtcEventLogOutput> output,
                     int64_t output_period_ms) override;
   void StopLogging() override;
+  void StopLogging(std::function<void()> callback) override;
 
   void Log(std::unique_ptr<RtcEvent> event) override;
 
@@ -80,6 +81,9 @@ class RtcEventLogImpl final : public RtcEventLog {
   int64_t last_output_ms_ RTC_GUARDED_BY(*task_queue_);
   bool output_scheduled_ RTC_GUARDED_BY(*task_queue_);
 
+  SequenceChecker logging_state_checker_;
+  bool logging_state_started_ RTC_GUARDED_BY(logging_state_checker_);
+
   // Since we are posting tasks bound to |this|,  it is critical that the event
   // log and its members outlive |task_queue_|. Keep the |task_queue_|
   // last to ensure it destructs first, or else tasks living on the queue might

test/scenario/BUILD.gn

@@ -173,6 +173,7 @@ if (rtc_include_tests) {
       "../../system_wrappers:field_trial",
       "../../test:field_trial",
       "../../test:test_support",
+      "../logging:log_writer",
       "//testing/gmock",
       "//third_party/abseil-cpp/absl/memory",
     ]

test/scenario/call_client.cc

@@ -150,6 +150,9 @@ CallClient::~CallClient() {
   SendTask([&] {
     call_.reset();
     fake_audio_setup_ = {};
+    rtc::Event done;
+    event_log_->StopLogging([&done] { done.Set(); });
+    done.Wait(rtc::Event::kForever);
     event_log_.reset();
   });
 }

test/scenario/scenario_unittest.cc

@@ -10,6 +10,7 @@
 #include <atomic>
 
 #include "test/gtest.h"
+#include "test/logging/memory_log_writer.h"
 #include "test/scenario/scenario.h"
 #include "test/scenario/stats_collection.h"
 
@@ -132,5 +133,17 @@ TEST(ScenarioTest, SimTimeFakeing) {
   s.RunFor(TimeDelta::seconds(10));
 }
 
+TEST(ScenarioTest, WritesToRtcEventLog) {
+  MemoryLogStorage storage;
+  {
+    Scenario s(storage.CreateFactory(), false);
+    SetupVideoCall(s, nullptr);
+    s.RunFor(TimeDelta::seconds(1));
+  }
+  auto logs = storage.logs();
+  // We expect that a rtc event log has been created and that it has some data.
+  EXPECT_GE(storage.logs().at("alice.rtc.dat").size(), 1u);
+}
+
 }  // namespace test
 }  // namespace webrtc