/* * Copyright 2004 The WebRTC Project Authors. All rights reserved. * * Use of this source code is governed by a BSD-style license * that can be found in the LICENSE file in the root of the source * tree. An additional intellectual property rights grant can be found * in the file PATENTS. All contributing project authors may * be found in the AUTHORS file in the root of the source tree. */ #if defined(WEBRTC_WIN) #define WIN32_LEAN_AND_MEAN #include <windows.h> #define snprintf _snprintf #undef ERROR // wingdi.h #endif #if defined(WEBRTC_MAC) && !defined(WEBRTC_IOS) #include <CoreServices/CoreServices.h> #elif defined(WEBRTC_ANDROID) #include <android/log.h> static const char kLibjingle[] = "libjingle"; // Android has a 1024 limit on log inputs. We use 60 chars as an // approx for the header/tag portion. // See android/system/core/liblog/logd_write.c static const int kMaxLogLineSize = 1024 - 60; #endif // WEBRTC_MAC && !defined(WEBRTC_IOS) || WEBRTC_ANDROID #include <time.h> #include <ostream> #include <iomanip> #include <limits.h> #include <vector> #include "webrtc/base/logging.h" #include "webrtc/base/stream.h" #include "webrtc/base/stringencode.h" #include "webrtc/base/stringutils.h" #include "webrtc/base/timeutils.h" namespace rtc { ///////////////////////////////////////////////////////////////////////////// // Constant Labels ///////////////////////////////////////////////////////////////////////////// const char * FindLabel(int value, const ConstantLabel entries[]) { for (int i = 0; entries[i].label; ++i) { if (value == entries[i].value) { return entries[i].label; } } return 0; } std::string ErrorName(int err, const ConstantLabel * err_table) { if (err == 0) return "No error"; if (err_table != 0) { if (const char * value = FindLabel(err, err_table)) return value; } char buffer[16]; snprintf(buffer, sizeof(buffer), "0x%08x", err); return buffer; } ///////////////////////////////////////////////////////////////////////////// // LogMessage ///////////////////////////////////////////////////////////////////////////// const int LogMessage::NO_LOGGING = LS_ERROR + 1; #if _DEBUG static const int LOG_DEFAULT = LS_INFO; #else // !_DEBUG static const int LOG_DEFAULT = LogMessage::NO_LOGGING; #endif // !_DEBUG // Global lock for log subsystem, only needed to serialize access to streams_. CriticalSection LogMessage::crit_; // By default, release builds don't log, debug builds at info level int LogMessage::min_sev_ = LOG_DEFAULT; int LogMessage::dbg_sev_ = LOG_DEFAULT; // Don't bother printing context for the ubiquitous INFO log messages int LogMessage::ctx_sev_ = LS_WARNING; // The list of logging streams currently configured. // Note: we explicitly do not clean this up, because of the uncertain ordering // of destructors at program exit. Let the person who sets the stream trigger // cleanup by setting to NULL, or let it leak (safe at program exit). LogMessage::StreamList LogMessage::streams_; // Boolean options default to false (0) bool LogMessage::thread_, LogMessage::timestamp_; // If we're in diagnostic mode, we'll be explicitly set that way; default=false. bool LogMessage::is_diagnostic_mode_ = false; LogMessage::LogMessage(const char* file, int line, LoggingSeverity sev, LogErrorContext err_ctx, int err, const char* module) : severity_(sev), warn_slow_logs_delay_(WARN_SLOW_LOGS_DELAY) { if (timestamp_) { uint32 time = TimeSince(LogStartTime()); // Also ensure WallClockStartTime is initialized, so that it matches // LogStartTime. WallClockStartTime(); print_stream_ << "[" << std::setfill('0') << std::setw(3) << (time / 1000) << ":" << std::setw(3) << (time % 1000) << std::setfill(' ') << "] "; } if (thread_) { #if defined(WEBRTC_WIN) DWORD id = GetCurrentThreadId(); print_stream_ << "[" << std::hex << id << std::dec << "] "; #endif // WEBRTC_WIN } if (severity_ >= ctx_sev_) { print_stream_ << Describe(sev) << "(" << DescribeFile(file) << ":" << line << "): "; } if (err_ctx != ERRCTX_NONE) { std::ostringstream tmp; tmp << "[0x" << std::setfill('0') << std::hex << std::setw(8) << err << "]"; switch (err_ctx) { case ERRCTX_ERRNO: tmp << " " << strerror(err); break; #if WEBRTC_WIN case ERRCTX_HRESULT: { char msgbuf[256]; DWORD flags = FORMAT_MESSAGE_FROM_SYSTEM; HMODULE hmod = GetModuleHandleA(module); if (hmod) flags |= FORMAT_MESSAGE_FROM_HMODULE; if (DWORD len = FormatMessageA( flags, hmod, err, MAKELANGID(LANG_NEUTRAL, SUBLANG_DEFAULT), msgbuf, sizeof(msgbuf) / sizeof(msgbuf[0]), NULL)) { while ((len > 0) && isspace(static_cast<unsigned char>(msgbuf[len-1]))) { msgbuf[--len] = 0; } tmp << " " << msgbuf; } break; } #endif // WEBRTC_WIN #if defined(WEBRTC_MAC) && !defined(WEBRTC_IOS) case ERRCTX_OSSTATUS: { tmp << " " << nonnull(GetMacOSStatusErrorString(err), "Unknown error"); if (const char* desc = GetMacOSStatusCommentString(err)) { tmp << ": " << desc; } break; } #endif // WEBRTC_MAC && !defined(WEBRTC_IOS) default: break; } extra_ = tmp.str(); } } LogMessage::~LogMessage() { if (!extra_.empty()) print_stream_ << " : " << extra_; print_stream_ << std::endl; const std::string& str = print_stream_.str(); if (severity_ >= dbg_sev_) { OutputToDebug(str, severity_); } uint32 before = Time(); // Must lock streams_ before accessing CritScope cs(&crit_); for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { if (severity_ >= it->second) { OutputToStream(it->first, str); } } uint32 delay = TimeSince(before); if (delay >= warn_slow_logs_delay_) { LogMessage slow_log_warning = rtc::LogMessage(__FILE__, __LINE__, LS_WARNING); // If our warning is slow, we don't want to warn about it, because // that would lead to inifinite recursion. So, give a really big // number for the delay threshold. slow_log_warning.warn_slow_logs_delay_ = UINT_MAX; slow_log_warning.stream() << "Slow log: took " << delay << "ms to write " << str.size() << " bytes."; } } uint32 LogMessage::LogStartTime() { static const uint32 g_start = Time(); return g_start; } uint32 LogMessage::WallClockStartTime() { static const uint32 g_start_wallclock = time(NULL); return g_start_wallclock; } void LogMessage::LogContext(int min_sev) { ctx_sev_ = min_sev; } void LogMessage::LogThreads(bool on) { thread_ = on; } void LogMessage::LogTimestamps(bool on) { timestamp_ = on; } void LogMessage::LogToDebug(int min_sev) { dbg_sev_ = min_sev; UpdateMinLogSeverity(); } void LogMessage::LogToStream(StreamInterface* stream, int min_sev) { CritScope cs(&crit_); // Discard and delete all previously installed streams for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { delete it->first; } streams_.clear(); // Install the new stream, if specified if (stream) { AddLogToStream(stream, min_sev); } } int LogMessage::GetLogToStream(StreamInterface* stream) { CritScope cs(&crit_); int sev = NO_LOGGING; for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { if (!stream || stream == it->first) { sev = _min(sev, it->second); } } return sev; } void LogMessage::AddLogToStream(StreamInterface* stream, int min_sev) { CritScope cs(&crit_); streams_.push_back(std::make_pair(stream, min_sev)); UpdateMinLogSeverity(); } void LogMessage::RemoveLogToStream(StreamInterface* stream) { CritScope cs(&crit_); for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { if (stream == it->first) { streams_.erase(it); break; } } UpdateMinLogSeverity(); } void LogMessage::ConfigureLogging(const char* params, const char* filename) { int current_level = LS_VERBOSE; int debug_level = GetLogToDebug(); int file_level = GetLogToStream(); std::vector<std::string> tokens; tokenize(params, ' ', &tokens); for (size_t i = 0; i < tokens.size(); ++i) { if (tokens[i].empty()) continue; // Logging features if (tokens[i] == "tstamp") { LogTimestamps(); } else if (tokens[i] == "thread") { LogThreads(); // Logging levels } else if (tokens[i] == "sensitive") { current_level = LS_SENSITIVE; } else if (tokens[i] == "verbose") { current_level = LS_VERBOSE; } else if (tokens[i] == "info") { current_level = LS_INFO; } else if (tokens[i] == "warning") { current_level = LS_WARNING; } else if (tokens[i] == "error") { current_level = LS_ERROR; } else if (tokens[i] == "none") { current_level = NO_LOGGING; // Logging targets } else if (tokens[i] == "file") { file_level = current_level; } else if (tokens[i] == "debug") { debug_level = current_level; } } #if defined(WEBRTC_WIN) if ((NO_LOGGING != debug_level) && !::IsDebuggerPresent()) { // First, attempt to attach to our parent's console... so if you invoke // from the command line, we'll see the output there. Otherwise, create // our own console window. // Note: These methods fail if a console already exists, which is fine. bool success = false; typedef BOOL (WINAPI* PFN_AttachConsole)(DWORD); if (HINSTANCE kernel32 = ::LoadLibrary(L"kernel32.dll")) { // AttachConsole is defined on WinXP+. if (PFN_AttachConsole attach_console = reinterpret_cast<PFN_AttachConsole> (::GetProcAddress(kernel32, "AttachConsole"))) { success = (FALSE != attach_console(ATTACH_PARENT_PROCESS)); } ::FreeLibrary(kernel32); } if (!success) { ::AllocConsole(); } } #endif // WEBRTC_WIN LogToDebug(debug_level); #if !defined(__native_client__) // No logging to file in NaCl. scoped_ptr<FileStream> stream; if (NO_LOGGING != file_level) { stream.reset(new FileStream); if (!stream->Open(filename, "wb", NULL) || !stream->DisableBuffering()) { stream.reset(); } } LogToStream(stream.release(), file_level); #endif } int LogMessage::ParseLogSeverity(const std::string& value) { int level = NO_LOGGING; if (value == "LS_SENSITIVE") { level = LS_SENSITIVE; } else if (value == "LS_VERBOSE") { level = LS_VERBOSE; } else if (value == "LS_INFO") { level = LS_INFO; } else if (value == "LS_WARNING") { level = LS_WARNING; } else if (value == "LS_ERROR") { level = LS_ERROR; } else if (isdigit(value[0])) { level = atoi(value.c_str()); // NOLINT } return level; } void LogMessage::UpdateMinLogSeverity() { int min_sev = dbg_sev_; for (StreamList::iterator it = streams_.begin(); it != streams_.end(); ++it) { min_sev = _min(dbg_sev_, it->second); } min_sev_ = min_sev; } const char* LogMessage::Describe(LoggingSeverity sev) { switch (sev) { case LS_SENSITIVE: return "Sensitive"; case LS_VERBOSE: return "Verbose"; case LS_INFO: return "Info"; case LS_WARNING: return "Warning"; case LS_ERROR: return "Error"; default: return "<unknown>"; } } const char* LogMessage::DescribeFile(const char* file) { const char* end1 = ::strrchr(file, '/'); const char* end2 = ::strrchr(file, '\\'); if (!end1 && !end2) return file; else return (end1 > end2) ? end1 + 1 : end2 + 1; } void LogMessage::OutputToDebug(const std::string& str, LoggingSeverity severity) { bool log_to_stderr = true; #if defined(WEBRTC_MAC) && !defined(WEBRTC_IOS) && (!defined(DEBUG) || defined(NDEBUG)) // On the Mac, all stderr output goes to the Console log and causes clutter. // So in opt builds, don't log to stderr unless the user specifically sets // a preference to do so. CFStringRef key = CFStringCreateWithCString(kCFAllocatorDefault, "logToStdErr", kCFStringEncodingUTF8); CFStringRef domain = CFBundleGetIdentifier(CFBundleGetMainBundle()); if (key != NULL && domain != NULL) { Boolean exists_and_is_valid; Boolean should_log = CFPreferencesGetAppBooleanValue(key, domain, &exists_and_is_valid); // If the key doesn't exist or is invalid or is false, we will not log to // stderr. log_to_stderr = exists_and_is_valid && should_log; } if (key != NULL) { CFRelease(key); } #endif #if defined(WEBRTC_WIN) // Always log to the debugger. // Perhaps stderr should be controlled by a preference, as on Mac? OutputDebugStringA(str.c_str()); if (log_to_stderr) { // This handles dynamically allocated consoles, too. if (HANDLE error_handle = ::GetStdHandle(STD_ERROR_HANDLE)) { log_to_stderr = false; DWORD written = 0; ::WriteFile(error_handle, str.data(), static_cast<DWORD>(str.size()), &written, 0); } } #endif // WEBRTC_WIN #if defined(WEBRTC_ANDROID) // Android's logging facility uses severity to log messages but we // need to map libjingle's severity levels to Android ones first. // Also write to stderr which maybe available to executable started // from the shell. int prio; switch (severity) { case LS_SENSITIVE: __android_log_write(ANDROID_LOG_INFO, kLibjingle, "SENSITIVE"); if (log_to_stderr) { fprintf(stderr, "SENSITIVE"); fflush(stderr); } return; case LS_VERBOSE: prio = ANDROID_LOG_VERBOSE; break; case LS_INFO: prio = ANDROID_LOG_INFO; break; case LS_WARNING: prio = ANDROID_LOG_WARN; break; case LS_ERROR: prio = ANDROID_LOG_ERROR; break; default: prio = ANDROID_LOG_UNKNOWN; } int size = str.size(); int line = 0; int idx = 0; const int max_lines = size / kMaxLogLineSize + 1; if (max_lines == 1) { __android_log_print(prio, kLibjingle, "%.*s", size, str.c_str()); } else { while (size > 0) { const int len = std::min(size, kMaxLogLineSize); // Use the size of the string in the format (str may have \0 in the // middle). __android_log_print(prio, kLibjingle, "[%d/%d] %.*s", line + 1, max_lines, len, str.c_str() + idx); idx += len; size -= len; ++line; } } #endif // WEBRTC_ANDROID if (log_to_stderr) { fprintf(stderr, "%s", str.c_str()); fflush(stderr); } } void LogMessage::OutputToStream(StreamInterface* stream, const std::string& str) { // If write isn't fully successful, what are we going to do, log it? :) stream->WriteAll(str.data(), str.size(), NULL, NULL); } ////////////////////////////////////////////////////////////////////// // Logging Helpers ////////////////////////////////////////////////////////////////////// void LogMultiline(LoggingSeverity level, const char* label, bool input, const void* data, size_t len, bool hex_mode, LogMultilineState* state) { if (!LOG_CHECK_LEVEL_V(level)) return; const char * direction = (input ? " << " : " >> "); // NULL data means to flush our count of unprintable characters. if (!data) { if (state && state->unprintable_count_[input]) { LOG_V(level) << label << direction << "## " << state->unprintable_count_[input] << " consecutive unprintable ##"; state->unprintable_count_[input] = 0; } return; } // The ctype classification functions want unsigned chars. const unsigned char* udata = static_cast<const unsigned char*>(data); if (hex_mode) { const size_t LINE_SIZE = 24; char hex_line[LINE_SIZE * 9 / 4 + 2], asc_line[LINE_SIZE + 1]; while (len > 0) { memset(asc_line, ' ', sizeof(asc_line)); memset(hex_line, ' ', sizeof(hex_line)); size_t line_len = _min(len, LINE_SIZE); for (size_t i = 0; i < line_len; ++i) { unsigned char ch = udata[i]; asc_line[i] = isprint(ch) ? ch : '.'; hex_line[i*2 + i/4] = hex_encode(ch >> 4); hex_line[i*2 + i/4 + 1] = hex_encode(ch & 0xf); } asc_line[sizeof(asc_line)-1] = 0; hex_line[sizeof(hex_line)-1] = 0; LOG_V(level) << label << direction << asc_line << " " << hex_line << " "; udata += line_len; len -= line_len; } return; } size_t consecutive_unprintable = state ? state->unprintable_count_[input] : 0; const unsigned char* end = udata + len; while (udata < end) { const unsigned char* line = udata; const unsigned char* end_of_line = strchrn<unsigned char>(udata, end - udata, '\n'); if (!end_of_line) { udata = end_of_line = end; } else { udata = end_of_line + 1; } bool is_printable = true; // If we are in unprintable mode, we need to see a line of at least // kMinPrintableLine characters before we'll switch back. const ptrdiff_t kMinPrintableLine = 4; if (consecutive_unprintable && ((end_of_line - line) < kMinPrintableLine)) { is_printable = false; } else { // Determine if the line contains only whitespace and printable // characters. bool is_entirely_whitespace = true; for (const unsigned char* pos = line; pos < end_of_line; ++pos) { if (isspace(*pos)) continue; is_entirely_whitespace = false; if (!isprint(*pos)) { is_printable = false; break; } } // Treat an empty line following unprintable data as unprintable. if (consecutive_unprintable && is_entirely_whitespace) { is_printable = false; } } if (!is_printable) { consecutive_unprintable += (udata - line); continue; } // Print out the current line, but prefix with a count of prior unprintable // characters. if (consecutive_unprintable) { LOG_V(level) << label << direction << "## " << consecutive_unprintable << " consecutive unprintable ##"; consecutive_unprintable = 0; } // Strip off trailing whitespace. while ((end_of_line > line) && isspace(*(end_of_line-1))) { --end_of_line; } // Filter out any private data std::string substr(reinterpret_cast<const char*>(line), end_of_line - line); std::string::size_type pos_private = substr.find("Email"); if (pos_private == std::string::npos) { pos_private = substr.find("Passwd"); } if (pos_private == std::string::npos) { LOG_V(level) << label << direction << substr; } else { LOG_V(level) << label << direction << "## omitted for privacy ##"; } } if (state) { state->unprintable_count_[input] = consecutive_unprintable; } } ////////////////////////////////////////////////////////////////////// } // namespace rtc