blob: 2c6a6be20929de6245ddf6f82fc5ae297a48f3fd [file] [log] [blame]
henrike@webrtc.orgf0488722014-05-13 18:00:26 +00001/*
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 06:47:31 +020011#include "rtc_base/logging.h"
Yves Gerey3e707812018-11-28 16:47:49 +010012
Artem Titov6a4a1462019-11-26 16:24:46 +010013#if RTC_LOG_ENABLED()
14
Yves Gerey3e707812018-11-28 16:47:49 +010015#include <string.h>
Jonas Olssona4d87372019-07-05 19:08:33 +020016
Yves Gerey3e707812018-11-28 16:47:49 +010017#include <algorithm>
18
Ali Tofigh6364d082022-03-14 13:32:04 +010019#include "absl/strings/string_view.h"
Tommifef05002018-02-27 13:51:08 +010020#include "rtc_base/arraysize.h"
21#include "rtc_base/checks.h"
22#include "rtc_base/event.h"
Tommifef05002018-02-27 13:51:08 +010023#include "rtc_base/platform_thread.h"
Steve Anton10542f22019-01-11 09:11:00 -080024#include "rtc_base/time_utils.h"
Evan Shrubsole7765f9e2022-04-25 11:04:12 +020025#include "test/gmock.h"
Yves Gerey3e707812018-11-28 16:47:49 +010026#include "test/gtest.h"
henrike@webrtc.orgf0488722014-05-13 18:00:26 +000027
28namespace rtc {
29
Niels Möllered3f9ec2021-03-29 12:12:29 +020030class LogSinkImpl : public LogSink {
Niels Möllerff3dd0c2018-06-20 10:27:53 +020031 public:
Niels Möllered3f9ec2021-03-29 12:12:29 +020032 explicit LogSinkImpl(std::string* log_data) : log_data_(log_data) {}
Tommi0eefb4d2015-05-23 09:54:07 +020033
Yves Gerey665174f2018-06-19 15:03:05 +020034 template <typename P>
Niels Möllered3f9ec2021-03-29 12:12:29 +020035 explicit LogSinkImpl(P* p) {}
Tommi0eefb4d2015-05-23 09:54:07 +020036
37 private:
38 void OnLogMessage(const std::string& message) override {
Ali Tofigh6364d082022-03-14 13:32:04 +010039 OnLogMessage(absl::string_view(message));
40 }
41 void OnLogMessage(absl::string_view message) override {
42 log_data_->append(message.begin(), message.end());
Tommi0eefb4d2015-05-23 09:54:07 +020043 }
Niels Möllered3f9ec2021-03-29 12:12:29 +020044 std::string* const log_data_;
Tommi0eefb4d2015-05-23 09:54:07 +020045};
46
Tommifef05002018-02-27 13:51:08 +010047class LogMessageForTesting : public LogMessage {
48 public:
49 LogMessageForTesting(const char* file,
50 int line,
51 LoggingSeverity sev,
52 LogErrorContext err_ctx = ERRCTX_NONE,
53 int err = 0)
54 : LogMessage(file, line, sev, err_ctx, err) {}
55
56 const std::string& get_extra() const { return extra_; }
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +020057#if defined(WEBRTC_ANDROID)
Mirko Bonadei96191f82022-08-03 08:12:33 +000058 const char* get_tag() const { return log_line_.tag().data(); }
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +020059#endif
Tommifef05002018-02-27 13:51:08 +010060
61 // Returns the contents of the internal log stream.
62 // Note that parts of the stream won't (as is) be available until *after* the
63 // dtor of the parent class has run. So, as is, this only represents a
64 // partially built stream.
65 std::string GetPrintStream() {
66 RTC_DCHECK(!is_finished_);
67 is_finished_ = true;
68 FinishPrintStream();
Jonas Olssond8c50782018-09-07 11:21:28 +020069 return print_stream_.Release();
Tommifef05002018-02-27 13:51:08 +010070 }
71
72 private:
73 bool is_finished_ = false;
74};
75
henrike@webrtc.orgf0488722014-05-13 18:00:26 +000076// Test basic logging operation. We should get the INFO log but not the VERBOSE.
77// We should restore the correct global state at the end.
78TEST(LogTest, SingleStream) {
deadbeef37f5ecf2017-02-27 14:06:41 -080079 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +000080
81 std::string str;
Niels Möllered3f9ec2021-03-29 12:12:29 +020082 LogSinkImpl stream(&str);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +000083 LogMessage::AddLogToStream(&stream, LS_INFO);
84 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
85
Mirko Bonadei675513b2017-11-09 11:09:25 +010086 RTC_LOG(LS_INFO) << "INFO";
87 RTC_LOG(LS_VERBOSE) << "VERBOSE";
henrike@webrtc.orgf0488722014-05-13 18:00:26 +000088 EXPECT_NE(std::string::npos, str.find("INFO"));
89 EXPECT_EQ(std::string::npos, str.find("VERBOSE"));
90
Jonas Olssonf2ce37c2018-09-12 15:32:47 +020091 int i = 1;
92 long l = 2l;
93 long long ll = 3ll;
94
95 unsigned int u = 4u;
96 unsigned long ul = 5ul;
97 unsigned long long ull = 6ull;
98
99 std::string s1 = "char*";
100 std::string s2 = "std::string";
101 std::string s3 = "absl::stringview";
Niels Möller65835be2019-02-04 19:23:58 +0100102 const char* null_string = nullptr;
Jonas Olssonf2ce37c2018-09-12 15:32:47 +0200103 void* p = reinterpret_cast<void*>(0xabcd);
104
105 // Log all suported types(except doubles/floats) as a sanity-check.
106 RTC_LOG(LS_INFO) << "|" << i << "|" << l << "|" << ll << "|" << u << "|" << ul
107 << "|" << ull << "|" << s1.c_str() << "|" << s2 << "|"
Niels Möller65835be2019-02-04 19:23:58 +0100108 << absl::string_view(s3) << "|" << p << "|" << null_string
109 << "|";
Jonas Olssonf2ce37c2018-09-12 15:32:47 +0200110
111 // Signed integers
112 EXPECT_NE(std::string::npos, str.find("|1|"));
113 EXPECT_NE(std::string::npos, str.find("|2|"));
114 EXPECT_NE(std::string::npos, str.find("|3|"));
115
116 // Unsigned integers
117 EXPECT_NE(std::string::npos, str.find("|4|"));
118 EXPECT_NE(std::string::npos, str.find("|5|"));
119 EXPECT_NE(std::string::npos, str.find("|6|"));
120
121 // Strings
122 EXPECT_NE(std::string::npos, str.find("|char*|"));
123 EXPECT_NE(std::string::npos, str.find("|std::string|"));
124 EXPECT_NE(std::string::npos, str.find("|absl::stringview|"));
125
126 // void*
127 EXPECT_NE(std::string::npos, str.find("|abcd|"));
128
Niels Möller65835be2019-02-04 19:23:58 +0100129 // null char*
130 EXPECT_NE(std::string::npos, str.find("|(null)|"));
131
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000132 LogMessage::RemoveLogToStream(&stream);
Tommi0eefb4d2015-05-23 09:54:07 +0200133 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream));
deadbeef37f5ecf2017-02-27 14:06:41 -0800134 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000135}
136
137// Test using multiple log streams. The INFO stream should get the INFO message,
138// the VERBOSE stream should get the INFO and the VERBOSE.
139// We should restore the correct global state at the end.
140TEST(LogTest, MultipleStreams) {
deadbeef37f5ecf2017-02-27 14:06:41 -0800141 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000142
143 std::string str1, str2;
Niels Möllered3f9ec2021-03-29 12:12:29 +0200144 LogSinkImpl stream1(&str1), stream2(&str2);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000145 LogMessage::AddLogToStream(&stream1, LS_INFO);
146 LogMessage::AddLogToStream(&stream2, LS_VERBOSE);
147 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream1));
148 EXPECT_EQ(LS_VERBOSE, LogMessage::GetLogToStream(&stream2));
149
Mirko Bonadei675513b2017-11-09 11:09:25 +0100150 RTC_LOG(LS_INFO) << "INFO";
151 RTC_LOG(LS_VERBOSE) << "VERBOSE";
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000152
153 EXPECT_NE(std::string::npos, str1.find("INFO"));
154 EXPECT_EQ(std::string::npos, str1.find("VERBOSE"));
155 EXPECT_NE(std::string::npos, str2.find("INFO"));
156 EXPECT_NE(std::string::npos, str2.find("VERBOSE"));
157
158 LogMessage::RemoveLogToStream(&stream2);
159 LogMessage::RemoveLogToStream(&stream1);
Tommi0eefb4d2015-05-23 09:54:07 +0200160 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream2));
161 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream1));
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000162
deadbeef37f5ecf2017-02-27 14:06:41 -0800163 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000164}
165
Tommifef05002018-02-27 13:51:08 +0100166class LogThread {
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000167 public:
Markus Handellad5037b2021-05-07 15:02:36 +0200168 void Start() {
169 thread_ = PlatformThread::SpawnJoinable(
170 [] { RTC_LOG(LS_VERBOSE) << "RTC_LOG"; }, "LogThread");
171 }
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000172
173 private:
Tommifef05002018-02-27 13:51:08 +0100174 PlatformThread thread_;
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000175};
176
Tommifef05002018-02-27 13:51:08 +0100177// Ensure we don't crash when adding/removing streams while threads are going.
178// We should restore the correct global state at the end.
henrike@webrtc.orgc732a3e2014-10-09 22:08:15 +0000179TEST(LogTest, MultipleThreads) {
deadbeef37f5ecf2017-02-27 14:06:41 -0800180 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000181
182 LogThread thread1, thread2, thread3;
183 thread1.Start();
184 thread2.Start();
185 thread3.Start();
186
Niels Möllerff3dd0c2018-06-20 10:27:53 +0200187 std::string s1, s2, s3;
Niels Möllered3f9ec2021-03-29 12:12:29 +0200188 LogSinkImpl stream1(&s1), stream2(&s2), stream3(&s3);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000189 for (int i = 0; i < 1000; ++i) {
Niels Möller25aefd32018-11-21 09:34:11 +0100190 LogMessage::AddLogToStream(&stream1, LS_WARNING);
191 LogMessage::AddLogToStream(&stream2, LS_INFO);
192 LogMessage::AddLogToStream(&stream3, LS_VERBOSE);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000193 LogMessage::RemoveLogToStream(&stream1);
194 LogMessage::RemoveLogToStream(&stream2);
195 LogMessage::RemoveLogToStream(&stream3);
196 }
197
deadbeef37f5ecf2017-02-27 14:06:41 -0800198 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000199}
200
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000201TEST(LogTest, WallClockStartTime) {
Peter Boström0c4e06b2015-10-07 12:23:21 +0200202 uint32_t time = LogMessage::WallClockStartTime();
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000203 // Expect the time to be in a sensible range, e.g. > 2012-01-01.
204 EXPECT_GT(time, 1325376000u);
205}
206
Tommifef05002018-02-27 13:51:08 +0100207TEST(LogTest, CheckExtraErrorField) {
208 LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_WARNING,
209 ERRCTX_ERRNO, 0xD);
Tommifef05002018-02-27 13:51:08 +0100210 log_msg.stream() << "This gets added at dtor time";
phoglundbb738732016-07-15 03:57:12 -0700211
Tommifef05002018-02-27 13:51:08 +0100212 const std::string& extra = log_msg.get_extra();
213 const size_t length_to_check = arraysize("[0x12345678]") - 1;
214 ASSERT_GE(extra.length(), length_to_check);
215 EXPECT_EQ(std::string("[0x0000000D]"), extra.substr(0, length_to_check));
216}
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000217
Tommifef05002018-02-27 13:51:08 +0100218TEST(LogTest, CheckFilePathParsed) {
Mirko Bonadei96191f82022-08-03 08:12:33 +0000219 std::string str;
220 LogSinkImpl stream(&str);
221 LogMessage::AddLogToStream(&stream, LS_INFO);
222 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +0200223#if defined(WEBRTC_ANDROID)
Mirko Bonadei96191f82022-08-03 08:12:33 +0000224 const char* tag = nullptr;
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +0200225#endif
Mirko Bonadei96191f82022-08-03 08:12:33 +0000226 {
227 LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO);
228 log_msg.stream() << "<- Does this look right?";
229#if defined(WEBRTC_ANDROID)
230 tag = log_msg.get_tag();
231#endif
232 }
233
234#if defined(WEBRTC_ANDROID)
235 EXPECT_NE(nullptr, strstr(tag, "myfile.cc"));
236 EXPECT_NE(std::string::npos, str.find("100"));
237#else
238 EXPECT_NE(std::string::npos, str.find("(myfile.cc:100)"));
239#endif
240 LogMessage::RemoveLogToStream(&stream);
Tommifef05002018-02-27 13:51:08 +0100241}
242
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +0200243#if defined(WEBRTC_ANDROID)
244TEST(LogTest, CheckTagAddedToStringInDefaultOnLogMessageAndroid) {
245 std::string str;
Niels Möllered3f9ec2021-03-29 12:12:29 +0200246 LogSinkImpl stream(&str);
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +0200247 LogMessage::AddLogToStream(&stream, LS_INFO);
248 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
249
250 RTC_LOG_TAG(LS_INFO, "my_tag") << "INFO";
251 EXPECT_NE(std::string::npos, str.find("INFO"));
252 EXPECT_NE(std::string::npos, str.find("my_tag"));
253}
254#endif
255
Tommifef05002018-02-27 13:51:08 +0100256// Test the time required to write 1000 80-character logs to a string.
257TEST(LogTest, Perf) {
258 std::string str;
Niels Möllered3f9ec2021-03-29 12:12:29 +0200259 LogSinkImpl stream(&str);
Niels Möller25aefd32018-11-21 09:34:11 +0100260 LogMessage::AddLogToStream(&stream, LS_VERBOSE);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000261
Tommifef05002018-02-27 13:51:08 +0100262 const std::string message(80, 'X');
Niels Möller25aefd32018-11-21 09:34:11 +0100263 { LogMessageForTesting sanity_check_msg(__FILE__, __LINE__, LS_VERBOSE); }
Tommifef05002018-02-27 13:51:08 +0100264
265 // We now know how many bytes the logging framework will tag onto every msg.
266 const size_t logging_overhead = str.size();
267 // Reset the stream to 0 size.
268 str.clear();
269 str.reserve(120000);
270 static const int kRepetitions = 1000;
271
Honghai Zhang82d78622016-05-06 11:29:15 -0700272 int64_t start = TimeMillis(), finish;
Tommifef05002018-02-27 13:51:08 +0100273 for (int i = 0; i < kRepetitions; ++i) {
Niels Möller25aefd32018-11-21 09:34:11 +0100274 LogMessageForTesting(__FILE__, __LINE__, LS_VERBOSE).stream() << message;
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000275 }
Honghai Zhang82d78622016-05-06 11:29:15 -0700276 finish = TimeMillis();
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000277
278 LogMessage::RemoveLogToStream(&stream);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000279
Tommifef05002018-02-27 13:51:08 +0100280 EXPECT_EQ(str.size(), (message.size() + logging_overhead) * kRepetitions);
Jonas Olssonb2b20312020-01-14 12:11:31 +0100281 RTC_LOG(LS_INFO) << "Total log time: " << TimeDiff(finish, start)
282 << " ms "
283 " total bytes logged: "
284 << str.size();
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000285}
286
Amit Hilbuch10c5a932019-03-18 13:09:18 -0700287TEST(LogTest, EnumsAreSupported) {
288 enum class TestEnum { kValue0 = 0, kValue1 = 1 };
289 std::string str;
Niels Möllered3f9ec2021-03-29 12:12:29 +0200290 LogSinkImpl stream(&str);
Amit Hilbuch10c5a932019-03-18 13:09:18 -0700291 LogMessage::AddLogToStream(&stream, LS_INFO);
292 RTC_LOG(LS_INFO) << "[" << TestEnum::kValue0 << "]";
293 EXPECT_NE(std::string::npos, str.find("[0]"));
294 EXPECT_EQ(std::string::npos, str.find("[1]"));
295 RTC_LOG(LS_INFO) << "[" << TestEnum::kValue1 << "]";
296 EXPECT_NE(std::string::npos, str.find("[1]"));
297 LogMessage::RemoveLogToStream(&stream);
Amit Hilbuch10c5a932019-03-18 13:09:18 -0700298}
299
Tomas Gunnarssonedd7f9e2020-09-21 16:44:55 +0200300TEST(LogTest, NoopSeverityDoesNotRunStringFormatting) {
301 if (!LogMessage::IsNoop(LS_VERBOSE)) {
302 RTC_LOG(LS_WARNING) << "Skipping test since verbose logging is turned on.";
303 return;
304 }
305 bool was_called = false;
306 auto cb = [&was_called]() {
307 was_called = true;
308 return "This could be an expensive callback.";
309 };
310 RTC_LOG(LS_VERBOSE) << "This should not be logged: " << cb();
311 EXPECT_FALSE(was_called);
312}
313
Evan Shrubsole7765f9e2022-04-25 11:04:12 +0200314struct TestStruct {};
315std::string ToLogString(TestStruct foo) {
316 return "bar";
317}
318
319TEST(LogTest, ToLogStringUsedForUnknownTypes) {
320 std::string str;
321 LogSinkImpl stream(&str);
322 LogMessage::AddLogToStream(&stream, LS_INFO);
323 TestStruct t;
324 RTC_LOG(LS_INFO) << t;
325 EXPECT_THAT(str, ::testing::HasSubstr("bar"));
326 LogMessage::RemoveLogToStream(&stream);
327}
328
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000329} // namespace rtc
Tomas Gunnarssonedd7f9e2020-09-21 16:44:55 +0200330#endif // RTC_LOG_ENABLED()