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 
35 namespace webrtc {
36 
37 #ifndef ENABLE_RTC_EVENT_LOG
38 
39 // No-op implementation if flag is not set.
40 class RtcEventLogImpl final : public RtcEventLog {
41  public:
SetBufferDuration(int64_t buffer_duration_us)42   void SetBufferDuration(int64_t buffer_duration_us) override {}
StartLogging(const std::string & file_name,int duration_ms)43   void StartLogging(const std::string& file_name, int duration_ms) override {}
StartLogging(rtc::PlatformFile log_file)44   bool StartLogging(rtc::PlatformFile log_file) override { return false; }
StopLogging(void)45   void StopLogging(void) override {}
LogVideoReceiveStreamConfig(const VideoReceiveStream::Config & config)46   void LogVideoReceiveStreamConfig(
47       const VideoReceiveStream::Config& config) override {}
LogVideoSendStreamConfig(const VideoSendStream::Config & config)48   void LogVideoSendStreamConfig(
49       const VideoSendStream::Config& config) override {}
LogRtpHeader(bool incoming,MediaType media_type,const uint8_t * header,size_t packet_length)50   void LogRtpHeader(bool incoming,
51                     MediaType media_type,
52                     const uint8_t* header,
53                     size_t packet_length) override {}
LogRtcpPacket(bool incoming,MediaType media_type,const uint8_t * packet,size_t length)54   void LogRtcpPacket(bool incoming,
55                      MediaType media_type,
56                      const uint8_t* packet,
57                      size_t length) override {}
LogAudioPlayout(uint32_t ssrc)58   void LogAudioPlayout(uint32_t ssrc) override {}
LogBwePacketLossEvent(int32_t bitrate,uint8_t fraction_loss,int32_t total_packets)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 
66 class 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 
124 namespace {
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 
133 rtclog::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 
147 rtclog::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 
164 namespace {
165 bool 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.
175 RtcEventLogImpl::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 
185 void RtcEventLogImpl::SetBufferDuration(int64_t buffer_duration_us) {
186   rtc::CritScope lock(&crit_);
187   buffer_duration_us_ = buffer_duration_us;
188 }
189 
190 void 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 
204 bool 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 
230 void 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 
255 void RtcEventLogImpl::StopLogging() {
256   rtc::CritScope lock(&crit_);
257   StopLoggingLocked();
258 }
259 
260 void 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 
298 void 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 
330 void 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 
361 void 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 
420 void 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 
430 void 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 
444 void 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 
464 void 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 
475 void 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 
489 void 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 
500 bool 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.
Create()519 rtc::scoped_ptr<RtcEventLog> RtcEventLog::Create() {
520   return rtc::scoped_ptr<RtcEventLog>(new RtcEventLogImpl());
521 }
522 
523 }  // namespace webrtc
524