Refactored CL for moving the output to a separate thread.

webrtc/call/rtc_event_log_unittest.cc

 /*
  *  Copyright (c) 2015 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.
  */
 
@@ skipping 206 matching lines @@
   ASSERT_TRUE(sender_config.has_encoder());
   ASSERT_TRUE(sender_config.encoder().has_name());
   ASSERT_TRUE(sender_config.encoder().has_payload_type());
   EXPECT_EQ(config.encoder_settings.payload_name,
             sender_config.encoder().name());
   EXPECT_EQ(config.encoder_settings.payload_type,
             sender_config.encoder().payload_type());
 }
 
 void VerifyRtpEvent(const rtclog::Event& event,
-                    bool incoming,
+                    PacketDirection direction,
                     MediaType media_type,
                     const uint8_t* header,
                     size_t header_size,
                     size_t total_size) {
   ASSERT_TRUE(IsValidBasicEvent(event));
   ASSERT_EQ(rtclog::Event::RTP_EVENT, event.type());
   const rtclog::RtpPacket& rtp_packet = event.rtp_packet();
   ASSERT_TRUE(rtp_packet.has_incoming());
-  EXPECT_EQ(incoming, rtp_packet.incoming());
+  EXPECT_EQ(direction == kIncomingPacket, rtp_packet.incoming());
   ASSERT_TRUE(rtp_packet.has_type());
   EXPECT_EQ(media_type, GetRuntimeMediaType(rtp_packet.type()));
   ASSERT_TRUE(rtp_packet.has_packet_length());
   EXPECT_EQ(total_size, rtp_packet.packet_length());
   ASSERT_TRUE(rtp_packet.has_header());
   ASSERT_EQ(header_size, rtp_packet.header().size());
   for (size_t i = 0; i < header_size; i++) {
     EXPECT_EQ(header[i], static_cast<uint8_t>(rtp_packet.header()[i]));
   }
 }
 
 void VerifyRtcpEvent(const rtclog::Event& event,
-                     bool incoming,
+                     PacketDirection direction,
                      MediaType media_type,
                      const uint8_t* packet,
                      size_t total_size) {
   ASSERT_TRUE(IsValidBasicEvent(event));
   ASSERT_EQ(rtclog::Event::RTCP_EVENT, event.type());
   const rtclog::RtcpPacket& rtcp_packet = event.rtcp_packet();
   ASSERT_TRUE(rtcp_packet.has_incoming());
-  EXPECT_EQ(incoming, rtcp_packet.incoming());
+  EXPECT_EQ(direction == kIncomingPacket, rtcp_packet.incoming());
   ASSERT_TRUE(rtcp_packet.has_type());
   EXPECT_EQ(media_type, GetRuntimeMediaType(rtcp_packet.type()));
   ASSERT_TRUE(rtcp_packet.has_packet_data());
   ASSERT_EQ(total_size, rtcp_packet.packet_data().size());
   for (size_t i = 0; i < total_size; i++) {
     EXPECT_EQ(packet[i], static_cast<uint8_t>(rtcp_packet.packet_data()[i]));
   }
 }
 
 void VerifyPlayoutEvent(const rtclog::Event& event, uint32_t ssrc) {
@@ skipping 17 matching lines @@
   EXPECT_EQ(fraction_loss, bwe_event.fraction_loss());
   ASSERT_TRUE(bwe_event.has_total_packets());
   EXPECT_EQ(total_packets, bwe_event.total_packets());
 }
 
 void VerifyLogStartEvent(const rtclog::Event& event) {
   ASSERT_TRUE(IsValidBasicEvent(event));
   EXPECT_EQ(rtclog::Event::LOG_START, event.type());
 }
 
