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