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 #include <string.h>
14 
15 #if RTC_LOG_ENABLED()
16 
17 #if defined(WEBRTC_WIN)
18 #include <windows.h>
19 #if _MSC_VER < 1900
20 #define snprintf _snprintf
21 #endif
22 #undef ERROR  // wingdi.h
23 #endif
24 
25 #if defined(WEBRTC_MAC) && !defined(WEBRTC_IOS)
26 #include <CoreServices/CoreServices.h>
27 #elif defined(WEBRTC_ANDROID)
28 #include <android/log.h>
29 
30 // Android has a 1024 limit on log inputs. We use 60 chars as an
31 // approx for the header/tag portion.
32 // See android/system/logging/liblog/logd_write.c
33 static const int kMaxLogLineSize = 1024 - 60;
34 #endif  // WEBRTC_MAC && !defined(WEBRTC_IOS) || WEBRTC_ANDROID
35 
36 #include <stdio.h>
37 #include <time.h>
38 
39 #include <algorithm>
40 #include <cstdarg>
41 #include <vector>
42 
43 #include "absl/base/attributes.h"
44 #include "rtc_base/checks.h"
45 #include "rtc_base/platform_thread_types.h"
46 #include "rtc_base/string_encode.h"
47 #include "rtc_base/string_utils.h"
48 #include "rtc_base/strings/string_builder.h"
49 #include "rtc_base/synchronization/mutex.h"
50 #include "rtc_base/thread_annotations.h"
51 #include "rtc_base/time_utils.h"
52 
53 namespace rtc {
54 namespace {
55 // By default, release builds don't log, debug builds at info level
56 #if !defined(NDEBUG)
57 static LoggingSeverity g_min_sev = LS_INFO;
58 static LoggingSeverity g_dbg_sev = LS_INFO;
59 #else
60 static LoggingSeverity g_min_sev = LS_NONE;
61 static LoggingSeverity g_dbg_sev = LS_NONE;
62 #endif
63 
64 // Return the filename portion of the string (that following the last slash).
FilenameFromPath(const char * file)65 const char* FilenameFromPath(const char* file) {
66   const char* end1 = ::strrchr(file, '/');
67   const char* end2 = ::strrchr(file, '\\');
68   if (!end1 && !end2)
69     return file;
70   else
71     return (end1 > end2) ? end1 + 1 : end2 + 1;
72 }
73 
74 // Global lock for log subsystem, only needed to serialize access to streams_.
75 // TODO(bugs.webrtc.org/11665): this is not currently constant initialized and
76 // trivially destructible.
77 webrtc::Mutex g_log_mutex_;
78 }  // namespace
79 
80 /////////////////////////////////////////////////////////////////////////////
81 // LogMessage
82 /////////////////////////////////////////////////////////////////////////////
83 
84 bool LogMessage::log_to_stderr_ = true;
85 
86 // The list of logging streams currently configured.
87 // Note: we explicitly do not clean this up, because of the uncertain ordering
88 // of destructors at program exit.  Let the person who sets the stream trigger
89 // cleanup by setting to null, or let it leak (safe at program exit).
90 ABSL_CONST_INIT LogSink* LogMessage::streams_ RTC_GUARDED_BY(g_log_mutex_) =
91     nullptr;
92 ABSL_CONST_INIT std::atomic<bool> LogMessage::streams_empty_ = {true};
93 
94 // Boolean options default to false (0)
95 bool LogMessage::thread_, LogMessage::timestamp_;
96 
LogMessage(const char * file,int line,LoggingSeverity sev)97 LogMessage::LogMessage(const char* file, int line, LoggingSeverity sev)
98     : LogMessage(file, line, sev, ERRCTX_NONE, 0) {}
99 
LogMessage(const char * file,int line,LoggingSeverity sev,LogErrorContext err_ctx,int err)100 LogMessage::LogMessage(const char* file,
101                        int line,
102                        LoggingSeverity sev,
103                        LogErrorContext err_ctx,
104                        int err)
105     : severity_(sev) {
106   if (timestamp_) {
107     // Use SystemTimeMillis so that even if tests use fake clocks, the timestamp
108     // in log messages represents the real system time.
109     int64_t time = TimeDiff(SystemTimeMillis(), LogStartTime());
110     // Also ensure WallClockStartTime is initialized, so that it matches
111     // LogStartTime.
112     WallClockStartTime();
113     print_stream_ << "[" << rtc::LeftPad('0', 3, rtc::ToString(time / 1000))
114                   << ":" << rtc::LeftPad('0', 3, rtc::ToString(time % 1000))
115                   << "] ";
116   }
117 
118   if (thread_) {
119     PlatformThreadId id = CurrentThreadId();
120     print_stream_ << "[" << id << "] ";
121   }
122 
123   if (file != nullptr) {
124 #if defined(WEBRTC_ANDROID)
125     tag_ = FilenameFromPath(file);
126     print_stream_ << "(line " << line << "): ";
127 #else
128     print_stream_ << "(" << FilenameFromPath(file) << ":" << line << "): ";
129 #endif
130   }
131 
132   if (err_ctx != ERRCTX_NONE) {
133     char tmp_buf[1024];
134     SimpleStringBuilder tmp(tmp_buf);
135     tmp.AppendFormat("[0x%08X]", err);
136     switch (err_ctx) {
137       case ERRCTX_ERRNO:
138         tmp << " " << strerror(err);
139         break;
140 #ifdef WEBRTC_WIN
141       case ERRCTX_HRESULT: {
142         char msgbuf[256];
143         DWORD flags =
144             FORMAT_MESSAGE_FROM_SYSTEM | FORMAT_MESSAGE_IGNORE_INSERTS;
145         if (DWORD len = FormatMessageA(
146                 flags, nullptr, err, MAKELANGID(LANG_NEUTRAL, SUBLANG_DEFAULT),
147                 msgbuf, sizeof(msgbuf) / sizeof(msgbuf[0]), nullptr)) {
148           while ((len > 0) &&
149                  isspace(static_cast<unsigned char>(msgbuf[len - 1]))) {
150             msgbuf[--len] = 0;
151           }
152           tmp << " " << msgbuf;
153         }
154         break;
155       }
156 #endif  // WEBRTC_WIN
157       default:
158         break;
159     }
160     extra_ = tmp.str();
161   }
162 }
163 
164 #if defined(WEBRTC_ANDROID)
LogMessage(const char * file,int line,LoggingSeverity sev,const char * tag)165 LogMessage::LogMessage(const char* file,
166                        int line,
167                        LoggingSeverity sev,
168                        const char* tag)
169     : LogMessage(file, line, sev, ERRCTX_NONE, 0 /* err */) {
170   tag_ = tag;
171   print_stream_ << tag << ": ";
172 }
173 #endif
174 
175 // DEPRECATED. Currently only used by downstream projects that use
176 // implementation details of logging.h. Work is ongoing to remove those
177 // dependencies.
LogMessage(const char * file,int line,LoggingSeverity sev,const std::string & tag)178 LogMessage::LogMessage(const char* file,
179                        int line,
180                        LoggingSeverity sev,
181                        const std::string& tag)
182     : LogMessage(file, line, sev) {
183   print_stream_ << tag << ": ";
184 }
185 
~LogMessage()186 LogMessage::~LogMessage() {
187   FinishPrintStream();
188 
189   const std::string str = print_stream_.Release();
190 
191   if (severity_ >= g_dbg_sev) {
192 #if defined(WEBRTC_ANDROID)
193     OutputToDebug(str, severity_, tag_);
194 #else
195     OutputToDebug(str, severity_);
196 #endif
197   }
198 
199   webrtc::MutexLock lock(&g_log_mutex_);
200   for (LogSink* entry = streams_; entry != nullptr; entry = entry->next_) {
201     if (severity_ >= entry->min_severity_) {
202 #if defined(WEBRTC_ANDROID)
203       entry->OnLogMessage(str, severity_, tag_);
204 #else
205       entry->OnLogMessage(str, severity_);
206 #endif
207     }
208   }
209 }
210 
AddTag(const char * tag)211 void LogMessage::AddTag(const char* tag) {
212 #ifdef WEBRTC_ANDROID
213   tag_ = tag;
214 #endif
215 }
216 
stream()217 rtc::StringBuilder& LogMessage::stream() {
218   return print_stream_;
219 }
220 
GetMinLogSeverity()221 int LogMessage::GetMinLogSeverity() {
222   return g_min_sev;
223 }
224 
GetLogToDebug()225 LoggingSeverity LogMessage::GetLogToDebug() {
226   return g_dbg_sev;
227 }
LogStartTime()228 int64_t LogMessage::LogStartTime() {
229   static const int64_t g_start = SystemTimeMillis();
230   return g_start;
231 }
232 
WallClockStartTime()233 uint32_t LogMessage::WallClockStartTime() {
234   static const uint32_t g_start_wallclock = time(nullptr);
235   return g_start_wallclock;
236 }
237 
LogThreads(bool on)238 void LogMessage::LogThreads(bool on) {
239   thread_ = on;
240 }
241 
LogTimestamps(bool on)242 void LogMessage::LogTimestamps(bool on) {
243   timestamp_ = on;
244 }
245 
LogToDebug(LoggingSeverity min_sev)246 void LogMessage::LogToDebug(LoggingSeverity min_sev) {
247   g_dbg_sev = min_sev;
248   webrtc::MutexLock lock(&g_log_mutex_);
249   UpdateMinLogSeverity();
250 }
251 
SetLogToStderr(bool log_to_stderr)252 void LogMessage::SetLogToStderr(bool log_to_stderr) {
253   log_to_stderr_ = log_to_stderr;
254 }
255 
GetLogToStream(LogSink * stream)256 int LogMessage::GetLogToStream(LogSink* stream) {
257   webrtc::MutexLock lock(&g_log_mutex_);
258   LoggingSeverity sev = LS_NONE;
259   for (LogSink* entry = streams_; entry != nullptr; entry = entry->next_) {
260     if (stream == nullptr || stream == entry) {
261       sev = std::min(sev, entry->min_severity_);
262     }
263   }
264   return sev;
265 }
266 
AddLogToStream(LogSink * stream,LoggingSeverity min_sev)267 void LogMessage::AddLogToStream(LogSink* stream, LoggingSeverity min_sev) {
268   webrtc::MutexLock lock(&g_log_mutex_);
269   stream->min_severity_ = min_sev;
270   stream->next_ = streams_;
271   streams_ = stream;
272   streams_empty_.store(false, std::memory_order_relaxed);
273   UpdateMinLogSeverity();
274 }
275 
RemoveLogToStream(LogSink * stream)276 void LogMessage::RemoveLogToStream(LogSink* stream) {
277   webrtc::MutexLock lock(&g_log_mutex_);
278   for (LogSink** entry = &streams_; *entry != nullptr;
279        entry = &(*entry)->next_) {
280     if (*entry == stream) {
281       *entry = (*entry)->next_;
282       break;
283     }
284   }
285   streams_empty_.store(streams_ == nullptr, std::memory_order_relaxed);
286   UpdateMinLogSeverity();
287 }
288 
ConfigureLogging(const char * params)289 void LogMessage::ConfigureLogging(const char* params) {
290   LoggingSeverity current_level = LS_VERBOSE;
291   LoggingSeverity debug_level = GetLogToDebug();
292 
293   std::vector<std::string> tokens;
294   tokenize(params, ' ', &tokens);
295 
296   for (const std::string& token : tokens) {
297     if (token.empty())
298       continue;
299 
300     // Logging features
301     if (token == "tstamp") {
302       LogTimestamps();
303     } else if (token == "thread") {
304       LogThreads();
305 
306       // Logging levels
307     } else if (token == "verbose") {
308       current_level = LS_VERBOSE;
309     } else if (token == "info") {
310       current_level = LS_INFO;
311     } else if (token == "warning") {
312       current_level = LS_WARNING;
313     } else if (token == "error") {
314       current_level = LS_ERROR;
315     } else if (token == "none") {
316       current_level = LS_NONE;
317 
318       // Logging targets
319     } else if (token == "debug") {
320       debug_level = current_level;
321     }
322   }
323 
324 #if defined(WEBRTC_WIN) && !defined(WINUWP)
325   if ((LS_NONE != debug_level) && !::IsDebuggerPresent()) {
326     // First, attempt to attach to our parent's console... so if you invoke
327     // from the command line, we'll see the output there.  Otherwise, create
328     // our own console window.
329     // Note: These methods fail if a console already exists, which is fine.
330     if (!AttachConsole(ATTACH_PARENT_PROCESS))
331       ::AllocConsole();
332   }
333 #endif  // defined(WEBRTC_WIN) && !defined(WINUWP)
334 
335   LogToDebug(debug_level);
336 }
337 
UpdateMinLogSeverity()338 void LogMessage::UpdateMinLogSeverity()
339     RTC_EXCLUSIVE_LOCKS_REQUIRED(g_log_mutex_) {
340   LoggingSeverity min_sev = g_dbg_sev;
341   for (LogSink* entry = streams_; entry != nullptr; entry = entry->next_) {
342     min_sev = std::min(min_sev, entry->min_severity_);
343   }
344   g_min_sev = min_sev;
345 }
346 
347 #if defined(WEBRTC_ANDROID)
OutputToDebug(const std::string & str,LoggingSeverity severity,const char * tag)348 void LogMessage::OutputToDebug(const std::string& str,
349                                LoggingSeverity severity,
350                                const char* tag) {
351 #else
352 void LogMessage::OutputToDebug(const std::string& str,
353                                LoggingSeverity severity) {
354 #endif
355   bool log_to_stderr = log_to_stderr_;
356 #if defined(WEBRTC_MAC) && !defined(WEBRTC_IOS) && defined(NDEBUG)
357   // On the Mac, all stderr output goes to the Console log and causes clutter.
358   // So in opt builds, don't log to stderr unless the user specifically sets
359   // a preference to do so.
360   CFStringRef key = CFStringCreateWithCString(
361       kCFAllocatorDefault, "logToStdErr", kCFStringEncodingUTF8);
362   CFStringRef domain = CFBundleGetIdentifier(CFBundleGetMainBundle());
363   if (key != nullptr && domain != nullptr) {
364     Boolean exists_and_is_valid;
365     Boolean should_log =
366         CFPreferencesGetAppBooleanValue(key, domain, &exists_and_is_valid);
367     // If the key doesn't exist or is invalid or is false, we will not log to
368     // stderr.
369     log_to_stderr = exists_and_is_valid && should_log;
370   }
371   if (key != nullptr) {
372     CFRelease(key);
373   }
374 #endif  // defined(WEBRTC_MAC) && !defined(WEBRTC_IOS) && defined(NDEBUG)
375 
376 #if defined(WEBRTC_WIN)
377   // Always log to the debugger.
378   // Perhaps stderr should be controlled by a preference, as on Mac?
379   OutputDebugStringA(str.c_str());
380   if (log_to_stderr) {
381     // This handles dynamically allocated consoles, too.
382     if (HANDLE error_handle = ::GetStdHandle(STD_ERROR_HANDLE)) {
383       log_to_stderr = false;
384       DWORD written = 0;
385       ::WriteFile(error_handle, str.data(), static_cast<DWORD>(str.size()),
386                   &written, 0);
387     }
388   }
389 #endif  // WEBRTC_WIN
390 
391 #if defined(WEBRTC_ANDROID)
392   // Android's logging facility uses severity to log messages but we
393   // need to map libjingle's severity levels to Android ones first.
394   // Also write to stderr which maybe available to executable started
395   // from the shell.
396   int prio;
397   switch (severity) {
398     case LS_VERBOSE:
399       prio = ANDROID_LOG_VERBOSE;
400       break;
401     case LS_INFO:
402       prio = ANDROID_LOG_INFO;
403       break;
404     case LS_WARNING:
405       prio = ANDROID_LOG_WARN;
406       break;
407     case LS_ERROR:
408       prio = ANDROID_LOG_ERROR;
409       break;
410     default:
411       prio = ANDROID_LOG_UNKNOWN;
412   }
413 
414   int size = str.size();
415   int line = 0;
416   int idx = 0;
417   const int max_lines = size / kMaxLogLineSize + 1;
418   if (max_lines == 1) {
419     __android_log_print(prio, tag, "%.*s", size, str.c_str());
420   } else {
421     while (size > 0) {
422       const int len = std::min(size, kMaxLogLineSize);
423       // Use the size of the string in the format (str may have \0 in the
424       // middle).
425       __android_log_print(prio, tag, "[%d/%d] %.*s", line + 1, max_lines, len,
426                           str.c_str() + idx);
427       idx += len;
428       size -= len;
429       ++line;
430     }
431   }
432 #endif  // WEBRTC_ANDROID
433   if (log_to_stderr) {
434     fprintf(stderr, "%s", str.c_str());
435     fflush(stderr);
436   }
437 }
438 
439 // static
440 bool LogMessage::IsNoop(LoggingSeverity severity) {
441   if (severity >= g_dbg_sev || severity >= g_min_sev)
442     return false;
443   return streams_empty_.load(std::memory_order_relaxed);
444 }
445 
446 void LogMessage::FinishPrintStream() {
447   if (!extra_.empty())
448     print_stream_ << " : " << extra_;
449   print_stream_ << "\n";
450 }
451 
452 namespace webrtc_logging_impl {
453 
454 void Log(const LogArgType* fmt, ...) {
455   va_list args;
456   va_start(args, fmt);
457 
458   LogMetadataErr meta;
459   const char* tag = nullptr;
460   switch (*fmt) {
461     case LogArgType::kLogMetadata: {
462       meta = {va_arg(args, LogMetadata), ERRCTX_NONE, 0};
463       break;
464     }
465     case LogArgType::kLogMetadataErr: {
466       meta = va_arg(args, LogMetadataErr);
467       break;
468     }
469 #ifdef WEBRTC_ANDROID
470     case LogArgType::kLogMetadataTag: {
471       const LogMetadataTag tag_meta = va_arg(args, LogMetadataTag);
472       meta = {{nullptr, 0, tag_meta.severity}, ERRCTX_NONE, 0};
473       tag = tag_meta.tag;
474       break;
475     }
476 #endif
477     default: {
478       RTC_NOTREACHED();
479       va_end(args);
480       return;
481     }
482   }
483 
484   if (LogMessage::IsNoop(meta.meta.Severity())) {
485     va_end(args);
486     return;
487   }
488 
489   LogMessage log_message(meta.meta.File(), meta.meta.Line(),
490                          meta.meta.Severity(), meta.err_ctx, meta.err);
491   if (tag) {
492     log_message.AddTag(tag);
493   }
494 
495   for (++fmt; *fmt != LogArgType::kEnd; ++fmt) {
496     switch (*fmt) {
497       case LogArgType::kInt:
498         log_message.stream() << va_arg(args, int);
499         break;
500       case LogArgType::kLong:
501         log_message.stream() << va_arg(args, long);
502         break;
503       case LogArgType::kLongLong:
504         log_message.stream() << va_arg(args, long long);
505         break;
506       case LogArgType::kUInt:
507         log_message.stream() << va_arg(args, unsigned);
508         break;
509       case LogArgType::kULong:
510         log_message.stream() << va_arg(args, unsigned long);
511         break;
512       case LogArgType::kULongLong:
513         log_message.stream() << va_arg(args, unsigned long long);
514         break;
515       case LogArgType::kDouble:
516         log_message.stream() << va_arg(args, double);
517         break;
518       case LogArgType::kLongDouble:
519         log_message.stream() << va_arg(args, long double);
520         break;
521       case LogArgType::kCharP: {
522         const char* s = va_arg(args, const char*);
523         log_message.stream() << (s ? s : "(null)");
524         break;
525       }
526       case LogArgType::kStdString:
527         log_message.stream() << *va_arg(args, const std::string*);
528         break;
529       case LogArgType::kStringView:
530         log_message.stream() << *va_arg(args, const absl::string_view*);
531         break;
532       case LogArgType::kVoidP:
533         log_message.stream() << rtc::ToHex(
534             reinterpret_cast<uintptr_t>(va_arg(args, const void*)));
535         break;
536       default:
537         RTC_NOTREACHED();
538         va_end(args);
539         return;
540     }
541   }
542 
543   va_end(args);
544 }
545 
546 }  // namespace webrtc_logging_impl
547 }  // namespace rtc
548 #endif
549 
550 namespace rtc {
551 // Inefficient default implementation, override is recommended.
OnLogMessage(const std::string & msg,LoggingSeverity severity,const char * tag)552 void LogSink::OnLogMessage(const std::string& msg,
553                            LoggingSeverity severity,
554                            const char* tag) {
555   OnLogMessage(tag + (": " + msg), severity);
556 }
557 
OnLogMessage(const std::string & msg,LoggingSeverity)558 void LogSink::OnLogMessage(const std::string& msg,
559                            LoggingSeverity /* severity */) {
560   OnLogMessage(msg);
561 }
562 }  // namespace rtc
563