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 "webrtc/call/rtc_event_log.h"
12
13#include <deque>
14#include <vector>
15
16#include "webrtc/base/checks.h"
17#include "webrtc/base/criticalsection.h"
18#include "webrtc/base/thread_annotations.h"
19#include "webrtc/call.h"
20#include "webrtc/modules/rtp_rtcp/include/rtp_rtcp_defines.h"
21#include "webrtc/modules/rtp_rtcp/source/byte_io.h"
22#include "webrtc/modules/rtp_rtcp/source/rtcp_utility.h"
23#include "webrtc/system_wrappers/include/clock.h"
24#include "webrtc/system_wrappers/include/file_wrapper.h"
25
26#ifdef ENABLE_RTC_EVENT_LOG
27// Files generated at build-time by the protobuf compiler.
28#ifdef WEBRTC_ANDROID_PLATFORM_BUILD
29#include "external/webrtc/webrtc/call/rtc_event_log.pb.h"
30#else
31#include "webrtc/call/rtc_event_log.pb.h"
32#endif
33#endif
34
35namespace webrtc {
36
37#ifndef ENABLE_RTC_EVENT_LOG
38
39// No-op implementation if flag is not set.
40class RtcEventLogImpl final : public RtcEventLog {
41 public:
42  void SetBufferDuration(int64_t buffer_duration_us) override {}
43  void StartLogging(const std::string& file_name, int duration_ms) override {}
44  bool StartLogging(rtc::PlatformFile log_file) override { return false; }
45  void StopLogging(void) override {}
46  void LogVideoReceiveStreamConfig(
47      const VideoReceiveStream::Config& config) override {}
48  void LogVideoSendStreamConfig(
49      const VideoSendStream::Config& config) override {}
50  void LogRtpHeader(bool incoming,
51                    MediaType media_type,
52                    const uint8_t* header,
53                    size_t packet_length) override {}
54  void LogRtcpPacket(bool incoming,
55                     MediaType media_type,
56                     const uint8_t* packet,
57                     size_t length) override {}
58  void LogAudioPlayout(uint32_t ssrc) override {}
59  void LogBwePacketLossEvent(int32_t bitrate,
60                             uint8_t fraction_loss,
61                             int32_t total_packets) override {}
62};
63
64#else  // ENABLE_RTC_EVENT_LOG is defined
65
66class RtcEventLogImpl final : public RtcEventLog {
67 public:
68  RtcEventLogImpl();
69
70  void SetBufferDuration(int64_t buffer_duration_us) override;
71  void StartLogging(const std::string& file_name, int duration_ms) override;
72  bool StartLogging(rtc::PlatformFile log_file) override;
73  void StopLogging() override;
74  void LogVideoReceiveStreamConfig(
75      const VideoReceiveStream::Config& config) override;
76  void LogVideoSendStreamConfig(const VideoSendStream::Config& config) override;
77  void LogRtpHeader(bool incoming,
78                    MediaType media_type,
79                    const uint8_t* header,
80                    size_t packet_length) override;
81  void LogRtcpPacket(bool incoming,
82                     MediaType media_type,
83                     const uint8_t* packet,
84                     size_t length) override;
85  void LogAudioPlayout(uint32_t ssrc) override;
86  void LogBwePacketLossEvent(int32_t bitrate,
87                             uint8_t fraction_loss,
88                             int32_t total_packets) override;
89
90 private:
91  // Starts logging. This function assumes the file_ has been opened succesfully
92  // and that the start_time_us_ and _duration_us_ have been set.
93  void StartLoggingLocked() EXCLUSIVE_LOCKS_REQUIRED(crit_);
94  // Stops logging and clears the stored data and buffers.
95  void StopLoggingLocked() EXCLUSIVE_LOCKS_REQUIRED(crit_);
96  // Adds a new event to the logfile if logging is active, or adds it to the
97  // list of recent log events otherwise.
98  void HandleEvent(rtclog::Event* event) EXCLUSIVE_LOCKS_REQUIRED(crit_);
99  // Writes the event to the file. Note that this will destroy the state of the
100  // input argument.
101  void StoreToFile(rtclog::Event* event) EXCLUSIVE_LOCKS_REQUIRED(crit_);
102  // Adds the event to the list of recent events, and removes any events that
103  // are too old and no longer fall in the time window.
104  void AddRecentEvent(const rtclog::Event& event)
105      EXCLUSIVE_LOCKS_REQUIRED(crit_);
106
107  rtc::CriticalSection crit_;
108  rtc::scoped_ptr<FileWrapper> file_ GUARDED_BY(crit_) =
109      rtc::scoped_ptr<FileWrapper>(FileWrapper::Create());
110  rtc::PlatformFile platform_file_ GUARDED_BY(crit_) =
111      rtc::kInvalidPlatformFileValue;
112  rtclog::EventStream stream_ GUARDED_BY(crit_);
113  std::deque<rtclog::Event> recent_log_events_ GUARDED_BY(crit_);
114  std::vector<rtclog::Event> config_events_ GUARDED_BY(crit_);
115
116  // Microseconds to record log events, before starting the actual log.
117  int64_t buffer_duration_us_ GUARDED_BY(crit_);
118  bool currently_logging_ GUARDED_BY(crit_);
119  int64_t start_time_us_ GUARDED_BY(crit_);
120  int64_t duration_us_ GUARDED_BY(crit_);
121  const Clock* const clock_;
122};
123
124namespace {
125// The functions in this namespace convert enums from the runtime format
126// that the rest of the WebRtc project can use, to the corresponding
127// serialized enum which is defined by the protobuf.
128
129// Do not add default return values to the conversion functions in this
130// unnamed namespace. The intention is to make the compiler warn if anyone
131// adds unhandled new events/modes/etc.
132
133rtclog::VideoReceiveConfig_RtcpMode ConvertRtcpMode(RtcpMode rtcp_mode) {
134  switch (rtcp_mode) {
135    case RtcpMode::kCompound:
136      return rtclog::VideoReceiveConfig::RTCP_COMPOUND;
137    case RtcpMode::kReducedSize:
138      return rtclog::VideoReceiveConfig::RTCP_REDUCEDSIZE;
139    case RtcpMode::kOff:
140      RTC_NOTREACHED();
141      return rtclog::VideoReceiveConfig::RTCP_COMPOUND;
142  }
143  RTC_NOTREACHED();
144  return rtclog::VideoReceiveConfig::RTCP_COMPOUND;
145}
146
147rtclog::MediaType ConvertMediaType(MediaType media_type) {
148  switch (media_type) {
149    case MediaType::ANY:
150      return rtclog::MediaType::ANY;
151    case MediaType::AUDIO:
152      return rtclog::MediaType::AUDIO;
153    case MediaType::VIDEO:
154      return rtclog::MediaType::VIDEO;
155    case MediaType::DATA:
156      return rtclog::MediaType::DATA;
157  }
158  RTC_NOTREACHED();
159  return rtclog::ANY;
160}
161
162}  // namespace
163
164namespace {
165bool IsConfigEvent(const rtclog::Event& event) {
166  rtclog::Event_EventType event_type = event.type();
167  return event_type == rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT ||
168         event_type == rtclog::Event::VIDEO_SENDER_CONFIG_EVENT ||
169         event_type == rtclog::Event::AUDIO_RECEIVER_CONFIG_EVENT ||
170         event_type == rtclog::Event::AUDIO_SENDER_CONFIG_EVENT;
171}
172}  // namespace
173
174// RtcEventLogImpl member functions.
175RtcEventLogImpl::RtcEventLogImpl()
176    : file_(FileWrapper::Create()),
177      stream_(),
178      buffer_duration_us_(10000000),
179      currently_logging_(false),
180      start_time_us_(0),
181      duration_us_(0),
182      clock_(Clock::GetRealTimeClock()) {
183}
184
185void RtcEventLogImpl::SetBufferDuration(int64_t buffer_duration_us) {
186  rtc::CritScope lock(&crit_);
187  buffer_duration_us_ = buffer_duration_us;
188}
189
190void RtcEventLogImpl::StartLogging(const std::string& file_name,
191                                   int duration_ms) {
192  rtc::CritScope lock(&crit_);
193  if (currently_logging_) {
194    StopLoggingLocked();
195  }
196  if (file_->OpenFile(file_name.c_str(), false) != 0) {
197    return;
198  }
199  start_time_us_ = clock_->TimeInMicroseconds();
200  duration_us_ = static_cast<int64_t>(duration_ms) * 1000;
201  StartLoggingLocked();
202}
203
204bool RtcEventLogImpl::StartLogging(rtc::PlatformFile log_file) {
205  rtc::CritScope lock(&crit_);
206
207  if (currently_logging_) {
208    StopLoggingLocked();
209  }
210  RTC_DCHECK(platform_file_ == rtc::kInvalidPlatformFileValue);
211
212  FILE* file_stream = rtc::FdopenPlatformFileForWriting(log_file);
213  if (!file_stream) {
214    rtc::ClosePlatformFile(log_file);
215    return false;
216  }
217
218  if (file_->OpenFromFileHandle(file_stream, true, false) != 0) {
219    rtc::ClosePlatformFile(log_file);
220    return false;
221  }
222  platform_file_ = log_file;
223  // Set the start time and duration to keep logging for 10 minutes.
224  start_time_us_ = clock_->TimeInMicroseconds();
225  duration_us_ = 10 * 60 * 1000000;
226  StartLoggingLocked();
227  return true;
228}
229
230void RtcEventLogImpl::StartLoggingLocked() {
231  currently_logging_ = true;
232
233  // Write all old configuration events to the log file.
234  for (auto& event : config_events_) {
235    StoreToFile(&event);
236  }
237  // Write all recent configuration events to the log file, and
238  // write all other recent events to the log file, ignoring any old events.
239  for (auto& event : recent_log_events_) {
240    if (IsConfigEvent(event)) {
241      StoreToFile(&event);
242      config_events_.push_back(event);
243    } else if (event.timestamp_us() >= start_time_us_ - buffer_duration_us_) {
244      StoreToFile(&event);
245    }
246  }
247  recent_log_events_.clear();
248  // Write a LOG_START event to the file.
249  rtclog::Event start_event;
250  start_event.set_timestamp_us(start_time_us_);
251  start_event.set_type(rtclog::Event::LOG_START);
252  StoreToFile(&start_event);
253}
254
255void RtcEventLogImpl::StopLogging() {
256  rtc::CritScope lock(&crit_);
257  StopLoggingLocked();
258}
259
260void RtcEventLogImpl::LogVideoReceiveStreamConfig(
261    const VideoReceiveStream::Config& config) {
262  rtc::CritScope lock(&crit_);
263
264  rtclog::Event event;
265  event.set_timestamp_us(clock_->TimeInMicroseconds());
266  event.set_type(rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT);
267
268  rtclog::VideoReceiveConfig* receiver_config =
269      event.mutable_video_receiver_config();
270  receiver_config->set_remote_ssrc(config.rtp.remote_ssrc);
271  receiver_config->set_local_ssrc(config.rtp.local_ssrc);
272
273  receiver_config->set_rtcp_mode(ConvertRtcpMode(config.rtp.rtcp_mode));
274  receiver_config->set_remb(config.rtp.remb);
275
276  for (const auto& kv : config.rtp.rtx) {
277    rtclog::RtxMap* rtx = receiver_config->add_rtx_map();
278    rtx->set_payload_type(kv.first);
279    rtx->mutable_config()->set_rtx_ssrc(kv.second.ssrc);
280    rtx->mutable_config()->set_rtx_payload_type(kv.second.payload_type);
281  }
282
283  for (const auto& e : config.rtp.extensions) {
284    rtclog::RtpHeaderExtension* extension =
285        receiver_config->add_header_extensions();
286    extension->set_name(e.name);
287    extension->set_id(e.id);
288  }
289
290  for (const auto& d : config.decoders) {
291    rtclog::DecoderConfig* decoder = receiver_config->add_decoders();
292    decoder->set_name(d.payload_name);
293    decoder->set_payload_type(d.payload_type);
294  }
295  HandleEvent(&event);
296}
297
298void RtcEventLogImpl::LogVideoSendStreamConfig(
299    const VideoSendStream::Config& config) {
300  rtc::CritScope lock(&crit_);
301
302  rtclog::Event event;
303  event.set_timestamp_us(clock_->TimeInMicroseconds());
304  event.set_type(rtclog::Event::VIDEO_SENDER_CONFIG_EVENT);
305
306  rtclog::VideoSendConfig* sender_config = event.mutable_video_sender_config();
307
308  for (const auto& ssrc : config.rtp.ssrcs) {
309    sender_config->add_ssrcs(ssrc);
310  }
311
312  for (const auto& e : config.rtp.extensions) {
313    rtclog::RtpHeaderExtension* extension =
314        sender_config->add_header_extensions();
315    extension->set_name(e.name);
316    extension->set_id(e.id);
317  }
318
319  for (const auto& rtx_ssrc : config.rtp.rtx.ssrcs) {
320    sender_config->add_rtx_ssrcs(rtx_ssrc);
321  }
322  sender_config->set_rtx_payload_type(config.rtp.rtx.payload_type);
323
324  rtclog::EncoderConfig* encoder = sender_config->mutable_encoder();
325  encoder->set_name(config.encoder_settings.payload_name);
326  encoder->set_payload_type(config.encoder_settings.payload_type);
327  HandleEvent(&event);
328}
329
330void RtcEventLogImpl::LogRtpHeader(bool incoming,
331                                   MediaType media_type,
332                                   const uint8_t* header,
333                                   size_t packet_length) {
334  // Read header length (in bytes) from packet data.
335  if (packet_length < 12u) {
336    return;  // Don't read outside the packet.
337  }
338  const bool x = (header[0] & 0x10) != 0;
339  const uint8_t cc = header[0] & 0x0f;
340  size_t header_length = 12u + cc * 4u;
341
342  if (x) {
343    if (packet_length < 12u + cc * 4u + 4u) {
344      return;  // Don't read outside the packet.
345    }
346    size_t x_len = ByteReader<uint16_t>::ReadBigEndian(header + 14 + cc * 4);
347    header_length += (x_len + 1) * 4;
348  }
349
350  rtc::CritScope lock(&crit_);
351  rtclog::Event rtp_event;
352  rtp_event.set_timestamp_us(clock_->TimeInMicroseconds());
353  rtp_event.set_type(rtclog::Event::RTP_EVENT);
354  rtp_event.mutable_rtp_packet()->set_incoming(incoming);
355  rtp_event.mutable_rtp_packet()->set_type(ConvertMediaType(media_type));
356  rtp_event.mutable_rtp_packet()->set_packet_length(packet_length);
357  rtp_event.mutable_rtp_packet()->set_header(header, header_length);
358  HandleEvent(&rtp_event);
359}
360
361void RtcEventLogImpl::LogRtcpPacket(bool incoming,
362                                    MediaType media_type,
363                                    const uint8_t* packet,
364                                    size_t length) {
365  rtc::CritScope lock(&crit_);
366  rtclog::Event rtcp_event;
367  rtcp_event.set_timestamp_us(clock_->TimeInMicroseconds());
368  rtcp_event.set_type(rtclog::Event::RTCP_EVENT);
369  rtcp_event.mutable_rtcp_packet()->set_incoming(incoming);
370  rtcp_event.mutable_rtcp_packet()->set_type(ConvertMediaType(media_type));
371
372  RTCPUtility::RtcpCommonHeader header;
373  const uint8_t* block_begin = packet;
374  const uint8_t* packet_end = packet + length;
375  RTC_DCHECK(length <= IP_PACKET_SIZE);
376  uint8_t buffer[IP_PACKET_SIZE];
377  uint32_t buffer_length = 0;
378  while (block_begin < packet_end) {
379    if (!RtcpParseCommonHeader(block_begin, packet_end - block_begin,
380                               &header)) {
381      break;  // Incorrect message header.
382    }
383    uint32_t block_size = header.BlockSize();
384    switch (header.packet_type) {
385      case RTCPUtility::PT_SR:
386        FALLTHROUGH();
387      case RTCPUtility::PT_RR:
388        FALLTHROUGH();
389      case RTCPUtility::PT_BYE:
390        FALLTHROUGH();
391      case RTCPUtility::PT_IJ:
392        FALLTHROUGH();
393      case RTCPUtility::PT_RTPFB:
394        FALLTHROUGH();
395      case RTCPUtility::PT_PSFB:
396        FALLTHROUGH();
397      case RTCPUtility::PT_XR:
398        // We log sender reports, receiver reports, bye messages
399        // inter-arrival jitter, third-party loss reports, payload-specific
400        // feedback and extended reports.
401        memcpy(buffer + buffer_length, block_begin, block_size);
402        buffer_length += block_size;
403        break;
404      case RTCPUtility::PT_SDES:
405        FALLTHROUGH();
406      case RTCPUtility::PT_APP:
407        FALLTHROUGH();
408      default:
409        // We don't log sender descriptions, application defined messages
410        // or message blocks of unknown type.
411        break;
412    }
413
414    block_begin += block_size;
415  }
416  rtcp_event.mutable_rtcp_packet()->set_packet_data(buffer, buffer_length);
417  HandleEvent(&rtcp_event);
418}
419
420void RtcEventLogImpl::LogAudioPlayout(uint32_t ssrc) {
421  rtc::CritScope lock(&crit_);
422  rtclog::Event event;
423  event.set_timestamp_us(clock_->TimeInMicroseconds());
424  event.set_type(rtclog::Event::AUDIO_PLAYOUT_EVENT);
425  auto playout_event = event.mutable_audio_playout_event();
426  playout_event->set_local_ssrc(ssrc);
427  HandleEvent(&event);
428}
429
430void RtcEventLogImpl::LogBwePacketLossEvent(int32_t bitrate,
431                                            uint8_t fraction_loss,
432                                            int32_t total_packets) {
433  rtc::CritScope lock(&crit_);
434  rtclog::Event event;
435  event.set_timestamp_us(clock_->TimeInMicroseconds());
436  event.set_type(rtclog::Event::BWE_PACKET_LOSS_EVENT);
437  auto bwe_event = event.mutable_bwe_packet_loss_event();
438  bwe_event->set_bitrate(bitrate);
439  bwe_event->set_fraction_loss(fraction_loss);
440  bwe_event->set_total_packets(total_packets);
441  HandleEvent(&event);
442}
443
444void RtcEventLogImpl::StopLoggingLocked() {
445  if (currently_logging_) {
446    currently_logging_ = false;
447    // Create a LogEnd event
448    rtclog::Event event;
449    event.set_timestamp_us(clock_->TimeInMicroseconds());
450    event.set_type(rtclog::Event::LOG_END);
451    // Store the event and close the file
452    RTC_DCHECK(file_->Open());
453    StoreToFile(&event);
454    file_->CloseFile();
455    if (platform_file_ != rtc::kInvalidPlatformFileValue) {
456      rtc::ClosePlatformFile(platform_file_);
457      platform_file_ = rtc::kInvalidPlatformFileValue;
458    }
459  }
460  RTC_DCHECK(!file_->Open());
461  stream_.Clear();
462}
463
464void RtcEventLogImpl::HandleEvent(rtclog::Event* event) {
465  if (currently_logging_) {
466    if (clock_->TimeInMicroseconds() < start_time_us_ + duration_us_) {
467      StoreToFile(event);
468      return;
469    }
470    StopLoggingLocked();
471  }
472  AddRecentEvent(*event);
473}
474
475void RtcEventLogImpl::StoreToFile(rtclog::Event* event) {
476  // Reuse the same object at every log event.
477  if (stream_.stream_size() < 1) {
478    stream_.add_stream();
479  }
480  RTC_DCHECK_EQ(stream_.stream_size(), 1);
481  stream_.mutable_stream(0)->Swap(event);
482  // TODO(terelius): Doesn't this create a new EventStream per event?
483  // Is this guaranteed to work e.g. in future versions of protobuf?
484  std::string dump_buffer;
485  stream_.SerializeToString(&dump_buffer);
486  file_->Write(dump_buffer.data(), dump_buffer.size());
487}
488
489void RtcEventLogImpl::AddRecentEvent(const rtclog::Event& event) {
490  recent_log_events_.push_back(event);
491  while (recent_log_events_.front().timestamp_us() <
492         event.timestamp_us() - buffer_duration_us_) {
493    if (IsConfigEvent(recent_log_events_.front())) {
494      config_events_.push_back(recent_log_events_.front());
495    }
496    recent_log_events_.pop_front();
497  }
498}
499
500bool RtcEventLog::ParseRtcEventLog(const std::string& file_name,
501                                   rtclog::EventStream* result) {
502  char tmp_buffer[1024];
503  int bytes_read = 0;
504  rtc::scoped_ptr<FileWrapper> dump_file(FileWrapper::Create());
505  if (dump_file->OpenFile(file_name.c_str(), true) != 0) {
506    return false;
507  }
508  std::string dump_buffer;
509  while ((bytes_read = dump_file->Read(tmp_buffer, sizeof(tmp_buffer))) > 0) {
510    dump_buffer.append(tmp_buffer, bytes_read);
511  }
512  dump_file->CloseFile();
513  return result->ParseFromString(dump_buffer);
514}
515
516#endif  // ENABLE_RTC_EVENT_LOG
517
518// RtcEventLog member functions.
519rtc::scoped_ptr<RtcEventLog> RtcEventLog::Create() {
520  return rtc::scoped_ptr<RtcEventLog>(new RtcEventLogImpl());
521}
522
523}  // namespace webrtc
524