From 58c71db1b344295a059ae72d9fe247b7c1cd1047 Mon Sep 17 00:00:00 2001 From: Sebastian Jansson Date: Wed, 22 May 2019 16:20:56 +0200 Subject: [PATCH] Fix for crash in event log when using scenario tests. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Reviewed-by: Björn Terelius Commit-Queue: Sebastian Jansson Cr-Commit-Position: refs/heads/master@{#28027} --- api/rtc_event_log/rtc_event_log.h | 9 ++++++ logging/rtc_event_log/rtc_event_log_impl.cc | 33 +++++++++++++-------- logging/rtc_event_log/rtc_event_log_impl.h | 4 +++ test/scenario/BUILD.gn | 1 + test/scenario/call_client.cc | 3 ++ test/scenario/scenario_unittest.cc | 13 ++++++++ 6 files changed, 51 insertions(+), 12 deletions(-) diff --git a/api/rtc_event_log/rtc_event_log.h b/api/rtc_event_log/rtc_event_log.h index 5839f4b2b0..05589b1e40 100644 --- a/api/rtc_event_log/rtc_event_log.h +++ b/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 callback) { + StopLogging(); + callback(); + } + // Log an RTC event (the type of event is determined by the subclass). virtual void Log(std::unique_ptr event) = 0; }; diff --git a/logging/rtc_event_log/rtc_event_log_impl.cc b/logging/rtc_event_log/rtc_event_log_impl.cc index 38e2ee7afd..7881190b3c 100644 --- a/logging/rtc_event_log/rtc_event_log_impl.cc +++ b/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(task_queue_factory->CreateTaskQueue( "rtc_event_log", @@ -89,7 +90,8 @@ RtcEventLogImpl::RtcEventLogImpl(RtcEventLog::EncodingType encoding_type, RtcEventLogImpl::~RtcEventLogImpl() { // If we're logging to the output, this will stop that. Blocking function. - StopLogging(); + if (logging_state_started_) + StopLogging(); // We want to block on any executing task by invoking ~TaskQueue() before // we set unique_ptr's internal pointer to null. @@ -125,6 +127,9 @@ bool RtcEventLogImpl::StartLogging(std::unique_ptr output, LogEventsFromMemoryToOutput(); }; + RTC_DCHECK_RUN_ON(&logging_state_checker_); + logging_state_started_ = true; + task_queue_->PostTask( absl::make_unique>( 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 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 event) { RTC_CHECK(event); diff --git a/logging/rtc_event_log/rtc_event_log_impl.h b/logging/rtc_event_log/rtc_event_log_impl.h index e1ba830b52..160c112114 100644 --- a/logging/rtc_event_log/rtc_event_log_impl.h +++ b/logging/rtc_event_log/rtc_event_log_impl.h @@ -43,6 +43,7 @@ class RtcEventLogImpl final : public RtcEventLog { bool StartLogging(std::unique_ptr output, int64_t output_period_ms) override; void StopLogging() override; + void StopLogging(std::function callback) override; void Log(std::unique_ptr 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 diff --git a/test/scenario/BUILD.gn b/test/scenario/BUILD.gn index 31c0db08e8..f136245ef8 100644 --- a/test/scenario/BUILD.gn +++ b/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", ] diff --git a/test/scenario/call_client.cc b/test/scenario/call_client.cc index a710ad1973..a4607bc586 100644 --- a/test/scenario/call_client.cc +++ b/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(); }); } diff --git a/test/scenario/scenario_unittest.cc b/test/scenario/scenario_unittest.cc index eea8d5946a..1a0e1ff2d6 100644 --- a/test/scenario/scenario_unittest.cc +++ b/test/scenario/scenario_unittest.cc @@ -10,6 +10,7 @@ #include #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