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