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 "rtc_base/arraysize.h"
20 #include "rtc_base/checks.h"
21 #include "rtc_base/event.h"
22 #include "rtc_base/platform_thread.h"
23 #include "rtc_base/time_utils.h"
24 #include "test/gtest.h"
25 
26 namespace rtc {
27 
28 class LogSinkImpl : public LogSink {
29  public:
LogSinkImpl(std::string * log_data)30   explicit LogSinkImpl(std::string* log_data) : log_data_(log_data) {}
31 
32   template <typename P>
LogSinkImpl(P * p)33   explicit LogSinkImpl(P* p) {}
34 
35  private:
OnLogMessage(const std::string & message)36   void OnLogMessage(const std::string& message) override {
37     log_data_->append(message);
38   }
39   std::string* const log_data_;
40 };
41 
42 class LogMessageForTesting : public LogMessage {
43  public:
LogMessageForTesting(const char * file,int line,LoggingSeverity sev,LogErrorContext err_ctx=ERRCTX_NONE,int err=0)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 
get_extra() const51   const std::string& get_extra() const { return extra_; }
52 #if defined(WEBRTC_ANDROID)
get_tag() const53   const char* get_tag() const { return tag_; }
54 #endif
55 
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.
GetPrintStream()60   std::string GetPrintStream() {
61     RTC_DCHECK(!is_finished_);
62     is_finished_ = true;
63     FinishPrintStream();
64     return print_stream_.Release();
65   }
66 
67  private:
68   bool is_finished_ = false;
69 };
70 
71 // 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.
TEST(LogTest,SingleStream)73 TEST(LogTest, SingleStream) {
74   int sev = LogMessage::GetLogToStream(nullptr);
75 
76   std::string str;
77   LogSinkImpl stream(&str);
78   LogMessage::AddLogToStream(&stream, LS_INFO);
79   EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream));
80 
81   RTC_LOG(LS_INFO) << "INFO";
82   RTC_LOG(LS_VERBOSE) << "VERBOSE";
83   EXPECT_NE(std::string::npos, str.find("INFO"));
84   EXPECT_EQ(std::string::npos, str.find("VERBOSE"));
85 
86   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";
97   const char* null_string = nullptr;
98   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 << "|"
103                    << absl::string_view(s3) << "|" << p << "|" << null_string
104                    << "|";
105 
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 
124   // null char*
125   EXPECT_NE(std::string::npos, str.find("|(null)|"));
126 
127   LogMessage::RemoveLogToStream(&stream);
128   EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream));
129   EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
130 }
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.
TEST(LogTest,MultipleStreams)135 TEST(LogTest, MultipleStreams) {
136   int sev = LogMessage::GetLogToStream(nullptr);
137 
138   std::string str1, str2;
139   LogSinkImpl stream1(&str1), stream2(&str2);
140   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 
145   RTC_LOG(LS_INFO) << "INFO";
146   RTC_LOG(LS_VERBOSE) << "VERBOSE";
147 
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);
155   EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream2));
156   EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream1));
157 
158   EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
159 }
160 
161 class LogThread {
162  public:
LogThread()163   LogThread() : thread_(&ThreadEntry, this, "LogThread") {}
~LogThread()164   ~LogThread() { thread_.Stop(); }
165 
Start()166   void Start() { thread_.Start(); }
167 
168  private:
Run()169   void Run() { RTC_LOG(LS_VERBOSE) << "RTC_LOG"; }
170 
ThreadEntry(void * p)171   static void ThreadEntry(void* p) { static_cast<LogThread*>(p)->Run(); }
172 
173   PlatformThread thread_;
174   Event event_;
175 };
176 
177 // Ensure we don't crash when adding/removing streams while threads are going.
178 // We should restore the correct global state at the end.
TEST(LogTest,MultipleThreads)179 TEST(LogTest, MultipleThreads) {
180   int sev = LogMessage::GetLogToStream(nullptr);
181 
182   LogThread thread1, thread2, thread3;
183   thread1.Start();
184   thread2.Start();
185   thread3.Start();
186 
187   std::string s1, s2, s3;
188   LogSinkImpl stream1(&s1), stream2(&s2), stream3(&s3);
189   for (int i = 0; i < 1000; ++i) {
190     LogMessage::AddLogToStream(&stream1, LS_WARNING);
191     LogMessage::AddLogToStream(&stream2, LS_INFO);
192     LogMessage::AddLogToStream(&stream3, LS_VERBOSE);
193     LogMessage::RemoveLogToStream(&stream1);
194     LogMessage::RemoveLogToStream(&stream2);
195     LogMessage::RemoveLogToStream(&stream3);
196   }
197 
198   EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr));
199 }
200 
TEST(LogTest,WallClockStartTime)201 TEST(LogTest, WallClockStartTime) {
202   uint32_t time = LogMessage::WallClockStartTime();
203   // Expect the time to be in a sensible range, e.g. > 2012-01-01.
204   EXPECT_GT(time, 1325376000u);
205 }
206 
TEST(LogTest,CheckExtraErrorField)207 TEST(LogTest, CheckExtraErrorField) {
208   LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_WARNING,
209                                ERRCTX_ERRNO, 0xD);
210   log_msg.stream() << "This gets added at dtor time";
211 
212   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 }
217 
TEST(LogTest,CheckFilePathParsed)218 TEST(LogTest, CheckFilePathParsed) {
219   LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO);
220   log_msg.stream() << "<- Does this look right?";
221 
222   const std::string stream = log_msg.GetPrintStream();
223 #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
228   EXPECT_NE(std::string::npos, stream.find("(myfile.cc:100)"));
229 #endif
230 }
231 
232 #if defined(WEBRTC_ANDROID)
TEST(LogTest,CheckTagAddedToStringInDefaultOnLogMessageAndroid)233 TEST(LogTest, CheckTagAddedToStringInDefaultOnLogMessageAndroid) {
234   std::string str;
235   LogSinkImpl stream(&str);
236   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 
245 // Test the time required to write 1000 80-character logs to a string.
TEST(LogTest,Perf)246 TEST(LogTest, Perf) {
247   std::string str;
248   LogSinkImpl stream(&str);
249   LogMessage::AddLogToStream(&stream, LS_VERBOSE);
250 
251   const std::string message(80, 'X');
252   { LogMessageForTesting sanity_check_msg(__FILE__, __LINE__, LS_VERBOSE); }
253 
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 
261   int64_t start = TimeMillis(), finish;
262   for (int i = 0; i < kRepetitions; ++i) {
263     LogMessageForTesting(__FILE__, __LINE__, LS_VERBOSE).stream() << message;
264   }
265   finish = TimeMillis();
266 
267   LogMessage::RemoveLogToStream(&stream);
268 
269   EXPECT_EQ(str.size(), (message.size() + logging_overhead) * kRepetitions);
270   RTC_LOG(LS_INFO) << "Total log time: " << TimeDiff(finish, start)
271                    << " ms "
272                       " total bytes logged: "
273                    << str.size();
274 }
275 
TEST(LogTest,EnumsAreSupported)276 TEST(LogTest, EnumsAreSupported) {
277   enum class TestEnum { kValue0 = 0, kValue1 = 1 };
278   std::string str;
279   LogSinkImpl stream(&str);
280   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);
287 }
288 
TEST(LogTest,NoopSeverityDoesNotRunStringFormatting)289 TEST(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 
303 }  // namespace rtc
304 #endif  // RTC_LOG_ENABLED()
305