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 #if defined(WEBRTC_WIN)
12 #if !defined(WIN32_LEAN_AND_MEAN)
13 #define WIN32_LEAN_AND_MEAN
14 #endif
15 #include <windows.h>
16 #define snprintf _snprintf
17 #undef ERROR  // wingdi.h
18 #endif
19 
20 #if defined(WEBRTC_MAC) && !defined(WEBRTC_IOS)
21 #include <CoreServices/CoreServices.h>
22 #elif defined(WEBRTC_ANDROID)
23 #include <android/log.h>
24 // Android has a 1024 limit on log inputs. We use 60 chars as an
25 // approx for the header/tag portion.
26 // See android/system/core/liblog/logd_write.c
27 static const int kMaxLogLineSize = 1024 - 60;
28 #endif  // WEBRTC_MAC && !defined(WEBRTC_IOS) || WEBRTC_ANDROID
29 
30 static const char kLibjingle[] = "libjingle";
31 
32 #include <time.h>
33 #include <limits.h>
34 
35 #include <algorithm>
36 #include <iomanip>
37 #include <ostream>
38 #include <vector>
39 
40 #include "webrtc/base/criticalsection.h"
41 #include "webrtc/base/logging.h"
42 #include "webrtc/base/platform_thread.h"
43 #include "webrtc/base/scoped_ptr.h"
44 #include "webrtc/base/stringencode.h"
45 #include "webrtc/base/stringutils.h"
46 #include "webrtc/base/timeutils.h"
47 
48 namespace rtc {
49 namespace {
50 
51 // Return the filename portion of the string (that following the last slash).
FilenameFromPath(const char * file)52 const char* FilenameFromPath(const char* file) {
53   const char* end1 = ::strrchr(file, '/');
54   const char* end2 = ::strrchr(file, '\\');
55   if (!end1 && !end2)
56     return file;
57   else
58     return (end1 > end2) ? end1 + 1 : end2 + 1;
59 }
60 
61 }  // namespace
62 
63 /////////////////////////////////////////////////////////////////////////////
64 // Constant Labels
65 /////////////////////////////////////////////////////////////////////////////
66 
FindLabel(int value,const ConstantLabel entries[])67 const char* FindLabel(int value, const ConstantLabel entries[]) {
68   for (int i = 0; entries[i].label; ++i) {
69     if (value == entries[i].value) {
70       return entries[i].label;
71     }
72   }
73   return 0;
74 }
75 
ErrorName(int err,const ConstantLabel * err_table)76 std::string ErrorName(int err, const ConstantLabel* err_table) {
77   if (err == 0)
78     return "No error";
79 
80   if (err_table != 0) {
81     if (const char* value = FindLabel(err, err_table))
82       return value;
83   }
84 
85   char buffer[16];
86   snprintf(buffer, sizeof(buffer), "0x%08x", err);
87   return buffer;
88 }
89 
90 /////////////////////////////////////////////////////////////////////////////
91 // LogMessage
92 /////////////////////////////////////////////////////////////////////////////
93 
94 // By default, release builds don't log, debug builds at info level
95 #if !defined(NDEBUG)
96 LoggingSeverity LogMessage::min_sev_ = LS_INFO;
97 LoggingSeverity LogMessage::dbg_sev_ = LS_INFO;
98 #else
99 LoggingSeverity LogMessage::min_sev_ = LS_NONE;
100 LoggingSeverity LogMessage::dbg_sev_ = LS_NONE;
101 #endif
102 bool LogMessage::log_to_stderr_ = true;
103 
104 namespace {
105 // Global lock for log subsystem, only needed to serialize access to streams_.
106 CriticalSection g_log_crit;
107 }  // namespace
108 
109 // The list of logging streams currently configured.
110 // Note: we explicitly do not clean this up, because of the uncertain ordering
111 // of destructors at program exit.  Let the person who sets the stream trigger
112 // cleanup by setting to NULL, or let it leak (safe at program exit).
113 LogMessage::StreamList LogMessage::streams_ GUARDED_BY(g_log_crit);
114 
115 // Boolean options default to false (0)
116 bool LogMessage::thread_, LogMessage::timestamp_;
117 
LogMessage(const char * file,int line,LoggingSeverity sev,LogErrorContext err_ctx,int err,const char * module)118 LogMessage::LogMessage(const char* file,
119                        int line,
120                        LoggingSeverity sev,
121                        LogErrorContext err_ctx,
122                        int err,
123                        const char* module)
124     : severity_(sev), tag_(kLibjingle) {
125   if (timestamp_) {
126     uint32_t time = TimeSince(LogStartTime());
127     // Also ensure WallClockStartTime is initialized, so that it matches
128     // LogStartTime.
129     WallClockStartTime();
130     print_stream_ << "[" << std::setfill('0') << std::setw(3) << (time / 1000)
131                   << ":" << std::setw(3) << (time % 1000) << std::setfill(' ')
132                   << "] ";
133   }
134 
135   if (thread_) {
136     PlatformThreadId id = CurrentThreadId();
137     print_stream_ << "[" << std::dec << id << "] ";
138   }
139 
140   if (file != NULL)
141     print_stream_ << "(" << FilenameFromPath(file)  << ":" << line << "): ";
142 
143   if (err_ctx != ERRCTX_NONE) {
144     std::ostringstream tmp;
145     tmp << "[0x" << std::setfill('0') << std::hex << std::setw(8) << err << "]";
146     switch (err_ctx) {
147       case ERRCTX_ERRNO:
148         tmp << " " << strerror(err);
149         break;
150 #if WEBRTC_WIN
151       case ERRCTX_HRESULT: {
152         char msgbuf[256];
153         DWORD flags = FORMAT_MESSAGE_FROM_SYSTEM;
154         HMODULE hmod = GetModuleHandleA(module);
155         if (hmod)
156           flags |= FORMAT_MESSAGE_FROM_HMODULE;
157         if (DWORD len = FormatMessageA(
158             flags, hmod, err,
159             MAKELANGID(LANG_NEUTRAL, SUBLANG_DEFAULT),
160             msgbuf, sizeof(msgbuf) / sizeof(msgbuf[0]), NULL)) {
161           while ((len > 0) &&
162               isspace(static_cast<unsigned char>(msgbuf[len-1]))) {
163             msgbuf[--len] = 0;
164           }
165           tmp << " " << msgbuf;
166         }
167         break;
168       }
169 #endif  // WEBRTC_WIN
170 #if defined(WEBRTC_MAC) && !defined(WEBRTC_IOS)
171       case ERRCTX_OSSTATUS: {
172         tmp << " " << nonnull(GetMacOSStatusErrorString(err), "Unknown error");
173         if (const char* desc = GetMacOSStatusCommentString(err)) {
174           tmp << ": " << desc;
175         }
176         break;
177       }
178 #endif  // WEBRTC_MAC && !defined(WEBRTC_IOS)
179       default:
180         break;
181     }
182     extra_ = tmp.str();
183   }
184 }
185 
LogMessage(const char * file,int line,LoggingSeverity sev,const std::string & tag)186 LogMessage::LogMessage(const char* file,
187                        int line,
188                        LoggingSeverity sev,
189                        const std::string& tag)
190     : LogMessage(file, line, sev, ERRCTX_NONE, 0 /* err */, NULL /* module */) {
191   tag_ = tag;
192   print_stream_ << tag << ": ";
193 }
194 
~LogMessage()195 LogMessage::~LogMessage() {
196   if (!extra_.empty())
197     print_stream_ << " : " << extra_;
198   print_stream_ << std::endl;
199 
200   const std::string& str = print_stream_.str();
201   if (severity_ >= dbg_sev_) {
202     OutputToDebug(str, severity_, tag_);
203   }
204 
205   CritScope cs(&g_log_crit);
206   for (auto& kv : streams_) {
207     if (severity_ >= kv.second) {
208       kv.first->OnLogMessage(str);
209     }
210   }
211 }
212 
LogStartTime()213 uint32_t LogMessage::LogStartTime() {
214   static const uint32_t g_start = Time();
215   return g_start;
216 }
217 
WallClockStartTime()218 uint32_t LogMessage::WallClockStartTime() {
219   static const uint32_t g_start_wallclock = time(NULL);
220   return g_start_wallclock;
221 }
222 
LogThreads(bool on)223 void LogMessage::LogThreads(bool on) {
224   thread_ = on;
225 }
226 
LogTimestamps(bool on)227 void LogMessage::LogTimestamps(bool on) {
228   timestamp_ = on;
229 }
230 
LogToDebug(LoggingSeverity min_sev)231 void LogMessage::LogToDebug(LoggingSeverity min_sev) {
232   dbg_sev_ = min_sev;
233   CritScope cs(&g_log_crit);
234   UpdateMinLogSeverity();
235 }
236 
SetLogToStderr(bool log_to_stderr)237 void LogMessage::SetLogToStderr(bool log_to_stderr) {
238   log_to_stderr_ = log_to_stderr;
239 }
240 
GetLogToStream(LogSink * stream)241 int LogMessage::GetLogToStream(LogSink* stream) {
242   CritScope cs(&g_log_crit);
243   LoggingSeverity sev = LS_NONE;
244   for (auto& kv : streams_) {
245     if (!stream || stream == kv.first) {
246       sev = std::min(sev, kv.second);
247     }
248   }
249   return sev;
250 }
251 
AddLogToStream(LogSink * stream,LoggingSeverity min_sev)252 void LogMessage::AddLogToStream(LogSink* stream, LoggingSeverity min_sev) {
253   CritScope cs(&g_log_crit);
254   streams_.push_back(std::make_pair(stream, min_sev));
255   UpdateMinLogSeverity();
256 }
257 
RemoveLogToStream(LogSink * stream)258 void LogMessage::RemoveLogToStream(LogSink* stream) {
259   CritScope cs(&g_log_crit);
260   for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) {
261     if (stream == it->first) {
262       streams_.erase(it);
263       break;
264     }
265   }
266   UpdateMinLogSeverity();
267 }
268 
ConfigureLogging(const char * params)269 void LogMessage::ConfigureLogging(const char* params) {
270   LoggingSeverity current_level = LS_VERBOSE;
271   LoggingSeverity debug_level = GetLogToDebug();
272 
273   std::vector<std::string> tokens;
274   tokenize(params, ' ', &tokens);
275 
276   for (const std::string& token : tokens) {
277     if (token.empty())
278       continue;
279 
280     // Logging features
281     if (token == "tstamp") {
282       LogTimestamps();
283     } else if (token == "thread") {
284       LogThreads();
285 
286     // Logging levels
287     } else if (token == "sensitive") {
288       current_level = LS_SENSITIVE;
289     } else if (token == "verbose") {
290       current_level = LS_VERBOSE;
291     } else if (token == "info") {
292       current_level = LS_INFO;
293     } else if (token == "warning") {
294       current_level = LS_WARNING;
295     } else if (token == "error") {
296       current_level = LS_ERROR;
297     } else if (token == "none") {
298       current_level = LS_NONE;
299 
300     // Logging targets
301     } else if (token == "debug") {
302       debug_level = current_level;
303     }
304   }
305 
306 #if defined(WEBRTC_WIN)
307   if ((LS_NONE != debug_level) && !::IsDebuggerPresent()) {
308     // First, attempt to attach to our parent's console... so if you invoke
309     // from the command line, we'll see the output there.  Otherwise, create
310     // our own console window.
311     // Note: These methods fail if a console already exists, which is fine.
312     bool success = false;
313     typedef BOOL (WINAPI* PFN_AttachConsole)(DWORD);
314     if (HINSTANCE kernel32 = ::LoadLibrary(L"kernel32.dll")) {
315       // AttachConsole is defined on WinXP+.
316       if (PFN_AttachConsole attach_console = reinterpret_cast<PFN_AttachConsole>
317             (::GetProcAddress(kernel32, "AttachConsole"))) {
318         success = (FALSE != attach_console(ATTACH_PARENT_PROCESS));
319       }
320       ::FreeLibrary(kernel32);
321     }
322     if (!success) {
323       ::AllocConsole();
324     }
325   }
326 #endif  // WEBRTC_WIN
327 
328   LogToDebug(debug_level);
329 }
330 
UpdateMinLogSeverity()331 void LogMessage::UpdateMinLogSeverity() EXCLUSIVE_LOCKS_REQUIRED(g_log_crit) {
332   LoggingSeverity min_sev = dbg_sev_;
333   for (auto& kv : streams_) {
334     min_sev = std::min(dbg_sev_, kv.second);
335   }
336   min_sev_ = min_sev;
337 }
338 
OutputToDebug(const std::string & str,LoggingSeverity severity,const std::string & tag)339 void LogMessage::OutputToDebug(const std::string& str,
340                                LoggingSeverity severity,
341                                const std::string& tag) {
342   bool log_to_stderr = log_to_stderr_;
343 #if defined(WEBRTC_MAC) && !defined(WEBRTC_IOS) && defined(NDEBUG)
344   // On the Mac, all stderr output goes to the Console log and causes clutter.
345   // So in opt builds, don't log to stderr unless the user specifically sets
346   // a preference to do so.
347   CFStringRef key = CFStringCreateWithCString(kCFAllocatorDefault,
348                                               "logToStdErr",
349                                               kCFStringEncodingUTF8);
350   CFStringRef domain = CFBundleGetIdentifier(CFBundleGetMainBundle());
351   if (key != NULL && domain != NULL) {
352     Boolean exists_and_is_valid;
353     Boolean should_log =
354         CFPreferencesGetAppBooleanValue(key, domain, &exists_and_is_valid);
355     // If the key doesn't exist or is invalid or is false, we will not log to
356     // stderr.
357     log_to_stderr = exists_and_is_valid && should_log;
358   }
359   if (key != NULL) {
360     CFRelease(key);
361   }
362 #endif
363 #if defined(WEBRTC_WIN)
364   // Always log to the debugger.
365   // Perhaps stderr should be controlled by a preference, as on Mac?
366   OutputDebugStringA(str.c_str());
367   if (log_to_stderr) {
368     // This handles dynamically allocated consoles, too.
369     if (HANDLE error_handle = ::GetStdHandle(STD_ERROR_HANDLE)) {
370       log_to_stderr = false;
371       DWORD written = 0;
372       ::WriteFile(error_handle, str.data(), static_cast<DWORD>(str.size()),
373                   &written, 0);
374     }
375   }
376 #endif  // WEBRTC_WIN
377 #if defined(WEBRTC_ANDROID)
378   // Android's logging facility uses severity to log messages but we
379   // need to map libjingle's severity levels to Android ones first.
380   // Also write to stderr which maybe available to executable started
381   // from the shell.
382   int prio;
383   switch (severity) {
384     case LS_SENSITIVE:
385       __android_log_write(ANDROID_LOG_INFO, tag.c_str(), "SENSITIVE");
386       if (log_to_stderr) {
387         fprintf(stderr, "SENSITIVE");
388         fflush(stderr);
389       }
390       return;
391     case LS_VERBOSE:
392       prio = ANDROID_LOG_VERBOSE;
393       break;
394     case LS_INFO:
395       prio = ANDROID_LOG_INFO;
396       break;
397     case LS_WARNING:
398       prio = ANDROID_LOG_WARN;
399       break;
400     case LS_ERROR:
401       prio = ANDROID_LOG_ERROR;
402       break;
403     default:
404       prio = ANDROID_LOG_UNKNOWN;
405   }
406 
407   int size = str.size();
408   int line = 0;
409   int idx = 0;
410   const int max_lines = size / kMaxLogLineSize + 1;
411   if (max_lines == 1) {
412     __android_log_print(prio, tag.c_str(), "%.*s", size, str.c_str());
413   } else {
414     while (size > 0) {
415       const int len = std::min(size, kMaxLogLineSize);
416       // Use the size of the string in the format (str may have \0 in the
417       // middle).
418       __android_log_print(prio, tag.c_str(), "[%d/%d] %.*s",
419                           line + 1, max_lines,
420                           len, str.c_str() + idx);
421       idx += len;
422       size -= len;
423       ++line;
424     }
425   }
426 #endif  // WEBRTC_ANDROID
427   if (log_to_stderr) {
428     fprintf(stderr, "%s", str.c_str());
429     fflush(stderr);
430   }
431 }
432 
433 //////////////////////////////////////////////////////////////////////
434 // Logging Helpers
435 //////////////////////////////////////////////////////////////////////
436 
LogMultiline(LoggingSeverity level,const char * label,bool input,const void * data,size_t len,bool hex_mode,LogMultilineState * state)437 void LogMultiline(LoggingSeverity level, const char* label, bool input,
438                   const void* data, size_t len, bool hex_mode,
439                   LogMultilineState* state) {
440   if (!LOG_CHECK_LEVEL_V(level))
441     return;
442 
443   const char * direction = (input ? " << " : " >> ");
444 
445   // NULL data means to flush our count of unprintable characters.
446   if (!data) {
447     if (state && state->unprintable_count_[input]) {
448       LOG_V(level) << label << direction << "## "
449                    << state->unprintable_count_[input]
450                    << " consecutive unprintable ##";
451       state->unprintable_count_[input] = 0;
452     }
453     return;
454   }
455 
456   // The ctype classification functions want unsigned chars.
457   const unsigned char* udata = static_cast<const unsigned char*>(data);
458 
459   if (hex_mode) {
460     const size_t LINE_SIZE = 24;
461     char hex_line[LINE_SIZE * 9 / 4 + 2], asc_line[LINE_SIZE + 1];
462     while (len > 0) {
463       memset(asc_line, ' ', sizeof(asc_line));
464       memset(hex_line, ' ', sizeof(hex_line));
465       size_t line_len = std::min(len, LINE_SIZE);
466       for (size_t i = 0; i < line_len; ++i) {
467         unsigned char ch = udata[i];
468         asc_line[i] = isprint(ch) ? ch : '.';
469         hex_line[i*2 + i/4] = hex_encode(ch >> 4);
470         hex_line[i*2 + i/4 + 1] = hex_encode(ch & 0xf);
471       }
472       asc_line[sizeof(asc_line)-1] = 0;
473       hex_line[sizeof(hex_line)-1] = 0;
474       LOG_V(level) << label << direction
475                    << asc_line << " " << hex_line << " ";
476       udata += line_len;
477       len -= line_len;
478     }
479     return;
480   }
481 
482   size_t consecutive_unprintable = state ? state->unprintable_count_[input] : 0;
483 
484   const unsigned char* end = udata + len;
485   while (udata < end) {
486     const unsigned char* line = udata;
487     const unsigned char* end_of_line = strchrn<unsigned char>(udata,
488                                                               end - udata,
489                                                               '\n');
490     if (!end_of_line) {
491       udata = end_of_line = end;
492     } else {
493       udata = end_of_line + 1;
494     }
495 
496     bool is_printable = true;
497 
498     // If we are in unprintable mode, we need to see a line of at least
499     // kMinPrintableLine characters before we'll switch back.
500     const ptrdiff_t kMinPrintableLine = 4;
501     if (consecutive_unprintable && ((end_of_line - line) < kMinPrintableLine)) {
502       is_printable = false;
503     } else {
504       // Determine if the line contains only whitespace and printable
505       // characters.
506       bool is_entirely_whitespace = true;
507       for (const unsigned char* pos = line; pos < end_of_line; ++pos) {
508         if (isspace(*pos))
509           continue;
510         is_entirely_whitespace = false;
511         if (!isprint(*pos)) {
512           is_printable = false;
513           break;
514         }
515       }
516       // Treat an empty line following unprintable data as unprintable.
517       if (consecutive_unprintable && is_entirely_whitespace) {
518         is_printable = false;
519       }
520     }
521     if (!is_printable) {
522       consecutive_unprintable += (udata - line);
523       continue;
524     }
525     // Print out the current line, but prefix with a count of prior unprintable
526     // characters.
527     if (consecutive_unprintable) {
528       LOG_V(level) << label << direction << "## " << consecutive_unprintable
529                   << " consecutive unprintable ##";
530       consecutive_unprintable = 0;
531     }
532     // Strip off trailing whitespace.
533     while ((end_of_line > line) && isspace(*(end_of_line-1))) {
534       --end_of_line;
535     }
536     // Filter out any private data
537     std::string substr(reinterpret_cast<const char*>(line), end_of_line - line);
538     std::string::size_type pos_private = substr.find("Email");
539     if (pos_private == std::string::npos) {
540       pos_private = substr.find("Passwd");
541     }
542     if (pos_private == std::string::npos) {
543       LOG_V(level) << label << direction << substr;
544     } else {
545       LOG_V(level) << label << direction << "## omitted for privacy ##";
546     }
547   }
548 
549   if (state) {
550     state->unprintable_count_[input] = consecutive_unprintable;
551   }
552 }
553 
554 //////////////////////////////////////////////////////////////////////
555 
556 }  // namespace rtc
557