1 /* 2 * libjingle 3 * Copyright 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 <iostream> 47 #include <iomanip> 48 #include <vector> 49 50 #include "talk/base/logging.h" 51 #include "talk/base/stream.h" 52 #include "talk/base/stringencode.h" 53 #include "talk/base/stringutils.h" 54 #include "talk/base/time.h" 55 56 namespace talk_base { 57 58 ///////////////////////////////////////////////////////////////////////////// 59 // Constant Labels 60 ///////////////////////////////////////////////////////////////////////////// 61 62 const char * FindLabel(int value, const ConstantLabel entries[]) { 63 for (int i = 0; entries[i].label; ++i) { 64 if (value == entries[i].value) { 65 return entries[i].label; 66 } 67 } 68 return 0; 69 } 70 71 std::string ErrorName(int err, const ConstantLabel * err_table) { 72 if (err == 0) 73 return "No error"; 74 75 if (err_table != 0) { 76 if (const char * value = FindLabel(err, err_table)) 77 return value; 78 } 79 80 char buffer[16]; 81 snprintf(buffer, sizeof(buffer), "0x%08x", err); 82 return buffer; 83 } 84 85 ///////////////////////////////////////////////////////////////////////////// 86 // LogMessage 87 ///////////////////////////////////////////////////////////////////////////// 88 89 const int LogMessage::NO_LOGGING = LS_ERROR + 1; 90 91 #if _DEBUG 92 static const int LOG_DEFAULT = LS_INFO; 93 #else // !_DEBUG 94 static const int LOG_DEFAULT = LogMessage::NO_LOGGING; 95 #endif // !_DEBUG 96 97 // Global lock for log subsystem, only needed to serialize access to streams_. 98 CriticalSection LogMessage::crit_; 99 100 // By default, release builds don't log, debug builds at info level 101 int LogMessage::min_sev_ = LOG_DEFAULT; 102 int LogMessage::dbg_sev_ = LOG_DEFAULT; 103 104 // Don't bother printing context for the ubiquitous INFO log messages 105 int LogMessage::ctx_sev_ = LS_WARNING; 106 107 // The list of logging streams currently configured. 108 // Note: we explicitly do not clean this up, because of the uncertain ordering 109 // of destructors at program exit. Let the person who sets the stream trigger 110 // cleanup by setting to NULL, or let it leak (safe at program exit). 111 LogMessage::StreamList LogMessage::streams_; 112 113 // Boolean options default to false (0) 114 bool LogMessage::thread_, LogMessage::timestamp_; 115 116 // Program start time 117 uint32 LogMessage::start_ = StartTime(); 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 // Android's logging facility keeps track of timestamp and thread. 126 #ifndef ANDROID 127 if (timestamp_) { 128 uint32 time = TimeSince(start_); 129 print_stream_ << "[" << std::setfill('0') << std::setw(3) << (time / 1000) 130 << ":" << std::setw(3) << (time % 1000) << std::setfill(' ') 131 << "] "; 132 } 133 134 if (thread_) { 135 #ifdef WIN32 136 DWORD id = GetCurrentThreadId(); 137 print_stream_ << "[" << std::hex << id << std::dec << "] "; 138 #endif // WIN32 139 } 140 #endif // !ANDROID 141 142 if (severity_ >= ctx_sev_) { 143 print_stream_ << Describe(sev) << "(" << DescribeFile(file) 144 << ":" << line << "): "; 145 } 146 147 if (err_ctx != ERRCTX_NONE) { 148 std::ostringstream tmp; 149 tmp << "[0x" << std::setfill('0') << std::hex << std::setw(8) << err << "]"; 150 switch (err_ctx) { 151 case ERRCTX_ERRNO: 152 tmp << " " << strerror(err); 153 break; 154 #if WIN32 155 case ERRCTX_HRESULT: { 156 char msgbuf[256]; 157 DWORD flags = FORMAT_MESSAGE_FROM_SYSTEM; 158 HMODULE hmod = GetModuleHandleA(module); 159 if (hmod) 160 flags |= FORMAT_MESSAGE_FROM_HMODULE; 161 if (DWORD len = FormatMessageA( 162 flags, hmod, err, 163 MAKELANGID(LANG_NEUTRAL, SUBLANG_DEFAULT), 164 msgbuf, sizeof(msgbuf) / sizeof(msgbuf[0]), NULL)) { 165 while ((len > 0) && 166 isspace(static_cast<unsigned char>(msgbuf[len-1]))) { 167 msgbuf[--len] = 0; 168 } 169 tmp << " " << msgbuf; 170 } 171 break; 172 } 173 #endif // WIN32 174 #if OSX 175 case ERRCTX_OSSTATUS: { 176 tmp << " " << nonnull(GetMacOSStatusErrorString(err), "Unknown error"); 177 if (const char* desc = GetMacOSStatusCommentString(err)) { 178 tmp << ": " << desc; 179 } 180 break; 181 } 182 #endif // OSX 183 default: 184 break; 185 } 186 extra_ = tmp.str(); 187 } 188 } 189 190 LogMessage::~LogMessage() { 191 if (!extra_.empty()) 192 print_stream_ << " : " << extra_; 193 print_stream_ << std::endl; 194 195 const std::string& str = print_stream_.str(); 196 if (severity_ >= dbg_sev_) { 197 OutputToDebug(str, severity_); 198 } 199 200 // Must lock streams_ before accessing 201 CritScope cs(&crit_); 202 for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { 203 if (severity_ >= it->second) { 204 OutputToStream(it->first, str); 205 } 206 } 207 } 208 209 void LogMessage::LogContext(int min_sev) { 210 ctx_sev_ = min_sev; 211 } 212 213 void LogMessage::LogThreads(bool on) { 214 thread_ = on; 215 } 216 217 void LogMessage::LogTimestamps(bool on) { 218 timestamp_ = on; 219 } 220 221 void LogMessage::ResetTimestamps() { 222 start_ = Time(); 223 } 224 225 void LogMessage::LogToDebug(int min_sev) { 226 dbg_sev_ = min_sev; 227 UpdateMinLogSeverity(); 228 } 229 230 void LogMessage::LogToStream(StreamInterface* stream, int min_sev) { 231 CritScope cs(&crit_); 232 // Discard and delete all previously installed streams 233 for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { 234 delete it->first; 235 } 236 streams_.clear(); 237 // Install the new stream, if specified 238 if (stream) { 239 AddLogToStream(stream, min_sev); 240 } 241 } 242 243 int LogMessage::GetLogToStream(StreamInterface* stream) { 244 CritScope cs(&crit_); 245 int sev = NO_LOGGING; 246 for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { 247 if (!stream || stream == it->first) { 248 sev = _min(sev, it->second); 249 } 250 } 251 return sev; 252 } 253 254 void LogMessage::AddLogToStream(StreamInterface* stream, int min_sev) { 255 CritScope cs(&crit_); 256 streams_.push_back(std::make_pair(stream, min_sev)); 257 UpdateMinLogSeverity(); 258 } 259 260 void LogMessage::RemoveLogToStream(StreamInterface* stream) { 261 CritScope cs(&crit_); 262 for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { 263 if (stream == it->first) { 264 streams_.erase(it); 265 break; 266 } 267 } 268 UpdateMinLogSeverity(); 269 } 270 271 void LogMessage::ConfigureLogging(const char* params, const char* filename) { 272 int current_level = LS_VERBOSE; 273 int debug_level = GetLogToDebug(); 274 int file_level = GetLogToStream(); 275 276 std::vector<std::string> tokens; 277 tokenize(params, ' ', &tokens); 278 279 for (size_t i = 0; i < tokens.size(); ++i) { 280 if (tokens[i].empty()) 281 continue; 282 283 // Logging features 284 if (tokens[i] == "tstamp") { 285 LogTimestamps(); 286 } else if (tokens[i] == "thread") { 287 LogThreads(); 288 289 // Logging levels 290 } else if (tokens[i] == "sensitive") { 291 current_level = LS_SENSITIVE; 292 } else if (tokens[i] == "verbose") { 293 current_level = LS_VERBOSE; 294 } else if (tokens[i] == "info") { 295 current_level = LS_INFO; 296 } else if (tokens[i] == "warning") { 297 current_level = LS_WARNING; 298 } else if (tokens[i] == "error") { 299 current_level = LS_ERROR; 300 } else if (tokens[i] == "none") { 301 current_level = NO_LOGGING; 302 303 // Logging targets 304 } else if (tokens[i] == "file") { 305 file_level = current_level; 306 } else if (tokens[i] == "debug") { 307 debug_level = current_level; 308 } 309 } 310 311 #ifdef WIN32 312 if ((NO_LOGGING != 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 // WIN32 332 333 scoped_ptr<FileStream> stream; 334 if (NO_LOGGING != file_level) { 335 stream.reset(new FileStream); 336 if (!stream->Open(filename, "wb") || !stream->DisableBuffering()) { 337 stream.reset(); 338 } 339 } 340 341 LogToDebug(debug_level); 342 LogToStream(stream.release(), file_level); 343 } 344 345 int LogMessage::ParseLogSeverity(const std::string& value) { 346 int level = NO_LOGGING; 347 if (value == "LS_SENSITIVE") { 348 level = LS_SENSITIVE; 349 } else if (value == "LS_VERBOSE") { 350 level = LS_VERBOSE; 351 } else if (value == "LS_INFO") { 352 level = LS_INFO; 353 } else if (value == "LS_WARNING") { 354 level = LS_WARNING; 355 } else if (value == "LS_ERROR") { 356 level = LS_ERROR; 357 } else if (isdigit(value[0])) { 358 level = atoi(value.c_str()); // NOLINT 359 } 360 return level; 361 } 362 363 void LogMessage::UpdateMinLogSeverity() { 364 int min_sev = dbg_sev_; 365 for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { 366 min_sev = _min(dbg_sev_, it->second); 367 } 368 min_sev_ = min_sev; 369 } 370 371 const char* LogMessage::Describe(LoggingSeverity sev) { 372 switch (sev) { 373 case LS_SENSITIVE: return "Sensitive"; 374 case LS_VERBOSE: return "Verbose"; 375 case LS_INFO: return "Info"; 376 case LS_WARNING: return "Warning"; 377 case LS_ERROR: return "Error"; 378 default: return "<unknown>"; 379 } 380 } 381 382 const char* LogMessage::DescribeFile(const char* file) { 383 const char* end1 = ::strrchr(file, '/'); 384 const char* end2 = ::strrchr(file, '\\'); 385 if (!end1 && !end2) 386 return file; 387 else 388 return (end1 > end2) ? end1 + 1 : end2 + 1; 389 } 390 391 void LogMessage::OutputToDebug(const std::string& str, 392 LoggingSeverity severity) { 393 bool log_to_stderr = true; 394 #if defined(OSX) && (!defined(DEBUG) || defined(NDEBUG)) 395 // On the Mac, all stderr output goes to the Console log and causes clutter. 396 // So in opt builds, don't log to stderr unless the user specifically sets 397 // a preference to do so. 398 CFStringRef key = CFStringCreateWithCString(kCFAllocatorDefault, 399 "logToStdErr", 400 kCFStringEncodingUTF8); 401 CFStringRef domain = CFBundleGetIdentifier(CFBundleGetMainBundle()); 402 if (key != NULL && domain != NULL) { 403 Boolean exists_and_is_valid; 404 Boolean should_log = 405 CFPreferencesGetAppBooleanValue(key, domain, &exists_and_is_valid); 406 // If the key doesn't exist or is invalid or is false, we will not log to 407 // stderr. 408 log_to_stderr = exists_and_is_valid && should_log; 409 } 410 if (key != NULL) { 411 CFRelease(key); 412 } 413 #endif 414 #ifdef WIN32 415 // Always log to the debugger. 416 // Perhaps stderr should be controlled by a preference, as on Mac? 417 OutputDebugStringA(str.c_str()); 418 if (log_to_stderr) { 419 // This handles dynamically allocated consoles, too. 420 if (HANDLE error_handle = ::GetStdHandle(STD_ERROR_HANDLE)) { 421 log_to_stderr = false; 422 unsigned long written; // NOLINT 423 ::WriteFile(error_handle, str.data(), str.size(), &written, 0); 424 } 425 } 426 #endif // WIN32 427 #ifdef ANDROID 428 // Android's logging facility uses severity to log messages but we 429 // need to map libjingle's severity levels to Android ones first. 430 // Also write to stderr which maybe available to executable started 431 // from the shell. 432 int prio; 433 switch (severity) { 434 case LS_SENSITIVE: 435 __android_log_write(ANDROID_LOG_INFO, kLibjingle, "SENSITIVE"); 436 if (log_to_stderr) { 437 std::cerr << "SENSITIVE"; 438 std::cerr.flush(); 439 } 440 return; 441 case LS_VERBOSE: 442 prio = ANDROID_LOG_VERBOSE; 443 break; 444 case LS_INFO: 445 prio = ANDROID_LOG_INFO; 446 break; 447 case LS_WARNING: 448 prio = ANDROID_LOG_WARN; 449 break; 450 case LS_ERROR: 451 prio = ANDROID_LOG_ERROR; 452 break; 453 default: 454 prio = ANDROID_LOG_UNKNOWN; 455 } 456 457 int size = str.size(); 458 int line = 0; 459 int idx = 0; 460 const int max_lines = size / kMaxLogLineSize + 1; 461 if (max_lines == 1) { 462 __android_log_print(prio, kLibjingle, "%.*s", size, str.c_str()); 463 } else { 464 while (size > 0) { 465 const int len = std::min(size, kMaxLogLineSize); 466 // Use the size of the string in the format (str may have \0 in the 467 // middle). 468 __android_log_print(prio, kLibjingle, "[%d/%d] %.*s", 469 line + 1, max_lines, 470 len, str.c_str() + idx); 471 idx += len; 472 size -= len; 473 ++line; 474 } 475 } 476 #endif // ANDROID 477 if (log_to_stderr) { 478 std::cerr << str; 479 std::cerr.flush(); 480 } 481 } 482 483 void LogMessage::OutputToStream(StreamInterface* stream, 484 const std::string& str) { 485 // If write isn't fully successful, what are we going to do, log it? :) 486 stream->WriteAll(str.data(), str.size(), NULL, NULL); 487 } 488 489 ////////////////////////////////////////////////////////////////////// 490 // Logging Helpers 491 ////////////////////////////////////////////////////////////////////// 492 493 void LogMultiline(LoggingSeverity level, const char* label, bool input, 494 const void* data, size_t len, bool hex_mode, 495 LogMultilineState* state) { 496 if (!LOG_CHECK_LEVEL_V(level)) 497 return; 498 499 const char * direction = (input ? " << " : " >> "); 500 501 // NULL data means to flush our count of unprintable characters. 502 if (!data) { 503 if (state && state->unprintable_count_[input]) { 504 LOG_V(level) << label << direction << "## " 505 << state->unprintable_count_[input] 506 << " consecutive unprintable ##"; 507 state->unprintable_count_[input] = 0; 508 } 509 return; 510 } 511 512 // The ctype classification functions want unsigned chars. 513 const unsigned char* udata = static_cast<const unsigned char*>(data); 514 515 if (hex_mode) { 516 const size_t LINE_SIZE = 24; 517 char hex_line[LINE_SIZE * 9 / 4 + 2], asc_line[LINE_SIZE + 1]; 518 while (len > 0) { 519 memset(asc_line, ' ', sizeof(asc_line)); 520 memset(hex_line, ' ', sizeof(hex_line)); 521 size_t line_len = _min(len, LINE_SIZE); 522 for (size_t i = 0; i < line_len; ++i) { 523 unsigned char ch = udata[i]; 524 asc_line[i] = isprint(ch) ? ch : '.'; 525 hex_line[i*2 + i/4] = hex_encode(ch >> 4); 526 hex_line[i*2 + i/4 + 1] = hex_encode(ch & 0xf); 527 } 528 asc_line[sizeof(asc_line)-1] = 0; 529 hex_line[sizeof(hex_line)-1] = 0; 530 LOG_V(level) << label << direction 531 << asc_line << " " << hex_line << " "; 532 udata += line_len; 533 len -= line_len; 534 } 535 return; 536 } 537 538 size_t consecutive_unprintable = state ? state->unprintable_count_[input] : 0; 539 540 const unsigned char* end = udata + len; 541 while (udata < end) { 542 const unsigned char* line = udata; 543 const unsigned char* end_of_line = strchrn<unsigned char>(udata, 544 end - udata, 545 '\n'); 546 if (!end_of_line) { 547 udata = end_of_line = end; 548 } else { 549 udata = end_of_line + 1; 550 } 551 552 bool is_printable = true; 553 554 // If we are in unprintable mode, we need to see a line of at least 555 // kMinPrintableLine characters before we'll switch back. 556 const ptrdiff_t kMinPrintableLine = 4; 557 if (consecutive_unprintable && ((end_of_line - line) < kMinPrintableLine)) { 558 is_printable = false; 559 } else { 560 // Determine if the line contains only whitespace and printable 561 // characters. 562 bool is_entirely_whitespace = true; 563 for (const unsigned char* pos = line; pos < end_of_line; ++pos) { 564 if (isspace(*pos)) 565 continue; 566 is_entirely_whitespace = false; 567 if (!isprint(*pos)) { 568 is_printable = false; 569 break; 570 } 571 } 572 // Treat an empty line following unprintable data as unprintable. 573 if (consecutive_unprintable && is_entirely_whitespace) { 574 is_printable = false; 575 } 576 } 577 if (!is_printable) { 578 consecutive_unprintable += (udata - line); 579 continue; 580 } 581 // Print out the current line, but prefix with a count of prior unprintable 582 // characters. 583 if (consecutive_unprintable) { 584 LOG_V(level) << label << direction << "## " << consecutive_unprintable 585 << " consecutive unprintable ##"; 586 consecutive_unprintable = 0; 587 } 588 // Strip off trailing whitespace. 589 while ((end_of_line > line) && isspace(*(end_of_line-1))) { 590 --end_of_line; 591 } 592 // Filter out any private data 593 std::string substr(reinterpret_cast<const char*>(line), end_of_line - line); 594 std::string::size_type pos_private = substr.find("Email"); 595 if (pos_private == std::string::npos) { 596 pos_private = substr.find("Passwd"); 597 } 598 if (pos_private == std::string::npos) { 599 LOG_V(level) << label << direction << substr; 600 } else { 601 LOG_V(level) << label << direction << "## omitted for privacy ##"; 602 } 603 } 604 605 if (state) { 606 state->unprintable_count_[input] = consecutive_unprintable; 607 } 608 } 609 610 ////////////////////////////////////////////////////////////////////// 611 612 } // namespace talk_base 613