Home | History | Annotate | Download | only in common 
      1 // Copyright (c) 2010 The Chromium Authors. All rights reserved.
      2 // Use of this source code is governed by a BSD-style license that can be
      3 // found in the LICENSE file.
      4 
      5 #include "build/build_config.h"
      6 
      7 // Need to include this before most other files because it defines
      8 // IPC_MESSAGE_LOG_ENABLED. We need to use it to define
      9 // IPC_MESSAGE_MACROS_LOG_ENABLED so render_messages.h will generate the
     10 // ViewMsgLog et al. functions.
     11 #include "ipc/ipc_message.h"
     12 
     13 // On Windows, the about:ipc dialog shows IPCs; on POSIX, we hook up a
     14 // logger in this file.  (We implement about:ipc on Mac but implement
     15 // the loggers here anyway).  We need to do this real early to be sure
     16 // IPC_MESSAGE_MACROS_LOG_ENABLED doesn't get undefined.
     17 #if defined(OS_POSIX) && defined(IPC_MESSAGE_LOG_ENABLED)
     18 #define IPC_MESSAGE_MACROS_LOG_ENABLED
     19 #include "chrome/common/devtools_messages.h"
     20 #include "chrome/common/render_messages.h"
     21 #include "content/common/plugin_messages.h"
     22 #include "content/common/worker_messages.h"
     23 #endif
     24 
     25 #if defined(OS_WIN)
     26 #include <windows.h>
     27 #endif
     28 
     29 #include <fstream>
     30 
     31 #include "chrome/common/logging_chrome.h"
     32 
     33 #include "base/command_line.h"
     34 #include "base/compiler_specific.h"
     35 #include "base/debug/debugger.h"
     36 #include "base/environment.h"
     37 #include "base/file_path.h"
     38 #include "base/file_util.h"
     39 #include "base/logging.h"
     40 #include "base/path_service.h"
     41 #include "base/string_number_conversions.h"
     42 #include "base/string_util.h"
     43 #include "base/threading/thread_restrictions.h"
     44 #include "base/time.h"
     45 #include "base/utf_string_conversions.h"
     46 #include "chrome/common/chrome_constants.h"
     47 #include "chrome/common/chrome_paths.h"
     48 #include "chrome/common/chrome_switches.h"
     49 #include "chrome/common/env_vars.h"
     50 #include "ipc/ipc_logging.h"
     51 
     52 #if defined(OS_WIN)
     53 #include "base/logging_win.h"
     54 #include <initguid.h>
     55 #endif
     56 
     57 namespace {
     58 
     59 // When true, this means that error dialogs should not be shown.
     60 bool dialogs_are_suppressed_ = false;
     61 
     62 // This should be true for exactly the period between the end of
     63 // InitChromeLogging() and the beginning of CleanupChromeLogging().
     64 bool chrome_logging_initialized_ = false;
     65 
     66 // Set if we caled InitChromeLogging() but failed to initialize.
     67 bool chrome_logging_failed_ = false;
     68 
     69 // This should be true for exactly the period between the end of
     70 // InitChromeLogging() and the beginning of CleanupChromeLogging().
     71 bool chrome_logging_redirected_ = false;
     72 
     73 #if defined(OS_WIN)
     74 // {7FE69228-633E-4f06-80C1-527FEA23E3A7}
     75 const GUID kChromeTraceProviderName = {
     76     0x7fe69228, 0x633e, 0x4f06,
     77         { 0x80, 0xc1, 0x52, 0x7f, 0xea, 0x23, 0xe3, 0xa7 } };
     78 #endif
     79 
     80 // Assertion handler for logging errors that occur when dialogs are
     81 // silenced.  To record a new error, pass the log string associated
     82 // with that error in the str parameter.
     83 MSVC_DISABLE_OPTIMIZE();
     84 void SilentRuntimeAssertHandler(const std::string& str) {
     85   base::debug::BreakDebugger();
     86 }
     87 void SilentRuntimeReportHandler(const std::string& str) {
     88 }
     89 #if defined(OS_WIN)
     90 // Handler to silently dump the current process when there is an assert in
     91 // chrome.
     92 void DumpProcessAssertHandler(const std::string& str) {
     93   // Get the breakpad pointer from chrome.exe
     94   typedef void (__cdecl *DumpProcessFunction)();
     95   DumpProcessFunction DumpProcess = reinterpret_cast<DumpProcessFunction>(
     96       ::GetProcAddress(::GetModuleHandle(chrome::kBrowserProcessExecutableName),
     97                        "DumpProcess"));
     98   if (DumpProcess)
     99     DumpProcess();
    100 }
    101 #endif  // OS_WIN
    102 MSVC_ENABLE_OPTIMIZE();
    103 
    104 // Suppresses error/assertion dialogs and enables the logging of
    105 // those errors into silenced_errors_.
    106 void SuppressDialogs() {
    107   if (dialogs_are_suppressed_)
    108     return;
    109 
    110   logging::SetLogAssertHandler(SilentRuntimeAssertHandler);
    111   logging::SetLogReportHandler(SilentRuntimeReportHandler);
    112 
    113 #if defined(OS_WIN)
    114   UINT new_flags = SEM_FAILCRITICALERRORS |
    115                    SEM_NOGPFAULTERRORBOX |
    116                    SEM_NOOPENFILEERRORBOX;
    117 
    118   // Preserve existing error mode, as discussed at http://t/dmea
    119   UINT existing_flags = SetErrorMode(new_flags);
    120   SetErrorMode(existing_flags | new_flags);
    121 #endif
    122 
    123   dialogs_are_suppressed_ = true;
    124 }
    125 
    126 }  // anonymous namespace
    127 
    128 namespace logging {
    129 
    130 LoggingDestination DetermineLogMode(const CommandLine& command_line) {
    131   // only use OutputDebugString in debug mode
    132 #ifdef NDEBUG
    133   bool enable_logging = false;
    134   const char *kInvertLoggingSwitch = switches::kEnableLogging;
    135   const logging::LoggingDestination kDefaultLoggingMode =
    136       logging::LOG_ONLY_TO_FILE;
    137 #else
    138   bool enable_logging = true;
    139   const char *kInvertLoggingSwitch = switches::kDisableLogging;
    140   const logging::LoggingDestination kDefaultLoggingMode =
    141       logging::LOG_TO_BOTH_FILE_AND_SYSTEM_DEBUG_LOG;
    142 #endif
    143 
    144   if (command_line.HasSwitch(kInvertLoggingSwitch))
    145     enable_logging = !enable_logging;
    146 
    147   logging::LoggingDestination log_mode;
    148   if (enable_logging) {
    149     // Let --enable-logging=stderr force only stderr, particularly useful for
    150     // non-debug builds where otherwise you can't get logs to stderr at all.
    151     if (command_line.GetSwitchValueASCII(switches::kEnableLogging) == "stderr")
    152       log_mode = logging::LOG_ONLY_TO_SYSTEM_DEBUG_LOG;
    153     else
    154       log_mode = kDefaultLoggingMode;
    155   } else {
    156     log_mode = logging::LOG_NONE;
    157   }
    158   return log_mode;
    159 }
    160 
    161 #if defined(OS_CHROMEOS)
    162 namespace {
    163 FilePath GenerateTimestampedName(const FilePath& base_path,
    164                                  base::Time timestamp) {
    165   base::Time::Exploded time_deets;
    166   timestamp.LocalExplode(&time_deets);
    167   std::string suffix = base::StringPrintf("_%02d%02d%02d-%02d%02d%02d",
    168                                           time_deets.year,
    169                                           time_deets.month,
    170                                           time_deets.day_of_month,
    171                                           time_deets.hour,
    172                                           time_deets.minute,
    173                                           time_deets.second);
    174   return base_path.InsertBeforeExtension(suffix);
    175 }
    176 
    177 FilePath SetUpSymlinkIfNeeded(const FilePath& symlink_path, bool new_log) {
    178   DCHECK(!symlink_path.empty());
    179 
    180   // If not starting a new log, then just log through the existing
    181   // symlink, but if the symlink doesn't exist, create it.  If
    182   // starting a new log, then delete the old symlink and make a new
    183   // one to a fresh log file.
    184   FilePath target_path;
    185   bool symlink_exists = file_util::PathExists(symlink_path);
    186   if (new_log || !symlink_exists) {
    187     target_path = GenerateTimestampedName(symlink_path, base::Time::Now());
    188 
    189     // We don't care if the unlink fails; we're going to continue anyway.
    190     if (::unlink(symlink_path.value().c_str()) == -1) {
    191       if (symlink_exists) // only warn if we might expect it to succeed.
    192         PLOG(WARNING) << "Unable to unlink " << symlink_path.value();
    193     }
    194     if (!file_util::CreateSymbolicLink(target_path, symlink_path)) {
    195       PLOG(ERROR) << "Unable to create symlink " << symlink_path.value()
    196                   << " pointing at " << target_path.value();
    197     }
    198   } else {
    199     if (!file_util::ReadSymbolicLink(symlink_path, &target_path))
    200       PLOG(ERROR) << "Unable to read symlink " << symlink_path.value();
    201   }
    202   return target_path;
    203 }
    204 
    205 void RemoveSymlinkAndLog(const FilePath& link_path,
    206                          const FilePath& target_path) {
    207   if (::unlink(link_path.value().c_str()) == -1)
    208     PLOG(WARNING) << "Unable to unlink symlink " << link_path.value();
    209   if (::unlink(target_path.value().c_str()) == -1)
    210     PLOG(WARNING) << "Unable to unlink log file " << target_path.value();
    211 }
    212 
    213 }  // anonymous namespace
    214 
    215 FilePath GetSessionLogFile(const CommandLine& command_line) {
    216   FilePath log_dir;
    217   std::string log_dir_str;
    218   scoped_ptr<base::Environment> env(base::Environment::Create());
    219   if (env->GetVar(env_vars::kSessionLogDir, &log_dir_str) &&
    220       !log_dir_str.empty()) {
    221     log_dir = FilePath(log_dir_str);
    222   } else {
    223     PathService::Get(chrome::DIR_USER_DATA, &log_dir);
    224     FilePath login_profile =
    225         command_line.GetSwitchValuePath(switches::kLoginProfile);
    226     log_dir = log_dir.Append(login_profile);
    227   }
    228   return log_dir.Append(GetLogFileName().BaseName());
    229 }
    230 
    231 void RedirectChromeLogging(const CommandLine& command_line) {
    232   DCHECK(!chrome_logging_redirected_) <<
    233     "Attempted to redirect logging when it was already initialized.";
    234 
    235   // Redirect logs to the session log directory, if set.  Otherwise
    236   // defaults to the profile dir.
    237   FilePath log_path = GetSessionLogFile(command_line);
    238 
    239   // Creating symlink causes us to do blocking IO on UI thread.
    240   // Temporarily allow it until we fix http://crbug.com/61143
    241   base::ThreadRestrictions::ScopedAllowIO allow_io;
    242   // Always force a new symlink when redirecting.
    243   FilePath target_path = SetUpSymlinkIfNeeded(log_path, true);
    244 
    245   logging::DcheckState dcheck_state =
    246       command_line.HasSwitch(switches::kEnableDCHECK) ?
    247       logging::ENABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS :
    248       logging::DISABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS;
    249 
    250   // ChromeOS always logs through the symlink, so it shouldn't be
    251   // deleted if it already exists.
    252   if (!InitLogging(log_path.value().c_str(),
    253                    DetermineLogMode(command_line),
    254                    logging::LOCK_LOG_FILE,
    255                    logging::APPEND_TO_OLD_LOG_FILE,
    256                    dcheck_state)) {
    257     LOG(ERROR) << "Unable to initialize logging to " << log_path.value();
    258     RemoveSymlinkAndLog(log_path, target_path);
    259   } else {
    260     chrome_logging_redirected_ = true;
    261   }
    262 }
    263 
    264 
    265 #endif
    266 
    267 void InitChromeLogging(const CommandLine& command_line,
    268                        OldFileDeletionState delete_old_log_file) {
    269   DCHECK(!chrome_logging_initialized_) <<
    270     "Attempted to initialize logging when it was already initialized.";
    271 
    272 #if defined(OS_POSIX) && defined(IPC_MESSAGE_LOG_ENABLED)
    273   IPC::Logging::set_log_function_map(&g_log_function_mapping);
    274 #endif
    275 
    276   FilePath log_path = GetLogFileName();
    277 
    278 #if defined(OS_CHROMEOS)
    279   // For BWSI (Incognito) logins, we want to put the logs in the user
    280   // profile directory that is created for the temporary session instead
    281   // of in the system log directory, for privacy reasons.
    282   if (command_line.HasSwitch(switches::kGuestSession))
    283     log_path = GetSessionLogFile(command_line);
    284 
    285   // On ChromeOS we log to the symlink.  We force creation of a new
    286   // symlink if we've been asked to delete the old log, since that
    287   // indicates the start of a new session.
    288   FilePath target_path = SetUpSymlinkIfNeeded(
    289       log_path, delete_old_log_file == logging::DELETE_OLD_LOG_FILE);
    290 
    291   // Because ChromeOS manages the move to a new session by redirecting
    292   // the link, it shouldn't remove the old file in the logging code,
    293   // since that will remove the newly created link instead.
    294   delete_old_log_file = logging::APPEND_TO_OLD_LOG_FILE;
    295 #endif
    296 
    297   logging::DcheckState dcheck_state =
    298       command_line.HasSwitch(switches::kEnableDCHECK) ?
    299       logging::ENABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS :
    300       logging::DISABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS;
    301 
    302   bool success = InitLogging(log_path.value().c_str(),
    303                              DetermineLogMode(command_line),
    304                              logging::LOCK_LOG_FILE,
    305                              delete_old_log_file,
    306                              dcheck_state);
    307 
    308 #if defined(OS_CHROMEOS)
    309   if (!success) {
    310     PLOG(ERROR) << "Unable to initialize logging to " << log_path.value()
    311                 << " (which should be a link to " << target_path.value() << ")";
    312     RemoveSymlinkAndLog(log_path, target_path);
    313     chrome_logging_failed_ = true;
    314     return;
    315   }
    316 #else
    317   if (!success) {
    318     PLOG(ERROR) << "Unable to initialize logging to " << log_path.value();
    319     chrome_logging_failed_ = true;
    320     return;
    321   }
    322 #endif
    323 
    324   // Default to showing error dialogs.
    325   if (!CommandLine::ForCurrentProcess()->HasSwitch(switches::kNoErrorDialogs))
    326     logging::SetShowErrorDialogs(true);
    327 
    328   // we want process and thread IDs because we have a lot of things running
    329   logging::SetLogItems(true,  // enable_process_id
    330                        true,  // enable_thread_id
    331                        false, // enable_timestamp
    332                        true); // enable_tickcount
    333 
    334   // We call running in unattended mode "headless", and allow
    335   // headless mode to be configured either by the Environment
    336   // Variable or by the Command Line Switch.  This is for
    337   // automated test purposes.
    338   scoped_ptr<base::Environment> env(base::Environment::Create());
    339   if (env->HasVar(env_vars::kHeadless) ||
    340       command_line.HasSwitch(switches::kNoErrorDialogs))
    341     SuppressDialogs();
    342 
    343   // Use a minimum log level if the command line asks for one,
    344   // otherwise leave it at the default level (INFO).
    345   if (command_line.HasSwitch(switches::kLoggingLevel)) {
    346     std::string log_level = command_line.GetSwitchValueASCII(
    347         switches::kLoggingLevel);
    348     int level = 0;
    349     if (base::StringToInt(log_level, &level) &&
    350         level >= 0 && level < LOG_NUM_SEVERITIES) {
    351       logging::SetMinLogLevel(level);
    352     } else {
    353       LOG(WARNING) << "Bad log level: " << log_level;
    354     }
    355   }
    356 
    357 #if defined(OS_WIN)
    358   // Enable trace control and transport through event tracing for Windows.
    359   if (env->HasVar(env_vars::kEtwLogging))
    360     logging::LogEventProvider::Initialize(kChromeTraceProviderName);
    361 #endif
    362 
    363 #ifdef NDEBUG
    364   if (command_line.HasSwitch(switches::kSilentDumpOnDCHECK) &&
    365       command_line.HasSwitch(switches::kEnableDCHECK)) {
    366 #if defined(OS_WIN)
    367     logging::SetLogReportHandler(DumpProcessAssertHandler);
    368 #endif
    369   }
    370 #endif  // NDEBUG
    371 
    372   chrome_logging_initialized_ = true;
    373 }
    374 
    375 // This is a no-op, but we'll keep it around in case
    376 // we need to do more cleanup in the future.
    377 void CleanupChromeLogging() {
    378   if (chrome_logging_failed_)
    379     return;  // We failed to initiailize logging, no cleanup.
    380 
    381   DCHECK(chrome_logging_initialized_) <<
    382     "Attempted to clean up logging when it wasn't initialized.";
    383 
    384   CloseLogFile();
    385 
    386   chrome_logging_initialized_ = false;
    387   chrome_logging_redirected_ = false;
    388 }
    389 
    390 FilePath GetLogFileName() {
    391   std::string filename;
    392   scoped_ptr<base::Environment> env(base::Environment::Create());
    393   if (env->GetVar(env_vars::kLogFileName, &filename) && !filename.empty()) {
    394 #if defined(OS_WIN)
    395     return FilePath(UTF8ToWide(filename).c_str());
    396 #elif defined(OS_POSIX)
    397     return FilePath(filename.c_str());
    398 #endif
    399   }
    400 
    401   const FilePath log_filename(FILE_PATH_LITERAL("chrome_debug.log"));
    402   FilePath log_path;
    403 
    404   if (PathService::Get(chrome::DIR_LOGS, &log_path)) {
    405     log_path = log_path.Append(log_filename);
    406     return log_path;
    407   } else {
    408     // error with path service, just use some default file somewhere
    409     return log_filename;
    410   }
    411 }
    412 
    413 bool DialogsAreSuppressed() {
    414   return dialogs_are_suppressed_;
    415 }
    416 
    417 size_t GetFatalAssertions(AssertionList* assertions) {
    418   // In this function, we don't assume that assertions is non-null, so
    419   // that if you just want an assertion count, you can pass in NULL.
    420   if (assertions)
    421     assertions->clear();
    422   size_t assertion_count = 0;
    423 
    424   std::ifstream log_file;
    425   log_file.open(GetLogFileName().value().c_str());
    426   if (!log_file.is_open())
    427     return 0;
    428 
    429   std::string utf8_line;
    430   std::wstring wide_line;
    431   while (!log_file.eof()) {
    432     getline(log_file, utf8_line);
    433     if (utf8_line.find(":FATAL:") != std::string::npos) {
    434       wide_line = UTF8ToWide(utf8_line);
    435       if (assertions)
    436         assertions->push_back(wide_line);
    437       ++assertion_count;
    438     }
    439   }
    440   log_file.close();
    441 
    442   return assertion_count;
    443 }
    444 
    445 }  // namespace logging
    446