+void VerifyLogEndEvent(const rtclog::Event& event) {
+  ASSERT_TRUE(IsValidBasicEvent(event));
+  EXPECT_EQ(rtclog::Event::LOG_END, event.type());
+}
+
 /*
  * Bit number i of extension_bitvector is set to indicate the
  * presence of extension number i from kExtensionTypes / kExtensionNames.
  * The least significant bit extension_bitvector has number 0.
  */
 size_t GenerateRtpPacket(uint32_t extensions_bitvector,
                          uint32_t csrcs_count,
                          uint8_t* packet,
                          size_t packet_size,
                          Random* prng) {
@@ skipping 161 matching lines @@
 
   // Find the name of the current test, in order to use it as a temporary
   // filename.
   auto test_info = ::testing::UnitTest::GetInstance()->current_test_info();
   const std::string temp_filename =
       test::OutputPath() + test_info->test_case_name() + test_info->name();
 
   // When log_dumper goes out of scope, it causes the log file to be flushed
   // to disk.
   {
-    rtc::scoped_ptr<RtcEventLog> log_dumper(RtcEventLog::Create());
+    SimulatedClock fake_clock(prng.Rand<uint32_t>());
+    rtc::scoped_ptr<RtcEventLog> log_dumper(RtcEventLog::Create(&fake_clock));
     log_dumper->LogVideoReceiveStreamConfig(receiver_config);
+    fake_clock.AdvanceTimeMicroseconds(prng.Rand(1, 1000));
     log_dumper->LogVideoSendStreamConfig(sender_config);
+    fake_clock.AdvanceTimeMicroseconds(prng.Rand(1, 1000));
     size_t rtcp_index = 1;
     size_t playout_index = 1;
     size_t bwe_loss_index = 1;
     for (size_t i = 1; i <= rtp_count; i++) {
       log_dumper->LogRtpHeader(
           (i % 2 == 0) ? kIncomingPacket : kOutgoingPacket,
           (i % 3 == 0) ? MediaType::AUDIO : MediaType::VIDEO,
           rtp_packets[i - 1].data(), rtp_packets[i - 1].size());
+      fake_clock.AdvanceTimeMicroseconds(prng.Rand(1, 1000));
       if (i * rtcp_count >= rtcp_index * rtp_count) {
         log_dumper->LogRtcpPacket(
             (rtcp_index % 2 == 0) ? kIncomingPacket : kOutgoingPacket,
             rtcp_index % 3 == 0 ? MediaType::AUDIO : MediaType::VIDEO,
             rtcp_packets[rtcp_index - 1]->Buffer(),
             rtcp_packets[rtcp_index - 1]->Length());
         rtcp_index++;
+        fake_clock.AdvanceTimeMicroseconds(prng.Rand(1, 1000));
       }
       if (i * playout_count >= playout_index * rtp_count) {
         log_dumper->LogAudioPlayout(playout_ssrcs[playout_index - 1]);
         playout_index++;
+        fake_clock.AdvanceTimeMicroseconds(prng.Rand(1, 1000));
       }
       if (i * bwe_loss_count >= bwe_loss_index * rtp_count) {
         log_dumper->LogBwePacketLossEvent(
             bwe_loss_updates[bwe_loss_index - 1].first,
             bwe_loss_updates[bwe_loss_index - 1].second, i);
         bwe_loss_index++;
+        fake_clock.AdvanceTimeMicroseconds(prng.Rand(1, 1000));
       }
       if (i == rtp_count / 2) {
         log_dumper->StartLogging(temp_filename, 10000000);
+        fake_clock.AdvanceTimeMicroseconds(prng.Rand(1, 1000));
       }
     }
+    log_dumper->StopLogging();
   }
 
   // Read the generated file from disk.
   rtclog::EventStream parsed_stream;
 
   ASSERT_TRUE(RtcEventLog::ParseRtcEventLog(temp_filename, &parsed_stream));
 
   // Verify that what we read back from the event log is the same as
   // what we wrote down. For RTCP we log the full packets, but for
   // RTP we should only log the header.
   const int event_count = config_count + playout_count + bwe_loss_count +
-                          rtcp_count + rtp_count + 1;
+                          rtcp_count + rtp_count + 2;
   EXPECT_EQ(event_count, parsed_stream.stream_size());
-  VerifyReceiveStreamConfig(parsed_stream.stream(0), receiver_config);
-  VerifySendStreamConfig(parsed_stream.stream(1), sender_config);
-  size_t event_index = config_count;
+  // Print the expected and actual event types for easier debugging.
+  if (event_count != parsed_stream.stream_size()) {
+    for (size_t i = 0; i < static_cast<size_t>(parsed_stream.stream_size());
+         i++) {
+      printf("%4d ", parsed_stream.stream(i).type());
+    }
+    printf("\n");
+    size_t rtcp_index = 1, playout_index = 1, bwe_loss_index = 1;
+    printf("strt  cfg  cfg ");
+    for (size_t i = 1; i <= rtp_count; i++) {
+      printf(" rtp ");
+      if (i * rtcp_count >= rtcp_index++ * rtp_count)
+        printf("rtcp ");
+      if (i * playout_count >= playout_index++ * rtp_count)
+        printf("play ");
+      if (i * bwe_loss_count >= bwe_loss_index++ * rtp_count)
+        printf("loss ");
+    }
+    printf("\n");
+  }
+  VerifyLogStartEvent(parsed_stream.stream(0));
+  VerifyReceiveStreamConfig(parsed_stream.stream(1), receiver_config);
+  VerifySendStreamConfig(parsed_stream.stream(2), sender_config);
+  size_t event_index = config_count + 1;
   size_t rtcp_index = 1;
   size_t playout_index = 1;
   size_t bwe_loss_index = 1;
   for (size_t i = 1; i <= rtp_count; i++) {
     VerifyRtpEvent(parsed_stream.stream(event_index),
-                   (i % 2 == 0),  // Every second packet is incoming.
+                   (i % 2 == 0) ? kIncomingPacket : kOutgoingPacket,
                    (i % 3 == 0) ? MediaType::AUDIO : MediaType::VIDEO,
                    rtp_packets[i - 1].data(), rtp_header_sizes[i - 1],
                    rtp_packets[i - 1].size());
     event_index++;
     if (i * rtcp_count >= rtcp_index * rtp_count) {
       VerifyRtcpEvent(parsed_stream.stream(event_index),
-                      rtcp_index % 2 == 0,  // Every second packet is incoming.
+                      (rtcp_index % 2 == 0) ? kIncomingPacket : kOutgoingPacket,
                       rtcp_index % 3 == 0 ? MediaType::AUDIO : MediaType::VIDEO,
                       rtcp_packets[rtcp_index - 1]->Buffer(),
                       rtcp_packets[rtcp_index - 1]->Length());
       event_index++;
       rtcp_index++;
     }
     if (i * playout_count >= playout_index * rtp_count) {
       VerifyPlayoutEvent(parsed_stream.stream(event_index),
                          playout_ssrcs[playout_index - 1]);
       event_index++;
       playout_index++;
     }
     if (i * bwe_loss_count >= bwe_loss_index * rtp_count) {
       VerifyBweLossEvent(parsed_stream.stream(event_index),
                          bwe_loss_updates[bwe_loss_index - 1].first,
                          bwe_loss_updates[bwe_loss_index - 1].second, i);
       event_index++;
       bwe_loss_index++;
     }
-    if (i == rtp_count / 2) {
-      VerifyLogStartEvent(parsed_stream.stream(event_index));
-      event_index++;
-    }
   }
 
   // Clean up temporary file - can be pretty slow.
   remove(temp_filename.c_str());
 }
 
 TEST(RtcEventLogTest, LogSessionAndReadBack) {
   // Log 5 RTP, 2 RTCP, 0 playout events and 0 BWE events
   // with no header extensions or CSRCS.
   LogSessionAndReadBack(5, 2, 0, 0, 0, 0, 321);
@@ skipping 19 matching lines @@
                             2 + csrcs_count,  // Number of RTCP packets.
                             3 + csrcs_count,  // Number of playout events.
                             1 + csrcs_count,  // Number of BWE loss events.
                             extensions,       // Bit vector choosing extensions.
                             csrcs_count,      // Number of contributing sources.
                             extensions * 3 + csrcs_count + 1);  // Random seed.
     }
   }
 }
 
