• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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 <algorithm>
12 #include <limits>
13 #include <map>
14 #include <memory>
15 #include <string>
16 #include <tuple>
17 #include <utility>
18 #include <vector>
19 
20 #include "api/rtc_event_log/rtc_event_log.h"
21 #include "api/rtc_event_log/rtc_event_log_factory.h"
22 #include "api/rtc_event_log_output_file.h"
23 #include "api/task_queue/default_task_queue_factory.h"
24 #include "logging/rtc_event_log/events/rtc_event_audio_network_adaptation.h"
25 #include "logging/rtc_event_log/events/rtc_event_audio_playout.h"
26 #include "logging/rtc_event_log/events/rtc_event_audio_receive_stream_config.h"
27 #include "logging/rtc_event_log/events/rtc_event_audio_send_stream_config.h"
28 #include "logging/rtc_event_log/events/rtc_event_bwe_update_delay_based.h"
29 #include "logging/rtc_event_log/events/rtc_event_bwe_update_loss_based.h"
30 #include "logging/rtc_event_log/events/rtc_event_dtls_transport_state.h"
31 #include "logging/rtc_event_log/events/rtc_event_dtls_writable_state.h"
32 #include "logging/rtc_event_log/events/rtc_event_generic_ack_received.h"
33 #include "logging/rtc_event_log/events/rtc_event_generic_packet_received.h"
34 #include "logging/rtc_event_log/events/rtc_event_generic_packet_sent.h"
35 #include "logging/rtc_event_log/events/rtc_event_probe_cluster_created.h"
36 #include "logging/rtc_event_log/events/rtc_event_probe_result_failure.h"
37 #include "logging/rtc_event_log/events/rtc_event_probe_result_success.h"
38 #include "logging/rtc_event_log/events/rtc_event_rtcp_packet_incoming.h"
39 #include "logging/rtc_event_log/events/rtc_event_rtcp_packet_outgoing.h"
40 #include "logging/rtc_event_log/events/rtc_event_rtp_packet_incoming.h"
41 #include "logging/rtc_event_log/events/rtc_event_rtp_packet_outgoing.h"
42 #include "logging/rtc_event_log/events/rtc_event_video_receive_stream_config.h"
43 #include "logging/rtc_event_log/events/rtc_event_video_send_stream_config.h"
44 #include "logging/rtc_event_log/rtc_event_log_parser.h"
45 #include "logging/rtc_event_log/rtc_event_log_unittest_helper.h"
46 #include "logging/rtc_event_log/rtc_stream_config.h"
47 #include "modules/rtp_rtcp/include/rtp_header_extension_map.h"
48 #include "modules/rtp_rtcp/source/rtp_header_extensions.h"
49 #include "rtc_base/checks.h"
50 #include "rtc_base/fake_clock.h"
51 #include "rtc_base/random.h"
52 #include "test/gtest.h"
53 #include "test/testsupport/file_utils.h"
54 
55 namespace webrtc {
56 
57 namespace {
58 
59 struct EventCounts {
60   size_t audio_send_streams = 0;
61   size_t audio_recv_streams = 0;
62   size_t video_send_streams = 0;
63   size_t video_recv_streams = 0;
64   size_t alr_states = 0;
65   size_t route_changes = 0;
66   size_t audio_playouts = 0;
67   size_t ana_configs = 0;
68   size_t bwe_loss_events = 0;
69   size_t bwe_delay_events = 0;
70   size_t dtls_transport_states = 0;
71   size_t dtls_writable_states = 0;
72   size_t probe_creations = 0;
73   size_t probe_successes = 0;
74   size_t probe_failures = 0;
75   size_t ice_configs = 0;
76   size_t ice_events = 0;
77   size_t incoming_rtp_packets = 0;
78   size_t outgoing_rtp_packets = 0;
79   size_t incoming_rtcp_packets = 0;
80   size_t outgoing_rtcp_packets = 0;
81   size_t generic_packets_sent = 0;
82   size_t generic_packets_received = 0;
83   size_t generic_acks_received = 0;
84 
total_nonconfig_eventswebrtc::__anon6f4bb29c0111::EventCounts85   size_t total_nonconfig_events() const {
86     return alr_states + route_changes + audio_playouts + ana_configs +
87            bwe_loss_events + bwe_delay_events + dtls_transport_states +
88            dtls_writable_states + probe_creations + probe_successes +
89            probe_failures + ice_configs + ice_events + incoming_rtp_packets +
90            outgoing_rtp_packets + incoming_rtcp_packets +
91            outgoing_rtcp_packets + generic_packets_sent +
92            generic_packets_received + generic_acks_received;
93   }
94 
total_config_eventswebrtc::__anon6f4bb29c0111::EventCounts95   size_t total_config_events() const {
96     return audio_send_streams + audio_recv_streams + video_send_streams +
97            video_recv_streams;
98   }
99 
total_eventswebrtc::__anon6f4bb29c0111::EventCounts100   size_t total_events() const {
101     return total_nonconfig_events() + total_config_events();
102   }
103 };
104 
105 class RtcEventLogSession
106     : public ::testing::TestWithParam<
107           std::tuple<uint64_t, int64_t, RtcEventLog::EncodingType>> {
108  public:
RtcEventLogSession()109   RtcEventLogSession()
110       : seed_(std::get<0>(GetParam())),
111         prng_(seed_),
112         output_period_ms_(std::get<1>(GetParam())),
113         encoding_type_(std::get<2>(GetParam())),
114         gen_(seed_ * 880001UL),
115         verifier_(encoding_type_) {
116     clock_.SetTime(Timestamp::Micros(prng_.Rand<uint32_t>()));
117     // Find the name of the current test, in order to use it as a temporary
118     // filename.
119     // TODO(terelius): Use a general utility function to generate a temp file.
120     auto test_info = ::testing::UnitTest::GetInstance()->current_test_info();
121     std::string test_name =
122         std::string(test_info->test_case_name()) + "_" + test_info->name();
123     std::replace(test_name.begin(), test_name.end(), '/', '_');
124     temp_filename_ = test::OutputPath() + test_name;
125   }
126 
127   // Create and buffer the config events and |num_events_before_log_start|
128   // randomized non-config events. Then call StartLogging and finally create and
129   // write the remaining non-config events.
130   void WriteLog(EventCounts count, size_t num_events_before_log_start);
131   void ReadAndVerifyLog();
132 
IsNewFormat()133   bool IsNewFormat() {
134     return encoding_type_ == RtcEventLog::EncodingType::NewFormat;
135   }
136 
137  private:
138   void WriteAudioRecvConfigs(size_t audio_recv_streams, RtcEventLog* event_log);
139   void WriteAudioSendConfigs(size_t audio_send_streams, RtcEventLog* event_log);
140   void WriteVideoRecvConfigs(size_t video_recv_streams, RtcEventLog* event_log);
141   void WriteVideoSendConfigs(size_t video_send_streams, RtcEventLog* event_log);
142 
143   std::vector<std::pair<uint32_t, RtpHeaderExtensionMap>> incoming_extensions_;
144   std::vector<std::pair<uint32_t, RtpHeaderExtensionMap>> outgoing_extensions_;
145 
146   // Config events.
147   std::vector<std::unique_ptr<RtcEventAudioSendStreamConfig>>
148       audio_send_config_list_;
149   std::vector<std::unique_ptr<RtcEventAudioReceiveStreamConfig>>
150       audio_recv_config_list_;
151   std::vector<std::unique_ptr<RtcEventVideoSendStreamConfig>>
152       video_send_config_list_;
153   std::vector<std::unique_ptr<RtcEventVideoReceiveStreamConfig>>
154       video_recv_config_list_;
155 
156   // Regular events.
157   std::vector<std::unique_ptr<RtcEventAlrState>> alr_state_list_;
158   std::map<uint32_t, std::vector<std::unique_ptr<RtcEventAudioPlayout>>>
159       audio_playout_map_;  // Groups audio by SSRC.
160   std::vector<std::unique_ptr<RtcEventAudioNetworkAdaptation>>
161       ana_configs_list_;
162   std::vector<std::unique_ptr<RtcEventBweUpdateDelayBased>> bwe_delay_list_;
163   std::vector<std::unique_ptr<RtcEventBweUpdateLossBased>> bwe_loss_list_;
164   std::vector<std::unique_ptr<RtcEventDtlsTransportState>>
165       dtls_transport_state_list_;
166   std::vector<std::unique_ptr<RtcEventDtlsWritableState>>
167       dtls_writable_state_list_;
168   std::vector<std::unique_ptr<RtcEventGenericAckReceived>>
169       generic_acks_received_;
170   std::vector<std::unique_ptr<RtcEventGenericPacketReceived>>
171       generic_packets_received_;
172   std::vector<std::unique_ptr<RtcEventGenericPacketSent>> generic_packets_sent_;
173   std::vector<std::unique_ptr<RtcEventIceCandidatePair>> ice_event_list_;
174   std::vector<std::unique_ptr<RtcEventIceCandidatePairConfig>> ice_config_list_;
175   std::vector<std::unique_ptr<RtcEventProbeClusterCreated>>
176       probe_creation_list_;
177   std::vector<std::unique_ptr<RtcEventProbeResultFailure>> probe_failure_list_;
178   std::vector<std::unique_ptr<RtcEventProbeResultSuccess>> probe_success_list_;
179   std::vector<std::unique_ptr<RtcEventRouteChange>> route_change_list_;
180   std::vector<std::unique_ptr<RtcEventRemoteEstimate>> remote_estimate_list_;
181   std::vector<std::unique_ptr<RtcEventRtcpPacketIncoming>> incoming_rtcp_list_;
182   std::vector<std::unique_ptr<RtcEventRtcpPacketOutgoing>> outgoing_rtcp_list_;
183   std::map<uint32_t, std::vector<std::unique_ptr<RtcEventRtpPacketIncoming>>>
184       incoming_rtp_map_;  // Groups incoming RTP by SSRC.
185   std::map<uint32_t, std::vector<std::unique_ptr<RtcEventRtpPacketOutgoing>>>
186       outgoing_rtp_map_;  // Groups outgoing RTP by SSRC.
187 
188   int64_t start_time_us_;
189   int64_t utc_start_time_us_;
190   int64_t stop_time_us_;
191 
192   int64_t first_timestamp_ms_ = std::numeric_limits<int64_t>::max();
193   int64_t last_timestamp_ms_ = std::numeric_limits<int64_t>::min();
194 
195   const uint64_t seed_;
196   Random prng_;
197   const int64_t output_period_ms_;
198   const RtcEventLog::EncodingType encoding_type_;
199   test::EventGenerator gen_;
200   test::EventVerifier verifier_;
201   rtc::ScopedFakeClock clock_;
202   std::string temp_filename_;
203 };
204 
SsrcUsed(uint32_t ssrc,const std::vector<std::pair<uint32_t,RtpHeaderExtensionMap>> & streams)205 bool SsrcUsed(
206     uint32_t ssrc,
207     const std::vector<std::pair<uint32_t, RtpHeaderExtensionMap>>& streams) {
208   for (const auto& kv : streams) {
209     if (kv.first == ssrc)
210       return true;
211   }
212   return false;
213 }
214 
WriteAudioRecvConfigs(size_t audio_recv_streams,RtcEventLog * event_log)215 void RtcEventLogSession::WriteAudioRecvConfigs(size_t audio_recv_streams,
216                                                RtcEventLog* event_log) {
217   RTC_CHECK(event_log != nullptr);
218   uint32_t ssrc;
219   for (size_t i = 0; i < audio_recv_streams; i++) {
220     clock_.AdvanceTime(TimeDelta::Millis(prng_.Rand(20)));
221     do {
222       ssrc = prng_.Rand<uint32_t>();
223     } while (SsrcUsed(ssrc, incoming_extensions_));
224     RtpHeaderExtensionMap extensions = gen_.NewRtpHeaderExtensionMap();
225     incoming_extensions_.emplace_back(ssrc, extensions);
226     auto event = gen_.NewAudioReceiveStreamConfig(ssrc, extensions);
227     event_log->Log(event->Copy());
228     audio_recv_config_list_.push_back(std::move(event));
229   }
230 }
231 
WriteAudioSendConfigs(size_t audio_send_streams,RtcEventLog * event_log)232 void RtcEventLogSession::WriteAudioSendConfigs(size_t audio_send_streams,
233                                                RtcEventLog* event_log) {
234   RTC_CHECK(event_log != nullptr);
235   uint32_t ssrc;
236   for (size_t i = 0; i < audio_send_streams; i++) {
237     clock_.AdvanceTime(TimeDelta::Millis(prng_.Rand(20)));
238     do {
239       ssrc = prng_.Rand<uint32_t>();
240     } while (SsrcUsed(ssrc, outgoing_extensions_));
241     RtpHeaderExtensionMap extensions = gen_.NewRtpHeaderExtensionMap();
242     outgoing_extensions_.emplace_back(ssrc, extensions);
243     auto event = gen_.NewAudioSendStreamConfig(ssrc, extensions);
244     event_log->Log(event->Copy());
245     audio_send_config_list_.push_back(std::move(event));
246   }
247 }
248 
WriteVideoRecvConfigs(size_t video_recv_streams,RtcEventLog * event_log)249 void RtcEventLogSession::WriteVideoRecvConfigs(size_t video_recv_streams,
250                                                RtcEventLog* event_log) {
251   RTC_CHECK(event_log != nullptr);
252   RTC_CHECK_GE(video_recv_streams, 1);
253 
254   // Force least one stream to use all header extensions, to ensure
255   // (statistically) that every extension is tested in packet creation.
256   RtpHeaderExtensionMap all_extensions =
257       ParsedRtcEventLog::GetDefaultHeaderExtensionMap();
258 
259   clock_.AdvanceTime(TimeDelta::Millis(prng_.Rand(20)));
260   uint32_t ssrc = prng_.Rand<uint32_t>();
261   incoming_extensions_.emplace_back(ssrc, all_extensions);
262   auto event = gen_.NewVideoReceiveStreamConfig(ssrc, all_extensions);
263   event_log->Log(event->Copy());
264   video_recv_config_list_.push_back(std::move(event));
265   for (size_t i = 1; i < video_recv_streams; i++) {
266     clock_.AdvanceTime(TimeDelta::Millis(prng_.Rand(20)));
267     do {
268       ssrc = prng_.Rand<uint32_t>();
269     } while (SsrcUsed(ssrc, incoming_extensions_));
270     RtpHeaderExtensionMap extensions = gen_.NewRtpHeaderExtensionMap();
271     incoming_extensions_.emplace_back(ssrc, extensions);
272     auto event = gen_.NewVideoReceiveStreamConfig(ssrc, extensions);
273     event_log->Log(event->Copy());
274     video_recv_config_list_.push_back(std::move(event));
275   }
276 }
277 
WriteVideoSendConfigs(size_t video_send_streams,RtcEventLog * event_log)278 void RtcEventLogSession::WriteVideoSendConfigs(size_t video_send_streams,
279                                                RtcEventLog* event_log) {
280   RTC_CHECK(event_log != nullptr);
281   RTC_CHECK_GE(video_send_streams, 1);
282 
283   // Force least one stream to use all header extensions, to ensure
284   // (statistically) that every extension is tested in packet creation.
285   RtpHeaderExtensionMap all_extensions =
286       ParsedRtcEventLog::GetDefaultHeaderExtensionMap();
287 
288   clock_.AdvanceTime(TimeDelta::Millis(prng_.Rand(20)));
289   uint32_t ssrc = prng_.Rand<uint32_t>();
290   outgoing_extensions_.emplace_back(ssrc, all_extensions);
291   auto event = gen_.NewVideoSendStreamConfig(ssrc, all_extensions);
292   event_log->Log(event->Copy());
293   video_send_config_list_.push_back(std::move(event));
294   for (size_t i = 1; i < video_send_streams; i++) {
295     clock_.AdvanceTime(TimeDelta::Millis(prng_.Rand(20)));
296     do {
297       ssrc = prng_.Rand<uint32_t>();
298     } while (SsrcUsed(ssrc, outgoing_extensions_));
299     RtpHeaderExtensionMap extensions = gen_.NewRtpHeaderExtensionMap();
300     outgoing_extensions_.emplace_back(ssrc, extensions);
301     auto event = gen_.NewVideoSendStreamConfig(ssrc, extensions);
302     event_log->Log(event->Copy());
303     video_send_config_list_.push_back(std::move(event));
304   }
305 }
306 
WriteLog(EventCounts count,size_t num_events_before_start)307 void RtcEventLogSession::WriteLog(EventCounts count,
308                                   size_t num_events_before_start) {
309   // TODO(terelius): Allow test to run with either a real or a fake clock_.
310   // Maybe always use the ScopedFakeClock, but conditionally SleepMs()?
311 
312   auto task_queue_factory = CreateDefaultTaskQueueFactory();
313   RtcEventLogFactory rtc_event_log_factory(task_queue_factory.get());
314   // The log file will be flushed to disk when the event_log goes out of scope.
315   std::unique_ptr<RtcEventLog> event_log =
316       rtc_event_log_factory.CreateRtcEventLog(encoding_type_);
317 
318   // We can't send or receive packets without configured streams.
319   RTC_CHECK_GE(count.video_recv_streams, 1);
320   RTC_CHECK_GE(count.video_send_streams, 1);
321 
322   WriteAudioRecvConfigs(count.audio_recv_streams, event_log.get());
323   WriteAudioSendConfigs(count.audio_send_streams, event_log.get());
324   WriteVideoRecvConfigs(count.video_recv_streams, event_log.get());
325   WriteVideoSendConfigs(count.video_send_streams, event_log.get());
326 
327   size_t remaining_events = count.total_nonconfig_events();
328   ASSERT_LE(num_events_before_start, remaining_events);
329   size_t remaining_events_at_start = remaining_events - num_events_before_start;
330   for (; remaining_events > 0; remaining_events--) {
331     if (remaining_events == remaining_events_at_start) {
332       clock_.AdvanceTime(TimeDelta::Millis(prng_.Rand(20)));
333       event_log->StartLogging(
334           std::make_unique<RtcEventLogOutputFile>(temp_filename_, 10000000),
335           output_period_ms_);
336       start_time_us_ = rtc::TimeMicros();
337       utc_start_time_us_ = rtc::TimeUTCMicros();
338     }
339 
340     clock_.AdvanceTime(TimeDelta::Millis(prng_.Rand(20)));
341     size_t selection = prng_.Rand(remaining_events - 1);
342     first_timestamp_ms_ = std::min(first_timestamp_ms_, rtc::TimeMillis());
343     last_timestamp_ms_ = std::max(last_timestamp_ms_, rtc::TimeMillis());
344 
345     if (selection < count.alr_states) {
346       auto event = gen_.NewAlrState();
347       event_log->Log(event->Copy());
348       alr_state_list_.push_back(std::move(event));
349       count.alr_states--;
350       continue;
351     }
352     selection -= count.alr_states;
353 
354     if (selection < count.route_changes) {
355       auto event = gen_.NewRouteChange();
356       event_log->Log(event->Copy());
357       route_change_list_.push_back(std::move(event));
358       count.route_changes--;
359       continue;
360     }
361     selection -= count.route_changes;
362 
363     if (selection < count.audio_playouts) {
364       size_t stream = prng_.Rand(incoming_extensions_.size() - 1);
365       // This might be a video SSRC, but the parser does not use the config.
366       uint32_t ssrc = incoming_extensions_[stream].first;
367       auto event = gen_.NewAudioPlayout(ssrc);
368       event_log->Log(event->Copy());
369       audio_playout_map_[ssrc].push_back(std::move(event));
370       count.audio_playouts--;
371       continue;
372     }
373     selection -= count.audio_playouts;
374 
375     if (selection < count.ana_configs) {
376       auto event = gen_.NewAudioNetworkAdaptation();
377       event_log->Log(event->Copy());
378       ana_configs_list_.push_back(std::move(event));
379       count.ana_configs--;
380       continue;
381     }
382     selection -= count.ana_configs;
383 
384     if (selection < count.bwe_loss_events) {
385       auto event = gen_.NewBweUpdateLossBased();
386       event_log->Log(event->Copy());
387       bwe_loss_list_.push_back(std::move(event));
388       count.bwe_loss_events--;
389       continue;
390     }
391     selection -= count.bwe_loss_events;
392 
393     if (selection < count.bwe_delay_events) {
394       auto event = gen_.NewBweUpdateDelayBased();
395       event_log->Log(event->Copy());
396       bwe_delay_list_.push_back(std::move(event));
397       count.bwe_delay_events--;
398       continue;
399     }
400     selection -= count.bwe_delay_events;
401 
402     if (selection < count.probe_creations) {
403       auto event = gen_.NewProbeClusterCreated();
404       event_log->Log(event->Copy());
405       probe_creation_list_.push_back(std::move(event));
406       count.probe_creations--;
407       continue;
408     }
409     selection -= count.probe_creations;
410 
411     if (selection < count.probe_successes) {
412       auto event = gen_.NewProbeResultSuccess();
413       event_log->Log(event->Copy());
414       probe_success_list_.push_back(std::move(event));
415       count.probe_successes--;
416       continue;
417     }
418     selection -= count.probe_successes;
419 
420     if (selection < count.probe_failures) {
421       auto event = gen_.NewProbeResultFailure();
422       event_log->Log(event->Copy());
423       probe_failure_list_.push_back(std::move(event));
424       count.probe_failures--;
425       continue;
426     }
427     selection -= count.probe_failures;
428 
429     if (selection < count.dtls_transport_states) {
430       auto event = gen_.NewDtlsTransportState();
431       event_log->Log(event->Copy());
432       dtls_transport_state_list_.push_back(std::move(event));
433       count.dtls_transport_states--;
434       continue;
435     }
436     selection -= count.dtls_transport_states;
437 
438     if (selection < count.dtls_writable_states) {
439       auto event = gen_.NewDtlsWritableState();
440       event_log->Log(event->Copy());
441       dtls_writable_state_list_.push_back(std::move(event));
442       count.dtls_writable_states--;
443       continue;
444     }
445     selection -= count.dtls_writable_states;
446 
447     if (selection < count.ice_configs) {
448       auto event = gen_.NewIceCandidatePairConfig();
449       event_log->Log(event->Copy());
450       ice_config_list_.push_back(std::move(event));
451       count.ice_configs--;
452       continue;
453     }
454     selection -= count.ice_configs;
455 
456     if (selection < count.ice_events) {
457       auto event = gen_.NewIceCandidatePair();
458       event_log->Log(event->Copy());
459       ice_event_list_.push_back(std::move(event));
460       count.ice_events--;
461       continue;
462     }
463     selection -= count.ice_events;
464 
465     if (selection < count.incoming_rtp_packets) {
466       size_t stream = prng_.Rand(incoming_extensions_.size() - 1);
467       uint32_t ssrc = incoming_extensions_[stream].first;
468       auto event =
469           gen_.NewRtpPacketIncoming(ssrc, incoming_extensions_[stream].second);
470       event_log->Log(event->Copy());
471       incoming_rtp_map_[ssrc].push_back(std::move(event));
472       count.incoming_rtp_packets--;
473       continue;
474     }
475     selection -= count.incoming_rtp_packets;
476 
477     if (selection < count.outgoing_rtp_packets) {
478       size_t stream = prng_.Rand(outgoing_extensions_.size() - 1);
479       uint32_t ssrc = outgoing_extensions_[stream].first;
480       auto event =
481           gen_.NewRtpPacketOutgoing(ssrc, outgoing_extensions_[stream].second);
482       event_log->Log(event->Copy());
483       outgoing_rtp_map_[ssrc].push_back(std::move(event));
484       count.outgoing_rtp_packets--;
485       continue;
486     }
487     selection -= count.outgoing_rtp_packets;
488 
489     if (selection < count.incoming_rtcp_packets) {
490       auto event = gen_.NewRtcpPacketIncoming();
491       event_log->Log(event->Copy());
492       incoming_rtcp_list_.push_back(std::move(event));
493       count.incoming_rtcp_packets--;
494       continue;
495     }
496     selection -= count.incoming_rtcp_packets;
497 
498     if (selection < count.outgoing_rtcp_packets) {
499       auto event = gen_.NewRtcpPacketOutgoing();
500       event_log->Log(event->Copy());
501       outgoing_rtcp_list_.push_back(std::move(event));
502       count.outgoing_rtcp_packets--;
503       continue;
504     }
505     selection -= count.outgoing_rtcp_packets;
506 
507     if (selection < count.generic_packets_sent) {
508       auto event = gen_.NewGenericPacketSent();
509       generic_packets_sent_.push_back(event->Copy());
510       event_log->Log(std::move(event));
511       count.generic_packets_sent--;
512       continue;
513     }
514     selection -= count.generic_packets_sent;
515 
516     if (selection < count.generic_packets_received) {
517       auto event = gen_.NewGenericPacketReceived();
518       generic_packets_received_.push_back(event->Copy());
519       event_log->Log(std::move(event));
520       count.generic_packets_received--;
521       continue;
522     }
523     selection -= count.generic_packets_received;
524 
525     if (selection < count.generic_acks_received) {
526       auto event = gen_.NewGenericAckReceived();
527       generic_acks_received_.push_back(event->Copy());
528       event_log->Log(std::move(event));
529       count.generic_acks_received--;
530       continue;
531     }
532     selection -= count.generic_acks_received;
533 
534     RTC_NOTREACHED();
535   }
536 
537   event_log->StopLogging();
538   stop_time_us_ = rtc::TimeMicros();
539 
540   ASSERT_EQ(count.total_nonconfig_events(), static_cast<size_t>(0));
541 }
542 
543 // Read the file and verify that what we read back from the event log is the
544 // same as what we wrote down.
ReadAndVerifyLog()545 void RtcEventLogSession::ReadAndVerifyLog() {
546   // Read the generated file from disk.
547   ParsedRtcEventLog parsed_log;
548   ASSERT_TRUE(parsed_log.ParseFile(temp_filename_).ok());
549 
550   // Start and stop events.
551   auto& parsed_start_log_events = parsed_log.start_log_events();
552   ASSERT_EQ(parsed_start_log_events.size(), static_cast<size_t>(1));
553   verifier_.VerifyLoggedStartEvent(start_time_us_, utc_start_time_us_,
554                                    parsed_start_log_events[0]);
555 
556   auto& parsed_stop_log_events = parsed_log.stop_log_events();
557   ASSERT_EQ(parsed_stop_log_events.size(), static_cast<size_t>(1));
558   verifier_.VerifyLoggedStopEvent(stop_time_us_, parsed_stop_log_events[0]);
559 
560   auto& parsed_alr_state_events = parsed_log.alr_state_events();
561   ASSERT_EQ(parsed_alr_state_events.size(), alr_state_list_.size());
562   for (size_t i = 0; i < parsed_alr_state_events.size(); i++) {
563     verifier_.VerifyLoggedAlrStateEvent(*alr_state_list_[i],
564                                         parsed_alr_state_events[i]);
565   }
566   auto& parsed_route_change_events = parsed_log.route_change_events();
567   ASSERT_EQ(parsed_route_change_events.size(), route_change_list_.size());
568   for (size_t i = 0; i < parsed_route_change_events.size(); i++) {
569     verifier_.VerifyLoggedRouteChangeEvent(*route_change_list_[i],
570                                            parsed_route_change_events[i]);
571   }
572 
573   const auto& parsed_audio_playout_map = parsed_log.audio_playout_events();
574   ASSERT_EQ(parsed_audio_playout_map.size(), audio_playout_map_.size());
575   for (const auto& kv : parsed_audio_playout_map) {
576     uint32_t ssrc = kv.first;
577     const auto& parsed_audio_playout_stream = kv.second;
578     const auto& audio_playout_stream = audio_playout_map_[ssrc];
579     ASSERT_EQ(parsed_audio_playout_stream.size(), audio_playout_stream.size());
580     for (size_t i = 0; i < parsed_audio_playout_map.size(); i++) {
581       verifier_.VerifyLoggedAudioPlayoutEvent(*audio_playout_stream[i],
582                                               parsed_audio_playout_stream[i]);
583     }
584   }
585 
586   auto& parsed_audio_network_adaptation_events =
587       parsed_log.audio_network_adaptation_events();
588   ASSERT_EQ(parsed_audio_network_adaptation_events.size(),
589             ana_configs_list_.size());
590   for (size_t i = 0; i < parsed_audio_network_adaptation_events.size(); i++) {
591     verifier_.VerifyLoggedAudioNetworkAdaptationEvent(
592         *ana_configs_list_[i], parsed_audio_network_adaptation_events[i]);
593   }
594 
595   auto& parsed_bwe_delay_updates = parsed_log.bwe_delay_updates();
596   ASSERT_EQ(parsed_bwe_delay_updates.size(), bwe_delay_list_.size());
597   for (size_t i = 0; i < parsed_bwe_delay_updates.size(); i++) {
598     verifier_.VerifyLoggedBweDelayBasedUpdate(*bwe_delay_list_[i],
599                                               parsed_bwe_delay_updates[i]);
600   }
601 
602   auto& parsed_bwe_loss_updates = parsed_log.bwe_loss_updates();
603   ASSERT_EQ(parsed_bwe_loss_updates.size(), bwe_loss_list_.size());
604   for (size_t i = 0; i < parsed_bwe_loss_updates.size(); i++) {
605     verifier_.VerifyLoggedBweLossBasedUpdate(*bwe_loss_list_[i],
606                                              parsed_bwe_loss_updates[i]);
607   }
608 
609   auto& parsed_bwe_probe_cluster_created_events =
610       parsed_log.bwe_probe_cluster_created_events();
611   ASSERT_EQ(parsed_bwe_probe_cluster_created_events.size(),
612             probe_creation_list_.size());
613   for (size_t i = 0; i < parsed_bwe_probe_cluster_created_events.size(); i++) {
614     verifier_.VerifyLoggedBweProbeClusterCreatedEvent(
615         *probe_creation_list_[i], parsed_bwe_probe_cluster_created_events[i]);
616   }
617 
618   auto& parsed_bwe_probe_failure_events = parsed_log.bwe_probe_failure_events();
619   ASSERT_EQ(parsed_bwe_probe_failure_events.size(), probe_failure_list_.size());
620   for (size_t i = 0; i < parsed_bwe_probe_failure_events.size(); i++) {
621     verifier_.VerifyLoggedBweProbeFailureEvent(
622         *probe_failure_list_[i], parsed_bwe_probe_failure_events[i]);
623   }
624 
625   auto& parsed_bwe_probe_success_events = parsed_log.bwe_probe_success_events();
626   ASSERT_EQ(parsed_bwe_probe_success_events.size(), probe_success_list_.size());
627   for (size_t i = 0; i < parsed_bwe_probe_success_events.size(); i++) {
628     verifier_.VerifyLoggedBweProbeSuccessEvent(
629         *probe_success_list_[i], parsed_bwe_probe_success_events[i]);
630   }
631 
632   auto& parsed_ice_candidate_pair_configs =
633       parsed_log.ice_candidate_pair_configs();
634   ASSERT_EQ(parsed_ice_candidate_pair_configs.size(), ice_config_list_.size());
635   for (size_t i = 0; i < parsed_ice_candidate_pair_configs.size(); i++) {
636     verifier_.VerifyLoggedIceCandidatePairConfig(
637         *ice_config_list_[i], parsed_ice_candidate_pair_configs[i]);
638   }
639 
640   auto& parsed_ice_candidate_pair_events =
641       parsed_log.ice_candidate_pair_events();
642   ASSERT_EQ(parsed_ice_candidate_pair_events.size(),
643             parsed_ice_candidate_pair_events.size());
644   for (size_t i = 0; i < parsed_ice_candidate_pair_events.size(); i++) {
645     verifier_.VerifyLoggedIceCandidatePairEvent(
646         *ice_event_list_[i], parsed_ice_candidate_pair_events[i]);
647   }
648 
649   auto& parsed_incoming_rtp_packets_by_ssrc =
650       parsed_log.incoming_rtp_packets_by_ssrc();
651   ASSERT_EQ(parsed_incoming_rtp_packets_by_ssrc.size(),
652             incoming_rtp_map_.size());
653   for (const auto& kv : parsed_incoming_rtp_packets_by_ssrc) {
654     uint32_t ssrc = kv.ssrc;
655     const auto& parsed_rtp_stream = kv.incoming_packets;
656     const auto& rtp_stream = incoming_rtp_map_[ssrc];
657     ASSERT_EQ(parsed_rtp_stream.size(), rtp_stream.size());
658     for (size_t i = 0; i < parsed_rtp_stream.size(); i++) {
659       verifier_.VerifyLoggedRtpPacketIncoming(*rtp_stream[i],
660                                               parsed_rtp_stream[i]);
661     }
662   }
663 
664   auto& parsed_outgoing_rtp_packets_by_ssrc =
665       parsed_log.outgoing_rtp_packets_by_ssrc();
666   ASSERT_EQ(parsed_outgoing_rtp_packets_by_ssrc.size(),
667             outgoing_rtp_map_.size());
668   for (const auto& kv : parsed_outgoing_rtp_packets_by_ssrc) {
669     uint32_t ssrc = kv.ssrc;
670     const auto& parsed_rtp_stream = kv.outgoing_packets;
671     const auto& rtp_stream = outgoing_rtp_map_[ssrc];
672     ASSERT_EQ(parsed_rtp_stream.size(), rtp_stream.size());
673     for (size_t i = 0; i < parsed_rtp_stream.size(); i++) {
674       verifier_.VerifyLoggedRtpPacketOutgoing(*rtp_stream[i],
675                                               parsed_rtp_stream[i]);
676     }
677   }
678 
679   auto& parsed_incoming_rtcp_packets = parsed_log.incoming_rtcp_packets();
680   ASSERT_EQ(parsed_incoming_rtcp_packets.size(), incoming_rtcp_list_.size());
681   for (size_t i = 0; i < parsed_incoming_rtcp_packets.size(); i++) {
682     verifier_.VerifyLoggedRtcpPacketIncoming(*incoming_rtcp_list_[i],
683                                              parsed_incoming_rtcp_packets[i]);
684   }
685 
686   auto& parsed_outgoing_rtcp_packets = parsed_log.outgoing_rtcp_packets();
687   ASSERT_EQ(parsed_outgoing_rtcp_packets.size(), outgoing_rtcp_list_.size());
688   for (size_t i = 0; i < parsed_outgoing_rtcp_packets.size(); i++) {
689     verifier_.VerifyLoggedRtcpPacketOutgoing(*outgoing_rtcp_list_[i],
690                                              parsed_outgoing_rtcp_packets[i]);
691   }
692   auto& parsed_audio_recv_configs = parsed_log.audio_recv_configs();
693   ASSERT_EQ(parsed_audio_recv_configs.size(), audio_recv_config_list_.size());
694   for (size_t i = 0; i < parsed_audio_recv_configs.size(); i++) {
695     verifier_.VerifyLoggedAudioRecvConfig(*audio_recv_config_list_[i],
696                                           parsed_audio_recv_configs[i]);
697   }
698   auto& parsed_audio_send_configs = parsed_log.audio_send_configs();
699   ASSERT_EQ(parsed_audio_send_configs.size(), audio_send_config_list_.size());
700   for (size_t i = 0; i < parsed_audio_send_configs.size(); i++) {
701     verifier_.VerifyLoggedAudioSendConfig(*audio_send_config_list_[i],
702                                           parsed_audio_send_configs[i]);
703   }
704   auto& parsed_video_recv_configs = parsed_log.video_recv_configs();
705   ASSERT_EQ(parsed_video_recv_configs.size(), video_recv_config_list_.size());
706   for (size_t i = 0; i < parsed_video_recv_configs.size(); i++) {
707     verifier_.VerifyLoggedVideoRecvConfig(*video_recv_config_list_[i],
708                                           parsed_video_recv_configs[i]);
709   }
710   auto& parsed_video_send_configs = parsed_log.video_send_configs();
711   ASSERT_EQ(parsed_video_send_configs.size(), video_send_config_list_.size());
712   for (size_t i = 0; i < parsed_video_send_configs.size(); i++) {
713     verifier_.VerifyLoggedVideoSendConfig(*video_send_config_list_[i],
714                                           parsed_video_send_configs[i]);
715   }
716 
717   auto& parsed_generic_packets_received = parsed_log.generic_packets_received();
718   ASSERT_EQ(parsed_generic_packets_received.size(),
719             generic_packets_received_.size());
720   for (size_t i = 0; i < parsed_generic_packets_received.size(); i++) {
721     verifier_.VerifyLoggedGenericPacketReceived(
722         *generic_packets_received_[i], parsed_generic_packets_received[i]);
723   }
724 
725   auto& parsed_generic_packets_sent = parsed_log.generic_packets_sent();
726   ASSERT_EQ(parsed_generic_packets_sent.size(), generic_packets_sent_.size());
727   for (size_t i = 0; i < parsed_generic_packets_sent.size(); i++) {
728     verifier_.VerifyLoggedGenericPacketSent(*generic_packets_sent_[i],
729                                             parsed_generic_packets_sent[i]);
730   }
731 
732   auto& parsed_generic_acks_received = parsed_log.generic_acks_received();
733   ASSERT_EQ(parsed_generic_acks_received.size(), generic_acks_received_.size());
734   for (size_t i = 0; i < parsed_generic_acks_received.size(); i++) {
735     verifier_.VerifyLoggedGenericAckReceived(*generic_acks_received_[i],
736                                              parsed_generic_acks_received[i]);
737   }
738 
739   EXPECT_EQ(first_timestamp_ms_, parsed_log.first_timestamp() / 1000);
740   EXPECT_EQ(last_timestamp_ms_, parsed_log.last_timestamp() / 1000);
741 
742   EXPECT_EQ(parsed_log.first_log_segment().start_time_ms(),
743             std::min(start_time_us_ / 1000, first_timestamp_ms_));
744   EXPECT_EQ(parsed_log.first_log_segment().stop_time_ms(),
745             stop_time_us_ / 1000);
746 
747   // Clean up temporary file - can be pretty slow.
748   remove(temp_filename_.c_str());
749 }
750 
751 }  // namespace
752 
TEST_P(RtcEventLogSession,StartLoggingFromBeginning)753 TEST_P(RtcEventLogSession, StartLoggingFromBeginning) {
754   EventCounts count;
755   count.audio_send_streams = 2;
756   count.audio_recv_streams = 2;
757   count.video_send_streams = 3;
758   count.video_recv_streams = 4;
759   count.alr_states = 4;
760   count.audio_playouts = 100;
761   count.ana_configs = 3;
762   count.bwe_loss_events = 20;
763   count.bwe_delay_events = 20;
764   count.dtls_transport_states = 4;
765   count.dtls_writable_states = 2;
766   count.probe_creations = 4;
767   count.probe_successes = 2;
768   count.probe_failures = 2;
769   count.ice_configs = 3;
770   count.ice_events = 10;
771   count.incoming_rtp_packets = 100;
772   count.outgoing_rtp_packets = 100;
773   count.incoming_rtcp_packets = 20;
774   count.outgoing_rtcp_packets = 20;
775   if (IsNewFormat()) {
776     count.route_changes = 4;
777     count.generic_packets_sent = 100;
778     count.generic_packets_received = 100;
779     count.generic_acks_received = 20;
780   }
781 
782   WriteLog(count, 0);
783   ReadAndVerifyLog();
784 }
785 
TEST_P(RtcEventLogSession,StartLoggingInTheMiddle)786 TEST_P(RtcEventLogSession, StartLoggingInTheMiddle) {
787   EventCounts count;
788   count.audio_send_streams = 3;
789   count.audio_recv_streams = 4;
790   count.video_send_streams = 5;
791   count.video_recv_streams = 6;
792   count.alr_states = 10;
793   count.audio_playouts = 500;
794   count.ana_configs = 10;
795   count.bwe_loss_events = 50;
796   count.bwe_delay_events = 50;
797   count.dtls_transport_states = 4;
798   count.dtls_writable_states = 5;
799   count.probe_creations = 10;
800   count.probe_successes = 5;
801   count.probe_failures = 5;
802   count.ice_configs = 10;
803   count.ice_events = 20;
804   count.incoming_rtp_packets = 500;
805   count.outgoing_rtp_packets = 500;
806   count.incoming_rtcp_packets = 50;
807   count.outgoing_rtcp_packets = 50;
808   if (IsNewFormat()) {
809     count.route_changes = 10;
810     count.generic_packets_sent = 500;
811     count.generic_packets_received = 500;
812     count.generic_acks_received = 50;
813   }
814 
815   WriteLog(count, 500);
816   ReadAndVerifyLog();
817 }
818 
819 INSTANTIATE_TEST_SUITE_P(
820     RtcEventLogTest,
821     RtcEventLogSession,
822     ::testing::Combine(
823         ::testing::Values(1234567, 7654321),
824         ::testing::Values(RtcEventLog::kImmediateOutput, 1, 5),
825         ::testing::Values(RtcEventLog::EncodingType::Legacy,
826                           RtcEventLog::EncodingType::NewFormat)));
827 
828 class RtcEventLogCircularBufferTest
829     : public ::testing::TestWithParam<RtcEventLog::EncodingType> {
830  public:
RtcEventLogCircularBufferTest()831   RtcEventLogCircularBufferTest()
832       : encoding_type_(GetParam()), verifier_(encoding_type_) {}
833   const RtcEventLog::EncodingType encoding_type_;
834   const test::EventVerifier verifier_;
835 };
836 
TEST_P(RtcEventLogCircularBufferTest,KeepsMostRecentEvents)837 TEST_P(RtcEventLogCircularBufferTest, KeepsMostRecentEvents) {
838   // TODO(terelius): Maybe make a separate RtcEventLogImplTest that can access
839   // the size of the cyclic buffer?
840   constexpr size_t kNumEvents = 20000;
841   constexpr int64_t kStartTimeSeconds = 1;
842   constexpr int32_t kStartBitrate = 1000000;
843 
844   auto test_info = ::testing::UnitTest::GetInstance()->current_test_info();
845   std::string test_name =
846       std::string(test_info->test_case_name()) + "_" + test_info->name();
847   std::replace(test_name.begin(), test_name.end(), '/', '_');
848   const std::string temp_filename = test::OutputPath() + test_name;
849 
850   std::unique_ptr<rtc::ScopedFakeClock> fake_clock =
851       std::make_unique<rtc::ScopedFakeClock>();
852   fake_clock->SetTime(Timestamp::Seconds(kStartTimeSeconds));
853 
854   auto task_queue_factory = CreateDefaultTaskQueueFactory();
855   RtcEventLogFactory rtc_event_log_factory(task_queue_factory.get());
856   // When log_dumper goes out of scope, it causes the log file to be flushed
857   // to disk.
858   std::unique_ptr<RtcEventLog> log_dumper =
859       rtc_event_log_factory.CreateRtcEventLog(encoding_type_);
860 
861   for (size_t i = 0; i < kNumEvents; i++) {
862     // The purpose of the test is to verify that the log can handle
863     // more events than what fits in the internal circular buffer. The exact
864     // type of events does not matter so we chose ProbeSuccess events for
865     // simplicity.
866     // We base the various values on the index. We use this for some basic
867     // consistency checks when we read back.
868     log_dumper->Log(std::make_unique<RtcEventProbeResultSuccess>(
869         i, kStartBitrate + i * 1000));
870     fake_clock->AdvanceTime(TimeDelta::Millis(10));
871   }
872   int64_t start_time_us = rtc::TimeMicros();
873   int64_t utc_start_time_us = rtc::TimeUTCMicros();
874   log_dumper->StartLogging(
875       std::make_unique<RtcEventLogOutputFile>(temp_filename, 10000000),
876       RtcEventLog::kImmediateOutput);
877   fake_clock->AdvanceTime(TimeDelta::Millis(10));
878   int64_t stop_time_us = rtc::TimeMicros();
879   log_dumper->StopLogging();
880 
881   // Read the generated file from disk.
882   ParsedRtcEventLog parsed_log;
883   ASSERT_TRUE(parsed_log.ParseFile(temp_filename).ok());
884 
885   const auto& start_log_events = parsed_log.start_log_events();
886   ASSERT_EQ(start_log_events.size(), 1u);
887   verifier_.VerifyLoggedStartEvent(start_time_us, utc_start_time_us,
888                                    start_log_events[0]);
889 
890   const auto& stop_log_events = parsed_log.stop_log_events();
891   ASSERT_EQ(stop_log_events.size(), 1u);
892   verifier_.VerifyLoggedStopEvent(stop_time_us, stop_log_events[0]);
893 
894   const auto& probe_success_events = parsed_log.bwe_probe_success_events();
895   // If the following fails, it probably means that kNumEvents isn't larger
896   // than the size of the cyclic buffer in the event log. Try increasing
897   // kNumEvents.
898   EXPECT_LT(probe_success_events.size(), kNumEvents);
899 
900   ASSERT_GT(probe_success_events.size(), 1u);
901   int64_t first_timestamp_us = probe_success_events[0].timestamp_us;
902   uint32_t first_id = probe_success_events[0].id;
903   int32_t first_bitrate_bps = probe_success_events[0].bitrate_bps;
904   // We want to reset the time to what we used when generating the events, but
905   // the fake clock implementation DCHECKS if time moves backwards. We therefore
906   // recreate the clock. However we must ensure that the old fake_clock is
907   // destroyed before the new one is created, so we have to reset() first.
908   fake_clock.reset();
909   fake_clock = std::make_unique<rtc::ScopedFakeClock>();
910   fake_clock->SetTime(Timestamp::Micros(first_timestamp_us));
911   for (size_t i = 1; i < probe_success_events.size(); i++) {
912     fake_clock->AdvanceTime(TimeDelta::Millis(10));
913     verifier_.VerifyLoggedBweProbeSuccessEvent(
914         RtcEventProbeResultSuccess(first_id + i, first_bitrate_bps + i * 1000),
915         probe_success_events[i]);
916   }
917 }
918 
919 INSTANTIATE_TEST_SUITE_P(
920     RtcEventLogTest,
921     RtcEventLogCircularBufferTest,
922     ::testing::Values(RtcEventLog::EncodingType::Legacy,
923                       RtcEventLog::EncodingType::NewFormat));
924 
925 // TODO(terelius): Verify parser behavior if the timestamps are not
926 // monotonically increasing in the log.
927 
928 }  // namespace webrtc
929