Home | History | Annotate | Download | only in call 
      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:
     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 
     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.
    519 rtc::scoped_ptr<RtcEventLog> RtcEventLog::Create() {
    520   return rtc::scoped_ptr<RtcEventLog>(new RtcEventLogImpl());
    521 }
    522 
    523 }  // namespace webrtc
    524