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