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