blob: 54f65496cfbac78e849d1229fd44ca79aa46c321 [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
13#include <string.h>
14#include <algorithm>
15
Tommifef05002018-02-27 12:51:0816#include "rtc_base/arraysize.h"
17#include "rtc_base/checks.h"
18#include "rtc_base/event.h"
Tommifef05002018-02-27 12:51:0819#include "rtc_base/platform_thread.h"
Mirko Bonadei92ea95e2017-09-15 04:47:3120#include "rtc_base/stream.h"
Steve Anton10542f22019-01-11 17:11:0021#include "rtc_base/time_utils.h"
Yves Gerey3e707812018-11-28 15:47:4922#include "test/gtest.h"
henrike@webrtc.orgf0488722014-05-13 18:00:2623
24namespace rtc {
25
Niels Möllerff3dd0c2018-06-20 08:27:5326namespace {
27
28class StringStream : public StreamInterface {
29 public:
30 explicit StringStream(std::string* str);
31 explicit StringStream(const std::string& str);
32
33 StreamState GetState() const override;
34 StreamResult Read(void* buffer,
35 size_t buffer_len,
36 size_t* read,
37 int* error) override;
38 StreamResult Write(const void* data,
39 size_t data_len,
40 size_t* written,
41 int* error) override;
42 void Close() override;
Niels Möllerff3dd0c2018-06-20 08:27:5343
44 private:
45 std::string& str_;
46 size_t read_pos_;
47 bool read_only_;
48};
49
50StringStream::StringStream(std::string* str)
51 : str_(*str), read_pos_(0), read_only_(false) {}
52
53StringStream::StringStream(const std::string& str)
54 : str_(const_cast<std::string&>(str)), read_pos_(0), read_only_(true) {}
55
56StreamState StringStream::GetState() const {
57 return SS_OPEN;
58}
59
60StreamResult StringStream::Read(void* buffer,
61 size_t buffer_len,
62 size_t* read,
63 int* error) {
64 size_t available = std::min(buffer_len, str_.size() - read_pos_);
65 if (!available)
66 return SR_EOS;
67 memcpy(buffer, str_.data() + read_pos_, available);
68 read_pos_ += available;
69 if (read)
70 *read = available;
71 return SR_SUCCESS;
72}
73
74StreamResult StringStream::Write(const void* data,
75 size_t data_len,
76 size_t* written,
77 int* error) {
78 if (read_only_) {
79 if (error) {
80 *error = -1;
81 }
82 return SR_ERROR;
83 }
84 str_.append(static_cast<const char*>(data),
85 static_cast<const char*>(data) + data_len);
86 if (written)
87 *written = data_len;
88 return SR_SUCCESS;
89}
90
91void StringStream::Close() {}
92
Niels Möllerff3dd0c2018-06-20 08:27:5393} // namespace
94
Tommi0eefb4d2015-05-23 07:54:0795template <typename Base>
Yves Gerey665174f2018-06-19 13:03:0596class LogSinkImpl : public LogSink, public Base {
Tommi0eefb4d2015-05-23 07:54:0797 public:
98 LogSinkImpl() {}
99
Yves Gerey665174f2018-06-19 13:03:05100 template <typename P>
Tommi00aac5a2015-05-25 09:25:59101 explicit LogSinkImpl(P* p) : Base(p) {}
Tommi0eefb4d2015-05-23 07:54:07102
103 private:
104 void OnLogMessage(const std::string& message) override {
Yves Gerey665174f2018-06-19 13:03:05105 static_cast<Base*>(this)->WriteAll(message.data(), message.size(), nullptr,
106 nullptr);
Tommi0eefb4d2015-05-23 07:54:07107 }
108};
109
Tommifef05002018-02-27 12:51:08110class LogMessageForTesting : public LogMessage {
111 public:
112 LogMessageForTesting(const char* file,
113 int line,
114 LoggingSeverity sev,
115 LogErrorContext err_ctx = ERRCTX_NONE,
116 int err = 0)
117 : LogMessage(file, line, sev, err_ctx, err) {}
118
119 const std::string& get_extra() const { return extra_; }
Paulina Hensmanf1e3cb42018-06-20 12:07:05120#if defined(WEBRTC_ANDROID)
121 const char* get_tag() const { return tag_; }
122#endif
Tommifef05002018-02-27 12:51:08123
124 // Returns the contents of the internal log stream.
125 // Note that parts of the stream won't (as is) be available until *after* the
126 // dtor of the parent class has run. So, as is, this only represents a
127 // partially built stream.
128 std::string GetPrintStream() {
129 RTC_DCHECK(!is_finished_);
130 is_finished_ = true;
131 FinishPrintStream();
Jonas Olssond8c50782018-09-07 09:21:28132 return print_stream_.Release();
Tommifef05002018-02-27 12:51:08133 }
134
135 private:
136 bool is_finished_ = false;
137};
138
henrike@webrtc.orgf0488722014-05-13 18:00:26139// Test basic logging operation. We should get the INFO log but not the VERBOSE.
140// We should restore the correct global state at the end.
141TEST(LogTest, SingleStream) {
deadbeef37f5ecf2017-02-27 22:06:41142 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:26143
144 std::string str;
Tommi00aac5a2015-05-25 09:25:59145 LogSinkImpl<StringStream> stream(&str);
henrike@webrtc.orgf0488722014-05-13 18:00:26146 LogMessage::AddLogToStream(&stream, LS_INFO);
147 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
148
Mirko Bonadei675513b2017-11-09 10:09:25149 RTC_LOG(LS_INFO) << "INFO";
150 RTC_LOG(LS_VERBOSE) << "VERBOSE";
henrike@webrtc.orgf0488722014-05-13 18:00:26151 EXPECT_NE(std::string::npos, str.find("INFO"));
152 EXPECT_EQ(std::string::npos, str.find("VERBOSE"));
153
Jonas Olssonf2ce37c2018-09-12 13:32:47154 int i = 1;
155 long l = 2l;
156 long long ll = 3ll;
157
158 unsigned int u = 4u;
159 unsigned long ul = 5ul;
160 unsigned long long ull = 6ull;
161
162 std::string s1 = "char*";
163 std::string s2 = "std::string";
164 std::string s3 = "absl::stringview";
Niels Möller65835be2019-02-04 18:23:58165 const char* null_string = nullptr;
Jonas Olssonf2ce37c2018-09-12 13:32:47166 void* p = reinterpret_cast<void*>(0xabcd);
167
168 // Log all suported types(except doubles/floats) as a sanity-check.
169 RTC_LOG(LS_INFO) << "|" << i << "|" << l << "|" << ll << "|" << u << "|" << ul
170 << "|" << ull << "|" << s1.c_str() << "|" << s2 << "|"
Niels Möller65835be2019-02-04 18:23:58171 << absl::string_view(s3) << "|" << p << "|" << null_string
172 << "|";
Jonas Olssonf2ce37c2018-09-12 13:32:47173
174 // Signed integers
175 EXPECT_NE(std::string::npos, str.find("|1|"));
176 EXPECT_NE(std::string::npos, str.find("|2|"));
177 EXPECT_NE(std::string::npos, str.find("|3|"));
178
179 // Unsigned integers
180 EXPECT_NE(std::string::npos, str.find("|4|"));
181 EXPECT_NE(std::string::npos, str.find("|5|"));
182 EXPECT_NE(std::string::npos, str.find("|6|"));
183
184 // Strings
185 EXPECT_NE(std::string::npos, str.find("|char*|"));
186 EXPECT_NE(std::string::npos, str.find("|std::string|"));
187 EXPECT_NE(std::string::npos, str.find("|absl::stringview|"));
188
189 // void*
190 EXPECT_NE(std::string::npos, str.find("|abcd|"));
191
Niels Möller65835be2019-02-04 18:23:58192 // null char*
193 EXPECT_NE(std::string::npos, str.find("|(null)|"));
194
henrike@webrtc.orgf0488722014-05-13 18:00:26195 LogMessage::RemoveLogToStream(&stream);
Tommi0eefb4d2015-05-23 07:54:07196 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream));
deadbeef37f5ecf2017-02-27 22:06:41197 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26198}
199
Jonas Olssonf8e5c112018-06-14 11:14:22200#if GTEST_HAS_DEATH_TEST && !defined(WEBRTC_ANDROID)
201TEST(LogTest, Checks) {
202 EXPECT_DEATH(FATAL() << "message",
203 "\n\n#\n"
Jonas Olssond000b0a2018-07-03 10:07:53204 "# Fatal error in: \\S+, line \\w+\n"
205 "# last system error: \\w+\n"
Jonas Olssonf8e5c112018-06-14 11:14:22206 "# Check failed: FATAL\\(\\)\n"
Jonas Olssond000b0a2018-07-03 10:07:53207 "# message");
Jonas Olssonf8e5c112018-06-14 11:14:22208
209 int a = 1, b = 2;
210 EXPECT_DEATH(RTC_CHECK_EQ(a, b) << 1 << 2u,
211 "\n\n#\n"
Jonas Olssond000b0a2018-07-03 10:07:53212 "# Fatal error in: \\S+, line \\w+\n"
213 "# last system error: \\w+\n"
Jonas Olssonf8e5c112018-06-14 11:14:22214 "# Check failed: a == b \\(1 vs. 2\\)\n"
Jonas Olssond000b0a2018-07-03 10:07:53215 "# 12");
Jonas Olssonf8e5c112018-06-14 11:14:22216 RTC_CHECK_EQ(5, 5);
217
218 RTC_CHECK(true) << "Shouldn't crash" << 1;
219 EXPECT_DEATH(RTC_CHECK(false) << "Hi there!",
220 "\n\n#\n"
Jonas Olssond000b0a2018-07-03 10:07:53221 "# Fatal error in: \\S+, line \\w+\n"
222 "# last system error: \\w+\n"
Jonas Olssonf8e5c112018-06-14 11:14:22223 "# Check failed: false\n"
Jonas Olssond000b0a2018-07-03 10:07:53224 "# Hi there!");
Jonas Olssonf8e5c112018-06-14 11:14:22225}
226#endif
Jonas Olssond000b0a2018-07-03 10:07:53227
henrike@webrtc.orgf0488722014-05-13 18:00:26228// Test using multiple log streams. The INFO stream should get the INFO message,
229// the VERBOSE stream should get the INFO and the VERBOSE.
230// We should restore the correct global state at the end.
231TEST(LogTest, MultipleStreams) {
deadbeef37f5ecf2017-02-27 22:06:41232 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:26233
234 std::string str1, str2;
Tommi00aac5a2015-05-25 09:25:59235 LogSinkImpl<StringStream> stream1(&str1), stream2(&str2);
henrike@webrtc.orgf0488722014-05-13 18:00:26236 LogMessage::AddLogToStream(&stream1, LS_INFO);
237 LogMessage::AddLogToStream(&stream2, LS_VERBOSE);
238 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream1));
239 EXPECT_EQ(LS_VERBOSE, LogMessage::GetLogToStream(&stream2));
240
Mirko Bonadei675513b2017-11-09 10:09:25241 RTC_LOG(LS_INFO) << "INFO";
242 RTC_LOG(LS_VERBOSE) << "VERBOSE";
henrike@webrtc.orgf0488722014-05-13 18:00:26243
244 EXPECT_NE(std::string::npos, str1.find("INFO"));
245 EXPECT_EQ(std::string::npos, str1.find("VERBOSE"));
246 EXPECT_NE(std::string::npos, str2.find("INFO"));
247 EXPECT_NE(std::string::npos, str2.find("VERBOSE"));
248
249 LogMessage::RemoveLogToStream(&stream2);
250 LogMessage::RemoveLogToStream(&stream1);
Tommi0eefb4d2015-05-23 07:54:07251 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream2));
252 EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream1));
henrike@webrtc.orgf0488722014-05-13 18:00:26253
deadbeef37f5ecf2017-02-27 22:06:41254 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26255}
256
Tommifef05002018-02-27 12:51:08257class LogThread {
henrike@webrtc.orgf0488722014-05-13 18:00:26258 public:
Tommifef05002018-02-27 12:51:08259 LogThread() : thread_(&ThreadEntry, this, "LogThread") {}
260 ~LogThread() { thread_.Stop(); }
tommie7251592017-07-14 21:44:46261
Tommifef05002018-02-27 12:51:08262 void Start() { thread_.Start(); }
henrike@webrtc.orgf0488722014-05-13 18:00:26263
264 private:
Niels Möller25aefd32018-11-21 08:34:11265 void Run() { RTC_LOG(LS_VERBOSE) << "RTC_LOG"; }
Tommifef05002018-02-27 12:51:08266
267 static void ThreadEntry(void* p) { static_cast<LogThread*>(p)->Run(); }
268
269 PlatformThread thread_;
Niels Möllerc572ff32018-11-07 07:43:50270 Event event_;
henrike@webrtc.orgf0488722014-05-13 18:00:26271};
272
Tommifef05002018-02-27 12:51:08273// Ensure we don't crash when adding/removing streams while threads are going.
274// We should restore the correct global state at the end.
henrike@webrtc.orgc732a3e2014-10-09 22:08:15275TEST(LogTest, MultipleThreads) {
deadbeef37f5ecf2017-02-27 22:06:41276 int sev = LogMessage::GetLogToStream(nullptr);
henrike@webrtc.orgf0488722014-05-13 18:00:26277
278 LogThread thread1, thread2, thread3;
279 thread1.Start();
280 thread2.Start();
281 thread3.Start();
282
Niels Möllerff3dd0c2018-06-20 08:27:53283 std::string s1, s2, s3;
284 LogSinkImpl<StringStream> stream1(&s1), stream2(&s2), stream3(&s3);
henrike@webrtc.orgf0488722014-05-13 18:00:26285 for (int i = 0; i < 1000; ++i) {
Niels Möller25aefd32018-11-21 08:34:11286 LogMessage::AddLogToStream(&stream1, LS_WARNING);
287 LogMessage::AddLogToStream(&stream2, LS_INFO);
288 LogMessage::AddLogToStream(&stream3, LS_VERBOSE);
henrike@webrtc.orgf0488722014-05-13 18:00:26289 LogMessage::RemoveLogToStream(&stream1);
290 LogMessage::RemoveLogToStream(&stream2);
291 LogMessage::RemoveLogToStream(&stream3);
292 }
293
deadbeef37f5ecf2017-02-27 22:06:41294 EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
henrike@webrtc.orgf0488722014-05-13 18:00:26295}
296
henrike@webrtc.orgf0488722014-05-13 18:00:26297TEST(LogTest, WallClockStartTime) {
Peter Boström0c4e06b2015-10-07 10:23:21298 uint32_t time = LogMessage::WallClockStartTime();
henrike@webrtc.orgf0488722014-05-13 18:00:26299 // Expect the time to be in a sensible range, e.g. > 2012-01-01.
300 EXPECT_GT(time, 1325376000u);
301}
302
Tommifef05002018-02-27 12:51:08303TEST(LogTest, CheckExtraErrorField) {
304 LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_WARNING,
305 ERRCTX_ERRNO, 0xD);
Tommifef05002018-02-27 12:51:08306 log_msg.stream() << "This gets added at dtor time";
phoglundbb738732016-07-15 10:57:12307
Tommifef05002018-02-27 12:51:08308 const std::string& extra = log_msg.get_extra();
309 const size_t length_to_check = arraysize("[0x12345678]") - 1;
310 ASSERT_GE(extra.length(), length_to_check);
311 EXPECT_EQ(std::string("[0x0000000D]"), extra.substr(0, length_to_check));
312}
henrike@webrtc.orgf0488722014-05-13 18:00:26313
Tommifef05002018-02-27 12:51:08314TEST(LogTest, CheckFilePathParsed) {
315 LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO);
Tommifef05002018-02-27 12:51:08316 log_msg.stream() << "<- Does this look right?";
317
318 const std::string stream = log_msg.GetPrintStream();
Paulina Hensmanf1e3cb42018-06-20 12:07:05319#if defined(WEBRTC_ANDROID)
320 const char* tag = log_msg.get_tag();
321 EXPECT_NE(nullptr, strstr(tag, "myfile.cc"));
322 EXPECT_NE(std::string::npos, stream.find("100"));
323#else
Tommifef05002018-02-27 12:51:08324 EXPECT_NE(std::string::npos, stream.find("(myfile.cc:100)"));
Paulina Hensmanf1e3cb42018-06-20 12:07:05325#endif
Tommifef05002018-02-27 12:51:08326}
327
Paulina Hensmanf1e3cb42018-06-20 12:07:05328#if defined(WEBRTC_ANDROID)
329TEST(LogTest, CheckTagAddedToStringInDefaultOnLogMessageAndroid) {
330 std::string str;
331 LogSinkImpl<StringStream> stream(&str);
332 LogMessage::AddLogToStream(&stream, LS_INFO);
333 EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
334
335 RTC_LOG_TAG(LS_INFO, "my_tag") << "INFO";
336 EXPECT_NE(std::string::npos, str.find("INFO"));
337 EXPECT_NE(std::string::npos, str.find("my_tag"));
338}
339#endif
340
Tommifef05002018-02-27 12:51:08341// Test the time required to write 1000 80-character logs to a string.
342TEST(LogTest, Perf) {
343 std::string str;
344 LogSinkImpl<StringStream> stream(&str);
Niels Möller25aefd32018-11-21 08:34:11345 LogMessage::AddLogToStream(&stream, LS_VERBOSE);
henrike@webrtc.orgf0488722014-05-13 18:00:26346
Tommifef05002018-02-27 12:51:08347 const std::string message(80, 'X');
Niels Möller25aefd32018-11-21 08:34:11348 { LogMessageForTesting sanity_check_msg(__FILE__, __LINE__, LS_VERBOSE); }
Tommifef05002018-02-27 12:51:08349
350 // We now know how many bytes the logging framework will tag onto every msg.
351 const size_t logging_overhead = str.size();
352 // Reset the stream to 0 size.
353 str.clear();
354 str.reserve(120000);
355 static const int kRepetitions = 1000;
356
Honghai Zhang82d78622016-05-06 18:29:15357 int64_t start = TimeMillis(), finish;
Tommifef05002018-02-27 12:51:08358 for (int i = 0; i < kRepetitions; ++i) {
Niels Möller25aefd32018-11-21 08:34:11359 LogMessageForTesting(__FILE__, __LINE__, LS_VERBOSE).stream() << message;
henrike@webrtc.orgf0488722014-05-13 18:00:26360 }
Honghai Zhang82d78622016-05-06 18:29:15361 finish = TimeMillis();
henrike@webrtc.orgf0488722014-05-13 18:00:26362
363 LogMessage::RemoveLogToStream(&stream);
364 stream.Close();
henrike@webrtc.orgf0488722014-05-13 18:00:26365
Tommifef05002018-02-27 12:51:08366 EXPECT_EQ(str.size(), (message.size() + logging_overhead) * kRepetitions);
367 RTC_LOG(LS_INFO) << "Total log time: " << TimeDiff(finish, start) << " ms "
368 << " total bytes logged: " << str.size();
henrike@webrtc.orgf0488722014-05-13 18:00:26369}
370
Amit Hilbuch10c5a932019-03-18 20:09:18371TEST(LogTest, EnumsAreSupported) {
372 enum class TestEnum { kValue0 = 0, kValue1 = 1 };
373 std::string str;
374 LogSinkImpl<StringStream> stream(&str);
375 LogMessage::AddLogToStream(&stream, LS_INFO);
376 RTC_LOG(LS_INFO) << "[" << TestEnum::kValue0 << "]";
377 EXPECT_NE(std::string::npos, str.find("[0]"));
378 EXPECT_EQ(std::string::npos, str.find("[1]"));
379 RTC_LOG(LS_INFO) << "[" << TestEnum::kValue1 << "]";
380 EXPECT_NE(std::string::npos, str.find("[1]"));
381 LogMessage::RemoveLogToStream(&stream);
382 stream.Close();
383}
384
henrike@webrtc.orgf0488722014-05-13 18:00:26385} // namespace rtc