blob: eb4340d0b9f520e11a118fcb0ee98c0638e26def [file] [log] [blame]
Bjorn Terelius36411852015-07-30 12:45:18 +02001/*
2 * Copyright (c) 2015 The WebRTC project authors. All Rights Reserved.
3 *
4 * Use of this source code is governed by a BSD-style license
5 * that can be found in the LICENSE file in the root of the source
6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree.
9 */
10
11#include "webrtc/video/rtc_event_log.h"
12
13#include <deque>
14
15#include "webrtc/base/checks.h"
16#include "webrtc/base/criticalsection.h"
17#include "webrtc/base/thread_annotations.h"
18#include "webrtc/call.h"
terelius2f9fd5d2015-09-04 03:39:42 -070019#include "webrtc/modules/rtp_rtcp/source/byte_io.h"
Bjorn Terelius36411852015-07-30 12:45:18 +020020#include "webrtc/system_wrappers/interface/clock.h"
21#include "webrtc/system_wrappers/interface/file_wrapper.h"
22
23#ifdef ENABLE_RTC_EVENT_LOG
24// Files generated at build-time by the protobuf compiler.
25#ifdef WEBRTC_ANDROID_PLATFORM_BUILD
26#include "external/webrtc/webrtc/video/rtc_event_log.pb.h"
27#else
28#include "webrtc/video/rtc_event_log.pb.h"
29#endif
30#endif
31
32namespace webrtc {
33
34#ifndef ENABLE_RTC_EVENT_LOG
35
36// No-op implementation if flag is not set.
37class RtcEventLogImpl final : public RtcEventLog {
38 public:
39 void StartLogging(const std::string& file_name, int duration_ms) override {}
40 void StopLogging(void) override {}
41 void LogVideoReceiveStreamConfig(
42 const VideoReceiveStream::Config& config) override {}
43 void LogVideoSendStreamConfig(
44 const VideoSendStream::Config& config) override {}
45 void LogRtpHeader(bool incoming,
46 MediaType media_type,
47 const uint8_t* header,
terelius2f9fd5d2015-09-04 03:39:42 -070048 size_t packet_length) override {}
Bjorn Terelius36411852015-07-30 12:45:18 +020049 void LogRtcpPacket(bool incoming,
50 MediaType media_type,
51 const uint8_t* packet,
52 size_t length) override {}
53 void LogDebugEvent(DebugEvent event_type) override {}
54};
55
56#else // ENABLE_RTC_EVENT_LOG is defined
57
58class RtcEventLogImpl final : public RtcEventLog {
59 public:
60 RtcEventLogImpl();
61
62 void StartLogging(const std::string& file_name, int duration_ms) override;
63 void StopLogging() override;
64 void LogVideoReceiveStreamConfig(
65 const VideoReceiveStream::Config& config) override;
66 void LogVideoSendStreamConfig(const VideoSendStream::Config& config) override;
67 void LogRtpHeader(bool incoming,
68 MediaType media_type,
69 const uint8_t* header,
terelius2f9fd5d2015-09-04 03:39:42 -070070 size_t packet_length) override;
Bjorn Terelius36411852015-07-30 12:45:18 +020071 void LogRtcpPacket(bool incoming,
72 MediaType media_type,
73 const uint8_t* packet,
74 size_t length) override;
75 void LogDebugEvent(DebugEvent event_type) override;
76
77 private:
78 // Stops logging and clears the stored data and buffers.
79 void StopLoggingLocked() EXCLUSIVE_LOCKS_REQUIRED(crit_);
80 // Adds a new event to the logfile if logging is active, or adds it to the
81 // list of recent log events otherwise.
82 void HandleEvent(rtclog::Event* event) EXCLUSIVE_LOCKS_REQUIRED(crit_);
83 // Writes the event to the file. Note that this will destroy the state of the
84 // input argument.
85 void StoreToFile(rtclog::Event* event) EXCLUSIVE_LOCKS_REQUIRED(crit_);
86 // Adds the event to the list of recent events, and removes any events that
87 // are too old and no longer fall in the time window.
88 void AddRecentEvent(const rtclog::Event& event)
89 EXCLUSIVE_LOCKS_REQUIRED(crit_);
90
91 // Amount of time in microseconds to record log events, before starting the
92 // actual log.
93 const int recent_log_duration_us = 10000000;
94
95 rtc::CriticalSection crit_;
96 rtc::scoped_ptr<FileWrapper> file_ GUARDED_BY(crit_);
97 rtclog::EventStream stream_ GUARDED_BY(crit_);
98 std::deque<rtclog::Event> recent_log_events_ GUARDED_BY(crit_);
99 bool currently_logging_ GUARDED_BY(crit_);
100 int64_t start_time_us_ GUARDED_BY(crit_);
101 int64_t duration_us_ GUARDED_BY(crit_);
102 const Clock* const clock_;
103};
104
105namespace {
106// The functions in this namespace convert enums from the runtime format
107// that the rest of the WebRtc project can use, to the corresponding
108// serialized enum which is defined by the protobuf.
109
110// Do not add default return values to the conversion functions in this
111// unnamed namespace. The intention is to make the compiler warn if anyone
112// adds unhandled new events/modes/etc.
113
114rtclog::DebugEvent_EventType ConvertDebugEvent(
115 RtcEventLog::DebugEvent event_type) {
116 switch (event_type) {
117 case RtcEventLog::DebugEvent::kLogStart:
118 return rtclog::DebugEvent::LOG_START;
119 case RtcEventLog::DebugEvent::kLogEnd:
120 return rtclog::DebugEvent::LOG_END;
121 case RtcEventLog::DebugEvent::kAudioPlayout:
122 return rtclog::DebugEvent::AUDIO_PLAYOUT;
123 }
124 RTC_NOTREACHED();
125 return rtclog::DebugEvent::UNKNOWN_EVENT;
126}
127
128rtclog::VideoReceiveConfig_RtcpMode ConvertRtcpMode(
129 newapi::RtcpMode rtcp_mode) {
130 switch (rtcp_mode) {
131 case newapi::kRtcpCompound:
132 return rtclog::VideoReceiveConfig::RTCP_COMPOUND;
133 case newapi::kRtcpReducedSize:
134 return rtclog::VideoReceiveConfig::RTCP_REDUCEDSIZE;
135 }
136 RTC_NOTREACHED();
137 return rtclog::VideoReceiveConfig::RTCP_COMPOUND;
138}
139
140rtclog::MediaType ConvertMediaType(MediaType media_type) {
141 switch (media_type) {
142 case MediaType::ANY:
143 return rtclog::MediaType::ANY;
144 case MediaType::AUDIO:
145 return rtclog::MediaType::AUDIO;
146 case MediaType::VIDEO:
147 return rtclog::MediaType::VIDEO;
148 case MediaType::DATA:
149 return rtclog::MediaType::DATA;
150 }
151 RTC_NOTREACHED();
152 return rtclog::ANY;
153}
154
155} // namespace
156
157// RtcEventLogImpl member functions.
158RtcEventLogImpl::RtcEventLogImpl()
159 : file_(FileWrapper::Create()),
160 stream_(),
161 currently_logging_(false),
162 start_time_us_(0),
163 duration_us_(0),
164 clock_(Clock::GetRealTimeClock()) {
165}
166
167void RtcEventLogImpl::StartLogging(const std::string& file_name,
168 int duration_ms) {
169 rtc::CritScope lock(&crit_);
170 if (currently_logging_) {
171 StopLoggingLocked();
172 }
173 if (file_->OpenFile(file_name.c_str(), false) != 0) {
174 return;
175 }
176 currently_logging_ = true;
177 start_time_us_ = clock_->TimeInMicroseconds();
178 duration_us_ = static_cast<int64_t>(duration_ms) * 1000;
179 // Write all the recent events to the log file, ignoring any old events.
180 for (auto& event : recent_log_events_) {
181 if (event.timestamp_us() >= start_time_us_ - recent_log_duration_us) {
182 StoreToFile(&event);
183 }
184 }
185 recent_log_events_.clear();
186 // Write a LOG_START event to the file.
187 rtclog::Event start_event;
188 start_event.set_timestamp_us(start_time_us_);
189 start_event.set_type(rtclog::Event::DEBUG_EVENT);
190 auto debug_event = start_event.mutable_debug_event();
191 debug_event->set_type(ConvertDebugEvent(DebugEvent::kLogStart));
192 StoreToFile(&start_event);
193}
194
195void RtcEventLogImpl::StopLogging() {
196 rtc::CritScope lock(&crit_);
197 StopLoggingLocked();
198}
199
200void RtcEventLogImpl::LogVideoReceiveStreamConfig(
201 const VideoReceiveStream::Config& config) {
202 rtc::CritScope lock(&crit_);
203
204 rtclog::Event event;
205 const int64_t timestamp = clock_->TimeInMicroseconds();
206 event.set_timestamp_us(timestamp);
207 event.set_type(rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT);
208
209 rtclog::VideoReceiveConfig* receiver_config =
210 event.mutable_video_receiver_config();
211 receiver_config->set_remote_ssrc(config.rtp.remote_ssrc);
212 receiver_config->set_local_ssrc(config.rtp.local_ssrc);
213
214 receiver_config->set_rtcp_mode(ConvertRtcpMode(config.rtp.rtcp_mode));
215
216 receiver_config->set_receiver_reference_time_report(
217 config.rtp.rtcp_xr.receiver_reference_time_report);
218 receiver_config->set_remb(config.rtp.remb);
219
220 for (const auto& kv : config.rtp.rtx) {
221 rtclog::RtxMap* rtx = receiver_config->add_rtx_map();
222 rtx->set_payload_type(kv.first);
223 rtx->mutable_config()->set_rtx_ssrc(kv.second.ssrc);
224 rtx->mutable_config()->set_rtx_payload_type(kv.second.payload_type);
225 }
226
227 for (const auto& e : config.rtp.extensions) {
228 rtclog::RtpHeaderExtension* extension =
229 receiver_config->add_header_extensions();
230 extension->set_name(e.name);
231 extension->set_id(e.id);
232 }
233
234 for (const auto& d : config.decoders) {
235 rtclog::DecoderConfig* decoder = receiver_config->add_decoders();
236 decoder->set_name(d.payload_name);
237 decoder->set_payload_type(d.payload_type);
238 }
239 // TODO(terelius): We should use a separate event queue for config events.
240 // The current approach of storing the configuration together with the
241 // RTP events causes the configuration information to be removed 10s
242 // after the ReceiveStream is created.
243 HandleEvent(&event);
244}
245
246void RtcEventLogImpl::LogVideoSendStreamConfig(
247 const VideoSendStream::Config& config) {
248 rtc::CritScope lock(&crit_);
249
250 rtclog::Event event;
251 const int64_t timestamp = clock_->TimeInMicroseconds();
252 event.set_timestamp_us(timestamp);
253 event.set_type(rtclog::Event::VIDEO_SENDER_CONFIG_EVENT);
254
255 rtclog::VideoSendConfig* sender_config = event.mutable_video_sender_config();
256
257 for (const auto& ssrc : config.rtp.ssrcs) {
258 sender_config->add_ssrcs(ssrc);
259 }
260
261 for (const auto& e : config.rtp.extensions) {
262 rtclog::RtpHeaderExtension* extension =
263 sender_config->add_header_extensions();
264 extension->set_name(e.name);
265 extension->set_id(e.id);
266 }
267
268 for (const auto& rtx_ssrc : config.rtp.rtx.ssrcs) {
269 sender_config->add_rtx_ssrcs(rtx_ssrc);
270 }
271 sender_config->set_rtx_payload_type(config.rtp.rtx.payload_type);
272
273 sender_config->set_c_name(config.rtp.c_name);
274
275 rtclog::EncoderConfig* encoder = sender_config->mutable_encoder();
276 encoder->set_name(config.encoder_settings.payload_name);
277 encoder->set_payload_type(config.encoder_settings.payload_type);
278
279 // TODO(terelius): We should use a separate event queue for config events.
280 // The current approach of storing the configuration together with the
281 // RTP events causes the configuration information to be removed 10s
282 // after the ReceiveStream is created.
283 HandleEvent(&event);
284}
285
Bjorn Terelius36411852015-07-30 12:45:18 +0200286void RtcEventLogImpl::LogRtpHeader(bool incoming,
287 MediaType media_type,
288 const uint8_t* header,
terelius2f9fd5d2015-09-04 03:39:42 -0700289 size_t packet_length) {
290 // Read header length (in bytes) from packet data.
291 if (packet_length < 12u) {
292 return; // Don't read outside the packet.
293 }
294 const bool x = (header[0] & 0x10) != 0;
295 const uint8_t cc = header[0] & 0x0f;
296 size_t header_length = 12u + cc * 4u;
297
298 if (x) {
299 if (packet_length < 12u + cc * 4u + 4u) {
300 return; // Don't read outside the packet.
301 }
302 size_t x_len = ByteReader<uint16_t>::ReadBigEndian(header + 14 + cc * 4);
303 header_length += (x_len + 1) * 4;
304 }
305
Bjorn Terelius36411852015-07-30 12:45:18 +0200306 rtc::CritScope lock(&crit_);
307 rtclog::Event rtp_event;
308 const int64_t timestamp = clock_->TimeInMicroseconds();
309 rtp_event.set_timestamp_us(timestamp);
310 rtp_event.set_type(rtclog::Event::RTP_EVENT);
311 rtp_event.mutable_rtp_packet()->set_incoming(incoming);
312 rtp_event.mutable_rtp_packet()->set_type(ConvertMediaType(media_type));
terelius2f9fd5d2015-09-04 03:39:42 -0700313 rtp_event.mutable_rtp_packet()->set_packet_length(packet_length);
Bjorn Terelius36411852015-07-30 12:45:18 +0200314 rtp_event.mutable_rtp_packet()->set_header(header, header_length);
315 HandleEvent(&rtp_event);
316}
317
318void RtcEventLogImpl::LogRtcpPacket(bool incoming,
319 MediaType media_type,
320 const uint8_t* packet,
321 size_t length) {
322 rtc::CritScope lock(&crit_);
323 rtclog::Event rtcp_event;
324 const int64_t timestamp = clock_->TimeInMicroseconds();
325 rtcp_event.set_timestamp_us(timestamp);
326 rtcp_event.set_type(rtclog::Event::RTCP_EVENT);
327 rtcp_event.mutable_rtcp_packet()->set_incoming(incoming);
328 rtcp_event.mutable_rtcp_packet()->set_type(ConvertMediaType(media_type));
329 rtcp_event.mutable_rtcp_packet()->set_packet_data(packet, length);
330 HandleEvent(&rtcp_event);
331}
332
333void RtcEventLogImpl::LogDebugEvent(DebugEvent event_type) {
334 rtc::CritScope lock(&crit_);
335 rtclog::Event event;
336 const int64_t timestamp = clock_->TimeInMicroseconds();
337 event.set_timestamp_us(timestamp);
338 event.set_type(rtclog::Event::DEBUG_EVENT);
339 auto debug_event = event.mutable_debug_event();
340 debug_event->set_type(ConvertDebugEvent(event_type));
341 HandleEvent(&event);
342}
343
344void RtcEventLogImpl::StopLoggingLocked() {
345 if (currently_logging_) {
346 currently_logging_ = false;
347 // Create a LogEnd debug event
348 rtclog::Event event;
349 int64_t timestamp = clock_->TimeInMicroseconds();
350 event.set_timestamp_us(timestamp);
351 event.set_type(rtclog::Event::DEBUG_EVENT);
352 auto debug_event = event.mutable_debug_event();
353 debug_event->set_type(ConvertDebugEvent(DebugEvent::kLogEnd));
354 // Store the event and close the file
355 DCHECK(file_->Open());
356 StoreToFile(&event);
357 file_->CloseFile();
358 }
359 DCHECK(!file_->Open());
360 stream_.Clear();
361}
362
363void RtcEventLogImpl::HandleEvent(rtclog::Event* event) {
364 if (currently_logging_) {
365 if (clock_->TimeInMicroseconds() < start_time_us_ + duration_us_) {
366 StoreToFile(event);
367 return;
368 }
369 StopLoggingLocked();
370 }
371 AddRecentEvent(*event);
372}
373
374void RtcEventLogImpl::StoreToFile(rtclog::Event* event) {
375 // Reuse the same object at every log event.
376 if (stream_.stream_size() < 1) {
377 stream_.add_stream();
378 }
379 DCHECK_EQ(stream_.stream_size(), 1);
380 stream_.mutable_stream(0)->Swap(event);
381 // TODO(terelius): Doesn't this create a new EventStream per event?
382 // Is this guaranteed to work e.g. in future versions of protobuf?
383 std::string dump_buffer;
384 stream_.SerializeToString(&dump_buffer);
385 file_->Write(dump_buffer.data(), dump_buffer.size());
386}
387
388void RtcEventLogImpl::AddRecentEvent(const rtclog::Event& event) {
389 recent_log_events_.push_back(event);
390 while (recent_log_events_.front().timestamp_us() <
391 event.timestamp_us() - recent_log_duration_us) {
392 recent_log_events_.pop_front();
393 }
394}
395
396bool RtcEventLog::ParseRtcEventLog(const std::string& file_name,
397 rtclog::EventStream* result) {
398 char tmp_buffer[1024];
399 int bytes_read = 0;
400 rtc::scoped_ptr<FileWrapper> dump_file(FileWrapper::Create());
401 if (dump_file->OpenFile(file_name.c_str(), true) != 0) {
402 return false;
403 }
404 std::string dump_buffer;
405 while ((bytes_read = dump_file->Read(tmp_buffer, sizeof(tmp_buffer))) > 0) {
406 dump_buffer.append(tmp_buffer, bytes_read);
407 }
408 dump_file->CloseFile();
409 return result->ParseFromString(dump_buffer);
410}
411
412#endif // ENABLE_RTC_EVENT_LOG
413
414// RtcEventLog member functions.
415rtc::scoped_ptr<RtcEventLog> RtcEventLog::Create() {
416 return rtc::scoped_ptr<RtcEventLog>(new RtcEventLogImpl());
417}
418} // namespace webrtc