diff --git a/logging/BUILD.gn b/logging/BUILD.gn index a654fc40ec..ac2336ceaa 100644 --- a/logging/BUILD.gn +++ b/logging/BUILD.gn @@ -59,11 +59,15 @@ rtc_source_set("rtc_event_log_api") { "rtc_event_log/events/rtc_event_video_receive_stream_config.h", "rtc_event_log/events/rtc_event_video_send_stream_config.cc", "rtc_event_log/events/rtc_event_video_send_stream_config.h", + "rtc_event_log/output/rtc_event_log_output.h", + "rtc_event_log/output/rtc_event_log_output_file.cc", + "rtc_event_log/output/rtc_event_log_output_file.h", "rtc_event_log/rtc_event_log.h", "rtc_event_log/rtc_event_log_factory_interface.h", "rtc_event_log/rtc_stream_config.cc", "rtc_event_log/rtc_stream_config.h", ] + deps = [ "..:webrtc_common", "../api:array_view", @@ -73,7 +77,14 @@ rtc_source_set("rtc_event_log_api") { "../modules/remote_bitrate_estimator:remote_bitrate_estimator", "../modules/rtp_rtcp:rtp_rtcp_format", "../rtc_base:rtc_base_approved", + "../system_wrappers", ] + + # TODO(eladalon): Remove this. + if (!build_with_chromium && is_clang) { + # Suppress warnings from the Chromium Clang plugin (bugs.webrtc.org/163). + suppressed_configs += [ "//build/config/clang:find_bad_constructs" ] + } } rtc_static_library("rtc_event_log_impl") { @@ -105,6 +116,8 @@ rtc_static_library("rtc_event_log_impl") { defines += [ "ENABLE_RTC_EVENT_LOG" ] deps += [ ":rtc_event_log_proto" ] } + + # TODO(eladalon): Remove this. if (!build_with_chromium && is_clang) { # Suppress warnings from the Chromium Clang plugin (bugs.webrtc.org/163). suppressed_configs += [ "//build/config/clang:find_bad_constructs" ] @@ -153,6 +166,7 @@ if (rtc_enable_protobuf) { defines = [ "ENABLE_RTC_EVENT_LOG" ] sources = [ "rtc_event_log/encoder/rtc_event_log_encoder_unittest.cc", + "rtc_event_log/output/rtc_event_log_output_file_unittest.cc", "rtc_event_log/rtc_event_log_unittest.cc", "rtc_event_log/rtc_event_log_unittest_helper.cc", "rtc_event_log/rtc_event_log_unittest_helper.h", diff --git a/logging/rtc_event_log/mock/mock_rtc_event_log.h b/logging/rtc_event_log/mock/mock_rtc_event_log.h index ef351a25b3..1f44c0b858 100644 --- a/logging/rtc_event_log/mock/mock_rtc_event_log.h +++ b/logging/rtc_event_log/mock/mock_rtc_event_log.h @@ -25,6 +25,11 @@ namespace webrtc { class MockRtcEventLog : public RtcEventLog { public: + virtual bool StartLogging(std::unique_ptr output) { + return StartLoggingProxy(output.get()); + } + MOCK_METHOD1(StartLoggingProxy, bool(RtcEventLogOutput*)); + MOCK_METHOD2(StartLogging, bool(const std::string& file_name, int64_t max_size_bytes)); diff --git a/logging/rtc_event_log/output/rtc_event_log_output.h b/logging/rtc_event_log/output/rtc_event_log_output.h new file mode 100644 index 0000000000..8b4dd1cef7 --- /dev/null +++ b/logging/rtc_event_log/output/rtc_event_log_output.h @@ -0,0 +1,38 @@ +/* + * Copyright (c) 2017 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#ifndef LOGGING_RTC_EVENT_LOG_OUTPUT_RTC_EVENT_LOG_OUTPUT_H_ +#define LOGGING_RTC_EVENT_LOG_OUTPUT_RTC_EVENT_LOG_OUTPUT_H_ + +#include + +namespace webrtc { + +class RtcEventLogOutput { + public: + virtual ~RtcEventLogOutput() = default; + + // An output normally starts out active, though that might not always be + // the case (e.g. failed to open a file for writing). + // Once an output has become inactive (e.g. maximum file size reached), it can + // never become active again. + virtual bool IsActive() const = 0; + + // Write encoded events to an output. Returns true if the output was + // successfully written in its entirety. Otherwise, no guarantee is given + // about how much data was written, if any. The output sink becomes inactive + // after the first time |false| is returned. Write() may not be called on + // an inactive output sink. + virtual bool Write(const std::string& output) = 0; +}; + +} // namespace webrtc + +#endif // LOGGING_RTC_EVENT_LOG_OUTPUT_RTC_EVENT_LOG_OUTPUT_H_ diff --git a/logging/rtc_event_log/output/rtc_event_log_output_file.cc b/logging/rtc_event_log/output/rtc_event_log_output_file.cc new file mode 100644 index 0000000000..2f8b81c20c --- /dev/null +++ b/logging/rtc_event_log/output/rtc_event_log_output_file.cc @@ -0,0 +1,113 @@ +/* + * Copyright (c) 2017 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#include + +#include "logging/rtc_event_log/output/rtc_event_log_output_file.h" +#include "logging/rtc_event_log/rtc_event_log.h" +#include "rtc_base/checks.h" +#include "rtc_base/logging.h" +#include "system_wrappers/include/file_wrapper.h" + +namespace webrtc { + +// Together with the assumption of no single Write() would ever be called on +// an input with length greater-than-or-equal-to (max(size_t) / 2), this +// guarantees no overflow of the check for remaining file capacity in Write(). +// This does *not* apply to files with unlimited size. +const size_t RtcEventLogOutputFile::kMaxReasonableFileSize = + std::numeric_limits::max() / 2; + +RtcEventLogOutputFile::RtcEventLogOutputFile(const std::string& file_name) + : RtcEventLogOutputFile(file_name, RtcEventLog::kUnlimitedOutput) {} + +RtcEventLogOutputFile::RtcEventLogOutputFile(const std::string& file_name, + size_t max_size_bytes) + : max_size_bytes_(max_size_bytes), file_(FileWrapper::Create()) { + RTC_CHECK_LE(max_size_bytes_, kMaxReasonableFileSize); + + if (!file_->OpenFile(file_name.c_str(), false)) { + LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; + file_.reset(); + return; + } +} + +RtcEventLogOutputFile::RtcEventLogOutputFile(rtc::PlatformFile file) + : RtcEventLogOutputFile(file, RtcEventLog::kUnlimitedOutput) {} + +RtcEventLogOutputFile::RtcEventLogOutputFile(rtc::PlatformFile file, + size_t max_size_bytes) + : max_size_bytes_(max_size_bytes), file_(FileWrapper::Create()) { + RTC_CHECK_LE(max_size_bytes_, kMaxReasonableFileSize); + + FILE* file_handle = rtc::FdopenPlatformFileForWriting(file); + if (!file_handle) { + LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; + // Even though we failed to open a FILE*, the file is still open + // and needs to be closed. + if (!rtc::ClosePlatformFile(file)) { + LOG(LS_ERROR) << "Can't close file."; + file_.reset(); + } + return; + } + + if (!file_->OpenFromFileHandle(file_handle)) { + LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; + file_.reset(); + return; + } +} + +RtcEventLogOutputFile::~RtcEventLogOutputFile() { + if (file_) { + RTC_DCHECK(IsActiveInternal()); + file_->CloseFile(); + file_.reset(); + } +} + +bool RtcEventLogOutputFile::IsActive() const { + return IsActiveInternal(); +} + +bool RtcEventLogOutputFile::Write(const std::string& output) { + RTC_DCHECK(IsActiveInternal()); + // No single write may be so big, that it would risk overflowing the + // calculation of (written_bytes_ + output.length()). + RTC_DCHECK_LT(output.length(), kMaxReasonableFileSize); + + bool written = false; + if (max_size_bytes_ == RtcEventLog::kUnlimitedOutput || + written_bytes_ + output.length() <= max_size_bytes_) { + written = file_->Write(output.c_str(), output.size()); + if (!written) { + LOG(LS_ERROR) << "FileWrapper failed to write WebRtcEventLog file."; + } + } else { + LOG(LS_VERBOSE) << "Max file size reached."; + } + + if (written) { + written_bytes_ += output.size(); + } else { + file_->CloseFile(); + file_.reset(); + } + + return written; +} + +bool RtcEventLogOutputFile::IsActiveInternal() const { + return file_ && file_->is_open(); +} + +} // namespace webrtc diff --git a/logging/rtc_event_log/output/rtc_event_log_output_file.h b/logging/rtc_event_log/output/rtc_event_log_output_file.h new file mode 100644 index 0000000000..0d181d1967 --- /dev/null +++ b/logging/rtc_event_log/output/rtc_event_log_output_file.h @@ -0,0 +1,60 @@ +/* + * Copyright (c) 2017 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#ifndef LOGGING_RTC_EVENT_LOG_OUTPUT_RTC_EVENT_LOG_OUTPUT_FILE_H_ +#define LOGGING_RTC_EVENT_LOG_OUTPUT_RTC_EVENT_LOG_OUTPUT_FILE_H_ + +#include + +#include +#include + +#include "logging/rtc_event_log/output/rtc_event_log_output.h" +#include "rtc_base/platform_file.h" // Can't neatly forward PlatformFile. + +namespace webrtc { + +class FileWrapper; + +class RtcEventLogOutputFile final : public RtcEventLogOutput { + public: + static const size_t kMaxReasonableFileSize; // Explanation at declaration. + + // Unlimited/limited-size output file (by filename). + explicit RtcEventLogOutputFile(const std::string& file_name); + RtcEventLogOutputFile(const std::string& file_name, size_t max_size_bytes); + + // Unlimited/limited-size output file (by file handle). + explicit RtcEventLogOutputFile(rtc::PlatformFile file); + RtcEventLogOutputFile(rtc::PlatformFile file, size_t max_size_bytes); + + ~RtcEventLogOutputFile() override; + + bool IsActive() const override; + + bool Write(const std::string& output) override; + + private: + // IsActive() can be called either from outside or from inside, but we don't + // want to incur the overhead of a virtual function call if called from inside + // some other function of this class. + inline bool IsActiveInternal() const; + + // TODO(eladalon): We're still discussing whether to use FileWrapper or not. + // If we end up keeping FileWrapper, we should use its own max-size logic, + // rather than duplicate it. + const size_t max_size_bytes_; + size_t written_bytes_{0}; + std::unique_ptr file_; +}; + +} // namespace webrtc + +#endif // LOGGING_RTC_EVENT_LOG_OUTPUT_RTC_EVENT_LOG_OUTPUT_FILE_H_ diff --git a/logging/rtc_event_log/output/rtc_event_log_output_file_unittest.cc b/logging/rtc_event_log/output/rtc_event_log_output_file_unittest.cc new file mode 100644 index 0000000000..ce6998c038 --- /dev/null +++ b/logging/rtc_event_log/output/rtc_event_log_output_file_unittest.cc @@ -0,0 +1,141 @@ +/* + * Copyright (c) 2017 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#include +#include +#include + +#include "logging/rtc_event_log/output/rtc_event_log_output_file.h" +#include "rtc_base/ptr_util.h" +#include "test/gtest.h" +#include "test/testsupport/fileutils.h" + +namespace webrtc { + +class RtcEventLogOutputFileTest : public ::testing::Test { + public: + RtcEventLogOutputFileTest() : output_file_name_(GetOutputFilePath()) { + // Ensure no leftovers from previous runs, which might not have terminated + // in an orderly fashion. + remove(output_file_name_.c_str()); + } + + ~RtcEventLogOutputFileTest() override { remove(output_file_name_.c_str()); } + + protected: + std::string GetOutputFilePath() const { + auto test_info = ::testing::UnitTest::GetInstance()->current_test_info(); + return test::OutputPath() + test_info->test_case_name() + test_info->name(); + } + + std::string GetOutputFileContents() const { + std::ifstream file(output_file_name_, + std::ios_base::in | std::ios_base::binary); + RTC_CHECK(file.is_open()); + RTC_CHECK(file.good()); + std::string file_str((std::istreambuf_iterator(file)), + std::istreambuf_iterator()); + return file_str; + } + + const std::string output_file_name_; +}; + +TEST_F(RtcEventLogOutputFileTest, NonDefectiveOutputsStartOutActive) { + auto output_file = rtc::MakeUnique(output_file_name_); + EXPECT_TRUE(output_file->IsActive()); +} + +TEST_F(RtcEventLogOutputFileTest, DefectiveOutputsStartOutInactive) { + const std::string illegal_filename = "/////////"; + auto output_file = rtc::MakeUnique(illegal_filename); + EXPECT_FALSE(output_file->IsActive()); +} + +// Sanity over opening a file (by filename) with an unlimited size. +TEST_F(RtcEventLogOutputFileTest, UnlimitedOutputFile) { + const std::string output_str = "one two three"; + + auto output_file = rtc::MakeUnique(output_file_name_); + output_file->Write(output_str); + output_file.reset(); // Closing the file flushes the buffer to disk. + + EXPECT_EQ(GetOutputFileContents(), output_str); +} + +// Do not allow writing more bytes to the file than +TEST_F(RtcEventLogOutputFileTest, LimitedOutputFileCappedToCapacity) { + // Fit two bytes, then the third should be rejected. + auto output_file = + rtc::MakeUnique(output_file_name_, 2); + + output_file->Write("1"); + output_file->Write("2"); + output_file->Write("3"); + // Unsuccessful writes close the file; no need to delete the output to flush. + + EXPECT_EQ(GetOutputFileContents(), "12"); +} + +// Make sure that calls to Write() either write everything to the file, or +// nothing (short of underlying issues in the module that handles the file, +// which would be beyond our control). +TEST_F(RtcEventLogOutputFileTest, DoNotWritePartialLines) { + const std::string output_str_1 = "0123456789"; + const std::string output_str_2 = "abcdefghij"; + + // Set a file size limit just shy of fitting the entire second line. + const size_t size_limit = output_str_1.length() + output_str_2.length() - 1; + auto output_file = + rtc::MakeUnique(output_file_name_, size_limit); + + output_file->Write(output_str_1); + output_file->Write(output_str_2); + // Unsuccessful writes close the file; no need to delete the output to flush. + + EXPECT_EQ(GetOutputFileContents(), output_str_1); +} + +TEST_F(RtcEventLogOutputFileTest, UnsuccessfulWriteReturnsFalse) { + auto output_file = + rtc::MakeUnique(output_file_name_, 2); + EXPECT_FALSE(output_file->Write("abc")); +} + +TEST_F(RtcEventLogOutputFileTest, SuccessfulWriteReturnsTrue) { + auto output_file = + rtc::MakeUnique(output_file_name_, 3); + EXPECT_TRUE(output_file->Write("abc")); +} + +// Even if capacity is reached, a successful write leaves the output active. +TEST_F(RtcEventLogOutputFileTest, FileStillActiveAfterSuccessfulWrite) { + auto output_file = + rtc::MakeUnique(output_file_name_, 3); + ASSERT_TRUE(output_file->Write("abc")); + EXPECT_TRUE(output_file->IsActive()); +} + +// Unsuccessful writes switch the output to inactive, even if capacity has +// not yet been reached. +TEST_F(RtcEventLogOutputFileTest, FileInactiveAfterUnsuccessfulWrite) { + auto output_file = + rtc::MakeUnique(output_file_name_, 2); + ASSERT_FALSE(output_file->Write("abc")); + EXPECT_FALSE(output_file->IsActive()); +} + +TEST_F(RtcEventLogOutputFileTest, AllowReasonableFileSizeLimits) { + auto output_file = rtc::MakeUnique( + output_file_name_, RtcEventLogOutputFile::kMaxReasonableFileSize); + EXPECT_TRUE(output_file->IsActive()); +} + +} // namespace webrtc diff --git a/logging/rtc_event_log/rtc_event_log.cc b/logging/rtc_event_log/rtc_event_log.cc index a3f7667d00..83ba029fb8 100644 --- a/logging/rtc_event_log/rtc_event_log.cc +++ b/logging/rtc_event_log/rtc_event_log.cc @@ -37,6 +37,8 @@ #include "logging/rtc_event_log/events/rtc_event_rtp_packet_outgoing.h" #include "logging/rtc_event_log/events/rtc_event_video_receive_stream_config.h" #include "logging/rtc_event_log/events/rtc_event_video_send_stream_config.h" +#include "logging/rtc_event_log/output/rtc_event_log_output.h" +#include "logging/rtc_event_log/output/rtc_event_log_output_file.h" #include "logging/rtc_event_log/rtc_stream_config.h" // TODO(eladalon): Remove these when deprecated functions are removed. #include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h" @@ -59,14 +61,11 @@ #include "rtc_base/constructormagic.h" #include "rtc_base/event.h" #include "rtc_base/logging.h" -#include "rtc_base/protobuf_utils.h" #include "rtc_base/ptr_util.h" +#include "rtc_base/safe_conversions.h" #include "rtc_base/sequenced_task_checker.h" #include "rtc_base/task_queue.h" #include "rtc_base/thread_annotations.h" -#include "rtc_base/timeutils.h" -// TODO(eladalon): Remove this when output is modularized away. -#include "system_wrappers/include/file_wrapper.h" #include "typedefs.h" // NOLINT(build/include) namespace webrtc { @@ -122,8 +121,14 @@ class RtcEventLogImpl final : public RtcEventLog { int64_t max_size_bytes) override; bool StartLogging(rtc::PlatformFile platform_file, int64_t max_size_bytes) override; + + // TODO(eladalon): We should change these name to reflect that what we're + // actually starting/stopping is the output of the log, not the log itself. + bool StartLogging(std::unique_ptr output) override; void StopLogging() override; + void Log(std::unique_ptr event) override; + void LogVideoReceiveStreamConfig(const rtclog::StreamConfig& config) override; void LogVideoSendStreamConfig(const rtclog::StreamConfig& config) override; void LogAudioReceiveStreamConfig(const rtclog::StreamConfig& config) override; @@ -166,21 +171,25 @@ class RtcEventLogImpl final : public RtcEventLog { ProbeFailureReason failure_reason) override; private: - void StartLoggingInternal(std::unique_ptr file, - int64_t max_size_bytes); - // Appends an event to the output protobuf string, returning true on success. // Fails and returns false in case the limit on output size prevents the // event from being added; in this case, the output string is left unchanged. // The event is encoded before being appended. + // We could have avoided this, because the output repeats the check, but this + // way, we minimize the number of lock acquisitions, task switches, etc., + // that might be associated with each call to RtcEventLogOutput::Write(). bool AppendEventToString(const RtcEvent& event, - ProtoString* output_string) RTC_WARN_UNUSED_RESULT; + std::string* output_string) RTC_WARN_UNUSED_RESULT; - void LogToMemory(std::unique_ptr event); + void LogToMemory(std::unique_ptr event) RTC_RUN_ON(&task_queue_); - void StartLogFile(); - void LogToFile(std::unique_ptr event); - void StopLogFile(int64_t stop_time); + void LogEventsFromMemoryToOutput() RTC_RUN_ON(&task_queue_); + void LogToOutput(std::unique_ptr event) RTC_RUN_ON(&task_queue_); + void StopOutput() RTC_RUN_ON(&task_queue_); + + void WriteToOutput(const std::string& output_string) RTC_RUN_ON(&task_queue_); + + void StopLoggingInternal() RTC_RUN_ON(&task_queue_); // Make sure that the event log is "managed" - created/destroyed, as well // as started/stopped - from the same thread/task-queue. @@ -193,12 +202,11 @@ class RtcEventLogImpl final : public RtcEventLog { // History containing the most recent (non-configuration) events (~10s). std::deque> history_ RTC_ACCESS_ON(task_queue_); - std::unique_ptr file_ RTC_ACCESS_ON(task_queue_); - size_t max_size_bytes_ RTC_ACCESS_ON(task_queue_); size_t written_bytes_ RTC_ACCESS_ON(task_queue_); std::unique_ptr event_encoder_ RTC_ACCESS_ON(task_queue_); + std::unique_ptr event_output_ RTC_ACCESS_ON(task_queue_); // Keep this last to ensure it destructs first, or else tasks living on the // queue might access other members after they've been torn down. @@ -209,8 +217,7 @@ class RtcEventLogImpl final : public RtcEventLog { RtcEventLogImpl::RtcEventLogImpl( std::unique_ptr event_encoder) - : file_(FileWrapper::Create()), - max_size_bytes_(std::numeric_limits::max()), + : max_size_bytes_(std::numeric_limits::max()), written_bytes_(0), event_encoder_(std::move(event_encoder)), task_queue_("rtc_event_log") {} @@ -218,7 +225,7 @@ RtcEventLogImpl::RtcEventLogImpl( RtcEventLogImpl::~RtcEventLogImpl() { RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); - // If we're logging to the file, this will stop that. Blocking function. + // If we're logging to the output, this will stop that. Blocking function. StopLogging(); int count = std::atomic_fetch_sub(&rtc_event_log_count, 1) - 1; @@ -227,40 +234,44 @@ RtcEventLogImpl::~RtcEventLogImpl() { bool RtcEventLogImpl::StartLogging(const std::string& file_name, int64_t max_size_bytes) { - RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); - - auto file = rtc::WrapUnique(FileWrapper::Create()); - if (!file->OpenFile(file_name.c_str(), false)) { - LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; - return false; - } - - StartLoggingInternal(std::move(file), max_size_bytes); - - return true; + RTC_CHECK(max_size_bytes > 0 || max_size_bytes == kUnlimitedOutput); + return StartLogging(rtc::MakeUnique( + file_name, rtc::saturated_cast(max_size_bytes))); } bool RtcEventLogImpl::StartLogging(rtc::PlatformFile platform_file, int64_t max_size_bytes) { + RTC_CHECK(max_size_bytes > 0 || max_size_bytes == kUnlimitedOutput); + return StartLogging(rtc::MakeUnique( + platform_file, rtc::saturated_cast(max_size_bytes))); +} + +bool RtcEventLogImpl::StartLogging(std::unique_ptr output) { RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); - auto file = rtc::WrapUnique(FileWrapper::Create()); - FILE* file_handle = rtc::FdopenPlatformFileForWriting(platform_file); - if (!file_handle) { - LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; - // Even though we failed to open a FILE*, the platform_file is still open - // and needs to be closed. - if (!rtc::ClosePlatformFile(platform_file)) { - LOG(LS_ERROR) << "Can't close file."; - } - return false; - } - if (!file->OpenFromFileHandle(file_handle)) { - LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; + if (!output->IsActive()) { return false; } - StartLoggingInternal(std::move(file), max_size_bytes); + LOG(LS_INFO) << "Starting WebRTC event log."; + + // |start_event| captured by value. This is done here because we want the + // timestamp to reflect when StartLogging() was called; not the queueing + // delay of the TaskQueue. + // This is a bit inefficient - especially since we copy again to get it + // to comply with LogToOutput()'s signature - but it's a small problem. + RtcEventLoggingStarted start_event; + + auto start = [this, start_event](std::unique_ptr output) { + RTC_DCHECK_RUN_ON(&task_queue_); + RTC_DCHECK(output->IsActive()); + event_output_ = std::move(output); + LogToOutput(rtc::MakeUnique(start_event)); + LogEventsFromMemoryToOutput(); + }; + + task_queue_.PostTask(rtc::MakeUnique>( + std::move(output), start)); return true; } @@ -270,19 +281,15 @@ void RtcEventLogImpl::StopLogging() { LOG(LS_INFO) << "Stopping WebRTC event log."; - const int64_t stop_time = rtc::TimeMicros(); + rtc::Event output_stopped(true, false); - rtc::Event file_finished(true, false); - - task_queue_.PostTask([this, stop_time, &file_finished]() { + task_queue_.PostTask([this, &output_stopped]() { RTC_DCHECK_RUN_ON(&task_queue_); - if (file_->is_open()) { - StopLogFile(stop_time); - } - file_finished.Set(); + StopLoggingInternal(); + output_stopped.Set(); }); - file_finished.Wait(rtc::Event::kForever); + output_stopped.Wait(rtc::Event::kForever); LOG(LS_INFO) << "WebRTC event log successfully stopped."; } @@ -292,8 +299,8 @@ void RtcEventLogImpl::Log(std::unique_ptr event) { auto event_handler = [this](std::unique_ptr unencoded_event) { RTC_DCHECK_RUN_ON(&task_queue_); - if (file_->is_open()) { - LogToFile(std::move(unencoded_event)); + if (event_output_) { + LogToOutput(std::move(unencoded_event)); } else { LogToMemory(std::move(unencoded_event)); } @@ -421,31 +428,8 @@ void RtcEventLogImpl::LogProbeResultFailure(int id, Log(rtc::MakeUnique(id, failure_reason)); } -void RtcEventLogImpl::StartLoggingInternal(std::unique_ptr file, - int64_t max_size_bytes) { - LOG(LS_INFO) << "Starting WebRTC event log."; - - max_size_bytes = (max_size_bytes <= 0) - ? std::numeric_limits::max() - : max_size_bytes; - auto file_handler = [this, - max_size_bytes](std::unique_ptr file) { - RTC_DCHECK_RUN_ON(&task_queue_); - if (!file_->is_open()) { - max_size_bytes_ = max_size_bytes; - file_ = std::move(file); - StartLogFile(); - } else { - // Already started. Ignore message and close file handle. - file->CloseFile(); - } - }; - task_queue_.PostTask(rtc::MakeUnique>( - std::move(file), file_handler)); -} - bool RtcEventLogImpl::AppendEventToString(const RtcEvent& event, - ProtoString* output_string) { + std::string* output_string) { RTC_DCHECK_RUN_ON(&task_queue_); std::string encoded_event = event_encoder_->Encode(event); @@ -454,6 +438,7 @@ bool RtcEventLogImpl::AppendEventToString(const RtcEvent& event, size_t potential_new_size = written_bytes_ + output_string->size() + encoded_event.length(); if (potential_new_size <= max_size_bytes_) { + // TODO(eladalon): This is inefficient; fix this in a separate CL. *output_string += encoded_event; appended = true; } else { @@ -464,8 +449,7 @@ bool RtcEventLogImpl::AppendEventToString(const RtcEvent& event, } void RtcEventLogImpl::LogToMemory(std::unique_ptr event) { - RTC_DCHECK_RUN_ON(&task_queue_); - RTC_DCHECK(!file_->is_open()); + RTC_DCHECK(!event_output_); if (event->IsConfigEvent()) { config_history_.push_back(std::move(event)); @@ -477,104 +461,92 @@ void RtcEventLogImpl::LogToMemory(std::unique_ptr event) { } } -void RtcEventLogImpl::StartLogFile() { - RTC_DCHECK_RUN_ON(&task_queue_); - RTC_DCHECK(file_->is_open()); +void RtcEventLogImpl::LogEventsFromMemoryToOutput() { + RTC_DCHECK(event_output_ && event_output_->IsActive()); - ProtoString output_string; - - // Create and serialize the LOG_START event. - // The timestamp used will correspond to when logging has started. The log - // may contain events earlier than the LOG_START event. (In general, the - // timestamps in the log are not monotonic.) - bool appended = AppendEventToString(RtcEventLoggingStarted(), &output_string); + std::string output_string; // Serialize the config information for all old streams, including streams - // which were already logged to previous files. + // which were already logged to previous outputs. + bool appended = true; for (auto& event : config_history_) { - if (!appended) { + if (!AppendEventToString(*event, &output_string)) { + appended = false; break; } - appended = AppendEventToString(*event, &output_string); } // Serialize the events in the event queue. while (appended && !history_.empty()) { appended = AppendEventToString(*history_.front(), &output_string); if (appended) { - // Known issue - if writing to the file fails, these events will have - // been lost. If we try to open a new file, these events will be missing + // Known issue - if writing to the output fails, these events will have + // been lost. If we try to open a new output, these events will be missing // from it. history_.pop_front(); } } - // Write to file. - if (!file_->Write(output_string.data(), output_string.size())) { - LOG(LS_ERROR) << "FileWrapper failed to write WebRtcEventLog file."; - // The current FileWrapper implementation closes the file on error. - RTC_DCHECK(!file_->is_open()); - return; - } - written_bytes_ += output_string.size(); + WriteToOutput(output_string); if (!appended) { - RTC_DCHECK(file_->is_open()); - StopLogFile(rtc::TimeMicros()); + // Successful partial write to the output. Some events could not be written; + // the output should be closed, to avoid gaps. + StopOutput(); } } -void RtcEventLogImpl::LogToFile(std::unique_ptr event) { - RTC_DCHECK_RUN_ON(&task_queue_); - RTC_DCHECK(file_->is_open()); +void RtcEventLogImpl::LogToOutput(std::unique_ptr event) { + RTC_DCHECK(event_output_ && event_output_->IsActive()); - ProtoString output_string; + std::string output_string; bool appended = AppendEventToString(*event, &output_string); if (event->IsConfigEvent()) { + // Config events need to be kept in memory too, so that they may be + // rewritten into future outputs, too. config_history_.push_back(std::move(event)); } if (!appended) { - RTC_DCHECK(file_->is_open()); - history_.push_back(std::move(event)); - StopLogFile(rtc::TimeMicros()); + if (!event->IsConfigEvent()) { + // This event will not fit into the output; push it into |history_| + // instead, so that it might be logged into the next output (if any). + history_.push_back(std::move(event)); + } + StopOutput(); return; } - // Write string to file. - if (file_->Write(output_string.data(), output_string.size())) { - written_bytes_ += output_string.size(); - } else { - LOG(LS_ERROR) << "FileWrapper failed to write WebRtcEventLog file."; - // The current FileWrapper implementation closes the file on error. - RTC_DCHECK(!file_->is_open()); - } + WriteToOutput(output_string); } -void RtcEventLogImpl::StopLogFile(int64_t stop_time) { - RTC_DCHECK_RUN_ON(&task_queue_); - RTC_DCHECK(file_->is_open()); - - ProtoString output_string; - - bool appended = AppendEventToString(RtcEventLoggingStopped(), &output_string); - - if (appended) { - if (!file_->Write(output_string.data(), output_string.size())) { - LOG(LS_ERROR) << "FileWrapper failed to write WebRtcEventLog file."; - // The current FileWrapper implementation closes the file on error. - RTC_DCHECK(!file_->is_open()); - } - written_bytes_ += output_string.size(); - } - +void RtcEventLogImpl::StopOutput() { max_size_bytes_ = std::numeric_limits::max(); written_bytes_ = 0; + event_output_.reset(); +} - file_->CloseFile(); - RTC_DCHECK(!file_->is_open()); +void RtcEventLogImpl::StopLoggingInternal() { + if (event_output_) { + RTC_DCHECK(event_output_->IsActive()); + event_output_->Write( + event_encoder_->Encode(*rtc::MakeUnique())); + } + StopOutput(); +} + +void RtcEventLogImpl::WriteToOutput(const std::string& output_string) { + RTC_DCHECK(event_output_ && event_output_->IsActive()); + if (!event_output_->Write(output_string)) { + LOG(LS_ERROR) << "Failed to write RTC event to output."; + // The first failure closes the output. + RTC_DCHECK(!event_output_->IsActive()); + StopOutput(); // Clean-up. + return; + } + written_bytes_ += output_string.size(); } } // namespace diff --git a/logging/rtc_event_log/rtc_event_log.h b/logging/rtc_event_log/rtc_event_log.h index 88ba10e5cc..cb9d097888 100644 --- a/logging/rtc_event_log/rtc_event_log.h +++ b/logging/rtc_event_log/rtc_event_log.h @@ -14,15 +14,16 @@ #include #include +// TODO(eladalon): Remove this include once LogIncomingRtcpPacket(), etc., have +// been removed (they are currently deprecated). #include "api/array_view.h" -// TODO(eladalon): Get rid of this later in the CL-stack. -#include "api/rtpparameters.h" #include "common_types.h" // NOLINT(build/include) +#include "logging/rtc_event_log/output/rtc_event_log_output.h" // TODO(eladalon): This is here because of ProbeFailureReason; remove this // dependency along with the deprecated LogProbeResultFailure(). #include "logging/rtc_event_log/events/rtc_event_probe_result_failure.h" -// TODO(eladalon): Remove this in an upcoming CL, that will modularize the -// log output into its own class. +// TODO(eladalon): Remove this #include once the deprecated versions of +// StartLogging() have been removed. #include "rtc_base/platform_file.h" namespace webrtc { @@ -44,6 +45,8 @@ enum PacketDirection { kIncomingPacket = 0, kOutgoingPacket }; class RtcEventLog { public: + enum : size_t { kUnlimitedOutput = 0 }; + // TODO(eladalon): Two stages are upcoming. // 1. Extend this to actually support the new encoding. // 2. Get rid of the legacy encoding, allowing us to get rid of this enum. @@ -68,18 +71,22 @@ class RtcEventLog { // Create an RtcEventLog object that does nothing. static std::unique_ptr CreateNull(); + // Starts logging to a given output. The output might be limited in size, + // and may close itself once it has reached the maximum size. + virtual bool StartLogging(std::unique_ptr output) = 0; + // Starts logging a maximum of max_size_bytes bytes to the specified file. // If the file already exists it will be overwritten. // If max_size_bytes <= 0, logging will be active until StopLogging is called. // The function has no effect and returns false if we can't start a new log // e.g. because we are already logging or the file cannot be opened. - virtual bool StartLogging(const std::string& file_name, - int64_t max_size_bytes) = 0; + RTC_DEPRECATED virtual bool StartLogging(const std::string& file_name, + int64_t max_size_bytes) = 0; // Same as above. The RtcEventLog takes ownership of the file if the call // is successful, i.e. if it returns true. - virtual bool StartLogging(rtc::PlatformFile platform_file, - int64_t max_size_bytes) = 0; + RTC_DEPRECATED virtual bool StartLogging(rtc::PlatformFile platform_file, + int64_t max_size_bytes) = 0; // Deprecated. Pass an explicit file size limit. RTC_DEPRECATED bool StartLogging(const std::string& file_name) { @@ -182,6 +189,9 @@ class RtcEventLog { // No-op implementation is used if flag is not set, or in tests. class RtcEventLogNullImpl : public RtcEventLog { public: + bool StartLogging(std::unique_ptr output) override { + return false; + } bool StartLogging(const std::string& file_name, int64_t max_size_bytes) override { return false; diff --git a/logging/rtc_event_log/rtc_event_log_unittest.cc b/logging/rtc_event_log/rtc_event_log_unittest.cc index d328dffd8e..ec553079c2 100644 --- a/logging/rtc_event_log/rtc_event_log_unittest.cc +++ b/logging/rtc_event_log/rtc_event_log_unittest.cc @@ -33,6 +33,7 @@ #include "logging/rtc_event_log/events/rtc_event_rtp_packet_outgoing.h" #include "logging/rtc_event_log/events/rtc_event_video_receive_stream_config.h" #include "logging/rtc_event_log/events/rtc_event_video_send_stream_config.h" +#include "logging/rtc_event_log/output/rtc_event_log_output_file.h" #include "logging/rtc_event_log/rtc_event_log.h" #include "logging/rtc_event_log/rtc_event_log_parser.h" #include "logging/rtc_event_log/rtc_event_log_unittest_helper.h" @@ -430,7 +431,8 @@ void RtcEventLogSessionDescription::WriteSession() { for (size_t i = 0; i < event_types.size(); i++) { fake_clock.AdvanceTimeMicros(prng.Rand(1, 1000)); if (i == event_types.size() / 2) - log_dumper->StartLogging(temp_filename, 10000000); + log_dumper->StartLogging( + rtc::MakeUnique(temp_filename, 10000000)); switch (event_types[i]) { case EventType::kIncomingRtp: RTC_CHECK(incoming_rtp_written < incoming_rtp_packets.size()); @@ -739,7 +741,8 @@ TEST(RtcEventLogTest, LogEventAndReadBack) { log_dumper->Log(rtc::MakeUnique(rtp_packet)); fake_clock.AdvanceTimeMicros(prng.Rand(1, 1000)); - log_dumper->StartLogging(temp_filename, 10000000); + log_dumper->StartLogging( + rtc::MakeUnique(temp_filename, 10000000)); fake_clock.AdvanceTimeMicros(prng.Rand(1, 1000)); log_dumper->Log(rtc::MakeUnique(rtcp_packet)); @@ -787,7 +790,8 @@ TEST(RtcEventLogTest, LogLossBasedBweUpdateAndReadBack) { fake_clock.SetTimeMicros(prng.Rand()); std::unique_ptr log_dumper( RtcEventLog::Create(RtcEventLog::EncodingType::Legacy)); - log_dumper->StartLogging(temp_filename, 10000000); + log_dumper->StartLogging( + rtc::MakeUnique(temp_filename, 10000000)); fake_clock.AdvanceTimeMicros(prng.Rand(1, 1000)); log_dumper->Log(rtc::MakeUnique( bitrate, fraction_lost, total_packets)); @@ -829,7 +833,8 @@ TEST(RtcEventLogTest, LogDelayBasedBweUpdateAndReadBack) { fake_clock.SetTimeMicros(prng.Rand()); std::unique_ptr log_dumper( RtcEventLog::Create(RtcEventLog::EncodingType::Legacy)); - log_dumper->StartLogging(temp_filename, 10000000); + log_dumper->StartLogging( + rtc::MakeUnique(temp_filename, 10000000)); fake_clock.AdvanceTimeMicros(prng.Rand(1, 1000)); log_dumper->Log(rtc::MakeUnique( bitrate1, BandwidthUsage::kBwNormal)); @@ -886,7 +891,8 @@ TEST(RtcEventLogTest, LogProbeClusterCreatedAndReadBack) { std::unique_ptr log_dumper( RtcEventLog::Create(RtcEventLog::EncodingType::Legacy)); - log_dumper->StartLogging(temp_filename, 10000000); + log_dumper->StartLogging( + rtc::MakeUnique(temp_filename, 10000000)); log_dumper->Log(rtc::MakeUnique( 0, bitrate_bps0, min_probes0, min_bytes0)); fake_clock.AdvanceTimeMicros(prng.Rand(1, 1000)); @@ -936,7 +942,8 @@ TEST(RtcEventLogTest, LogProbeResultSuccessAndReadBack) { std::unique_ptr log_dumper( RtcEventLog::Create(RtcEventLog::EncodingType::Legacy)); - log_dumper->StartLogging(temp_filename, 10000000); + log_dumper->StartLogging( + rtc::MakeUnique(temp_filename, 10000000)); log_dumper->Log(rtc::MakeUnique(0, bitrate_bps0)); fake_clock.AdvanceTimeMicros(prng.Rand(1, 1000)); log_dumper->Log(rtc::MakeUnique(1, bitrate_bps1)); @@ -979,7 +986,8 @@ TEST(RtcEventLogTest, LogProbeResultFailureAndReadBack) { std::unique_ptr log_dumper( RtcEventLog::Create(RtcEventLog::EncodingType::Legacy)); - log_dumper->StartLogging(temp_filename, 10000000); + log_dumper->StartLogging( + rtc::MakeUnique(temp_filename, 10000000)); log_dumper->Log(rtc::MakeUnique( 0, ProbeFailureReason::kInvalidSendReceiveInterval)); fake_clock.AdvanceTimeMicros(prng.Rand(1, 1000)); @@ -1040,7 +1048,8 @@ class ConfigReadWriteTest { std::unique_ptr log_dumper( RtcEventLog::Create(RtcEventLog::EncodingType::Legacy)); - log_dumper->StartLogging(temp_filename, 10000000); + log_dumper->StartLogging( + rtc::MakeUnique(temp_filename, 10000000)); LogConfig(log_dumper.get()); log_dumper->StopLogging(); diff --git a/pc/peerconnection.cc b/pc/peerconnection.cc index 77e8e024f1..bc95895a8e 100644 --- a/pc/peerconnection.cc +++ b/pc/peerconnection.cc @@ -20,6 +20,7 @@ #include "api/mediastreamproxy.h" #include "api/mediastreamtrackproxy.h" #include "call/call.h" +#include "logging/rtc_event_log/output/rtc_event_log_output_file.h" #include "logging/rtc_event_log/rtc_event_log.h" #include "media/sctp/sctptransport.h" #include "pc/audiotrack.h" @@ -36,6 +37,8 @@ #include "rtc_base/bind.h" #include "rtc_base/checks.h" #include "rtc_base/logging.h" +#include "rtc_base/ptr_util.h" +#include "rtc_base/safe_conversions.h" #include "rtc_base/stringencode.h" #include "rtc_base/stringutils.h" #include "rtc_base/trace_event.h" @@ -2533,7 +2536,14 @@ bool PeerConnection::StartRtcEventLog_w(rtc::PlatformFile file, if (!event_log_) { return false; } - return event_log_->StartLogging(file, max_size_bytes); + + // TODO(eladalon): It would be better to not allow negative values into PC. + const size_t max_size = (max_size_bytes < 0) + ? RtcEventLog::kUnlimitedOutput + : rtc::saturated_cast(max_size_bytes); + + return event_log_->StartLogging( + rtc::MakeUnique(file, max_size)); } void PeerConnection::StopRtcEventLog_w() { diff --git a/video/video_quality_test.cc b/video/video_quality_test.cc index 0008b1f7fa..2b1d448b02 100644 --- a/video/video_quality_test.cc +++ b/video/video_quality_test.cc @@ -21,6 +21,7 @@ #include "api/optional.h" #include "call/call.h" #include "common_video/libyuv/include/webrtc_libyuv.h" +#include "logging/rtc_event_log/output/rtc_event_log_output_file.h" #include "logging/rtc_event_log/rtc_event_log.h" #include "media/engine/webrtcvideoengine.h" #include "modules/audio_mixer/audio_mixer_impl.h" @@ -1818,7 +1819,8 @@ void VideoQualityTest::RunWithAnalyzer(const Params& params) { if (!params.logging.rtc_event_log_name.empty()) { event_log_ = RtcEventLog::Create(clock_, RtcEventLog::EncodingType::Legacy); bool event_log_started = - event_log_->StartLogging(params.logging.rtc_event_log_name, -1); + event_log_->StartLogging(rtc::MakeUnique( + params.logging.rtc_event_log_name, RtcEventLog::kUnlimitedOutput)); RTC_DCHECK(event_log_started); } diff --git a/voice_engine/channel.cc b/voice_engine/channel.cc index 4ac040bee0..8125e96738 100644 --- a/voice_engine/channel.cc +++ b/voice_engine/channel.cc @@ -81,6 +81,11 @@ class RtcEventLogProxy final : public webrtc::RtcEventLog { public: RtcEventLogProxy() : event_log_(nullptr) {} + bool StartLogging(std::unique_ptr output) override { + RTC_NOTREACHED(); + return false; + } + bool StartLogging(const std::string& file_name, int64_t max_size_bytes) override { RTC_NOTREACHED();