/* * Copyright (c) 2016 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 "webrtc/call/rtc_event_log_helper_thread.h" #include #include "webrtc/base/checks.h" #include "webrtc/system_wrappers/include/logging.h" #ifdef ENABLE_RTC_EVENT_LOG namespace webrtc { namespace { const int kEventsInHistory = 10000; bool IsConfigEvent(const rtclog::Event& event) { rtclog::Event_EventType event_type = event.type(); return event_type == rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT || event_type == rtclog::Event::VIDEO_SENDER_CONFIG_EVENT || event_type == rtclog::Event::AUDIO_RECEIVER_CONFIG_EVENT || event_type == rtclog::Event::AUDIO_SENDER_CONFIG_EVENT; } } // namespace // RtcEventLogImpl member functions. RtcEventLogHelperThread::RtcEventLogHelperThread( SwapQueue* message_queue, SwapQueue>* event_queue, const Clock* const clock) : message_queue_(message_queue), event_queue_(event_queue), history_(kEventsInHistory), config_history_(), file_(FileWrapper::Create()), thread_(&ThreadOutputFunction, this, "RtcEventLog thread"), max_size_bytes_(std::numeric_limits::max()), written_bytes_(0), start_time_(0), stop_time_(std::numeric_limits::max()), has_recent_event_(false), most_recent_event_(), output_string_(), wake_periodically_(false, false), wake_from_hibernation_(false, false), file_finished_(false, false), clock_(clock) { RTC_DCHECK(message_queue_); RTC_DCHECK(event_queue_); RTC_DCHECK(clock_); thread_.Start(); } RtcEventLogHelperThread::~RtcEventLogHelperThread() { ControlMessage message; message.message_type = ControlMessage::TERMINATE_THREAD; message.stop_time = clock_->TimeInMicroseconds(); while (!message_queue_->Insert(&message)) { // We can't destroy the event log until we have stopped the thread, // so clear the message queue and try again. Note that if we clear // any STOP_FILE events, then the threads calling StopLogging would likely // wait indefinitely. However, there should not be any such calls as we // are executing the destructor. LOG(LS_WARNING) << "Clearing message queue to terminate thread."; message_queue_->Clear(); } wake_from_hibernation_.Set(); wake_periodically_.Set(); // Wake up the output thread. thread_.Stop(); // Wait for the thread to terminate. } void RtcEventLogHelperThread::WaitForFileFinished() { wake_from_hibernation_.Set(); wake_periodically_.Set(); file_finished_.Wait(rtc::Event::kForever); } void RtcEventLogHelperThread::SignalNewEvent() { wake_from_hibernation_.Set(); } bool RtcEventLogHelperThread::AppendEventToString(rtclog::Event* event) { rtclog::EventStream event_stream; event_stream.add_stream(); event_stream.mutable_stream(0)->Swap(event); // We create a new event stream per event but because of the way protobufs // are encoded, events can be merged by concatenating them. Therefore, // it will look like a single stream when we read it back from file. bool stop = true; if (written_bytes_ + static_cast(output_string_.size()) + event_stream.ByteSize() <= max_size_bytes_) { event_stream.AppendToString(&output_string_); stop = false; } // Swap the event back so that we don't mix event types in the queues. event_stream.mutable_stream(0)->Swap(event); return stop; } bool RtcEventLogHelperThread::LogToMemory() { RTC_DCHECK(!file_->is_open()); bool message_received = false; // Process each event earlier than the current time and append it to the // appropriate history_. int64_t current_time = clock_->TimeInMicroseconds(); if (!has_recent_event_) { has_recent_event_ = event_queue_->Remove(&most_recent_event_); } while (has_recent_event_ && most_recent_event_->timestamp_us() <= current_time) { if (IsConfigEvent(*most_recent_event_)) { config_history_.push_back(std::move(most_recent_event_)); } else { history_.push_back(std::move(most_recent_event_)); } has_recent_event_ = event_queue_->Remove(&most_recent_event_); message_received = true; } return message_received; } void RtcEventLogHelperThread::StartLogFile() { RTC_DCHECK(file_->is_open()); bool stop = false; output_string_.clear(); // Create and serialize the LOG_START event. rtclog::Event start_event; start_event.set_timestamp_us(start_time_); start_event.set_type(rtclog::Event::LOG_START); AppendEventToString(&start_event); // Serialize the config information for all old streams. for (auto& event : config_history_) { AppendEventToString(event.get()); } // Serialize the events in the event queue. while (!history_.empty() && !stop) { stop = AppendEventToString(history_.front().get()); if (!stop) { 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(); // Free the allocated memory since we probably won't need this amount of // space again. output_string_.clear(); output_string_.shrink_to_fit(); if (stop) { RTC_DCHECK(file_->is_open()); StopLogFile(); } } bool RtcEventLogHelperThread::LogToFile() { RTC_DCHECK(file_->is_open()); output_string_.clear(); bool message_received = false; // Append each event older than both the current time and the stop time // to the output_string_. int64_t current_time = clock_->TimeInMicroseconds(); int64_t time_limit = std::min(current_time, stop_time_); if (!has_recent_event_) { has_recent_event_ = event_queue_->Remove(&most_recent_event_); } bool stop = false; while (!stop && has_recent_event_ && most_recent_event_->timestamp_us() <= time_limit) { stop = AppendEventToString(most_recent_event_.get()); if (!stop) { if (IsConfigEvent(*most_recent_event_)) { config_history_.push_back(std::move(most_recent_event_)); } has_recent_event_ = event_queue_->Remove(&most_recent_event_); } message_received = true; } // Write string 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 message_received; } written_bytes_ += output_string_.size(); // We want to stop logging if we have reached the file size limit. We also // want to stop logging if the remaining events are more recent than the // time limit, or in other words if we have terminated the loop despite // having more events in the queue. if ((has_recent_event_ && most_recent_event_->timestamp_us() > stop_time_) || stop) { RTC_DCHECK(file_->is_open()); StopLogFile(); } return message_received; } void RtcEventLogHelperThread::StopLogFile() { RTC_DCHECK(file_->is_open()); output_string_.clear(); rtclog::Event end_event; end_event.set_timestamp_us(stop_time_); end_event.set_type(rtclog::Event::LOG_END); AppendEventToString(&end_event); if (written_bytes_ + static_cast(output_string_.size()) <= max_size_bytes_) { 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(); } max_size_bytes_ = std::numeric_limits::max(); written_bytes_ = 0; start_time_ = 0; stop_time_ = std::numeric_limits::max(); output_string_.clear(); file_->CloseFile(); RTC_DCHECK(!file_->is_open()); } void RtcEventLogHelperThread::ProcessEvents() { ControlMessage message; while (true) { bool message_received = false; // Process control messages. while (message_queue_->Remove(&message)) { switch (message.message_type) { case ControlMessage::START_FILE: if (!file_->is_open()) { max_size_bytes_ = message.max_size_bytes; start_time_ = message.start_time; stop_time_ = message.stop_time; file_.swap(message.file); StartLogFile(); } else { // Already started. Ignore message and close file handle. message.file->CloseFile(); } message_received = true; break; case ControlMessage::STOP_FILE: if (file_->is_open()) { stop_time_ = message.stop_time; LogToFile(); // Log remaining events from message queues. } // LogToFile might stop on it's own so we need to recheck the state. if (file_->is_open()) { StopLogFile(); } file_finished_.Set(); message_received = true; break; case ControlMessage::TERMINATE_THREAD: if (file_->is_open()) { StopLogFile(); } return; } } // Write events to file or memory. if (file_->is_open()) { message_received |= LogToFile(); } else { message_received |= LogToMemory(); } // Accumulate a new batch of events instead of processing them one at a // time. if (message_received) { wake_periodically_.Wait(100); } else { wake_from_hibernation_.Wait(rtc::Event::kForever); } } } bool RtcEventLogHelperThread::ThreadOutputFunction(void* obj) { RtcEventLogHelperThread* helper = static_cast(obj); helper->ProcessEvents(); return false; } } // namespace webrtc #endif // ENABLE_RTC_EVENT_LOG