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