blob: 225d66d13d332569d69cb3fb7430ab693b154816 [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
Tommifef05002018-02-27 13:51:08 +010019#include "rtc_base/arraysize.h"
20#include "rtc_base/checks.h"
21#include "rtc_base/event.h"
Tommifef05002018-02-27 13:51:08 +010022#include "rtc_base/platform_thread.h"
Steve Anton10542f22019-01-11 09:11:00 -080023#include "rtc_base/time_utils.h"
Yves Gerey3e707812018-11-28 16:47:49 +010024#include "test/gtest.h"
henrike@webrtc.orgf0488722014-05-13 18:00:26 +000025
26namespace rtc {
27
Niels Möllered3f9ec2021-03-29 12:12:29 +020028class LogSinkImpl : public LogSink {
Niels Möllerff3dd0c2018-06-20 10:27:53 +020029 public:
Niels Möllered3f9ec2021-03-29 12:12:29 +020030 explicit LogSinkImpl(std::string* log_data) : log_data_(log_data) {}
Tommi0eefb4d2015-05-23 09:54:07 +020031
Yves Gerey665174f2018-06-19 15:03:05 +020032 template <typename P>
Niels Möllered3f9ec2021-03-29 12:12:29 +020033 explicit LogSinkImpl(P* p) {}
Tommi0eefb4d2015-05-23 09:54:07 +020034
35 private:
36 void OnLogMessage(const std::string& message) override {
Niels Möllered3f9ec2021-03-29 12:12:29 +020037 log_data_->append(message);
Tommi0eefb4d2015-05-23 09:54:07 +020038 }
Niels Möllered3f9ec2021-03-29 12:12:29 +020039 std::string* const log_data_;
Tommi0eefb4d2015-05-23 09:54:07 +020040};
41
Tommifef05002018-02-27 13:51:08 +010042class LogMessageForTesting : public LogMessage {
43 public:
44 LogMessageForTesting(const char* file,
45 int line,
46 LoggingSeverity sev,
47 LogErrorContext err_ctx = ERRCTX_NONE,
48 int err = 0)
49 : LogMessage(file, line, sev, err_ctx, err) {}
50
51 const std::string& get_extra() const { return extra_; }
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +020052#if defined(WEBRTC_ANDROID)
53 const char* get_tag() const { return tag_; }
54#endif
Tommifef05002018-02-27 13:51:08 +010055
56 // Returns the contents of the internal log stream.
57 // Note that parts of the stream won't (as is) be available until *after* the
58 // dtor of the parent class has run. So, as is, this only represents a
59 // partially built stream.
60 std::string GetPrintStream() {
61 RTC_DCHECK(!is_finished_);
62 is_finished_ = true;
63 FinishPrintStream();
Jonas Olssond8c50782018-09-07 11:21:28 +020064 return print_stream_.Release();
Tommifef05002018-02-27 13:51:08 +010065 }
66
67 private:
68 bool is_finished_ = false;
69};
70
henrike@webrtc.orgf0488722014-05-13 18:00:26 +000071// Test basic logging operation. We should get the INFO log but not the VERBOSE.
72// We should restore the correct global state at the end.
73TEST(LogTest, SingleStream) {
deadbeef37f5ecf2017-02-27 14:06:41 -080074 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +000075
76 std::string str;
Niels Möllered3f9ec2021-03-29 12:12:29 +020077 LogSinkImpl stream(&str);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +000078 LogMessage::AddLogToStream(&stream, LS_INFO);
79 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
80
Mirko Bonadei675513b2017-11-09 11:09:25 +010081 RTC_LOG(LS_INFO) << "INFO";
82 RTC_LOG(LS_VERBOSE) << "VERBOSE";
henrike@webrtc.orgf0488722014-05-13 18:00:26 +000083 EXPECT_NE(std::string::npos, str.find("INFO"));
84 EXPECT_EQ(std::string::npos, str.find("VERBOSE"));
85
Jonas Olssonf2ce37c2018-09-12 15:32:47 +020086 int i = 1;
87 long l = 2l;
88 long long ll = 3ll;
89
90 unsigned int u = 4u;
91 unsigned long ul = 5ul;
92 unsigned long long ull = 6ull;
93
94 std::string s1 = "char*";
95 std::string s2 = "std::string";
96 std::string s3 = "absl::stringview";
Niels Möller65835be2019-02-04 19:23:58 +010097 const char* null_string = nullptr;
Jonas Olssonf2ce37c2018-09-12 15:32:47 +020098 void* p = reinterpret_cast<void*>(0xabcd);
99
100 // Log all suported types(except doubles/floats) as a sanity-check.
101 RTC_LOG(LS_INFO) << "|" << i << "|" << l << "|" << ll << "|" << u << "|" << ul
102 << "|" << ull << "|" << s1.c_str() << "|" << s2 << "|"
Niels Möller65835be2019-02-04 19:23:58 +0100103 << absl::string_view(s3) << "|" << p << "|" << null_string
104 << "|";
Jonas Olssonf2ce37c2018-09-12 15:32:47 +0200105
106 // Signed integers
107 EXPECT_NE(std::string::npos, str.find("|1|"));
108 EXPECT_NE(std::string::npos, str.find("|2|"));
109 EXPECT_NE(std::string::npos, str.find("|3|"));
110
111 // Unsigned integers
112 EXPECT_NE(std::string::npos, str.find("|4|"));
113 EXPECT_NE(std::string::npos, str.find("|5|"));
114 EXPECT_NE(std::string::npos, str.find("|6|"));
115
116 // Strings
117 EXPECT_NE(std::string::npos, str.find("|char*|"));
118 EXPECT_NE(std::string::npos, str.find("|std::string|"));
119 EXPECT_NE(std::string::npos, str.find("|absl::stringview|"));
120
121 // void*
122 EXPECT_NE(std::string::npos, str.find("|abcd|"));
123
Niels Möller65835be2019-02-04 19:23:58 +0100124 // null char*
125 EXPECT_NE(std::string::npos, str.find("|(null)|"));
126
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000127 LogMessage::RemoveLogToStream(&stream);
Tommi0eefb4d2015-05-23 09:54:07 +0200128 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream));
deadbeef37f5ecf2017-02-27 14:06:41 -0800129 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000130}
131
132// Test using multiple log streams. The INFO stream should get the INFO message,
133// the VERBOSE stream should get the INFO and the VERBOSE.
134// We should restore the correct global state at the end.
135TEST(LogTest, MultipleStreams) {
deadbeef37f5ecf2017-02-27 14:06:41 -0800136 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000137
138 std::string str1, str2;
Niels Möllered3f9ec2021-03-29 12:12:29 +0200139 LogSinkImpl stream1(&str1), stream2(&str2);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000140 LogMessage::AddLogToStream(&stream1, LS_INFO);
141 LogMessage::AddLogToStream(&stream2, LS_VERBOSE);
142 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream1));
143 EXPECT_EQ(LS_VERBOSE, LogMessage::GetLogToStream(&stream2));
144
Mirko Bonadei675513b2017-11-09 11:09:25 +0100145 RTC_LOG(LS_INFO) << "INFO";
146 RTC_LOG(LS_VERBOSE) << "VERBOSE";
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000147
148 EXPECT_NE(std::string::npos, str1.find("INFO"));
149 EXPECT_EQ(std::string::npos, str1.find("VERBOSE"));
150 EXPECT_NE(std::string::npos, str2.find("INFO"));
151 EXPECT_NE(std::string::npos, str2.find("VERBOSE"));
152
153 LogMessage::RemoveLogToStream(&stream2);
154 LogMessage::RemoveLogToStream(&stream1);
Tommi0eefb4d2015-05-23 09:54:07 +0200155 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream2));
156 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream1));
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000157
deadbeef37f5ecf2017-02-27 14:06:41 -0800158 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000159}
160
Tommifef05002018-02-27 13:51:08 +0100161class LogThread {
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000162 public:
Tommifef05002018-02-27 13:51:08 +0100163 LogThread() : thread_(&ThreadEntry, this, "LogThread") {}
164 ~LogThread() { thread_.Stop(); }
tommie7251592017-07-14 14:44:46 -0700165
Tommifef05002018-02-27 13:51:08 +0100166 void Start() { thread_.Start(); }
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000167
168 private:
Niels Möller25aefd32018-11-21 09:34:11 +0100169 void Run() { RTC_LOG(LS_VERBOSE) << "RTC_LOG"; }
Tommifef05002018-02-27 13:51:08 +0100170
171 static void ThreadEntry(void* p) { static_cast<LogThread*>(p)->Run(); }
172
173 PlatformThread thread_;
Niels Möllerc572ff32018-11-07 08:43:50 +0100174 Event event_;
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) {
219 LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO);
Tommifef05002018-02-27 13:51:08 +0100220 log_msg.stream() << "<- Does this look right?";
221
222 const std::string stream = log_msg.GetPrintStream();
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +0200223#if defined(WEBRTC_ANDROID)
224 const char* tag = log_msg.get_tag();
225 EXPECT_NE(nullptr, strstr(tag, "myfile.cc"));
226 EXPECT_NE(std::string::npos, stream.find("100"));
227#else
Tommifef05002018-02-27 13:51:08 +0100228 EXPECT_NE(std::string::npos, stream.find("(myfile.cc:100)"));
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +0200229#endif
Tommifef05002018-02-27 13:51:08 +0100230}
231
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +0200232#if defined(WEBRTC_ANDROID)
233TEST(LogTest, CheckTagAddedToStringInDefaultOnLogMessageAndroid) {
234 std::string str;
Niels Möllered3f9ec2021-03-29 12:12:29 +0200235 LogSinkImpl stream(&str);
Paulina Hensmanf1e3cb42018-06-20 14:07:05 +0200236 LogMessage::AddLogToStream(&stream, LS_INFO);
237 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
238
239 RTC_LOG_TAG(LS_INFO, "my_tag") << "INFO";
240 EXPECT_NE(std::string::npos, str.find("INFO"));
241 EXPECT_NE(std::string::npos, str.find("my_tag"));
242}
243#endif
244
Tommifef05002018-02-27 13:51:08 +0100245// Test the time required to write 1000 80-character logs to a string.
246TEST(LogTest, Perf) {
247 std::string str;
Niels Möllered3f9ec2021-03-29 12:12:29 +0200248 LogSinkImpl stream(&str);
Niels Möller25aefd32018-11-21 09:34:11 +0100249 LogMessage::AddLogToStream(&stream, LS_VERBOSE);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000250
Tommifef05002018-02-27 13:51:08 +0100251 const std::string message(80, 'X');
Niels Möller25aefd32018-11-21 09:34:11 +0100252 { LogMessageForTesting sanity_check_msg(__FILE__, __LINE__, LS_VERBOSE); }
Tommifef05002018-02-27 13:51:08 +0100253
254 // We now know how many bytes the logging framework will tag onto every msg.
255 const size_t logging_overhead = str.size();
256 // Reset the stream to 0 size.
257 str.clear();
258 str.reserve(120000);
259 static const int kRepetitions = 1000;
260
Honghai Zhang82d78622016-05-06 11:29:15 -0700261 int64_t start = TimeMillis(), finish;
Tommifef05002018-02-27 13:51:08 +0100262 for (int i = 0; i < kRepetitions; ++i) {
Niels Möller25aefd32018-11-21 09:34:11 +0100263 LogMessageForTesting(__FILE__, __LINE__, LS_VERBOSE).stream() << message;
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000264 }
Honghai Zhang82d78622016-05-06 11:29:15 -0700265 finish = TimeMillis();
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000266
267 LogMessage::RemoveLogToStream(&stream);
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000268
Tommifef05002018-02-27 13:51:08 +0100269 EXPECT_EQ(str.size(), (message.size() + logging_overhead) * kRepetitions);
Jonas Olssonb2b20312020-01-14 12:11:31 +0100270 RTC_LOG(LS_INFO) << "Total log time: " << TimeDiff(finish, start)
271 << " ms "
272 " total bytes logged: "
273 << str.size();
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000274}
275
Amit Hilbuch10c5a932019-03-18 13:09:18 -0700276TEST(LogTest, EnumsAreSupported) {
277 enum class TestEnum { kValue0 = 0, kValue1 = 1 };
278 std::string str;
Niels Möllered3f9ec2021-03-29 12:12:29 +0200279 LogSinkImpl stream(&str);
Amit Hilbuch10c5a932019-03-18 13:09:18 -0700280 LogMessage::AddLogToStream(&stream, LS_INFO);
281 RTC_LOG(LS_INFO) << "[" << TestEnum::kValue0 << "]";
282 EXPECT_NE(std::string::npos, str.find("[0]"));
283 EXPECT_EQ(std::string::npos, str.find("[1]"));
284 RTC_LOG(LS_INFO) << "[" << TestEnum::kValue1 << "]";
285 EXPECT_NE(std::string::npos, str.find("[1]"));
286 LogMessage::RemoveLogToStream(&stream);
Amit Hilbuch10c5a932019-03-18 13:09:18 -0700287}
288
Tomas Gunnarssonedd7f9e2020-09-21 16:44:55 +0200289TEST(LogTest, NoopSeverityDoesNotRunStringFormatting) {
290 if (!LogMessage::IsNoop(LS_VERBOSE)) {
291 RTC_LOG(LS_WARNING) << "Skipping test since verbose logging is turned on.";
292 return;
293 }
294 bool was_called = false;
295 auto cb = [&was_called]() {
296 was_called = true;
297 return "This could be an expensive callback.";
298 };
299 RTC_LOG(LS_VERBOSE) << "This should not be logged: " << cb();
300 EXPECT_FALSE(was_called);
301}
302
henrike@webrtc.orgf0488722014-05-13 18:00:26 +0000303} // namespace rtc
Tomas Gunnarssonedd7f9e2020-09-21 16:44:55 +0200304#endif // RTC_LOG_ENABLED()