Home | History | Annotate | Download | only in base 
      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