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>
39static 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
43static 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
56namespace talk_base {
57
58/////////////////////////////////////////////////////////////////////////////
59// Constant Labels
60/////////////////////////////////////////////////////////////////////////////
61
62const 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
71std::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
89const int LogMessage::NO_LOGGING = LS_ERROR + 1;
90
91#if _DEBUG
92static const int LOG_DEFAULT = LS_INFO;
93#else  // !_DEBUG
94static const int LOG_DEFAULT = LogMessage::NO_LOGGING;
95#endif  // !_DEBUG
96
97// Global lock for log subsystem, only needed to serialize access to streams_.
98CriticalSection LogMessage::crit_;
99
100// By default, release builds don't log, debug builds at info level
101int LogMessage::min_sev_ = LOG_DEFAULT;
102int LogMessage::dbg_sev_ = LOG_DEFAULT;
103
104// Don't bother printing context for the ubiquitous INFO log messages
105int 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).
111LogMessage::StreamList LogMessage::streams_;
112
113// Boolean options default to false (0)
114bool LogMessage::thread_, LogMessage::timestamp_;
115
116// Program start time
117uint32 LogMessage::start_ = StartTime();
118
119// If we're in diagnostic mode, we'll be explicitly set that way; default=false.
120bool LogMessage::is_diagnostic_mode_ = false;
121
122LogMessage::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
190LogMessage::~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
209void LogMessage::LogContext(int min_sev) {
210  ctx_sev_ = min_sev;
211}
212
213void LogMessage::LogThreads(bool on) {
214  thread_ = on;
215}
216
217void LogMessage::LogTimestamps(bool on) {
218  timestamp_ = on;
219}
220
221void LogMessage::ResetTimestamps() {
222  start_ = Time();
223}
224
225void LogMessage::LogToDebug(int min_sev) {
226  dbg_sev_ = min_sev;
227  UpdateMinLogSeverity();
228}
229
230void 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
243int 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
254void 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
260void 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
271void 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
345int 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
363void 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
371const 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
382const 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
391void 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
483void 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
493void 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