1 /*
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
11 #include "rtc_base/logging.h"
12
13 #if RTC_LOG_ENABLED()
14
15 #include <string.h>
16
17 #include <algorithm>
18
19 #include "absl/strings/string_view.h"
20 #include "rtc_base/arraysize.h"
21 #include "rtc_base/checks.h"
22 #include "rtc_base/event.h"
23 #include "rtc_base/platform_thread.h"
24 #include "rtc_base/time_utils.h"
25 #include "test/gmock.h"
26 #include "test/gtest.h"
27
28 namespace rtc {
29
30 namespace {
31
32 #if defined(WEBRTC_WIN)
33 constexpr char kFakeFilePath[] = "some\\path\\myfile.cc";
34 #else
35 constexpr char kFakeFilePath[] = "some/path/myfile.cc";
36 #endif
37
38 } // namespace
39
40 class LogSinkImpl : public LogSink {
41 public:
LogSinkImpl(std::string * log_data)42 explicit LogSinkImpl(std::string* log_data) : log_data_(log_data) {}
43
44 template <typename P>
LogSinkImpl(P * p)45 explicit LogSinkImpl(P* p) {}
46
47 private:
OnLogMessage(const std::string & message)48 void OnLogMessage(const std::string& message) override {
49 OnLogMessage(absl::string_view(message));
50 }
OnLogMessage(absl::string_view message)51 void OnLogMessage(absl::string_view message) override {
52 log_data_->append(message.begin(), message.end());
53 }
54 std::string* const log_data_;
55 };
56
57 class LogMessageForTesting : public LogMessage {
58 public:
LogMessageForTesting(const char * file,int line,LoggingSeverity sev,LogErrorContext err_ctx=ERRCTX_NONE,int err=0)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
get_extra() const66 const std::string& get_extra() const { return extra_; }
67 #if defined(WEBRTC_ANDROID)
get_tag() const68 const char* get_tag() const { return log_line_.tag().data(); }
69 #endif
70
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.
GetPrintStream()75 std::string GetPrintStream() {
76 RTC_DCHECK(!is_finished_);
77 is_finished_ = true;
78 FinishPrintStream();
79 return print_stream_.Release();
80 }
81
82 private:
83 bool is_finished_ = false;
84 };
85
86 // 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.
TEST(LogTest,SingleStream)88 TEST(LogTest, SingleStream) {
89 int sev = LogMessage::GetLogToStream(nullptr);
90
91 std::string str;
92 LogSinkImpl stream(&str);
93 LogMessage::AddLogToStream(&stream, LS_INFO);
94 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
95
96 RTC_LOG(LS_INFO) << "INFO";
97 RTC_LOG(LS_VERBOSE) << "VERBOSE";
98 EXPECT_NE(std::string::npos, str.find("INFO"));
99 EXPECT_EQ(std::string::npos, str.find("VERBOSE"));
100
101 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";
112 const char* null_string = nullptr;
113 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 << "|"
118 << absl::string_view(s3) << "|" << p << "|" << null_string
119 << "|";
120
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
139 // null char*
140 EXPECT_NE(std::string::npos, str.find("|(null)|"));
141
142 LogMessage::RemoveLogToStream(&stream);
143 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream));
144 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
145 }
146
TEST(LogTest,LogIfLogIfConditionIsTrue)147 TEST(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
TEST(LogTest,LogIfDontLogIfConditionIsFalse)158 TEST(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
TEST(LogTest,LogIfFLogIfConditionIsTrue)169 TEST(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
TEST(LogTest,LogIfFDontLogIfConditionIsFalse)181 TEST(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
193 // 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.
TEST(LogTest,MultipleStreams)196 TEST(LogTest, MultipleStreams) {
197 int sev = LogMessage::GetLogToStream(nullptr);
198
199 std::string str1, str2;
200 LogSinkImpl stream1(&str1), stream2(&str2);
201 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
206 RTC_LOG(LS_INFO) << "INFO";
207 RTC_LOG(LS_VERBOSE) << "VERBOSE";
208
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);
216 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream2));
217 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream1));
218
219 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
220 }
221
222 class LogThread {
223 public:
Start()224 void Start() {
225 thread_ = PlatformThread::SpawnJoinable(
226 [] { RTC_LOG(LS_VERBOSE) << "RTC_LOG"; }, "LogThread");
227 }
228
229 private:
230 PlatformThread thread_;
231 };
232
233 // Ensure we don't crash when adding/removing streams while threads are going.
234 // We should restore the correct global state at the end.
TEST(LogTest,MultipleThreads)235 TEST(LogTest, MultipleThreads) {
236 int sev = LogMessage::GetLogToStream(nullptr);
237
238 LogThread thread1, thread2, thread3;
239 thread1.Start();
240 thread2.Start();
241 thread3.Start();
242
243 std::string s1, s2, s3;
244 LogSinkImpl stream1(&s1), stream2(&s2), stream3(&s3);
245 for (int i = 0; i < 1000; ++i) {
246 LogMessage::AddLogToStream(&stream1, LS_WARNING);
247 LogMessage::AddLogToStream(&stream2, LS_INFO);
248 LogMessage::AddLogToStream(&stream3, LS_VERBOSE);
249 LogMessage::RemoveLogToStream(&stream1);
250 LogMessage::RemoveLogToStream(&stream2);
251 LogMessage::RemoveLogToStream(&stream3);
252 }
253
254 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
255 }
256
TEST(LogTest,WallClockStartTime)257 TEST(LogTest, WallClockStartTime) {
258 uint32_t time = LogMessage::WallClockStartTime();
259 // Expect the time to be in a sensible range, e.g. > 2012-01-01.
260 EXPECT_GT(time, 1325376000u);
261 }
262
TEST(LogTest,CheckExtraErrorField)263 TEST(LogTest, CheckExtraErrorField) {
264 LogMessageForTesting log_msg(kFakeFilePath, 100, LS_WARNING, ERRCTX_ERRNO,
265 0xD);
266 log_msg.stream() << "This gets added at dtor time";
267
268 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 }
273
TEST(LogTest,CheckFilePathParsed)274 TEST(LogTest, CheckFilePathParsed) {
275 std::string str;
276 LogSinkImpl stream(&str);
277 LogMessage::AddLogToStream(&stream, LS_INFO);
278 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
279 #if defined(WEBRTC_ANDROID)
280 const char* tag = nullptr;
281 #endif
282 {
283 LogMessageForTesting log_msg(kFakeFilePath, 100, LS_INFO);
284 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);
297 }
298
299 #if defined(WEBRTC_ANDROID)
TEST(LogTest,CheckTagAddedToStringInDefaultOnLogMessageAndroid)300 TEST(LogTest, CheckTagAddedToStringInDefaultOnLogMessageAndroid) {
301 std::string str;
302 LogSinkImpl stream(&str);
303 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
312 // Test the time required to write 1000 80-character logs to a string.
TEST(LogTest,Perf)313 TEST(LogTest, Perf) {
314 std::string str;
315 LogSinkImpl stream(&str);
316 LogMessage::AddLogToStream(&stream, LS_VERBOSE);
317
318 const std::string message(80, 'X');
319 { LogMessageForTesting sanity_check_msg(__FILE__, __LINE__, LS_VERBOSE); }
320
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
328 int64_t start = TimeMillis(), finish;
329 for (int i = 0; i < kRepetitions; ++i) {
330 LogMessageForTesting(__FILE__, __LINE__, LS_VERBOSE).stream() << message;
331 }
332 finish = TimeMillis();
333
334 LogMessage::RemoveLogToStream(&stream);
335
336 EXPECT_EQ(str.size(), (message.size() + logging_overhead) * kRepetitions);
337 RTC_LOG(LS_INFO) << "Total log time: " << TimeDiff(finish, start)
338 << " ms "
339 " total bytes logged: "
340 << str.size();
341 }
342
TEST(LogTest,EnumsAreSupported)343 TEST(LogTest, EnumsAreSupported) {
344 enum class TestEnum { kValue0 = 0, kValue1 = 1 };
345 std::string str;
346 LogSinkImpl stream(&str);
347 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);
354 }
355
TEST(LogTest,NoopSeverityDoesNotRunStringFormatting)356 TEST(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
370 struct TestStruct {};
ToLogString(TestStruct foo)371 std::string ToLogString(TestStruct foo) {
372 return "bar";
373 }
374
TEST(LogTest,ToLogStringUsedForUnknownTypes)375 TEST(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
385 } // namespace rtc
386 #endif // RTC_LOG_ENABLED()
387