-// Tests that the event queue works correctly, i.e. drops old RTP, RTCP and
-// debug events, but keeps config events even if they are older than the limit.
-void DropOldEvents(uint32_t extensions_bitvector,
-                   uint32_t csrcs_count,
-                   unsigned int random_seed) {
-  rtc::Buffer old_rtp_packet;
-  rtc::Buffer recent_rtp_packet;
-  rtc::scoped_ptr<rtcp::RawPacket> old_rtcp_packet;
-  rtc::scoped_ptr<rtcp::RawPacket> recent_rtcp_packet;
+TEST(RtcEventLogTest, LogEventAndReadBack) {
+  Random prng(987654321);
 
-  VideoReceiveStream::Config receiver_config(nullptr);
-  VideoSendStream::Config sender_config(nullptr);
-
-  Random prng(random_seed);
-
-  // Create two RTP packets containing random data.
+  // Create one RTP and one RTCP packet containing random data.
   size_t packet_size = prng.Rand(1000, 1100);
-  old_rtp_packet.SetSize(packet_size);
-  GenerateRtpPacket(extensions_bitvector, csrcs_count, old_rtp_packet.data(),
-                    packet_size, &prng);
-  packet_size = prng.Rand(1000, 1100);
-  recent_rtp_packet.SetSize(packet_size);
-  size_t recent_header_size =
-      GenerateRtpPacket(extensions_bitvector, csrcs_count,
-                        recent_rtp_packet.data(), packet_size, &prng);
-
-  // Create two RTCP packets containing random data.
-  old_rtcp_packet = GenerateRtcpPacket(&prng);
-  recent_rtcp_packet = GenerateRtcpPacket(&prng);
-
-  // Create configurations for the video streams.
-  GenerateVideoReceiveConfig(extensions_bitvector, &receiver_config, &prng);
-  GenerateVideoSendConfig(extensions_bitvector, &sender_config, &prng);
+  rtc::Buffer rtp_packet(packet_size);
+  size_t header_size =
+      GenerateRtpPacket(0, 0, rtp_packet.data(), packet_size, &prng);
+  rtc::scoped_ptr<rtcp::RawPacket> rtcp_packet = GenerateRtcpPacket(&prng);
 
   // Find the name of the current test, in order to use it as a temporary
   // filename.
   auto test_info = ::testing::UnitTest::GetInstance()->current_test_info();
   const std::string temp_filename =
       test::OutputPath() + test_info->test_case_name() + test_info->name();
 
-  // The log file will be flushed to disk when the log_dumper goes out of scope.
-  {
-    rtc::scoped_ptr<RtcEventLog> log_dumper(RtcEventLog::Create());
-    // Reduce the time old events are stored to 50 ms.
-    log_dumper->SetBufferDuration(50000);
-    log_dumper->LogVideoReceiveStreamConfig(receiver_config);
-    log_dumper->LogVideoSendStreamConfig(sender_config);
-    log_dumper->LogRtpHeader(kOutgoingPacket, MediaType::AUDIO,
-                             old_rtp_packet.data(), old_rtp_packet.size());
-    log_dumper->LogRtcpPacket(kIncomingPacket, MediaType::AUDIO,
-                              old_rtcp_packet->Buffer(),
-                              old_rtcp_packet->Length());
-    // Sleep 55 ms to let old events be removed from the queue.
-    rtc::Thread::SleepMs(55);
-    log_dumper->StartLogging(temp_filename, 10000000);
-    log_dumper->LogRtpHeader(kIncomingPacket, MediaType::VIDEO,
-                             recent_rtp_packet.data(),
-                             recent_rtp_packet.size());
-    log_dumper->LogRtcpPacket(kOutgoingPacket, MediaType::VIDEO,
-                              recent_rtcp_packet->Buffer(),
-                              recent_rtcp_packet->Length());
-  }
+  // Add RTP, start logging, add RTCP and then stop logging
+  SimulatedClock fake_clock(prng.Rand<uint32_t>());
+  rtc::scoped_ptr<RtcEventLog> log_dumper(RtcEventLog::Create(&fake_clock));
+
+  log_dumper->LogRtpHeader(kIncomingPacket, MediaType::VIDEO, rtp_packet.data(),
+                           rtp_packet.size());
+  fake_clock.AdvanceTimeMicroseconds(prng.Rand(1, 1000));
+
+  log_dumper->StartLogging(temp_filename, 10000000);
+  fake_clock.AdvanceTimeMicroseconds(prng.Rand(1, 1000));
+
+  log_dumper->LogRtcpPacket(kOutgoingPacket, MediaType::VIDEO,
+                            rtcp_packet->Buffer(), rtcp_packet->Length());
+  fake_clock.AdvanceTimeMicroseconds(prng.Rand(1, 1000));
+
+  log_dumper->StopLogging();
 
   // Read the generated file from disk.
   rtclog::EventStream parsed_stream;
   ASSERT_TRUE(RtcEventLog::ParseRtcEventLog(temp_filename, &parsed_stream));
 
   // Verify that what we read back from the event log is the same as
-  // what we wrote. Old RTP and RTCP events should have been discarded,
-  // but old configuration events should still be available.
-  EXPECT_EQ(5, parsed_stream.stream_size());
-  VerifyReceiveStreamConfig(parsed_stream.stream(0), receiver_config);
-  VerifySendStreamConfig(parsed_stream.stream(1), sender_config);
-  VerifyLogStartEvent(parsed_stream.stream(2));
-  VerifyRtpEvent(parsed_stream.stream(3), true, MediaType::VIDEO,
-                 recent_rtp_packet.data(), recent_header_size,
-                 recent_rtp_packet.size());
-  VerifyRtcpEvent(parsed_stream.stream(4), false, MediaType::VIDEO,
-                  recent_rtcp_packet->Buffer(), recent_rtcp_packet->Length());
+  // what we wrote down.
+  EXPECT_EQ(4, parsed_stream.stream_size());
 
-  // Clean up temporary file - can be pretty slow.
-  remove(temp_filename.c_str());
+  VerifyLogStartEvent(parsed_stream.stream(0));
+
+  VerifyRtpEvent(parsed_stream.stream(1), kIncomingPacket, MediaType::VIDEO,
+                 rtp_packet.data(), header_size, rtp_packet.size());
+
+  VerifyRtcpEvent(parsed_stream.stream(2), kOutgoingPacket, MediaType::VIDEO,
+                  rtcp_packet->Buffer(), rtcp_packet->Length());
+
+  VerifyLogEndEvent(parsed_stream.stream(3));
 }
 
-TEST(RtcEventLogTest, DropOldEvents) {
-  // Enable all header extensions
-  uint32_t extensions = (1u << kNumExtensions) - 1;
-  uint32_t csrcs_count = 2;
-  DropOldEvents(extensions, csrcs_count, 141421356);
-  DropOldEvents(extensions, csrcs_count, 173205080);
-}
+// // Tests that the event queue works correctly, i.e. drops old RTP, RTCP and
+// // debug events, but keeps config events even if they are older than the
+// limit.
+// void DropOldEvents(uint32_t extensions_bitvector,
+//                    uint32_t csrcs_count,
+//                    unsigned int random_seed) {
+//   rtc::Buffer old_rtp_packet;
+//   rtc::Buffer recent_rtp_packet;
+//   rtc::scoped_ptr<rtcp::RawPacket> old_rtcp_packet;
+//   rtc::scoped_ptr<rtcp::RawPacket> recent_rtcp_packet;
+
+//   VideoReceiveStream::Config receiver_config(nullptr);
+//   VideoSendStream::Config sender_config(nullptr);
+
+//   Random prng(random_seed);
+
+//   // Create two RTP packets containing random data.
+//   size_t packet_size = prng.Rand(1000, 1100);
+//   old_rtp_packet.SetSize(packet_size);
+//   GenerateRtpPacket(extensions_bitvector, csrcs_count, old_rtp_packet.data(),
+//                     packet_size, &prng);
+//   packet_size = prng.Rand(1000, 1100);
+//   recent_rtp_packet.SetSize(packet_size);
+//   size_t recent_header_size =
+//       GenerateRtpPacket(extensions_bitvector, csrcs_count,
+//                         recent_rtp_packet.data(), packet_size, &prng);
+
+//   // Create two RTCP packets containing random data.
+//   old_rtcp_packet = GenerateRtcpPacket(&prng);
+//   recent_rtcp_packet = GenerateRtcpPacket(&prng);
+
+//   // Create configurations for the video streams.
+//   GenerateVideoReceiveConfig(extensions_bitvector, &receiver_config, &prng);
+//   GenerateVideoSendConfig(extensions_bitvector, &sender_config, &prng);
+
+//   // Find the name of the current test, in order to use it as a temporary
+//   // filename.
+//   auto test_info = ::testing::UnitTest::GetInstance()->current_test_info();
+//   const std::string temp_filename =
+//       test::OutputPath() + test_info->test_case_name() + test_info->name();
+
+//   // The log file will be flushed to disk when the log_dumper goes out of
+//   scope.
+//   {
+//     rtc::scoped_ptr<RtcEventLog>
+//     log_dumper(RtcEventLog::Create(Clock::GetRealTimeClock()));
+//     // Reduce the time old events are stored to 50 ms.
+//     log_dumper->SetBufferDuration(50000);
+//     log_dumper->LogVideoReceiveStreamConfig(receiver_config);
+//     log_dumper->LogVideoSendStreamConfig(sender_config);
+//     log_dumper->LogRtpHeader(kOutgoingPacket, MediaType::AUDIO,
+//                              old_rtp_packet.data(), old_rtp_packet.size());
+//     log_dumper->LogRtcpPacket(kIncomingPacket, MediaType::AUDIO,
+//                               old_rtcp_packet->Buffer(),
+//                               old_rtcp_packet->Length());
+//     // Sleep 55 ms to let old events be removed from the queue.
+//     rtc::Thread::SleepMs(55);
+//     log_dumper->StartLogging(temp_filename, 10000000);
+//     log_dumper->LogRtpHeader(kIncomingPacket, MediaType::VIDEO,
+//                              recent_rtp_packet.data(),
+//                              recent_rtp_packet.size());
+//     log_dumper->LogRtcpPacket(kOutgoingPacket, MediaType::VIDEO,
+//                               recent_rtcp_packet->Buffer(),
+//                               recent_rtcp_packet->Length());
+//   }
+
+//   // Read the generated file from disk.
+//   rtclog::EventStream parsed_stream;
+//   ASSERT_TRUE(RtcEventLog::ParseRtcEventLog(temp_filename, &parsed_stream));
+
+//   // Verify that what we read back from the event log is the same as
+//   // what we wrote. Old RTP and RTCP events should have been discarded,
+//   // but old configuration events should still be available.
+//   EXPECT_EQ(5, parsed_stream.stream_size());
+//   VerifyReceiveStreamConfig(parsed_stream.stream(0), receiver_config);
+//   VerifySendStreamConfig(parsed_stream.stream(1), sender_config);
+//   VerifyLogStartEvent(parsed_stream.stream(2));
+//   VerifyRtpEvent(parsed_stream.stream(3), true, MediaType::VIDEO,
+//                  recent_rtp_packet.data(), recent_header_size,
+//                  recent_rtp_packet.size());
+//   VerifyRtcpEvent(parsed_stream.stream(4), false, MediaType::VIDEO,
+//                   recent_rtcp_packet->Buffer(),
+//                   recent_rtcp_packet->Length());
+
+//   // Clean up temporary file - can be pretty slow.
+//   remove(temp_filename.c_str());
+// }
+
+// TEST(RtcEventLogTest, DropOldEvents) {
+//   // Enable all header extensions
+//   uint32_t extensions = (1u << kNumExtensions) - 1;
+//   uint32_t csrcs_count = 2;
+//   DropOldEvents(extensions, csrcs_count, 141421356);
+//   DropOldEvents(extensions, csrcs_count, 173205080);
+// }
 
 }  // namespace webrtc
 
 #endif  // ENABLE_RTC_EVENT_LOG