1 /* 2 * libjingle 3 * Copyright 2004--2011, Google Inc. 4 * 5 * Redistribution and use in source and binary forms, with or without 6 * modification, are permitted provided that the following conditions are met: 7 * 8 * 1. Redistributions of source code must retain the above copyright notice, 9 * this list of conditions and the following disclaimer. 10 * 2. Redistributions in binary form must reproduce the above copyright notice, 11 * this list of conditions and the following disclaimer in the documentation 12 * and/or other materials provided with the distribution. 13 * 3. The name of the author may not be used to endorse or promote products 14 * derived from this software without specific prior written permission. 15 * 16 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR ``AS IS'' AND ANY EXPRESS OR IMPLIED 17 * WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES OF 18 * MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO 19 * EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, 20 * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, 21 * PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; 22 * OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, 23 * WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR 24 * OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF 25 * ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. 26 */ 27 28 #ifdef WIN32 29 #define WIN32_LEAN_AND_MEAN 30 #include <windows.h> 31 #define snprintf _snprintf 32 #undef ERROR // wingdi.h 33 #endif 34 35 #ifdef OSX 36 #include <CoreServices/CoreServices.h> 37 #elif defined(ANDROID) 38 #include <android/log.h> 39 static const char kLibjingle[] = "libjingle"; 40 // Android has a 1024 limit on log inputs. We use 60 chars as an 41 // approx for the header/tag portion. 42 // See android/system/core/liblog/logd_write.c 43 static const int kMaxLogLineSize = 1024 - 60; 44 #endif // OSX || ANDROID 45 46 #include <time.h> 47 48 #include <ostream> 49 #include <iomanip> 50 #include <limits.h> 51 #include <vector> 52 53 #include "talk/base/logging.h" 54 #include "talk/base/stream.h" 55 #include "talk/base/stringencode.h" 56 #include "talk/base/stringutils.h" 57 #include "talk/base/timeutils.h" 58 59 namespace talk_base { 60 61 ///////////////////////////////////////////////////////////////////////////// 62 // Constant Labels 63 ///////////////////////////////////////////////////////////////////////////// 64 65 const char * FindLabel(int value, const ConstantLabel entries[]) { 66 for (int i = 0; entries[i].label; ++i) { 67 if (value == entries[i].value) { 68 return entries[i].label; 69 } 70 } 71 return 0; 72 } 73 74 std::string ErrorName(int err, const ConstantLabel * err_table) { 75 if (err == 0) 76 return "No error"; 77 78 if (err_table != 0) { 79 if (const char * value = FindLabel(err, err_table)) 80 return value; 81 } 82 83 char buffer[16]; 84 snprintf(buffer, sizeof(buffer), "0x%08x", err); 85 return buffer; 86 } 87 88 ///////////////////////////////////////////////////////////////////////////// 89 // LogMessage 90 ///////////////////////////////////////////////////////////////////////////// 91 92 const int LogMessage::NO_LOGGING = LS_ERROR + 1; 93 94 #if _DEBUG 95 static const int LOG_DEFAULT = LS_INFO; 96 #else // !_DEBUG 97 static const int LOG_DEFAULT = LogMessage::NO_LOGGING; 98 #endif // !_DEBUG 99 100 // Global lock for log subsystem, only needed to serialize access to streams_. 101 CriticalSection LogMessage::crit_; 102 103 // By default, release builds don't log, debug builds at info level 104 int LogMessage::min_sev_ = LOG_DEFAULT; 105 int LogMessage::dbg_sev_ = LOG_DEFAULT; 106 107 // Don't bother printing context for the ubiquitous INFO log messages 108 int LogMessage::ctx_sev_ = LS_WARNING; 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_; 115 116 // Boolean options default to false (0) 117 bool LogMessage::thread_, LogMessage::timestamp_; 118 119 // If we're in diagnostic mode, we'll be explicitly set that way; default=false. 120 bool LogMessage::is_diagnostic_mode_ = false; 121 122 LogMessage::LogMessage(const char* file, int line, LoggingSeverity sev, 123 LogErrorContext err_ctx, int err, const char* module) 124 : severity_(sev), 125 warn_slow_logs_delay_(WARN_SLOW_LOGS_DELAY) { 126 // Android's logging facility keeps track of timestamp and thread. 127 #ifndef ANDROID 128 if (timestamp_) { 129 uint32 time = TimeSince(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 #ifdef WIN32 140 DWORD id = GetCurrentThreadId(); 141 print_stream_ << "[" << std::hex << id << std::dec << "] "; 142 #endif // WIN32 143 } 144 #endif // !ANDROID 145 146 if (severity_ >= ctx_sev_) { 147 print_stream_ << Describe(sev) << "(" << DescribeFile(file) 148 << ":" << line << "): "; 149 } 150 151 if (err_ctx != ERRCTX_NONE) { 152 std::ostringstream tmp; 153 tmp << "[0x" << std::setfill('0') << std::hex << std::setw(8) << err << "]"; 154 switch (err_ctx) { 155 case ERRCTX_ERRNO: 156 tmp << " " << strerror(err); 157 break; 158 #if WIN32 159 case ERRCTX_HRESULT: { 160 char msgbuf[256]; 161 DWORD flags = FORMAT_MESSAGE_FROM_SYSTEM; 162 HMODULE hmod = GetModuleHandleA(module); 163 if (hmod) 164 flags |= FORMAT_MESSAGE_FROM_HMODULE; 165 if (DWORD len = FormatMessageA( 166 flags, hmod, err, 167 MAKELANGID(LANG_NEUTRAL, SUBLANG_DEFAULT), 168 msgbuf, sizeof(msgbuf) / sizeof(msgbuf[0]), NULL)) { 169 while ((len > 0) && 170 isspace(static_cast<unsigned char>(msgbuf[len-1]))) { 171 msgbuf[--len] = 0; 172 } 173 tmp << " " << msgbuf; 174 } 175 break; 176 } 177 #endif // WIN32 178 #if OSX 179 case ERRCTX_OSSTATUS: { 180 tmp << " " << nonnull(GetMacOSStatusErrorString(err), "Unknown error"); 181 if (const char* desc = GetMacOSStatusCommentString(err)) { 182 tmp << ": " << desc; 183 } 184 break; 185 } 186 #endif // OSX 187 default: 188 break; 189 } 190 extra_ = tmp.str(); 191 } 192 } 193 194 LogMessage::~LogMessage() { 195 if (!extra_.empty()) 196 print_stream_ << " : " << extra_; 197 print_stream_ << std::endl; 198 199 const std::string& str = print_stream_.str(); 200 if (severity_ >= dbg_sev_) { 201 OutputToDebug(str, severity_); 202 } 203 204 uint32 before = Time(); 205 // Must lock streams_ before accessing 206 CritScope cs(&crit_); 207 for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { 208 if (severity_ >= it->second) { 209 OutputToStream(it->first, str); 210 } 211 } 212 uint32 delay = TimeSince(before); 213 if (delay >= warn_slow_logs_delay_) { 214 LogMessage slow_log_warning = 215 talk_base::LogMessage(__FILE__, __LINE__, LS_WARNING); 216 // If our warning is slow, we don't want to warn about it, because 217 // that would lead to inifinite recursion. So, give a really big 218 // number for the delay threshold. 219 slow_log_warning.warn_slow_logs_delay_ = UINT_MAX; 220 slow_log_warning.stream() << "Slow log: took " << delay << "ms to write " 221 << str.size() << " bytes."; 222 } 223 } 224 225 uint32 LogMessage::LogStartTime() { 226 static const uint32 g_start = Time(); 227 return g_start; 228 } 229 230 uint32 LogMessage::WallClockStartTime() { 231 static const uint32 g_start_wallclock = time(NULL); 232 return g_start_wallclock; 233 } 234 235 void LogMessage::LogContext(int min_sev) { 236 ctx_sev_ = min_sev; 237 } 238 239 void LogMessage::LogThreads(bool on) { 240 thread_ = on; 241 } 242 243 void LogMessage::LogTimestamps(bool on) { 244 timestamp_ = on; 245 } 246 247 void LogMessage::LogToDebug(int min_sev) { 248 dbg_sev_ = min_sev; 249 UpdateMinLogSeverity(); 250 } 251 252 void LogMessage::LogToStream(StreamInterface* stream, int min_sev) { 253 CritScope cs(&crit_); 254 // Discard and delete all previously installed streams 255 for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { 256 delete it->first; 257 } 258 streams_.clear(); 259 // Install the new stream, if specified 260 if (stream) { 261 AddLogToStream(stream, min_sev); 262 } 263 } 264 265 int LogMessage::GetLogToStream(StreamInterface* stream) { 266 CritScope cs(&crit_); 267 int sev = NO_LOGGING; 268 for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { 269 if (!stream || stream == it->first) { 270 sev = _min(sev, it->second); 271 } 272 } 273 return sev; 274 } 275 276 void LogMessage::AddLogToStream(StreamInterface* stream, int min_sev) { 277 CritScope cs(&crit_); 278 streams_.push_back(std::make_pair(stream, min_sev)); 279 UpdateMinLogSeverity(); 280 } 281 282 void LogMessage::RemoveLogToStream(StreamInterface* stream) { 283 CritScope cs(&crit_); 284 for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { 285 if (stream == it->first) { 286 streams_.erase(it); 287 break; 288 } 289 } 290 UpdateMinLogSeverity(); 291 } 292 293 void LogMessage::ConfigureLogging(const char* params, const char* filename) { 294 int current_level = LS_VERBOSE; 295 int debug_level = GetLogToDebug(); 296 int file_level = GetLogToStream(); 297 298 std::vector<std::string> tokens; 299 tokenize(params, ' ', &tokens); 300 301 for (size_t i = 0; i < tokens.size(); ++i) { 302 if (tokens[i].empty()) 303 continue; 304 305 // Logging features 306 if (tokens[i] == "tstamp") { 307 LogTimestamps(); 308 } else if (tokens[i] == "thread") { 309 LogThreads(); 310 311 // Logging levels 312 } else if (tokens[i] == "sensitive") { 313 current_level = LS_SENSITIVE; 314 } else if (tokens[i] == "verbose") { 315 current_level = LS_VERBOSE; 316 } else if (tokens[i] == "info") { 317 current_level = LS_INFO; 318 } else if (tokens[i] == "warning") { 319 current_level = LS_WARNING; 320 } else if (tokens[i] == "error") { 321 current_level = LS_ERROR; 322 } else if (tokens[i] == "none") { 323 current_level = NO_LOGGING; 324 325 // Logging targets 326 } else if (tokens[i] == "file") { 327 file_level = current_level; 328 } else if (tokens[i] == "debug") { 329 debug_level = current_level; 330 } 331 } 332 333 #ifdef WIN32 334 if ((NO_LOGGING != debug_level) && !::IsDebuggerPresent()) { 335 // First, attempt to attach to our parent's console... so if you invoke 336 // from the command line, we'll see the output there. Otherwise, create 337 // our own console window. 338 // Note: These methods fail if a console already exists, which is fine. 339 bool success = false; 340 typedef BOOL (WINAPI* PFN_AttachConsole)(DWORD); 341 if (HINSTANCE kernel32 = ::LoadLibrary(L"kernel32.dll")) { 342 // AttachConsole is defined on WinXP+. 343 if (PFN_AttachConsole attach_console = reinterpret_cast<PFN_AttachConsole> 344 (::GetProcAddress(kernel32, "AttachConsole"))) { 345 success = (FALSE != attach_console(ATTACH_PARENT_PROCESS)); 346 } 347 ::FreeLibrary(kernel32); 348 } 349 if (!success) { 350 ::AllocConsole(); 351 } 352 } 353 #endif // WIN32 354 355 scoped_ptr<FileStream> stream; 356 if (NO_LOGGING != file_level) { 357 stream.reset(new FileStream); 358 if (!stream->Open(filename, "wb", NULL) || !stream->DisableBuffering()) { 359 stream.reset(); 360 } 361 } 362 363 LogToDebug(debug_level); 364 LogToStream(stream.release(), file_level); 365 } 366 367 int LogMessage::ParseLogSeverity(const std::string& value) { 368 int level = NO_LOGGING; 369 if (value == "LS_SENSITIVE") { 370 level = LS_SENSITIVE; 371 } else if (value == "LS_VERBOSE") { 372 level = LS_VERBOSE; 373 } else if (value == "LS_INFO") { 374 level = LS_INFO; 375 } else if (value == "LS_WARNING") { 376 level = LS_WARNING; 377 } else if (value == "LS_ERROR") { 378 level = LS_ERROR; 379 } else if (isdigit(value[0])) { 380 level = atoi(value.c_str()); // NOLINT 381 } 382 return level; 383 } 384 385 void LogMessage::UpdateMinLogSeverity() { 386 int min_sev = dbg_sev_; 387 for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { 388 min_sev = _min(dbg_sev_, it->second); 389 } 390 min_sev_ = min_sev; 391 } 392 393 const char* LogMessage::Describe(LoggingSeverity sev) { 394 switch (sev) { 395 case LS_SENSITIVE: return "Sensitive"; 396 case LS_VERBOSE: return "Verbose"; 397 case LS_INFO: return "Info"; 398 case LS_WARNING: return "Warning"; 399 case LS_ERROR: return "Error"; 400 default: return "<unknown>"; 401 } 402 } 403 404 const char* LogMessage::DescribeFile(const char* file) { 405 const char* end1 = ::strrchr(file, '/'); 406 const char* end2 = ::strrchr(file, '\\'); 407 if (!end1 && !end2) 408 return file; 409 else 410 return (end1 > end2) ? end1 + 1 : end2 + 1; 411 } 412 413 void LogMessage::OutputToDebug(const std::string& str, 414 LoggingSeverity severity) { 415 bool log_to_stderr = true; 416 #if defined(OSX) && (!defined(DEBUG) || defined(NDEBUG)) 417 // On the Mac, all stderr output goes to the Console log and causes clutter. 418 // So in opt builds, don't log to stderr unless the user specifically sets 419 // a preference to do so. 420 CFStringRef key = CFStringCreateWithCString(kCFAllocatorDefault, 421 "logToStdErr", 422 kCFStringEncodingUTF8); 423 CFStringRef domain = CFBundleGetIdentifier(CFBundleGetMainBundle()); 424 if (key != NULL && domain != NULL) { 425 Boolean exists_and_is_valid; 426 Boolean should_log = 427 CFPreferencesGetAppBooleanValue(key, domain, &exists_and_is_valid); 428 // If the key doesn't exist or is invalid or is false, we will not log to 429 // stderr. 430 log_to_stderr = exists_and_is_valid && should_log; 431 } 432 if (key != NULL) { 433 CFRelease(key); 434 } 435 #endif 436 #ifdef WIN32 437 // Always log to the debugger. 438 // Perhaps stderr should be controlled by a preference, as on Mac? 439 OutputDebugStringA(str.c_str()); 440 if (log_to_stderr) { 441 // This handles dynamically allocated consoles, too. 442 if (HANDLE error_handle = ::GetStdHandle(STD_ERROR_HANDLE)) { 443 log_to_stderr = false; 444 DWORD written = 0; 445 ::WriteFile(error_handle, str.data(), static_cast<DWORD>(str.size()), 446 &written, 0); 447 } 448 } 449 #endif // WIN32 450 #ifdef ANDROID 451 // Android's logging facility uses severity to log messages but we 452 // need to map libjingle's severity levels to Android ones first. 453 // Also write to stderr which maybe available to executable started 454 // from the shell. 455 int prio; 456 switch (severity) { 457 case LS_SENSITIVE: 458 __android_log_write(ANDROID_LOG_INFO, kLibjingle, "SENSITIVE"); 459 if (log_to_stderr) { 460 fprintf(stderr, "SENSITIVE"); 461 fflush(stderr); 462 } 463 return; 464 case LS_VERBOSE: 465 prio = ANDROID_LOG_VERBOSE; 466 break; 467 case LS_INFO: 468 prio = ANDROID_LOG_INFO; 469 break; 470 case LS_WARNING: 471 prio = ANDROID_LOG_WARN; 472 break; 473 case LS_ERROR: 474 prio = ANDROID_LOG_ERROR; 475 break; 476 default: 477 prio = ANDROID_LOG_UNKNOWN; 478 } 479 480 int size = str.size(); 481 int line = 0; 482 int idx = 0; 483 const int max_lines = size / kMaxLogLineSize + 1; 484 if (max_lines == 1) { 485 __android_log_print(prio, kLibjingle, "%.*s", size, str.c_str()); 486 } else { 487 while (size > 0) { 488 const int len = std::min(size, kMaxLogLineSize); 489 // Use the size of the string in the format (str may have \0 in the 490 // middle). 491 __android_log_print(prio, kLibjingle, "[%d/%d] %.*s", 492 line + 1, max_lines, 493 len, str.c_str() + idx); 494 idx += len; 495 size -= len; 496 ++line; 497 } 498 } 499 #endif // ANDROID 500 if (log_to_stderr) { 501 fprintf(stderr, "%s", str.c_str()); 502 fflush(stderr); 503 } 504 } 505 506 void LogMessage::OutputToStream(StreamInterface* stream, 507 const std::string& str) { 508 // If write isn't fully successful, what are we going to do, log it? :) 509 stream->WriteAll(str.data(), str.size(), NULL, NULL); 510 } 511 512 ////////////////////////////////////////////////////////////////////// 513 // Logging Helpers 514 ////////////////////////////////////////////////////////////////////// 515 516 void LogMultiline(LoggingSeverity level, const char* label, bool input, 517 const void* data, size_t len, bool hex_mode, 518 LogMultilineState* state) { 519 if (!LOG_CHECK_LEVEL_V(level)) 520 return; 521 522 const char * direction = (input ? " << " : " >> "); 523 524 // NULL data means to flush our count of unprintable characters. 525 if (!data) { 526 if (state && state->unprintable_count_[input]) { 527 LOG_V(level) << label << direction << "## " 528 << state->unprintable_count_[input] 529 << " consecutive unprintable ##"; 530 state->unprintable_count_[input] = 0; 531 } 532 return; 533 } 534 535 // The ctype classification functions want unsigned chars. 536 const unsigned char* udata = static_cast<const unsigned char*>(data); 537 538 if (hex_mode) { 539 const size_t LINE_SIZE = 24; 540 char hex_line[LINE_SIZE * 9 / 4 + 2], asc_line[LINE_SIZE + 1]; 541 while (len > 0) { 542 memset(asc_line, ' ', sizeof(asc_line)); 543 memset(hex_line, ' ', sizeof(hex_line)); 544 size_t line_len = _min(len, LINE_SIZE); 545 for (size_t i = 0; i < line_len; ++i) { 546 unsigned char ch = udata[i]; 547 asc_line[i] = isprint(ch) ? ch : '.'; 548 hex_line[i*2 + i/4] = hex_encode(ch >> 4); 549 hex_line[i*2 + i/4 + 1] = hex_encode(ch & 0xf); 550 } 551 asc_line[sizeof(asc_line)-1] = 0; 552 hex_line[sizeof(hex_line)-1] = 0; 553 LOG_V(level) << label << direction 554 << asc_line << " " << hex_line << " "; 555 udata += line_len; 556 len -= line_len; 557 } 558 return; 559 } 560 561 size_t consecutive_unprintable = state ? state->unprintable_count_[input] : 0; 562 563 const unsigned char* end = udata + len; 564 while (udata < end) { 565 const unsigned char* line = udata; 566 const unsigned char* end_of_line = strchrn<unsigned char>(udata, 567 end - udata, 568 '\n'); 569 if (!end_of_line) { 570 udata = end_of_line = end; 571 } else { 572 udata = end_of_line + 1; 573 } 574 575 bool is_printable = true; 576 577 // If we are in unprintable mode, we need to see a line of at least 578 // kMinPrintableLine characters before we'll switch back. 579 const ptrdiff_t kMinPrintableLine = 4; 580 if (consecutive_unprintable && ((end_of_line - line) < kMinPrintableLine)) { 581 is_printable = false; 582 } else { 583 // Determine if the line contains only whitespace and printable 584 // characters. 585 bool is_entirely_whitespace = true; 586 for (const unsigned char* pos = line; pos < end_of_line; ++pos) { 587 if (isspace(*pos)) 588 continue; 589 is_entirely_whitespace = false; 590 if (!isprint(*pos)) { 591 is_printable = false; 592 break; 593 } 594 } 595 // Treat an empty line following unprintable data as unprintable. 596 if (consecutive_unprintable && is_entirely_whitespace) { 597 is_printable = false; 598 } 599 } 600 if (!is_printable) { 601 consecutive_unprintable += (udata - line); 602 continue; 603 } 604 // Print out the current line, but prefix with a count of prior unprintable 605 // characters. 606 if (consecutive_unprintable) { 607 LOG_V(level) << label << direction << "## " << consecutive_unprintable 608 << " consecutive unprintable ##"; 609 consecutive_unprintable = 0; 610 } 611 // Strip off trailing whitespace. 612 while ((end_of_line > line) && isspace(*(end_of_line-1))) { 613 --end_of_line; 614 } 615 // Filter out any private data 616 std::string substr(reinterpret_cast<const char*>(line), end_of_line - line); 617 std::string::size_type pos_private = substr.find("Email"); 618 if (pos_private == std::string::npos) { 619 pos_private = substr.find("Passwd"); 620 } 621 if (pos_private == std::string::npos) { 622 LOG_V(level) << label << direction << substr; 623 } else { 624 LOG_V(level) << label << direction << "## omitted for privacy ##"; 625 } 626 } 627 628 if (state) { 629 state->unprintable_count_[input] = consecutive_unprintable; 630 } 631 } 632 633 ////////////////////////////////////////////////////////////////////// 634 635 } // namespace talk_base 636