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