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>
22static 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
26static 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
42namespace rtc {
43
44/////////////////////////////////////////////////////////////////////////////
45// Constant Labels
46/////////////////////////////////////////////////////////////////////////////
47
48const 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
57std::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
75const int LogMessage::NO_LOGGING = LS_ERROR + 1;
76
77#if _DEBUG
78static const int LOG_DEFAULT = LS_INFO;
79#else  // !_DEBUG
80static const int LOG_DEFAULT = LogMessage::NO_LOGGING;
81#endif  // !_DEBUG
82
83// Global lock for log subsystem, only needed to serialize access to streams_.
84CriticalSection LogMessage::crit_;
85
86// By default, release builds don't log, debug builds at info level
87int LogMessage::min_sev_ = LOG_DEFAULT;
88int LogMessage::dbg_sev_ = LOG_DEFAULT;
89
90// Don't bother printing context for the ubiquitous INFO log messages
91int 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).
97LogMessage::StreamList LogMessage::streams_;
98
99// Boolean options default to false (0)
100bool LogMessage::thread_, LogMessage::timestamp_;
101
102// If we're in diagnostic mode, we'll be explicitly set that way; default=false.
103bool LogMessage::is_diagnostic_mode_ = false;
104
105LogMessage::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
174LogMessage::~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
205uint32 LogMessage::LogStartTime() {
206  static const uint32 g_start = Time();
207  return g_start;
208}
209
210uint32 LogMessage::WallClockStartTime() {
211  static const uint32 g_start_wallclock = time(NULL);
212  return g_start_wallclock;
213}
214
215void LogMessage::LogContext(int min_sev) {
216  ctx_sev_ = min_sev;
217}
218
219void LogMessage::LogThreads(bool on) {
220  thread_ = on;
221}
222
223void LogMessage::LogTimestamps(bool on) {
224  timestamp_ = on;
225}
226
227void LogMessage::LogToDebug(int min_sev) {
228  dbg_sev_ = min_sev;
229  UpdateMinLogSeverity();
230}
231
232void 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
245int 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
256void 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
262void 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
273void 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
350int 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
368void 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
376const 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
387const 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
396void 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
489void 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
499void 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