Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 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 | |
Mirko Bonadei | 92ea95e | 2017-09-15 06:47:31 +0200 | [diff] [blame] | 11 | #include "logging/rtc_event_log/rtc_event_log.h" |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 12 | |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 13 | #include <atomic> |
| 14 | #include <deque> |
| 15 | #include <functional> |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 16 | #include <limits> |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 17 | #include <memory> |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 18 | #include <utility> |
terelius | 1adce14 | 2015-10-16 08:51:08 -0700 | [diff] [blame] | 19 | #include <vector> |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 20 | |
Mirko Bonadei | 92ea95e | 2017-09-15 06:47:31 +0200 | [diff] [blame] | 21 | #include "modules/audio_coding/audio_network_adaptor/include/audio_network_adaptor.h" |
| 22 | #include "modules/remote_bitrate_estimator/include/bwe_defines.h" |
| 23 | #include "modules/rtp_rtcp/include/rtp_rtcp_defines.h" |
| 24 | #include "modules/rtp_rtcp/source/byte_io.h" |
| 25 | #include "modules/rtp_rtcp/source/rtcp_packet/app.h" |
| 26 | #include "modules/rtp_rtcp/source/rtcp_packet/bye.h" |
| 27 | #include "modules/rtp_rtcp/source/rtcp_packet/common_header.h" |
| 28 | #include "modules/rtp_rtcp/source/rtcp_packet/extended_jitter_report.h" |
| 29 | #include "modules/rtp_rtcp/source/rtcp_packet/extended_reports.h" |
| 30 | #include "modules/rtp_rtcp/source/rtcp_packet/psfb.h" |
| 31 | #include "modules/rtp_rtcp/source/rtcp_packet/receiver_report.h" |
| 32 | #include "modules/rtp_rtcp/source/rtcp_packet/rtpfb.h" |
| 33 | #include "modules/rtp_rtcp/source/rtcp_packet/sdes.h" |
| 34 | #include "modules/rtp_rtcp/source/rtcp_packet/sender_report.h" |
| 35 | #include "rtc_base/checks.h" |
| 36 | #include "rtc_base/constructormagic.h" |
| 37 | #include "rtc_base/event.h" |
| 38 | #include "rtc_base/ignore_wundef.h" |
| 39 | #include "rtc_base/logging.h" |
| 40 | #include "rtc_base/protobuf_utils.h" |
| 41 | #include "rtc_base/ptr_util.h" |
| 42 | #include "rtc_base/sequenced_task_checker.h" |
| 43 | #include "rtc_base/task_queue.h" |
| 44 | #include "rtc_base/thread_annotations.h" |
| 45 | #include "rtc_base/timeutils.h" |
| 46 | #include "system_wrappers/include/file_wrapper.h" |
Mirko Bonadei | 7120742 | 2017-09-15 13:58:09 +0200 | [diff] [blame^] | 47 | #include "typedefs.h" // NOLINT(build/include) |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 48 | |
| 49 | #ifdef ENABLE_RTC_EVENT_LOG |
mbonadei | 7c2c843 | 2017-04-07 00:59:12 -0700 | [diff] [blame] | 50 | // *.pb.h files are generated at build-time by the protobuf compiler. |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 51 | RTC_PUSH_IGNORING_WUNDEF() |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 52 | #ifdef WEBRTC_ANDROID_PLATFORM_BUILD |
skvlad | cc91d28 | 2016-10-03 18:31:22 -0700 | [diff] [blame] | 53 | #include "external/webrtc/webrtc/logging/rtc_event_log/rtc_event_log.pb.h" |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 54 | #else |
Mirko Bonadei | 92ea95e | 2017-09-15 06:47:31 +0200 | [diff] [blame] | 55 | #include "logging/rtc_event_log/rtc_event_log.pb.h" |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 56 | #endif |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 57 | RTC_POP_IGNORING_WUNDEF() |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 58 | #endif |
| 59 | |
| 60 | namespace webrtc { |
| 61 | |
ivoc | 14d5dbe | 2016-07-04 07:06:55 -0700 | [diff] [blame] | 62 | #ifdef ENABLE_RTC_EVENT_LOG |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 63 | |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 64 | namespace { |
| 65 | const int kEventsInHistory = 10000; |
| 66 | |
| 67 | bool IsConfigEvent(const rtclog::Event& event) { |
| 68 | rtclog::Event_EventType event_type = event.type(); |
| 69 | return event_type == rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT || |
| 70 | event_type == rtclog::Event::VIDEO_SENDER_CONFIG_EVENT || |
| 71 | event_type == rtclog::Event::AUDIO_RECEIVER_CONFIG_EVENT || |
| 72 | event_type == rtclog::Event::AUDIO_SENDER_CONFIG_EVENT; |
| 73 | } |
| 74 | |
| 75 | // TODO(eladalon): This class exists because C++11 doesn't allow transferring a |
| 76 | // unique_ptr to a lambda (a copy constructor is required). We should get |
| 77 | // rid of this when we move to C++14. |
| 78 | template <typename T> |
| 79 | class ResourceOwningTask final : public rtc::QueuedTask { |
| 80 | public: |
| 81 | ResourceOwningTask(std::unique_ptr<T> resource, |
| 82 | std::function<void(std::unique_ptr<T>)> handler) |
| 83 | : resource_(std::move(resource)), handler_(handler) {} |
| 84 | |
| 85 | bool Run() override { |
| 86 | handler_(std::move(resource_)); |
| 87 | return true; |
| 88 | } |
| 89 | |
| 90 | private: |
| 91 | std::unique_ptr<T> resource_; |
| 92 | std::function<void(std::unique_ptr<T>)> handler_; |
| 93 | }; |
| 94 | } // namespace |
| 95 | |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 96 | class RtcEventLogImpl final : public RtcEventLog { |
terelius | c8e0552 | 2017-06-28 06:40:51 -0700 | [diff] [blame] | 97 | friend std::unique_ptr<RtcEventLog> RtcEventLog::Create(); |
| 98 | |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 99 | public: |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 100 | ~RtcEventLogImpl() override; |
terelius | 1adce14 | 2015-10-16 08:51:08 -0700 | [diff] [blame] | 101 | |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 102 | bool StartLogging(const std::string& file_name, |
| 103 | int64_t max_size_bytes) override; |
| 104 | bool StartLogging(rtc::PlatformFile platform_file, |
| 105 | int64_t max_size_bytes) override; |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 106 | void StopLogging() override; |
perkj | 09e71da | 2017-05-22 03:26:49 -0700 | [diff] [blame] | 107 | void LogVideoReceiveStreamConfig(const rtclog::StreamConfig& config) override; |
perkj | c0876aa | 2017-05-22 04:08:28 -0700 | [diff] [blame] | 108 | void LogVideoSendStreamConfig(const rtclog::StreamConfig& config) override; |
perkj | ac8f52d | 2017-05-22 09:36:28 -0700 | [diff] [blame] | 109 | void LogAudioReceiveStreamConfig(const rtclog::StreamConfig& config) override; |
perkj | f472699 | 2017-05-22 10:12:26 -0700 | [diff] [blame] | 110 | void LogAudioSendStreamConfig(const rtclog::StreamConfig& config) override; |
terelius | 429c345 | 2016-01-21 05:42:04 -0800 | [diff] [blame] | 111 | void LogRtpHeader(PacketDirection direction, |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 112 | const uint8_t* header, |
terelius | 2f9fd5d | 2015-09-04 03:39:42 -0700 | [diff] [blame] | 113 | size_t packet_length) override; |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 114 | void LogRtpHeader(PacketDirection direction, |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 115 | const uint8_t* header, |
| 116 | size_t packet_length, |
| 117 | int probe_cluster_id) override; |
terelius | 429c345 | 2016-01-21 05:42:04 -0800 | [diff] [blame] | 118 | void LogRtcpPacket(PacketDirection direction, |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 119 | const uint8_t* packet, |
| 120 | size_t length) override; |
Ivo Creusen | ae856f2 | 2015-09-17 16:30:16 +0200 | [diff] [blame] | 121 | void LogAudioPlayout(uint32_t ssrc) override; |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 122 | void LogLossBasedBweUpdate(int32_t bitrate_bps, |
terelius | 006d93d | 2015-11-05 12:02:15 -0800 | [diff] [blame] | 123 | uint8_t fraction_loss, |
| 124 | int32_t total_packets) override; |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 125 | void LogDelayBasedBweUpdate(int32_t bitrate_bps, |
terelius | 0baf55d | 2017-02-17 03:38:28 -0800 | [diff] [blame] | 126 | BandwidthUsage detector_state) override; |
minyue | 4b7c952 | 2017-01-24 04:54:59 -0800 | [diff] [blame] | 127 | void LogAudioNetworkAdaptation( |
michaelt | cde46b7 | 2017-04-06 05:59:10 -0700 | [diff] [blame] | 128 | const AudioEncoderRuntimeConfig& config) override; |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 129 | void LogProbeClusterCreated(int id, |
| 130 | int bitrate_bps, |
| 131 | int min_probes, |
| 132 | int min_bytes) override; |
| 133 | void LogProbeResultSuccess(int id, int bitrate_bps) override; |
| 134 | void LogProbeResultFailure(int id, |
| 135 | ProbeFailureReason failure_reason) override; |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 136 | |
| 137 | private: |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 138 | void StartLoggingInternal(std::unique_ptr<FileWrapper> file, |
| 139 | int64_t max_size_bytes); |
| 140 | |
| 141 | RtcEventLogImpl(); // Creation is done by RtcEventLog::Create. |
terelius | c8e0552 | 2017-06-28 06:40:51 -0700 | [diff] [blame] | 142 | |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 143 | void StoreEvent(std::unique_ptr<rtclog::Event> event); |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 144 | void LogProbeResult(int id, |
| 145 | rtclog::BweProbeResult::ResultType result, |
| 146 | int bitrate_bps); |
terelius | bea8959 | 2016-06-08 07:20:29 -0700 | [diff] [blame] | 147 | |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 148 | // Appends an event to the output protobuf string, returning true on success. |
| 149 | // Fails and returns false in case the limit on output size prevents the |
| 150 | // event from being added; in this case, the output string is left unchanged. |
| 151 | bool AppendEventToString(rtclog::Event* event, |
| 152 | ProtoString* output_string) RTC_WARN_UNUSED_RESULT; |
terelius | c8e0552 | 2017-06-28 06:40:51 -0700 | [diff] [blame] | 153 | |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 154 | void LogToMemory(std::unique_ptr<rtclog::Event> event); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 155 | |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 156 | void StartLogFile(); |
| 157 | void LogToFile(std::unique_ptr<rtclog::Event> event); |
| 158 | void StopLogFile(int64_t stop_time); |
terelius | 1adce14 | 2015-10-16 08:51:08 -0700 | [diff] [blame] | 159 | |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 160 | // Observe a limit on the number of concurrent logs, so as not to run into |
| 161 | // OS-imposed limits on open files and/or threads/task-queues. |
| 162 | // TODO(eladalon): Known issue - there's a race over |log_count_|. |
| 163 | static std::atomic<int> log_count_; |
| 164 | |
| 165 | // Make sure that the event log is "managed" - created/destroyed, as well |
| 166 | // as started/stopped - from the same thread/task-queue. |
| 167 | rtc::SequencedTaskChecker owner_sequence_checker_; |
| 168 | |
| 169 | // History containing all past configuration events. |
| 170 | std::vector<std::unique_ptr<rtclog::Event>> config_history_ |
danilchap | a37de39 | 2017-09-09 04:17:22 -0700 | [diff] [blame] | 171 | RTC_ACCESS_ON(task_queue_); |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 172 | |
| 173 | // History containing the most recent (non-configuration) events (~10s). |
danilchap | a37de39 | 2017-09-09 04:17:22 -0700 | [diff] [blame] | 174 | std::deque<std::unique_ptr<rtclog::Event>> history_ |
| 175 | RTC_ACCESS_ON(task_queue_); |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 176 | |
danilchap | a37de39 | 2017-09-09 04:17:22 -0700 | [diff] [blame] | 177 | std::unique_ptr<FileWrapper> file_ RTC_ACCESS_ON(task_queue_); |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 178 | |
danilchap | a37de39 | 2017-09-09 04:17:22 -0700 | [diff] [blame] | 179 | size_t max_size_bytes_ RTC_ACCESS_ON(task_queue_); |
| 180 | size_t written_bytes_ RTC_ACCESS_ON(task_queue_); |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 181 | |
| 182 | // Keep this last to ensure it destructs first, or else tasks living on the |
| 183 | // queue might access other members after they've been torn down. |
| 184 | rtc::TaskQueue task_queue_; |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 185 | |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 186 | RTC_DISALLOW_COPY_AND_ASSIGN(RtcEventLogImpl); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 187 | }; |
| 188 | |
| 189 | namespace { |
| 190 | // The functions in this namespace convert enums from the runtime format |
| 191 | // that the rest of the WebRtc project can use, to the corresponding |
| 192 | // serialized enum which is defined by the protobuf. |
| 193 | |
pbos | da903ea | 2015-10-02 02:36:56 -0700 | [diff] [blame] | 194 | rtclog::VideoReceiveConfig_RtcpMode ConvertRtcpMode(RtcpMode rtcp_mode) { |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 195 | switch (rtcp_mode) { |
pbos | da903ea | 2015-10-02 02:36:56 -0700 | [diff] [blame] | 196 | case RtcpMode::kCompound: |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 197 | return rtclog::VideoReceiveConfig::RTCP_COMPOUND; |
pbos | da903ea | 2015-10-02 02:36:56 -0700 | [diff] [blame] | 198 | case RtcpMode::kReducedSize: |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 199 | return rtclog::VideoReceiveConfig::RTCP_REDUCEDSIZE; |
pbos | da903ea | 2015-10-02 02:36:56 -0700 | [diff] [blame] | 200 | case RtcpMode::kOff: |
| 201 | RTC_NOTREACHED(); |
| 202 | return rtclog::VideoReceiveConfig::RTCP_COMPOUND; |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 203 | } |
| 204 | RTC_NOTREACHED(); |
| 205 | return rtclog::VideoReceiveConfig::RTCP_COMPOUND; |
| 206 | } |
| 207 | |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 208 | rtclog::DelayBasedBweUpdate::DetectorState ConvertDetectorState( |
terelius | 0baf55d | 2017-02-17 03:38:28 -0800 | [diff] [blame] | 209 | BandwidthUsage state) { |
| 210 | switch (state) { |
| 211 | case BandwidthUsage::kBwNormal: |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 212 | return rtclog::DelayBasedBweUpdate::BWE_NORMAL; |
terelius | 0baf55d | 2017-02-17 03:38:28 -0800 | [diff] [blame] | 213 | case BandwidthUsage::kBwUnderusing: |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 214 | return rtclog::DelayBasedBweUpdate::BWE_UNDERUSING; |
terelius | 0baf55d | 2017-02-17 03:38:28 -0800 | [diff] [blame] | 215 | case BandwidthUsage::kBwOverusing: |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 216 | return rtclog::DelayBasedBweUpdate::BWE_OVERUSING; |
terelius | 0baf55d | 2017-02-17 03:38:28 -0800 | [diff] [blame] | 217 | } |
| 218 | RTC_NOTREACHED(); |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 219 | return rtclog::DelayBasedBweUpdate::BWE_NORMAL; |
terelius | 0baf55d | 2017-02-17 03:38:28 -0800 | [diff] [blame] | 220 | } |
| 221 | |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 222 | rtclog::BweProbeResult::ResultType ConvertProbeResultType( |
| 223 | ProbeFailureReason failure_reason) { |
| 224 | switch (failure_reason) { |
| 225 | case kInvalidSendReceiveInterval: |
| 226 | return rtclog::BweProbeResult::INVALID_SEND_RECEIVE_INTERVAL; |
| 227 | case kInvalidSendReceiveRatio: |
| 228 | return rtclog::BweProbeResult::INVALID_SEND_RECEIVE_RATIO; |
| 229 | case kTimeout: |
| 230 | return rtclog::BweProbeResult::TIMEOUT; |
| 231 | } |
| 232 | RTC_NOTREACHED(); |
| 233 | return rtclog::BweProbeResult::SUCCESS; |
| 234 | } |
| 235 | |
terelius | 1adce14 | 2015-10-16 08:51:08 -0700 | [diff] [blame] | 236 | } // namespace |
| 237 | |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 238 | std::atomic<int> RtcEventLogImpl::log_count_(0); |
terelius | c8e0552 | 2017-06-28 06:40:51 -0700 | [diff] [blame] | 239 | |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 240 | RtcEventLogImpl::RtcEventLogImpl() |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 241 | : file_(FileWrapper::Create()), |
| 242 | max_size_bytes_(std::numeric_limits<decltype(max_size_bytes_)>::max()), |
| 243 | written_bytes_(0), |
| 244 | task_queue_("rtc_event_log") {} |
terelius | 1adce14 | 2015-10-16 08:51:08 -0700 | [diff] [blame] | 245 | |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 246 | RtcEventLogImpl::~RtcEventLogImpl() { |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 247 | RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); |
| 248 | |
| 249 | // If we're logging to the file, this will stop that. Blocking function. |
| 250 | StopLogging(); |
| 251 | |
| 252 | int count = std::atomic_fetch_sub(&RtcEventLogImpl::log_count_, 1) - 1; |
terelius | c8e0552 | 2017-06-28 06:40:51 -0700 | [diff] [blame] | 253 | RTC_DCHECK_GE(count, 0); |
terelius | 1adce14 | 2015-10-16 08:51:08 -0700 | [diff] [blame] | 254 | } |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 255 | |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 256 | bool RtcEventLogImpl::StartLogging(const std::string& file_name, |
| 257 | int64_t max_size_bytes) { |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 258 | RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); |
| 259 | |
| 260 | auto file = rtc::WrapUnique<FileWrapper>(FileWrapper::Create()); |
| 261 | if (!file->OpenFile(file_name.c_str(), false)) { |
terelius | 43587e3 | 2016-05-27 02:22:51 -0700 | [diff] [blame] | 262 | LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; |
ivoc | 112a3d8 | 2015-10-16 02:22:18 -0700 | [diff] [blame] | 263 | return false; |
| 264 | } |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 265 | |
| 266 | StartLoggingInternal(std::move(file), max_size_bytes); |
| 267 | |
ivoc | 112a3d8 | 2015-10-16 02:22:18 -0700 | [diff] [blame] | 268 | return true; |
| 269 | } |
| 270 | |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 271 | bool RtcEventLogImpl::StartLogging(rtc::PlatformFile platform_file, |
| 272 | int64_t max_size_bytes) { |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 273 | RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); |
| 274 | |
| 275 | auto file = rtc::WrapUnique<FileWrapper>(FileWrapper::Create()); |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 276 | FILE* file_handle = rtc::FdopenPlatformFileForWriting(platform_file); |
| 277 | if (!file_handle) { |
terelius | 43587e3 | 2016-05-27 02:22:51 -0700 | [diff] [blame] | 278 | LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; |
| 279 | // Even though we failed to open a FILE*, the platform_file is still open |
| 280 | // and needs to be closed. |
| 281 | if (!rtc::ClosePlatformFile(platform_file)) { |
| 282 | LOG(LS_ERROR) << "Can't close file."; |
| 283 | } |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 284 | return false; |
terelius | 1adce14 | 2015-10-16 08:51:08 -0700 | [diff] [blame] | 285 | } |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 286 | if (!file->OpenFromFileHandle(file_handle)) { |
terelius | 43587e3 | 2016-05-27 02:22:51 -0700 | [diff] [blame] | 287 | LOG(LS_ERROR) << "Can't open file. WebRTC event log not started."; |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 288 | return false; |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 289 | } |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 290 | |
| 291 | StartLoggingInternal(std::move(file), max_size_bytes); |
| 292 | |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 293 | return true; |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 294 | } |
| 295 | |
| 296 | void RtcEventLogImpl::StopLogging() { |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 297 | RTC_DCHECK_CALLED_SEQUENTIALLY(&owner_sequence_checker_); |
| 298 | |
terelius | 43587e3 | 2016-05-27 02:22:51 -0700 | [diff] [blame] | 299 | LOG(LS_INFO) << "Stopping WebRTC event log."; |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 300 | |
| 301 | const int64_t stop_time = rtc::TimeMicros(); |
| 302 | |
| 303 | rtc::Event file_finished(true, false); |
| 304 | |
| 305 | task_queue_.PostTask([this, stop_time, &file_finished]() { |
| 306 | RTC_DCHECK_RUN_ON(&task_queue_); |
| 307 | if (file_->is_open()) { |
| 308 | StopLogFile(stop_time); |
| 309 | } |
| 310 | file_finished.Set(); |
| 311 | }); |
| 312 | |
| 313 | file_finished.Wait(rtc::Event::kForever); |
| 314 | |
| 315 | LOG(LS_INFO) << "WebRTC event log successfully stopped."; |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 316 | } |
| 317 | |
| 318 | void RtcEventLogImpl::LogVideoReceiveStreamConfig( |
perkj | 09e71da | 2017-05-22 03:26:49 -0700 | [diff] [blame] | 319 | const rtclog::StreamConfig& config) { |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 320 | std::unique_ptr<rtclog::Event> event(new rtclog::Event()); |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 321 | event->set_timestamp_us(rtc::TimeMicros()); |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 322 | event->set_type(rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 323 | |
| 324 | rtclog::VideoReceiveConfig* receiver_config = |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 325 | event->mutable_video_receiver_config(); |
perkj | 09e71da | 2017-05-22 03:26:49 -0700 | [diff] [blame] | 326 | receiver_config->set_remote_ssrc(config.remote_ssrc); |
| 327 | receiver_config->set_local_ssrc(config.local_ssrc); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 328 | |
perkj | 09e71da | 2017-05-22 03:26:49 -0700 | [diff] [blame] | 329 | // TODO(perkj): Add field for rsid. |
| 330 | receiver_config->set_rtcp_mode(ConvertRtcpMode(config.rtcp_mode)); |
| 331 | receiver_config->set_remb(config.remb); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 332 | |
perkj | 09e71da | 2017-05-22 03:26:49 -0700 | [diff] [blame] | 333 | for (const auto& e : config.rtp_extensions) { |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 334 | rtclog::RtpHeaderExtension* extension = |
| 335 | receiver_config->add_header_extensions(); |
isheriff | 6f8d686 | 2016-05-26 11:24:55 -0700 | [diff] [blame] | 336 | extension->set_name(e.uri); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 337 | extension->set_id(e.id); |
| 338 | } |
| 339 | |
perkj | 09e71da | 2017-05-22 03:26:49 -0700 | [diff] [blame] | 340 | for (const auto& d : config.codecs) { |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 341 | rtclog::DecoderConfig* decoder = receiver_config->add_decoders(); |
| 342 | decoder->set_name(d.payload_name); |
| 343 | decoder->set_payload_type(d.payload_type); |
perkj | 09e71da | 2017-05-22 03:26:49 -0700 | [diff] [blame] | 344 | if (d.rtx_payload_type != 0) { |
| 345 | rtclog::RtxMap* rtx = receiver_config->add_rtx_map(); |
| 346 | rtx->set_payload_type(d.payload_type); |
| 347 | rtx->mutable_config()->set_rtx_ssrc(config.rtx_ssrc); |
| 348 | rtx->mutable_config()->set_rtx_payload_type(d.rtx_payload_type); |
| 349 | } |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 350 | } |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 351 | StoreEvent(std::move(event)); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 352 | } |
| 353 | |
| 354 | void RtcEventLogImpl::LogVideoSendStreamConfig( |
perkj | c0876aa | 2017-05-22 04:08:28 -0700 | [diff] [blame] | 355 | const rtclog::StreamConfig& config) { |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 356 | std::unique_ptr<rtclog::Event> event(new rtclog::Event()); |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 357 | event->set_timestamp_us(rtc::TimeMicros()); |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 358 | event->set_type(rtclog::Event::VIDEO_SENDER_CONFIG_EVENT); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 359 | |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 360 | rtclog::VideoSendConfig* sender_config = event->mutable_video_sender_config(); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 361 | |
perkj | c0876aa | 2017-05-22 04:08:28 -0700 | [diff] [blame] | 362 | // TODO(perkj): rtclog::VideoSendConfig should only contain one SSRC. |
| 363 | sender_config->add_ssrcs(config.local_ssrc); |
| 364 | if (config.rtx_ssrc != 0) { |
| 365 | sender_config->add_rtx_ssrcs(config.rtx_ssrc); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 366 | } |
| 367 | |
perkj | c0876aa | 2017-05-22 04:08:28 -0700 | [diff] [blame] | 368 | for (const auto& e : config.rtp_extensions) { |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 369 | rtclog::RtpHeaderExtension* extension = |
| 370 | sender_config->add_header_extensions(); |
isheriff | 6f8d686 | 2016-05-26 11:24:55 -0700 | [diff] [blame] | 371 | extension->set_name(e.uri); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 372 | extension->set_id(e.id); |
| 373 | } |
| 374 | |
perkj | c0876aa | 2017-05-22 04:08:28 -0700 | [diff] [blame] | 375 | // TODO(perkj): rtclog::VideoSendConfig should contain many possible codec |
| 376 | // configurations. |
| 377 | for (const auto& codec : config.codecs) { |
| 378 | sender_config->set_rtx_payload_type(codec.rtx_payload_type); |
| 379 | rtclog::EncoderConfig* encoder = sender_config->mutable_encoder(); |
| 380 | encoder->set_name(codec.payload_name); |
| 381 | encoder->set_payload_type(codec.payload_type); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 382 | |
perkj | c0876aa | 2017-05-22 04:08:28 -0700 | [diff] [blame] | 383 | if (config.codecs.size() > 1) { |
| 384 | LOG(WARNING) << "LogVideoSendStreamConfig currently only supports one " |
| 385 | << "codec. Logging codec :" << codec.payload_name; |
| 386 | break; |
| 387 | } |
| 388 | } |
| 389 | |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 390 | StoreEvent(std::move(event)); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 391 | } |
| 392 | |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 393 | void RtcEventLogImpl::LogAudioReceiveStreamConfig( |
perkj | ac8f52d | 2017-05-22 09:36:28 -0700 | [diff] [blame] | 394 | const rtclog::StreamConfig& config) { |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 395 | std::unique_ptr<rtclog::Event> event(new rtclog::Event()); |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 396 | event->set_timestamp_us(rtc::TimeMicros()); |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 397 | event->set_type(rtclog::Event::AUDIO_RECEIVER_CONFIG_EVENT); |
| 398 | |
| 399 | rtclog::AudioReceiveConfig* receiver_config = |
| 400 | event->mutable_audio_receiver_config(); |
perkj | ac8f52d | 2017-05-22 09:36:28 -0700 | [diff] [blame] | 401 | receiver_config->set_remote_ssrc(config.remote_ssrc); |
| 402 | receiver_config->set_local_ssrc(config.local_ssrc); |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 403 | |
perkj | ac8f52d | 2017-05-22 09:36:28 -0700 | [diff] [blame] | 404 | for (const auto& e : config.rtp_extensions) { |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 405 | rtclog::RtpHeaderExtension* extension = |
| 406 | receiver_config->add_header_extensions(); |
| 407 | extension->set_name(e.uri); |
| 408 | extension->set_id(e.id); |
| 409 | } |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 410 | StoreEvent(std::move(event)); |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 411 | } |
| 412 | |
| 413 | void RtcEventLogImpl::LogAudioSendStreamConfig( |
perkj | f472699 | 2017-05-22 10:12:26 -0700 | [diff] [blame] | 414 | const rtclog::StreamConfig& config) { |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 415 | std::unique_ptr<rtclog::Event> event(new rtclog::Event()); |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 416 | event->set_timestamp_us(rtc::TimeMicros()); |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 417 | event->set_type(rtclog::Event::AUDIO_SENDER_CONFIG_EVENT); |
| 418 | |
| 419 | rtclog::AudioSendConfig* sender_config = event->mutable_audio_sender_config(); |
| 420 | |
perkj | f472699 | 2017-05-22 10:12:26 -0700 | [diff] [blame] | 421 | sender_config->set_ssrc(config.local_ssrc); |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 422 | |
perkj | f472699 | 2017-05-22 10:12:26 -0700 | [diff] [blame] | 423 | for (const auto& e : config.rtp_extensions) { |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 424 | rtclog::RtpHeaderExtension* extension = |
| 425 | sender_config->add_header_extensions(); |
| 426 | extension->set_name(e.uri); |
| 427 | extension->set_id(e.id); |
| 428 | } |
| 429 | |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 430 | StoreEvent(std::move(event)); |
ivoc | e0928d8 | 2016-10-10 05:12:51 -0700 | [diff] [blame] | 431 | } |
| 432 | |
terelius | 429c345 | 2016-01-21 05:42:04 -0800 | [diff] [blame] | 433 | void RtcEventLogImpl::LogRtpHeader(PacketDirection direction, |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 434 | const uint8_t* header, |
terelius | 2f9fd5d | 2015-09-04 03:39:42 -0700 | [diff] [blame] | 435 | size_t packet_length) { |
perkj | 77cd58e | 2017-05-30 03:52:10 -0700 | [diff] [blame] | 436 | LogRtpHeader(direction, header, packet_length, PacedPacketInfo::kNotAProbe); |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 437 | } |
| 438 | |
| 439 | void RtcEventLogImpl::LogRtpHeader(PacketDirection direction, |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 440 | const uint8_t* header, |
| 441 | size_t packet_length, |
| 442 | int probe_cluster_id) { |
terelius | 2f9fd5d | 2015-09-04 03:39:42 -0700 | [diff] [blame] | 443 | // Read header length (in bytes) from packet data. |
| 444 | if (packet_length < 12u) { |
| 445 | return; // Don't read outside the packet. |
| 446 | } |
| 447 | const bool x = (header[0] & 0x10) != 0; |
| 448 | const uint8_t cc = header[0] & 0x0f; |
| 449 | size_t header_length = 12u + cc * 4u; |
| 450 | |
| 451 | if (x) { |
| 452 | if (packet_length < 12u + cc * 4u + 4u) { |
| 453 | return; // Don't read outside the packet. |
| 454 | } |
| 455 | size_t x_len = ByteReader<uint16_t>::ReadBigEndian(header + 14 + cc * 4); |
| 456 | header_length += (x_len + 1) * 4; |
| 457 | } |
| 458 | |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 459 | std::unique_ptr<rtclog::Event> rtp_event(new rtclog::Event()); |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 460 | rtp_event->set_timestamp_us(rtc::TimeMicros()); |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 461 | rtp_event->set_type(rtclog::Event::RTP_EVENT); |
| 462 | rtp_event->mutable_rtp_packet()->set_incoming(direction == kIncomingPacket); |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 463 | rtp_event->mutable_rtp_packet()->set_packet_length(packet_length); |
| 464 | rtp_event->mutable_rtp_packet()->set_header(header, header_length); |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 465 | if (probe_cluster_id != PacedPacketInfo::kNotAProbe) |
| 466 | rtp_event->mutable_rtp_packet()->set_probe_cluster_id(probe_cluster_id); |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 467 | StoreEvent(std::move(rtp_event)); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 468 | } |
| 469 | |
terelius | 429c345 | 2016-01-21 05:42:04 -0800 | [diff] [blame] | 470 | void RtcEventLogImpl::LogRtcpPacket(PacketDirection direction, |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 471 | const uint8_t* packet, |
| 472 | size_t length) { |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 473 | std::unique_ptr<rtclog::Event> rtcp_event(new rtclog::Event()); |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 474 | rtcp_event->set_timestamp_us(rtc::TimeMicros()); |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 475 | rtcp_event->set_type(rtclog::Event::RTCP_EVENT); |
| 476 | rtcp_event->mutable_rtcp_packet()->set_incoming(direction == kIncomingPacket); |
terelius | d66daa2 | 2015-11-06 09:00:18 -0800 | [diff] [blame] | 477 | |
danilchap | bf369fe | 2016-10-07 07:39:54 -0700 | [diff] [blame] | 478 | rtcp::CommonHeader header; |
terelius | d66daa2 | 2015-11-06 09:00:18 -0800 | [diff] [blame] | 479 | const uint8_t* block_begin = packet; |
| 480 | const uint8_t* packet_end = packet + length; |
| 481 | RTC_DCHECK(length <= IP_PACKET_SIZE); |
| 482 | uint8_t buffer[IP_PACKET_SIZE]; |
| 483 | uint32_t buffer_length = 0; |
| 484 | while (block_begin < packet_end) { |
danilchap | bf369fe | 2016-10-07 07:39:54 -0700 | [diff] [blame] | 485 | if (!header.Parse(block_begin, packet_end - block_begin)) { |
terelius | d66daa2 | 2015-11-06 09:00:18 -0800 | [diff] [blame] | 486 | break; // Incorrect message header. |
| 487 | } |
danilchap | bf369fe | 2016-10-07 07:39:54 -0700 | [diff] [blame] | 488 | const uint8_t* next_block = header.NextPacket(); |
| 489 | uint32_t block_size = next_block - block_begin; |
| 490 | switch (header.type()) { |
| 491 | case rtcp::SenderReport::kPacketType: |
| 492 | case rtcp::ReceiverReport::kPacketType: |
| 493 | case rtcp::Bye::kPacketType: |
| 494 | case rtcp::ExtendedJitterReport::kPacketType: |
| 495 | case rtcp::Rtpfb::kPacketType: |
| 496 | case rtcp::Psfb::kPacketType: |
| 497 | case rtcp::ExtendedReports::kPacketType: |
terelius | d66daa2 | 2015-11-06 09:00:18 -0800 | [diff] [blame] | 498 | // We log sender reports, receiver reports, bye messages |
| 499 | // inter-arrival jitter, third-party loss reports, payload-specific |
| 500 | // feedback and extended reports. |
| 501 | memcpy(buffer + buffer_length, block_begin, block_size); |
| 502 | buffer_length += block_size; |
| 503 | break; |
danilchap | bf369fe | 2016-10-07 07:39:54 -0700 | [diff] [blame] | 504 | case rtcp::Sdes::kPacketType: |
| 505 | case rtcp::App::kPacketType: |
terelius | d66daa2 | 2015-11-06 09:00:18 -0800 | [diff] [blame] | 506 | default: |
| 507 | // We don't log sender descriptions, application defined messages |
| 508 | // or message blocks of unknown type. |
| 509 | break; |
| 510 | } |
| 511 | |
| 512 | block_begin += block_size; |
| 513 | } |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 514 | rtcp_event->mutable_rtcp_packet()->set_packet_data(buffer, buffer_length); |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 515 | StoreEvent(std::move(rtcp_event)); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 516 | } |
| 517 | |
Ivo Creusen | ae856f2 | 2015-09-17 16:30:16 +0200 | [diff] [blame] | 518 | void RtcEventLogImpl::LogAudioPlayout(uint32_t ssrc) { |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 519 | std::unique_ptr<rtclog::Event> event(new rtclog::Event()); |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 520 | event->set_timestamp_us(rtc::TimeMicros()); |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 521 | event->set_type(rtclog::Event::AUDIO_PLAYOUT_EVENT); |
| 522 | auto playout_event = event->mutable_audio_playout_event(); |
Ivo Creusen | 301aaed | 2015-10-08 18:07:41 +0200 | [diff] [blame] | 523 | playout_event->set_local_ssrc(ssrc); |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 524 | StoreEvent(std::move(event)); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 525 | } |
| 526 | |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 527 | void RtcEventLogImpl::LogLossBasedBweUpdate(int32_t bitrate_bps, |
terelius | 006d93d | 2015-11-05 12:02:15 -0800 | [diff] [blame] | 528 | uint8_t fraction_loss, |
| 529 | int32_t total_packets) { |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 530 | std::unique_ptr<rtclog::Event> event(new rtclog::Event()); |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 531 | event->set_timestamp_us(rtc::TimeMicros()); |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 532 | event->set_type(rtclog::Event::LOSS_BASED_BWE_UPDATE); |
| 533 | auto bwe_event = event->mutable_loss_based_bwe_update(); |
| 534 | bwe_event->set_bitrate_bps(bitrate_bps); |
terelius | 006d93d | 2015-11-05 12:02:15 -0800 | [diff] [blame] | 535 | bwe_event->set_fraction_loss(fraction_loss); |
| 536 | bwe_event->set_total_packets(total_packets); |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 537 | StoreEvent(std::move(event)); |
terelius | bea8959 | 2016-06-08 07:20:29 -0700 | [diff] [blame] | 538 | } |
| 539 | |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 540 | void RtcEventLogImpl::LogDelayBasedBweUpdate(int32_t bitrate_bps, |
terelius | 0baf55d | 2017-02-17 03:38:28 -0800 | [diff] [blame] | 541 | BandwidthUsage detector_state) { |
| 542 | std::unique_ptr<rtclog::Event> event(new rtclog::Event()); |
| 543 | event->set_timestamp_us(rtc::TimeMicros()); |
terelius | 424e6cf | 2017-02-20 05:14:41 -0800 | [diff] [blame] | 544 | event->set_type(rtclog::Event::DELAY_BASED_BWE_UPDATE); |
| 545 | auto bwe_event = event->mutable_delay_based_bwe_update(); |
| 546 | bwe_event->set_bitrate_bps(bitrate_bps); |
terelius | 0baf55d | 2017-02-17 03:38:28 -0800 | [diff] [blame] | 547 | bwe_event->set_detector_state(ConvertDetectorState(detector_state)); |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 548 | StoreEvent(std::move(event)); |
terelius | 0baf55d | 2017-02-17 03:38:28 -0800 | [diff] [blame] | 549 | } |
| 550 | |
minyue | 4b7c952 | 2017-01-24 04:54:59 -0800 | [diff] [blame] | 551 | void RtcEventLogImpl::LogAudioNetworkAdaptation( |
michaelt | cde46b7 | 2017-04-06 05:59:10 -0700 | [diff] [blame] | 552 | const AudioEncoderRuntimeConfig& config) { |
minyue | 4b7c952 | 2017-01-24 04:54:59 -0800 | [diff] [blame] | 553 | std::unique_ptr<rtclog::Event> event(new rtclog::Event()); |
| 554 | event->set_timestamp_us(rtc::TimeMicros()); |
| 555 | event->set_type(rtclog::Event::AUDIO_NETWORK_ADAPTATION_EVENT); |
| 556 | auto audio_network_adaptation = event->mutable_audio_network_adaptation(); |
| 557 | if (config.bitrate_bps) |
| 558 | audio_network_adaptation->set_bitrate_bps(*config.bitrate_bps); |
| 559 | if (config.frame_length_ms) |
| 560 | audio_network_adaptation->set_frame_length_ms(*config.frame_length_ms); |
| 561 | if (config.uplink_packet_loss_fraction) { |
| 562 | audio_network_adaptation->set_uplink_packet_loss_fraction( |
| 563 | *config.uplink_packet_loss_fraction); |
| 564 | } |
| 565 | if (config.enable_fec) |
| 566 | audio_network_adaptation->set_enable_fec(*config.enable_fec); |
| 567 | if (config.enable_dtx) |
| 568 | audio_network_adaptation->set_enable_dtx(*config.enable_dtx); |
| 569 | if (config.num_channels) |
| 570 | audio_network_adaptation->set_num_channels(*config.num_channels); |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 571 | StoreEvent(std::move(event)); |
minyue | 4b7c952 | 2017-01-24 04:54:59 -0800 | [diff] [blame] | 572 | } |
| 573 | |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 574 | void RtcEventLogImpl::LogProbeClusterCreated(int id, |
| 575 | int bitrate_bps, |
| 576 | int min_probes, |
| 577 | int min_bytes) { |
| 578 | std::unique_ptr<rtclog::Event> event(new rtclog::Event()); |
| 579 | event->set_timestamp_us(rtc::TimeMicros()); |
| 580 | event->set_type(rtclog::Event::BWE_PROBE_CLUSTER_CREATED_EVENT); |
| 581 | |
| 582 | auto probe_cluster = event->mutable_probe_cluster(); |
| 583 | probe_cluster->set_id(id); |
| 584 | probe_cluster->set_bitrate_bps(bitrate_bps); |
| 585 | probe_cluster->set_min_packets(min_probes); |
| 586 | probe_cluster->set_min_bytes(min_bytes); |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 587 | StoreEvent(std::move(event)); |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 588 | } |
| 589 | |
| 590 | void RtcEventLogImpl::LogProbeResultSuccess(int id, int bitrate_bps) { |
| 591 | LogProbeResult(id, rtclog::BweProbeResult::SUCCESS, bitrate_bps); |
| 592 | } |
| 593 | |
| 594 | void RtcEventLogImpl::LogProbeResultFailure(int id, |
| 595 | ProbeFailureReason failure_reason) { |
| 596 | rtclog::BweProbeResult::ResultType result = |
| 597 | ConvertProbeResultType(failure_reason); |
| 598 | LogProbeResult(id, result, -1); |
| 599 | } |
| 600 | |
| 601 | void RtcEventLogImpl::LogProbeResult(int id, |
| 602 | rtclog::BweProbeResult::ResultType result, |
| 603 | int bitrate_bps) { |
| 604 | std::unique_ptr<rtclog::Event> event(new rtclog::Event()); |
| 605 | event->set_timestamp_us(rtc::TimeMicros()); |
| 606 | event->set_type(rtclog::Event::BWE_PROBE_RESULT_EVENT); |
| 607 | |
| 608 | auto probe_result = event->mutable_probe_result(); |
| 609 | probe_result->set_id(id); |
| 610 | probe_result->set_result(result); |
| 611 | if (result == rtclog::BweProbeResult::SUCCESS) |
| 612 | probe_result->set_bitrate_bps(bitrate_bps); |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 613 | StoreEvent(std::move(event)); |
philipel | 32d0010 | 2017-02-27 02:18:46 -0800 | [diff] [blame] | 614 | } |
| 615 | |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 616 | void RtcEventLogImpl::StartLoggingInternal(std::unique_ptr<FileWrapper> file, |
| 617 | int64_t max_size_bytes) { |
| 618 | LOG(LS_INFO) << "Starting WebRTC event log."; |
| 619 | |
| 620 | max_size_bytes = (max_size_bytes <= 0) |
| 621 | ? std::numeric_limits<decltype(max_size_bytes)>::max() |
| 622 | : max_size_bytes; |
| 623 | auto file_handler = [this, |
| 624 | max_size_bytes](std::unique_ptr<FileWrapper> file) { |
| 625 | RTC_DCHECK_RUN_ON(&task_queue_); |
| 626 | if (!file_->is_open()) { |
| 627 | max_size_bytes_ = max_size_bytes; |
| 628 | file_ = std::move(file); |
| 629 | StartLogFile(); |
| 630 | } else { |
| 631 | // Already started. Ignore message and close file handle. |
| 632 | file->CloseFile(); |
| 633 | } |
| 634 | }; |
| 635 | task_queue_.PostTask(rtc::MakeUnique<ResourceOwningTask<FileWrapper>>( |
| 636 | std::move(file), file_handler)); |
| 637 | } |
| 638 | |
eladalon | 333264f | 2017-07-16 16:44:08 -0700 | [diff] [blame] | 639 | void RtcEventLogImpl::StoreEvent(std::unique_ptr<rtclog::Event> event) { |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 640 | RTC_DCHECK(event); |
| 641 | |
| 642 | auto event_handler = [this](std::unique_ptr<rtclog::Event> rtclog_event) { |
| 643 | RTC_DCHECK_RUN_ON(&task_queue_); |
| 644 | if (file_->is_open()) { |
| 645 | LogToFile(std::move(rtclog_event)); |
| 646 | } else { |
| 647 | LogToMemory(std::move(rtclog_event)); |
| 648 | } |
| 649 | }; |
| 650 | |
| 651 | task_queue_.PostTask(rtc::MakeUnique<ResourceOwningTask<rtclog::Event>>( |
| 652 | std::move(event), event_handler)); |
| 653 | } |
| 654 | |
| 655 | bool RtcEventLogImpl::AppendEventToString(rtclog::Event* event, |
| 656 | ProtoString* output_string) { |
| 657 | RTC_DCHECK_RUN_ON(&task_queue_); |
| 658 | |
| 659 | // Even though we're only serializing a single event during this call, what |
| 660 | // we intend to get is a list of events, with a tag and length preceding |
| 661 | // each actual event. To produce that, we serialize a list of a single event. |
| 662 | // If we later serialize additional events, the resulting ProtoString will |
| 663 | // be a proper concatenation of all those events. |
| 664 | |
| 665 | rtclog::EventStream event_stream; |
| 666 | event_stream.add_stream(); |
| 667 | |
| 668 | // As a tweak, we swap the new event into the event-stream, write that to |
| 669 | // file, then swap back. This saves on some copying. |
| 670 | rtclog::Event* output_event = event_stream.mutable_stream(0); |
| 671 | output_event->Swap(event); |
| 672 | |
| 673 | bool appended; |
| 674 | size_t potential_new_size = |
| 675 | written_bytes_ + output_string->size() + event_stream.ByteSize(); |
| 676 | if (potential_new_size <= max_size_bytes_) { |
| 677 | event_stream.AppendToString(output_string); |
| 678 | appended = true; |
| 679 | } else { |
| 680 | appended = false; |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 681 | } |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 682 | |
| 683 | // When the function returns, the original Event will be unchanged. |
| 684 | output_event->Swap(event); |
| 685 | |
| 686 | return appended; |
| 687 | } |
| 688 | |
| 689 | void RtcEventLogImpl::LogToMemory(std::unique_ptr<rtclog::Event> event) { |
| 690 | RTC_DCHECK_RUN_ON(&task_queue_); |
| 691 | RTC_DCHECK(!file_->is_open()); |
| 692 | |
| 693 | if (IsConfigEvent(*event.get())) { |
| 694 | config_history_.push_back(std::move(event)); |
| 695 | } else { |
| 696 | history_.push_back(std::move(event)); |
| 697 | if (history_.size() > kEventsInHistory) { |
| 698 | history_.pop_front(); |
| 699 | } |
| 700 | } |
| 701 | } |
| 702 | |
| 703 | void RtcEventLogImpl::StartLogFile() { |
| 704 | RTC_DCHECK_RUN_ON(&task_queue_); |
| 705 | RTC_DCHECK(file_->is_open()); |
| 706 | |
| 707 | ProtoString output_string; |
| 708 | |
| 709 | // Create and serialize the LOG_START event. |
| 710 | // The timestamp used will correspond to when logging has started. The log |
| 711 | // may contain events earlier than the LOG_START event. (In general, the |
| 712 | // timestamps in the log are not monotonic.) |
| 713 | rtclog::Event start_event; |
| 714 | start_event.set_timestamp_us(rtc::TimeMicros()); |
| 715 | start_event.set_type(rtclog::Event::LOG_START); |
| 716 | bool appended = AppendEventToString(&start_event, &output_string); |
| 717 | |
| 718 | // Serialize the config information for all old streams, including streams |
| 719 | // which were already logged to previous files. |
| 720 | for (auto& event : config_history_) { |
| 721 | if (!appended) { |
| 722 | break; |
| 723 | } |
| 724 | appended = AppendEventToString(event.get(), &output_string); |
| 725 | } |
| 726 | |
| 727 | // Serialize the events in the event queue. |
| 728 | while (appended && !history_.empty()) { |
| 729 | appended = AppendEventToString(history_.front().get(), &output_string); |
| 730 | if (appended) { |
| 731 | // Known issue - if writing to the file fails, these events will have |
| 732 | // been lost. If we try to open a new file, these events will be missing |
| 733 | // from it. |
| 734 | history_.pop_front(); |
| 735 | } |
| 736 | } |
| 737 | |
| 738 | // Write to file. |
| 739 | if (!file_->Write(output_string.data(), output_string.size())) { |
| 740 | LOG(LS_ERROR) << "FileWrapper failed to write WebRtcEventLog file."; |
| 741 | // The current FileWrapper implementation closes the file on error. |
| 742 | RTC_DCHECK(!file_->is_open()); |
| 743 | return; |
| 744 | } |
| 745 | written_bytes_ += output_string.size(); |
| 746 | |
| 747 | if (!appended) { |
| 748 | RTC_DCHECK(file_->is_open()); |
| 749 | StopLogFile(rtc::TimeMicros()); |
| 750 | } |
| 751 | } |
| 752 | |
| 753 | void RtcEventLogImpl::LogToFile(std::unique_ptr<rtclog::Event> event) { |
| 754 | RTC_DCHECK_RUN_ON(&task_queue_); |
| 755 | RTC_DCHECK(file_->is_open()); |
| 756 | |
| 757 | ProtoString output_string; |
| 758 | |
| 759 | bool appended = AppendEventToString(event.get(), &output_string); |
| 760 | |
| 761 | if (IsConfigEvent(*event.get())) { |
| 762 | config_history_.push_back(std::move(event)); |
| 763 | } |
| 764 | |
| 765 | if (!appended) { |
| 766 | RTC_DCHECK(file_->is_open()); |
| 767 | history_.push_back(std::move(event)); |
| 768 | StopLogFile(rtc::TimeMicros()); |
| 769 | return; |
| 770 | } |
| 771 | |
| 772 | // Write string to file. |
| 773 | if (file_->Write(output_string.data(), output_string.size())) { |
| 774 | written_bytes_ += output_string.size(); |
| 775 | } else { |
| 776 | LOG(LS_ERROR) << "FileWrapper failed to write WebRtcEventLog file."; |
| 777 | // The current FileWrapper implementation closes the file on error. |
| 778 | RTC_DCHECK(!file_->is_open()); |
| 779 | } |
| 780 | } |
| 781 | |
| 782 | void RtcEventLogImpl::StopLogFile(int64_t stop_time) { |
| 783 | RTC_DCHECK_RUN_ON(&task_queue_); |
| 784 | RTC_DCHECK(file_->is_open()); |
| 785 | |
| 786 | ProtoString output_string; |
| 787 | |
| 788 | rtclog::Event end_event; |
| 789 | end_event.set_timestamp_us(stop_time); |
| 790 | end_event.set_type(rtclog::Event::LOG_END); |
| 791 | bool appended = AppendEventToString(&end_event, &output_string); |
| 792 | |
| 793 | if (appended) { |
| 794 | if (!file_->Write(output_string.data(), output_string.size())) { |
| 795 | LOG(LS_ERROR) << "FileWrapper failed to write WebRtcEventLog file."; |
| 796 | // The current FileWrapper implementation closes the file on error. |
| 797 | RTC_DCHECK(!file_->is_open()); |
| 798 | } |
| 799 | written_bytes_ += output_string.size(); |
| 800 | } |
| 801 | |
| 802 | max_size_bytes_ = std::numeric_limits<decltype(max_size_bytes_)>::max(); |
| 803 | written_bytes_ = 0; |
| 804 | |
| 805 | file_->CloseFile(); |
| 806 | RTC_DCHECK(!file_->is_open()); |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 807 | } |
| 808 | |
| 809 | bool RtcEventLog::ParseRtcEventLog(const std::string& file_name, |
| 810 | rtclog::EventStream* result) { |
| 811 | char tmp_buffer[1024]; |
| 812 | int bytes_read = 0; |
kwiberg | b25345e | 2016-03-12 06:10:44 -0800 | [diff] [blame] | 813 | std::unique_ptr<FileWrapper> dump_file(FileWrapper::Create()); |
tommi | a6219cc | 2016-06-15 10:30:14 -0700 | [diff] [blame] | 814 | if (!dump_file->OpenFile(file_name.c_str(), true)) { |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 815 | return false; |
| 816 | } |
mbonadei | 7c2c843 | 2017-04-07 00:59:12 -0700 | [diff] [blame] | 817 | ProtoString dump_buffer; |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 818 | while ((bytes_read = dump_file->Read(tmp_buffer, sizeof(tmp_buffer))) > 0) { |
| 819 | dump_buffer.append(tmp_buffer, bytes_read); |
| 820 | } |
| 821 | dump_file->CloseFile(); |
| 822 | return result->ParseFromString(dump_buffer); |
| 823 | } |
| 824 | |
| 825 | #endif // ENABLE_RTC_EVENT_LOG |
| 826 | |
| 827 | // RtcEventLog member functions. |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 828 | std::unique_ptr<RtcEventLog> RtcEventLog::Create() { |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 829 | #ifdef ENABLE_RTC_EVENT_LOG |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 830 | // TODO(eladalon): Known issue - there's a race over |log_count_| here. |
terelius | c8e0552 | 2017-06-28 06:40:51 -0700 | [diff] [blame] | 831 | constexpr int kMaxLogCount = 5; |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 832 | int count = 1 + std::atomic_fetch_add(&RtcEventLogImpl::log_count_, 1); |
terelius | c8e0552 | 2017-06-28 06:40:51 -0700 | [diff] [blame] | 833 | if (count > kMaxLogCount) { |
| 834 | LOG(LS_WARNING) << "Denied creation of additional WebRTC event logs. " |
| 835 | << count - 1 << " logs open already."; |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 836 | std::atomic_fetch_sub(&RtcEventLogImpl::log_count_, 1); |
terelius | c8e0552 | 2017-06-28 06:40:51 -0700 | [diff] [blame] | 837 | return std::unique_ptr<RtcEventLog>(new RtcEventLogNullImpl()); |
| 838 | } |
nisse | 3061276 | 2016-12-20 05:03:58 -0800 | [diff] [blame] | 839 | return std::unique_ptr<RtcEventLog>(new RtcEventLogImpl()); |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 840 | #else |
eladalon | 248fd4f | 2017-09-06 05:18:15 -0700 | [diff] [blame] | 841 | return CreateNull(); |
terelius | 4311ba5 | 2016-04-22 12:40:37 -0700 | [diff] [blame] | 842 | #endif // ENABLE_RTC_EVENT_LOG |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 843 | } |
terelius | 1adce14 | 2015-10-16 08:51:08 -0700 | [diff] [blame] | 844 | |
ivoc | 14d5dbe | 2016-07-04 07:06:55 -0700 | [diff] [blame] | 845 | std::unique_ptr<RtcEventLog> RtcEventLog::CreateNull() { |
| 846 | return std::unique_ptr<RtcEventLog>(new RtcEventLogNullImpl()); |
| 847 | } |
| 848 | |
Bjorn Terelius | 3641185 | 2015-07-30 12:45:18 +0200 | [diff] [blame] | 849 | } // namespace webrtc |