blob: b05907e74a17b086febfcd9214042ebd0bb42b6c [file] [log] [blame]
henrike@webrtc.orgf0488722014-05-13 18:00:261/*
2 * Copyright 2004 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 Bonadei92ea95e2017-09-15 04:47:3111#include "rtc_base/logging.h"
Yves Gerey3e707812018-11-28 15:47:4912
Artem Titov6a4a1462019-11-26 15:24:4613#if RTC_LOG_ENABLED()
14
Yves Gerey3e707812018-11-28 15:47:4915#include <string.h>
Jonas Olssona4d87372019-07-05 17:08:3316
Yves Gerey3e707812018-11-28 15:47:4917#include <algorithm>
18
Ali Tofigh6364d082022-03-14 12:32:0419#include "absl/strings/string_view.h"
Tommifef05002018-02-27 12:51:0820#include "rtc_base/arraysize.h"
21#include "rtc_base/checks.h"
22#include "rtc_base/event.h"
Tommifef05002018-02-27 12:51:0823#include "rtc_base/platform_thread.h"
Steve Anton10542f22019-01-11 17:11:0024#include "rtc_base/time_utils.h"
Evan Shrubsole7765f9e2022-04-25 09:04:1225#include "test/gmock.h"
Yves Gerey3e707812018-11-28 15:47:4926#include "test/gtest.h"
henrike@webrtc.orgf0488722014-05-13 18:00:2627
28namespace rtc {
29
Mirko Bonadei70ed4712022-08-03 12:49:4030namespace {
31
32#if defined(WEBRTC_WIN)
33constexpr char kFakeFilePath[] = "some\\path\\myfile.cc";
34#else
35constexpr char kFakeFilePath[] = "some/path/myfile.cc";
36#endif
37
38} // namespace
39
Niels Möllered3f9ec2021-03-29 10:12:2940class LogSinkImpl : public LogSink {
Niels Möllerff3dd0c2018-06-20 08:27:5341 public:
Niels Möllered3f9ec2021-03-29 10:12:2942 explicit LogSinkImpl(std::string* log_data) : log_data_(log_data) {}
Tommi0eefb4d2015-05-23 07:54:0743
Yves Gerey665174f2018-06-19 13:03:0544 template <typename P>
Niels Möllered3f9ec2021-03-29 10:12:2945 explicit LogSinkImpl(P* p) {}
Tommi0eefb4d2015-05-23 07:54:0746
47 private:
48 void OnLogMessage(const std::string& message) override {
Ali Tofigh6364d082022-03-14 12:32:0449 OnLogMessage(absl::string_view(message));
50 }
51 void OnLogMessage(absl::string_view message) override {
52 log_data_->append(message.begin(), message.end());
Tommi0eefb4d2015-05-23 07:54:0753 }
Niels Möllered3f9ec2021-03-29 10:12:2954 std::string* const log_data_;
Tommi0eefb4d2015-05-23 07:54:0755};
56
Tommifef05002018-02-27 12:51:0857class LogMessageForTesting : public LogMessage {
58 public:
59 LogMessageForTesting(const char* file,
60 int line,
61 LoggingSeverity sev,
62 LogErrorContext err_ctx = ERRCTX_NONE,
63 int err = 0)
64 : LogMessage(file, line, sev, err_ctx, err) {}
65
66 const std::string& get_extra() const { return extra_; }
Paulina Hensmanf1e3cb42018-06-20 12:07:0567#if defined(WEBRTC_ANDROID)
Mirko Bonadei96191f82022-08-03 08:12:3368 const char* get_tag() const { return log_line_.tag().data(); }
Paulina Hensmanf1e3cb42018-06-20 12:07:0569#endif
Tommifef05002018-02-27 12:51:0870
71 // Returns the contents of the internal log stream.
72 // Note that parts of the stream won't (as is) be available until *after* the
73 // dtor of the parent class has run. So, as is, this only represents a
74 // partially built stream.
75 std::string GetPrintStream() {
76 RTC_DCHECK(!is_finished_);
77 is_finished_ = true;
78 FinishPrintStream();
Jonas Olssond8c50782018-09-07 09:21:2879 return print_stream_.Release();
Tommifef05002018-02-27 12:51:0880 }
81
82 private:
83 bool is_finished_ = false;
84};
85
henrike@webrtc.orgf0488722014-05-13 18:00:2686// Test basic logging operation. We should get the INFO log but not the VERBOSE.
87// We should restore the correct global state at the end.
88TEST(LogTest, SingleStream) {
deadbeef37f5ecf2017-02-27 22:06:4189 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:2690
91 std::string str;
Niels Möllered3f9ec2021-03-29 10:12:2992 LogSinkImpl stream(&str);
henrike@webrtc.orgf0488722014-05-13 18:00:2693 LogMessage::AddLogToStream(&stream, LS_INFO);
94 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
95
Mirko Bonadei675513b2017-11-09 10:09:2596 RTC_LOG(LS_INFO) << "INFO";
97 RTC_LOG(LS_VERBOSE) << "VERBOSE";
henrike@webrtc.orgf0488722014-05-13 18:00:2698 EXPECT_NE(std::string::npos, str.find("INFO"));
99 EXPECT_EQ(std::string::npos, str.find("VERBOSE"));
100
Jonas Olssonf2ce37c2018-09-12 13:32:47101 int i = 1;
102 long l = 2l;
103 long long ll = 3ll;
104
105 unsigned int u = 4u;
106 unsigned long ul = 5ul;
107 unsigned long long ull = 6ull;
108
109 std::string s1 = "char*";
110 std::string s2 = "std::string";
111 std::string s3 = "absl::stringview";
Niels Möller65835be2019-02-04 18:23:58112 const char* null_string = nullptr;
Jonas Olssonf2ce37c2018-09-12 13:32:47113 void* p = reinterpret_cast<void*>(0xabcd);
114
115 // Log all suported types(except doubles/floats) as a sanity-check.
116 RTC_LOG(LS_INFO) << "|" << i << "|" << l << "|" << ll << "|" << u << "|" << ul
117 << "|" << ull << "|" << s1.c_str() << "|" << s2 << "|"
Niels Möller65835be2019-02-04 18:23:58118 << absl::string_view(s3) << "|" << p << "|" << null_string
119 << "|";
Jonas Olssonf2ce37c2018-09-12 13:32:47120
121 // Signed integers
122 EXPECT_NE(std::string::npos, str.find("|1|"));
123 EXPECT_NE(std::string::npos, str.find("|2|"));
124 EXPECT_NE(std::string::npos, str.find("|3|"));
125
126 // Unsigned integers
127 EXPECT_NE(std::string::npos, str.find("|4|"));
128 EXPECT_NE(std::string::npos, str.find("|5|"));
129 EXPECT_NE(std::string::npos, str.find("|6|"));
130
131 // Strings
132 EXPECT_NE(std::string::npos, str.find("|char*|"));
133 EXPECT_NE(std::string::npos, str.find("|std::string|"));
134 EXPECT_NE(std::string::npos, str.find("|absl::stringview|"));
135
136 // void*
137 EXPECT_NE(std::string::npos, str.find("|abcd|"));
138
Niels Möller65835be2019-02-04 18:23:58139 // null char*
140 EXPECT_NE(std::string::npos, str.find("|(null)|"));
141
henrike@webrtc.orgf0488722014-05-13 18:00:26142 LogMessage::RemoveLogToStream(&stream);
Tommi0eefb4d2015-05-23 07:54:07143 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream));
deadbeef37f5ecf2017-02-27 22:06:41144 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26145}
146
Per Kjellander4d419132022-09-30 10:50:41147TEST(LogTest, LogIfLogIfConditionIsTrue) {
148 std::string str;
149 LogSinkImpl stream(&str);
150 LogMessage::AddLogToStream(&stream, LS_INFO);
151
152 RTC_LOG_IF(LS_INFO, true) << "Hello";
153 EXPECT_NE(std::string::npos, str.find("Hello"));
154
155 LogMessage::RemoveLogToStream(&stream);
156}
157
158TEST(LogTest, LogIfDontLogIfConditionIsFalse) {
159 std::string str;
160 LogSinkImpl stream(&str);
161 LogMessage::AddLogToStream(&stream, LS_INFO);
162
163 RTC_LOG_IF(LS_INFO, false) << "Hello";
164 EXPECT_EQ(std::string::npos, str.find("Hello"));
165
166 LogMessage::RemoveLogToStream(&stream);
167}
168
169TEST(LogTest, LogIfFLogIfConditionIsTrue) {
170 std::string str;
171 LogSinkImpl stream(&str);
172 LogMessage::AddLogToStream(&stream, LS_INFO);
173
174 RTC_LOG_IF_F(LS_INFO, true) << "Hello";
175 EXPECT_NE(std::string::npos, str.find(__FUNCTION__));
176 EXPECT_NE(std::string::npos, str.find("Hello"));
177
178 LogMessage::RemoveLogToStream(&stream);
179}
180
181TEST(LogTest, LogIfFDontLogIfConditionIsFalse) {
182 std::string str;
183 LogSinkImpl stream(&str);
184 LogMessage::AddLogToStream(&stream, LS_INFO);
185
186 RTC_LOG_IF_F(LS_INFO, false) << "Not";
187 EXPECT_EQ(std::string::npos, str.find(__FUNCTION__));
188 EXPECT_EQ(std::string::npos, str.find("Not"));
189
190 LogMessage::RemoveLogToStream(&stream);
191}
192
henrike@webrtc.orgf0488722014-05-13 18:00:26193// Test using multiple log streams. The INFO stream should get the INFO message,
194// the VERBOSE stream should get the INFO and the VERBOSE.
195// We should restore the correct global state at the end.
196TEST(LogTest, MultipleStreams) {
deadbeef37f5ecf2017-02-27 22:06:41197 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:26198
199 std::string str1, str2;
Niels Möllered3f9ec2021-03-29 10:12:29200 LogSinkImpl stream1(&str1), stream2(&str2);
henrike@webrtc.orgf0488722014-05-13 18:00:26201 LogMessage::AddLogToStream(&stream1, LS_INFO);
202 LogMessage::AddLogToStream(&stream2, LS_VERBOSE);
203 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream1));
204 EXPECT_EQ(LS_VERBOSE, LogMessage::GetLogToStream(&stream2));
205
Mirko Bonadei675513b2017-11-09 10:09:25206 RTC_LOG(LS_INFO) << "INFO";
207 RTC_LOG(LS_VERBOSE) << "VERBOSE";
henrike@webrtc.orgf0488722014-05-13 18:00:26208
209 EXPECT_NE(std::string::npos, str1.find("INFO"));
210 EXPECT_EQ(std::string::npos, str1.find("VERBOSE"));
211 EXPECT_NE(std::string::npos, str2.find("INFO"));
212 EXPECT_NE(std::string::npos, str2.find("VERBOSE"));
213
214 LogMessage::RemoveLogToStream(&stream2);
215 LogMessage::RemoveLogToStream(&stream1);
Tommi0eefb4d2015-05-23 07:54:07216 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream2));
217 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream1));
henrike@webrtc.orgf0488722014-05-13 18:00:26218
deadbeef37f5ecf2017-02-27 22:06:41219 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26220}
221
Tommifef05002018-02-27 12:51:08222class LogThread {
henrike@webrtc.orgf0488722014-05-13 18:00:26223 public:
Markus Handellad5037b2021-05-07 13:02:36224 void Start() {
225 thread_ = PlatformThread::SpawnJoinable(
226 [] { RTC_LOG(LS_VERBOSE) << "RTC_LOG"; }, "LogThread");
227 }
henrike@webrtc.orgf0488722014-05-13 18:00:26228
229 private:
Tommifef05002018-02-27 12:51:08230 PlatformThread thread_;
henrike@webrtc.orgf0488722014-05-13 18:00:26231};
232
Tommifef05002018-02-27 12:51:08233// Ensure we don't crash when adding/removing streams while threads are going.
234// We should restore the correct global state at the end.
henrike@webrtc.orgc732a3e2014-10-09 22:08:15235TEST(LogTest, MultipleThreads) {
deadbeef37f5ecf2017-02-27 22:06:41236 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:26237
238 LogThread thread1, thread2, thread3;
239 thread1.Start();
240 thread2.Start();
241 thread3.Start();
242
Niels Möllerff3dd0c2018-06-20 08:27:53243 std::string s1, s2, s3;
Niels Möllered3f9ec2021-03-29 10:12:29244 LogSinkImpl stream1(&s1), stream2(&s2), stream3(&s3);
henrike@webrtc.orgf0488722014-05-13 18:00:26245 for (int i = 0; i < 1000; ++i) {
Niels Möller25aefd32018-11-21 08:34:11246 LogMessage::AddLogToStream(&stream1, LS_WARNING);
247 LogMessage::AddLogToStream(&stream2, LS_INFO);
248 LogMessage::AddLogToStream(&stream3, LS_VERBOSE);
henrike@webrtc.orgf0488722014-05-13 18:00:26249 LogMessage::RemoveLogToStream(&stream1);
250 LogMessage::RemoveLogToStream(&stream2);
251 LogMessage::RemoveLogToStream(&stream3);
252 }
253
deadbeef37f5ecf2017-02-27 22:06:41254 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26255}
256
henrike@webrtc.orgf0488722014-05-13 18:00:26257TEST(LogTest, WallClockStartTime) {
Peter Boström0c4e06b2015-10-07 10:23:21258 uint32_t time = LogMessage::WallClockStartTime();
henrike@webrtc.orgf0488722014-05-13 18:00:26259 // Expect the time to be in a sensible range, e.g. > 2012-01-01.
260 EXPECT_GT(time, 1325376000u);
261}
262
Tommifef05002018-02-27 12:51:08263TEST(LogTest, CheckExtraErrorField) {
Mirko Bonadei70ed4712022-08-03 12:49:40264 LogMessageForTesting log_msg(kFakeFilePath, 100, LS_WARNING, ERRCTX_ERRNO,
265 0xD);
Tommifef05002018-02-27 12:51:08266 log_msg.stream() << "This gets added at dtor time";
phoglundbb738732016-07-15 10:57:12267
Tommifef05002018-02-27 12:51:08268 const std::string& extra = log_msg.get_extra();
269 const size_t length_to_check = arraysize("[0x12345678]") - 1;
270 ASSERT_GE(extra.length(), length_to_check);
271 EXPECT_EQ(std::string("[0x0000000D]"), extra.substr(0, length_to_check));
272}
henrike@webrtc.orgf0488722014-05-13 18:00:26273
Tommifef05002018-02-27 12:51:08274TEST(LogTest, CheckFilePathParsed) {
Mirko Bonadei96191f82022-08-03 08:12:33275 std::string str;
276 LogSinkImpl stream(&str);
277 LogMessage::AddLogToStream(&stream, LS_INFO);
278 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
Paulina Hensmanf1e3cb42018-06-20 12:07:05279#if defined(WEBRTC_ANDROID)
Mirko Bonadei96191f82022-08-03 08:12:33280 const char* tag = nullptr;
Paulina Hensmanf1e3cb42018-06-20 12:07:05281#endif
Mirko Bonadei96191f82022-08-03 08:12:33282 {
Mirko Bonadei70ed4712022-08-03 12:49:40283 LogMessageForTesting log_msg(kFakeFilePath, 100, LS_INFO);
Mirko Bonadei96191f82022-08-03 08:12:33284 log_msg.stream() << "<- Does this look right?";
285#if defined(WEBRTC_ANDROID)
286 tag = log_msg.get_tag();
287#endif
288 }
289
290#if defined(WEBRTC_ANDROID)
291 EXPECT_NE(nullptr, strstr(tag, "myfile.cc"));
292 EXPECT_NE(std::string::npos, str.find("100"));
293#else
294 EXPECT_NE(std::string::npos, str.find("(myfile.cc:100)"));
295#endif
296 LogMessage::RemoveLogToStream(&stream);
Tommifef05002018-02-27 12:51:08297}
298
Paulina Hensmanf1e3cb42018-06-20 12:07:05299#if defined(WEBRTC_ANDROID)
300TEST(LogTest, CheckTagAddedToStringInDefaultOnLogMessageAndroid) {
301 std::string str;
Niels Möllered3f9ec2021-03-29 10:12:29302 LogSinkImpl stream(&str);
Paulina Hensmanf1e3cb42018-06-20 12:07:05303 LogMessage::AddLogToStream(&stream, LS_INFO);
304 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
305
306 RTC_LOG_TAG(LS_INFO, "my_tag") << "INFO";
307 EXPECT_NE(std::string::npos, str.find("INFO"));
308 EXPECT_NE(std::string::npos, str.find("my_tag"));
309}
310#endif
311
Tommifef05002018-02-27 12:51:08312// Test the time required to write 1000 80-character logs to a string.
313TEST(LogTest, Perf) {
314 std::string str;
Niels Möllered3f9ec2021-03-29 10:12:29315 LogSinkImpl stream(&str);
Niels Möller25aefd32018-11-21 08:34:11316 LogMessage::AddLogToStream(&stream, LS_VERBOSE);
henrike@webrtc.orgf0488722014-05-13 18:00:26317
Tommifef05002018-02-27 12:51:08318 const std::string message(80, 'X');
Niels Möller25aefd32018-11-21 08:34:11319 { LogMessageForTesting sanity_check_msg(__FILE__, __LINE__, LS_VERBOSE); }
Tommifef05002018-02-27 12:51:08320
321 // We now know how many bytes the logging framework will tag onto every msg.
322 const size_t logging_overhead = str.size();
323 // Reset the stream to 0 size.
324 str.clear();
325 str.reserve(120000);
326 static const int kRepetitions = 1000;
327
Honghai Zhang82d78622016-05-06 18:29:15328 int64_t start = TimeMillis(), finish;
Tommifef05002018-02-27 12:51:08329 for (int i = 0; i < kRepetitions; ++i) {
Niels Möller25aefd32018-11-21 08:34:11330 LogMessageForTesting(__FILE__, __LINE__, LS_VERBOSE).stream() << message;
henrike@webrtc.orgf0488722014-05-13 18:00:26331 }
Honghai Zhang82d78622016-05-06 18:29:15332 finish = TimeMillis();
henrike@webrtc.orgf0488722014-05-13 18:00:26333
334 LogMessage::RemoveLogToStream(&stream);
henrike@webrtc.orgf0488722014-05-13 18:00:26335
Tommifef05002018-02-27 12:51:08336 EXPECT_EQ(str.size(), (message.size() + logging_overhead) * kRepetitions);
Jonas Olssonb2b20312020-01-14 11:11:31337 RTC_LOG(LS_INFO) << "Total log time: " << TimeDiff(finish, start)
338 << " ms "
339 " total bytes logged: "
340 << str.size();
henrike@webrtc.orgf0488722014-05-13 18:00:26341}
342
Amit Hilbuch10c5a932019-03-18 20:09:18343TEST(LogTest, EnumsAreSupported) {
344 enum class TestEnum { kValue0 = 0, kValue1 = 1 };
345 std::string str;
Niels Möllered3f9ec2021-03-29 10:12:29346 LogSinkImpl stream(&str);
Amit Hilbuch10c5a932019-03-18 20:09:18347 LogMessage::AddLogToStream(&stream, LS_INFO);
348 RTC_LOG(LS_INFO) << "[" << TestEnum::kValue0 << "]";
349 EXPECT_NE(std::string::npos, str.find("[0]"));
350 EXPECT_EQ(std::string::npos, str.find("[1]"));
351 RTC_LOG(LS_INFO) << "[" << TestEnum::kValue1 << "]";
352 EXPECT_NE(std::string::npos, str.find("[1]"));
353 LogMessage::RemoveLogToStream(&stream);
Amit Hilbuch10c5a932019-03-18 20:09:18354}
355
Tomas Gunnarssonedd7f9e2020-09-21 14:44:55356TEST(LogTest, NoopSeverityDoesNotRunStringFormatting) {
357 if (!LogMessage::IsNoop(LS_VERBOSE)) {
358 RTC_LOG(LS_WARNING) << "Skipping test since verbose logging is turned on.";
359 return;
360 }
361 bool was_called = false;
362 auto cb = [&was_called]() {
363 was_called = true;
364 return "This could be an expensive callback.";
365 };
366 RTC_LOG(LS_VERBOSE) << "This should not be logged: " << cb();
367 EXPECT_FALSE(was_called);
368}
369
Evan Shrubsole7765f9e2022-04-25 09:04:12370struct TestStruct {};
371std::string ToLogString(TestStruct foo) {
372 return "bar";
373}
374
375TEST(LogTest, ToLogStringUsedForUnknownTypes) {
376 std::string str;
377 LogSinkImpl stream(&str);
378 LogMessage::AddLogToStream(&stream, LS_INFO);
379 TestStruct t;
380 RTC_LOG(LS_INFO) << t;
381 EXPECT_THAT(str, ::testing::HasSubstr("bar"));
382 LogMessage::RemoveLogToStream(&stream);
383}
384
henrike@webrtc.orgf0488722014-05-13 18:00:26385} // namespace rtc
Tomas Gunnarssonedd7f9e2020-09-21 14:44:55386#endif // RTC_LOG_ENABLED()