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