1 /*
2 * Copyright (c) 2015 The WebRTC project authors. All Rights Reserved.
3 *
4 * Use of this source code is governed by a BSD-style license
5 * that can be found in the LICENSE file in the root of the source
6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree.
9 */
10
11 #include "logging/rtc_event_log/rtc_event_log.h"
12
13 #include <atomic>
14 #include <deque>
15 #include <functional>
16 #include <limits>
17 #include <memory>
18 #include <utility>
19 #include <vector>
20
21 #include "logging/rtc_event_log/encoder/rtc_event_log_encoder_legacy.h"
22 #include "logging/rtc_event_log/events/rtc_event_logging_started.h"
23 #include "logging/rtc_event_log/events/rtc_event_logging_stopped.h"
24 #include "logging/rtc_event_log/output/rtc_event_log_output_file.h"
25 #include "rtc_base/checks.h"
26 #include "rtc_base/constructormagic.h"
27 #include "rtc_base/event.h"
28 #include "rtc_base/logging.h"
29 #include "rtc_base/numerics/safe_conversions.h"
30 #include "rtc_base/numerics/safe_minmax.h"
31 #include "rtc_base/ptr_util.h"
32 #include "rtc_base/sequenced_task_checker.h"
33 #include "rtc_base/task_queue.h"
34 #include "rtc_base/thread_annotations.h"
35
36 namespace webrtc {
37
38 #ifdef ENABLE_RTC_EVENT_LOG
39
40 namespace {
41 constexpr size_t kMaxEventsInHistory = 10000;
42 // The config-history is supposed to be unbounded, but needs to have some bound
43 // to prevent an attack via unreasonable memory use.
44 constexpr size_t kMaxEventsInConfigHistory = 1000;
45
46 // Observe a limit on the number of concurrent logs, so as not to run into
47 // OS-imposed limits on open files and/or threads/task-queues.
48 // TODO(eladalon): Known issue - there's a race over |rtc_event_log_count|.
49 std::atomic<int> rtc_event_log_count(0);
50
51 // TODO(eladalon): This class exists because C++11 doesn't allow transferring a
52 // unique_ptr to a lambda (a copy constructor is required). We should get
53 // rid of this when we move to C++14.
54 template <typename T>
55 class ResourceOwningTask final : public rtc::QueuedTask {
56 public:
ResourceOwningTask(std::unique_ptr<T> resource,std::function<void (std::unique_ptr<T>)> handler)57 ResourceOwningTask(std::unique_ptr<T> resource,
58 std::function<void(std::unique_ptr<T>)> handler)
59 : resource_(std::move(resource)), handler_(handler) {}
60
Run()61 bool Run() override {
62 handler_(std::move(resource_));
63 return true;
64 }
65
66 private:
67 std::unique_ptr<T> resource_;
68 std::function<void(std::unique_ptr<T>)> handler_;
69 };
70
CreateEncoder(RtcEventLog::EncodingType type)71 std::unique_ptr<RtcEventLogEncoder> CreateEncoder(
72 RtcEventLog::EncodingType type) {
73 switch (type) {
74 case RtcEventLog::EncodingType::Legacy:
75 return rtc::MakeUnique<RtcEventLogEncoderLegacy>();
76 default:
77 RTC_LOG(LS_ERROR) << "Unknown RtcEventLog encoder type (" << int(type)
78 << ")";
79 RTC_NOTREACHED();
80 return std::unique_ptr<RtcEventLogEncoder>(nullptr);
81 }
82 }
83
84 class RtcEventLogImpl final : public RtcEventLog {
85 public:
86 explicit RtcEventLogImpl(std::unique_ptr<RtcEventLogEncoder> event_encoder);
87 ~RtcEventLogImpl() override;
88
89 // TODO(eladalon): We should change these name to reflect that what we're
90 // actually starting/stopping is the output of the log, not the log itself.
91 bool StartLogging(std::unique_ptr<RtcEventLogOutput> output,
92 int64_t output_period_ms) override;
93 void StopLogging() override;
94
95 void Log(std::unique_ptr<RtcEvent> event) override;
96
97 private:
98 // Appends an event to the output protobuf string, returning true on success.
99 // Fails and returns false in case the limit on output size prevents the
100 // event from being added; in this case, the output string is left unchanged.
101 // The event is encoded before being appended.
102 // We could have avoided this, because the output repeats the check, but this
103 // way, we minimize the number of lock acquisitions, task switches, etc.,
104 // that might be associated with each call to RtcEventLogOutput::Write().
105 bool AppendEventToString(const RtcEvent& event,
106 std::string* output_string) RTC_WARN_UNUSED_RESULT;
107
108 void LogToMemory(std::unique_ptr<RtcEvent> event) RTC_RUN_ON(&task_queue_);
109
110 void LogEventsFromMemoryToOutput() RTC_RUN_ON(&task_queue_);
111 void LogToOutput(std::unique_ptr<RtcEvent> event) RTC_RUN_ON(&task_queue_);
112 void StopOutput() RTC_RUN_ON(&task_queue_);
113
114 void WriteToOutput(const std::string& output_string) RTC_RUN_ON(&task_queue_);
115
116 void StopLoggingInternal() RTC_RUN_ON(&task_queue_);
117
118 void ScheduleOutput() RTC_RUN_ON(&task_queue_);
119
120 // Make sure that the event log is "managed" - created/destroyed, as well
121 // as started/stopped - from the same thread/task-queue.
122 rtc::SequencedTaskChecker owner_sequence_checker_;
123
124 // History containing all past configuration events.
125 std::deque<std::unique_ptr<RtcEvent>> config_history_
126 RTC_ACCESS_ON(task_queue_);
127
128 // History containing the most recent (non-configuration) events (~10s).
129 std::deque<std::unique_ptr<RtcEvent>> history_ RTC_ACCESS_ON(task_queue_);
130
131 size_t max_size_bytes_ RTC_ACCESS_ON(task_queue_);
132 size_t written_bytes_ RTC_ACCESS_ON(task_queue_);
133
134 std::unique_ptr<RtcEventLogEncoder> event_encoder_ RTC_ACCESS_ON(task_queue_);
135 std::unique_ptr<RtcEventLogOutput> event_output_ RTC_ACCESS_ON(task_queue_);
136
137 size_t num_config_events_written_ RTC_ACCESS_ON(task_queue_);
138 int64_t output_period_ms_ RTC_ACCESS_ON(task_queue_);
139 int64_t last_output_ms_ RTC_ACCESS_ON(task_queue_);
140 bool output_scheduled_ RTC_ACCESS_ON(task_queue_);
141
142 // Since we are posting tasks bound to |this|, it is critical that the event
143 // log and it's members outlive the |task_queue_|. Keep the "task_queue_|
144 // last to ensure it destructs first, or else tasks living on the queue might
145 // access other members after they've been torn down.
146 rtc::TaskQueue task_queue_;
147
148 RTC_DISALLOW_COPY_AND_ASSIGN(RtcEventLogImpl);
149 };
150
RtcEventLogImpl(std::unique_ptr<RtcEventLogEncoder> event_encoder)151 RtcEventLogImpl::RtcEventLogImpl(
152 std::unique_ptr<RtcEventLogEncoder> event_encoder)
153 : max_size_bytes_(std::numeric_limits<decltype(max_size_bytes_)>::max()),
154 written_bytes_(0),
155 event_encoder_(std::move(event_encoder)),
156 num_config_events_written_(0),
157 output_period_ms_(kImmediateOutput),
158 last_output_ms_(rtc::TimeMillis()),
159 output_scheduled_(false),
160 task_queue_("rtc_event_log") {}
161
~RtcEventLogImpl()162 RtcEventLogImpl::~RtcEventLogImpl() {
163 RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_);
164
165 // If we're logging to the output, this will stop that. Blocking function.
166 StopLogging();
167
168 int count = std::atomic_fetch_sub(&rtc_event_log_count, 1) - 1;
169 RTC_DCHECK_GE(count, 0);
170 }
171
StartLogging(std::unique_ptr<RtcEventLogOutput> output,int64_t output_period_ms)172 bool RtcEventLogImpl::StartLogging(std::unique_ptr<RtcEventLogOutput> output,
173 int64_t output_period_ms) {
174 RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_);
175
176 RTC_DCHECK(output_period_ms == kImmediateOutput || output_period_ms > 0);
177
178 if (!output->IsActive()) {
179 // TODO(eladalon): We may want to remove the IsActive method. Otherwise
180 // we probably want to be consistent and terminate any existing output.
181 return false;
182 }
183
184 RTC_LOG(LS_INFO) << "Starting WebRTC event log.";
185
186 // |start_event| captured by value. This is done here because we want the
187 // timestamp to reflect when StartLogging() was called; not the queueing
188 // delay of the TaskQueue.
189 // This is a bit inefficient - especially since we copy again to get it
190 // to comply with LogToOutput()'s signature - but it's a small problem.
191 RtcEventLoggingStarted start_event;
192
193 // Binding to |this| is safe because |this| outlives the |task_queue_|.
194 auto start = [this, start_event](std::unique_ptr<RtcEventLogOutput> output) {
195 RTC_DCHECK_RUN_ON(&task_queue_);
196 RTC_DCHECK(output->IsActive());
197 event_output_ = std::move(output);
198 num_config_events_written_ = 0;
199 LogToOutput(rtc::MakeUnique<RtcEventLoggingStarted>(start_event));
200 LogEventsFromMemoryToOutput();
201 };
202
203 task_queue_.PostTask(rtc::MakeUnique<ResourceOwningTask<RtcEventLogOutput>>(
204 std::move(output), start));
205
206 return true;
207 }
208
StopLogging()209 void RtcEventLogImpl::StopLogging() {
210 RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_);
211
212 RTC_LOG(LS_INFO) << "Stopping WebRTC event log.";
213
214 rtc::Event output_stopped(true, false);
215
216 // Binding to |this| is safe because |this| outlives the |task_queue_|.
217 task_queue_.PostTask([this, &output_stopped]() {
218 RTC_DCHECK_RUN_ON(&task_queue_);
219 if (event_output_) {
220 RTC_DCHECK(event_output_->IsActive());
221 LogEventsFromMemoryToOutput();
222 }
223 StopLoggingInternal();
224 output_stopped.Set();
225 });
226
227 output_stopped.Wait(rtc::Event::kForever);
228
229 RTC_LOG(LS_INFO) << "WebRTC event log successfully stopped.";
230 }
231
Log(std::unique_ptr<RtcEvent> event)232 void RtcEventLogImpl::Log(std::unique_ptr<RtcEvent> event) {
233 RTC_DCHECK(event);
234
235 // Binding to |this| is safe because |this| outlives the |task_queue_|.
236 auto event_handler = [this](std::unique_ptr<RtcEvent> unencoded_event) {
237 RTC_DCHECK_RUN_ON(&task_queue_);
238 LogToMemory(std::move(unencoded_event));
239 if (event_output_)
240 ScheduleOutput();
241 };
242
243 task_queue_.PostTask(rtc::MakeUnique<ResourceOwningTask<RtcEvent>>(
244 std::move(event), event_handler));
245 }
246
ScheduleOutput()247 void RtcEventLogImpl::ScheduleOutput() {
248 RTC_DCHECK(event_output_ && event_output_->IsActive());
249 if (history_.size() >= kMaxEventsInHistory) {
250 // We have to emergency drain the buffer. We can't wait for the scheduled
251 // output task because there might be other event incoming before that.
252 LogEventsFromMemoryToOutput();
253 return;
254 }
255
256 if (output_period_ms_ == kImmediateOutput) {
257 // We are already on the |task_queue_| so there is no reason to post a task
258 // if we want to output immediately.
259 LogEventsFromMemoryToOutput();
260 return;
261 }
262
263 if (!output_scheduled_) {
264 output_scheduled_ = true;
265 // Binding to |this| is safe because |this| outlives the |task_queue_|.
266 auto output_task = [this]() {
267 RTC_DCHECK_RUN_ON(&task_queue_);
268 if (event_output_) {
269 RTC_DCHECK(event_output_->IsActive());
270 LogEventsFromMemoryToOutput();
271 }
272 output_scheduled_ = false;
273 };
274 int64_t now_ms = rtc::TimeMillis();
275 int64_t time_since_output_ms = now_ms - last_output_ms_;
276 uint32_t delay = rtc::SafeClamp(output_period_ms_ - time_since_output_ms, 0,
277 output_period_ms_);
278 task_queue_.PostDelayedTask(output_task, delay);
279 }
280 }
281
AppendEventToString(const RtcEvent & event,std::string * output_string)282 bool RtcEventLogImpl::AppendEventToString(const RtcEvent& event,
283 std::string* output_string) {
284 RTC_DCHECK_RUN_ON(&task_queue_);
285
286 std::string encoded_event = event_encoder_->Encode(event);
287
288 bool appended;
289 size_t potential_new_size =
290 written_bytes_ + output_string->size() + encoded_event.length();
291 if (potential_new_size <= max_size_bytes_) {
292 // TODO(eladalon): This is inefficient; fix this in a separate CL.
293 *output_string += encoded_event;
294 appended = true;
295 } else {
296 appended = false;
297 }
298
299 return appended;
300 }
301
LogToMemory(std::unique_ptr<RtcEvent> event)302 void RtcEventLogImpl::LogToMemory(std::unique_ptr<RtcEvent> event) {
303 std::deque<std::unique_ptr<RtcEvent>>& container =
304 event->IsConfigEvent() ? config_history_ : history_;
305 const size_t container_max_size =
306 event->IsConfigEvent() ? kMaxEventsInConfigHistory : kMaxEventsInHistory;
307
308 if (container.size() >= container_max_size) {
309 RTC_DCHECK(!event_output_); // Shouldn't lose events if we have an output.
310 container.pop_front();
311 }
312 container.push_back(std::move(event));
313 }
314
LogEventsFromMemoryToOutput()315 void RtcEventLogImpl::LogEventsFromMemoryToOutput() {
316 RTC_DCHECK(event_output_ && event_output_->IsActive());
317 last_output_ms_ = rtc::TimeMillis();
318
319 std::string output_string;
320
321 // Serialize all stream configurations that haven't already been written to
322 // this output. |num_config_events_written_| is used to track which configs we
323 // have already written. (Note that the config may have been written to
324 // previous outputs; configs are not discarded.)
325 bool appended = true;
326 while (num_config_events_written_ < config_history_.size()) {
327 appended = AppendEventToString(*config_history_[num_config_events_written_],
328 &output_string);
329 if (!appended)
330 break;
331 ++num_config_events_written_;
332 }
333
334 // Serialize the events in the event queue.
335 while (appended && !history_.empty()) {
336 appended = AppendEventToString(*history_.front(), &output_string);
337 if (appended) {
338 // Known issue - if writing to the output fails, these events will have
339 // been lost. If we try to open a new output, these events will be missing
340 // from it.
341 history_.pop_front();
342 }
343 }
344
345 WriteToOutput(output_string);
346
347 if (!appended) {
348 // Successful partial write to the output. Some events could not be written;
349 // the output should be closed, to avoid gaps.
350 StopOutput();
351 }
352 }
353
LogToOutput(std::unique_ptr<RtcEvent> event)354 void RtcEventLogImpl::LogToOutput(std::unique_ptr<RtcEvent> event) {
355 RTC_DCHECK(event_output_ && event_output_->IsActive());
356
357 std::string output_string;
358
359 bool appended = AppendEventToString(*event, &output_string);
360
361 if (event->IsConfigEvent()) {
362 // Config events need to be kept in memory too, so that they may be
363 // rewritten into future outputs, too.
364 config_history_.push_back(std::move(event));
365 }
366
367 if (!appended) {
368 if (!event->IsConfigEvent()) {
369 // This event will not fit into the output; push it into |history_|
370 // instead, so that it might be logged into the next output (if any).
371 history_.push_back(std::move(event));
372 }
373 StopOutput();
374 return;
375 }
376
377 WriteToOutput(output_string);
378 }
379
StopOutput()380 void RtcEventLogImpl::StopOutput() {
381 max_size_bytes_ = std::numeric_limits<decltype(max_size_bytes_)>::max();
382 written_bytes_ = 0;
383 event_output_.reset();
384 }
385
StopLoggingInternal()386 void RtcEventLogImpl::StopLoggingInternal() {
387 if (event_output_) {
388 RTC_DCHECK(event_output_->IsActive());
389 event_output_->Write(
390 event_encoder_->Encode(*rtc::MakeUnique<RtcEventLoggingStopped>()));
391 }
392 StopOutput();
393 }
394
WriteToOutput(const std::string & output_string)395 void RtcEventLogImpl::WriteToOutput(const std::string& output_string) {
396 RTC_DCHECK(event_output_ && event_output_->IsActive());
397 if (!event_output_->Write(output_string)) {
398 RTC_LOG(LS_ERROR) << "Failed to write RTC event to output.";
399 // The first failure closes the output.
400 RTC_DCHECK(!event_output_->IsActive());
401 StopOutput(); // Clean-up.
402 return;
403 }
404 written_bytes_ += output_string.size();
405 }
406
407 } // namespace
408
409 #endif // ENABLE_RTC_EVENT_LOG
410
411 // RtcEventLog member functions.
Create(EncodingType encoding_type)412 std::unique_ptr<RtcEventLog> RtcEventLog::Create(EncodingType encoding_type) {
413 #ifdef ENABLE_RTC_EVENT_LOG
414 // TODO(eladalon): Known issue - there's a race over |rtc_event_log_count|.
415 constexpr int kMaxLogCount = 5;
416 int count = 1 + std::atomic_fetch_add(&rtc_event_log_count, 1);
417 if (count > kMaxLogCount) {
418 RTC_LOG(LS_WARNING) << "Denied creation of additional WebRTC event logs. "
419 << count - 1 << " logs open already.";
420 std::atomic_fetch_sub(&rtc_event_log_count, 1);
421 return CreateNull();
422 }
423 auto encoder = CreateEncoder(encoding_type);
424 return rtc::MakeUnique<RtcEventLogImpl>(std::move(encoder));
425 #else
426 return CreateNull();
427 #endif // ENABLE_RTC_EVENT_LOG
428 }
429
CreateNull()430 std::unique_ptr<RtcEventLog> RtcEventLog::CreateNull() {
431 return std::unique_ptr<RtcEventLog>(new RtcEventLogNullImpl());
432 }
433
434 } // namespace webrtc
435