Home | History | Annotate | Download | only in common
      1 // Copyright (c) 2012 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 "content/public/common/content_ipc_logging.h"
     20 #define IPC_LOG_TABLE_ADD_ENTRY(msg_id, logger) \
     21     content::RegisterIPCLogger(msg_id, logger)
     22 #include "chrome/common/all_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_util.h"
     38 #include "base/files/file_path.h"
     39 #include "base/logging.h"
     40 #include "base/path_service.h"
     41 #include "base/strings/string_number_conversions.h"
     42 #include "base/strings/string_util.h"
     43 #include "base/strings/stringprintf.h"
     44 #include "base/strings/utf_string_conversions.h"
     45 #include "base/threading/thread_restrictions.h"
     46 #include "base/time/time.h"
     47 #include "chrome/common/chrome_constants.h"
     48 #include "chrome/common/chrome_paths.h"
     49 #include "chrome/common/chrome_switches.h"
     50 #include "chrome/common/dump_without_crashing.h"
     51 #include "chrome/common/env_vars.h"
     52 #include "ipc/ipc_logging.h"
     53 
     54 #if defined(OS_CHROMEOS)
     55 #include "chromeos/chromeos_switches.h"
     56 #endif
     57 
     58 #if defined(OS_WIN)
     59 #include <initguid.h>
     60 #include "base/logging_win.h"
     61 #endif
     62 
     63 namespace {
     64 
     65 // When true, this means that error dialogs should not be shown.
     66 bool dialogs_are_suppressed_ = false;
     67 
     68 // This should be true for exactly the period between the end of
     69 // InitChromeLogging() and the beginning of CleanupChromeLogging().
     70 bool chrome_logging_initialized_ = false;
     71 
     72 // Set if we called InitChromeLogging() but failed to initialize.
     73 bool chrome_logging_failed_ = false;
     74 
     75 // This should be true for exactly the period between the end of
     76 // InitChromeLogging() and the beginning of CleanupChromeLogging().
     77 bool chrome_logging_redirected_ = false;
     78 
     79 #if defined(OS_WIN)
     80 // {7FE69228-633E-4f06-80C1-527FEA23E3A7}
     81 const GUID kChromeTraceProviderName = {
     82     0x7fe69228, 0x633e, 0x4f06,
     83         { 0x80, 0xc1, 0x52, 0x7f, 0xea, 0x23, 0xe3, 0xa7 } };
     84 #endif
     85 
     86 // Assertion handler for logging errors that occur when dialogs are
     87 // silenced.  To record a new error, pass the log string associated
     88 // with that error in the str parameter.
     89 MSVC_DISABLE_OPTIMIZE();
     90 void SilentRuntimeAssertHandler(const std::string& str) {
     91   base::debug::BreakDebugger();
     92 }
     93 void SilentRuntimeReportHandler(const std::string& str) {
     94 }
     95 #if defined(OS_WIN)
     96 // Handler to silently dump the current process when there is an assert in
     97 // chrome.
     98 void DumpProcessAssertHandler(const std::string& str) {
     99   logging::DumpWithoutCrashing();
    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 = logging::LOG_TO_FILE;
    136 #else
    137   bool enable_logging = true;
    138   const char *kInvertLoggingSwitch = switches::kDisableLogging;
    139   const logging::LoggingDestination kDefaultLoggingMode = logging::LOG_TO_ALL;
    140 #endif
    141 
    142   if (command_line.HasSwitch(kInvertLoggingSwitch))
    143     enable_logging = !enable_logging;
    144 
    145   logging::LoggingDestination log_mode;
    146   if (enable_logging) {
    147     // Let --enable-logging=stderr force only stderr, particularly useful for
    148     // non-debug builds where otherwise you can't get logs to stderr at all.
    149     if (command_line.GetSwitchValueASCII(switches::kEnableLogging) == "stderr")
    150       log_mode = logging::LOG_TO_SYSTEM_DEBUG_LOG;
    151     else
    152       log_mode = kDefaultLoggingMode;
    153   } else {
    154     log_mode = logging::LOG_NONE;
    155   }
    156   return log_mode;
    157 }
    158 
    159 #if defined(OS_CHROMEOS)
    160 namespace {
    161 base::FilePath SetUpSymlinkIfNeeded(const base::FilePath& symlink_path,
    162                                     bool new_log) {
    163   DCHECK(!symlink_path.empty());
    164 
    165   // If not starting a new log, then just log through the existing
    166   // symlink, but if the symlink doesn't exist, create it.  If
    167   // starting a new log, then delete the old symlink and make a new
    168   // one to a fresh log file.
    169   base::FilePath target_path;
    170   bool symlink_exists = base::PathExists(symlink_path);
    171   if (new_log || !symlink_exists) {
    172     target_path = GenerateTimestampedName(symlink_path, base::Time::Now());
    173 
    174     // We don't care if the unlink fails; we're going to continue anyway.
    175     if (::unlink(symlink_path.value().c_str()) == -1) {
    176       if (symlink_exists) // only warn if we might expect it to succeed.
    177         DPLOG(WARNING) << "Unable to unlink " << symlink_path.value();
    178     }
    179     if (!base::CreateSymbolicLink(target_path, symlink_path)) {
    180       DPLOG(ERROR) << "Unable to create symlink " << symlink_path.value()
    181                    << " pointing at " << target_path.value();
    182     }
    183   } else {
    184     if (!base::ReadSymbolicLink(symlink_path, &target_path))
    185       DPLOG(ERROR) << "Unable to read symlink " << symlink_path.value();
    186   }
    187   return target_path;
    188 }
    189 
    190 void RemoveSymlinkAndLog(const base::FilePath& link_path,
    191                          const base::FilePath& target_path) {
    192   if (::unlink(link_path.value().c_str()) == -1)
    193     DPLOG(WARNING) << "Unable to unlink symlink " << link_path.value();
    194   if (::unlink(target_path.value().c_str()) == -1)
    195     DPLOG(WARNING) << "Unable to unlink log file " << target_path.value();
    196 }
    197 
    198 }  // anonymous namespace
    199 
    200 base::FilePath GetSessionLogFile(const CommandLine& command_line) {
    201   base::FilePath log_dir;
    202   std::string log_dir_str;
    203   scoped_ptr<base::Environment> env(base::Environment::Create());
    204   if (env->GetVar(env_vars::kSessionLogDir, &log_dir_str) &&
    205       !log_dir_str.empty()) {
    206     log_dir = base::FilePath(log_dir_str);
    207   } else if (command_line.HasSwitch(chromeos::switches::kLoginProfile)) {
    208     PathService::Get(chrome::DIR_USER_DATA, &log_dir);
    209     base::FilePath profile_dir;
    210     std::string login_profile_value =
    211         command_line.GetSwitchValueASCII(chromeos::switches::kLoginProfile);
    212     if (login_profile_value == chrome::kLegacyProfileDir) {
    213       profile_dir = base::FilePath(login_profile_value);
    214     } else {
    215       // We could not use g_browser_process > profile_helper() here.
    216       std::string profile_dir_str = chrome::kProfileDirPrefix;
    217       profile_dir_str.append(login_profile_value);
    218       profile_dir = base::FilePath(profile_dir_str);
    219     }
    220     log_dir = log_dir.Append(profile_dir);
    221   }
    222   return log_dir.Append(GetLogFileName().BaseName());
    223 }
    224 
    225 void RedirectChromeLogging(const CommandLine& command_line) {
    226   if (CommandLine::ForCurrentProcess()->HasSwitch(switches::kMultiProfiles) &&
    227       chrome_logging_redirected_) {
    228     // TODO(nkostylev): Support multiple active users. http://crbug.com/230345
    229     LOG(ERROR) << "NOT redirecting logging for multi-profiles case.";
    230     return;
    231   }
    232 
    233   DCHECK(!chrome_logging_redirected_) <<
    234     "Attempted to redirect logging when it was already initialized.";
    235 
    236   // Redirect logs to the session log directory, if set.  Otherwise
    237   // defaults to the profile dir.
    238   base::FilePath log_path = GetSessionLogFile(command_line);
    239 
    240   // Creating symlink causes us to do blocking IO on UI thread.
    241   // Temporarily allow it until we fix http://crbug.com/61143
    242   base::ThreadRestrictions::ScopedAllowIO allow_io;
    243   // Always force a new symlink when redirecting.
    244   base::FilePath target_path = SetUpSymlinkIfNeeded(log_path, true);
    245 
    246   logging::DcheckState dcheck_state =
    247       command_line.HasSwitch(switches::kEnableDCHECK) ?
    248       logging::ENABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS :
    249       logging::DISABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS;
    250 
    251   // ChromeOS always logs through the symlink, so it shouldn't be
    252   // deleted if it already exists.
    253   logging::LoggingSettings settings;
    254   settings.logging_dest = DetermineLogMode(command_line);
    255   settings.log_file = log_path.value().c_str();
    256   settings.dcheck_state = dcheck_state;
    257   if (!logging::InitLogging(settings)) {
    258     DLOG(ERROR) << "Unable to initialize logging to " << log_path.value();
    259     RemoveSymlinkAndLog(log_path, target_path);
    260   } else {
    261     chrome_logging_redirected_ = true;
    262   }
    263 }
    264 
    265 #endif  // OS_CHROMEOS
    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   LoggingDestination logging_dest = DetermineLogMode(command_line);
    273   LogLockingState log_locking_state = LOCK_LOG_FILE;
    274   base::FilePath log_path;
    275 #if defined(OS_CHROMEOS)
    276   base::FilePath target_path;
    277 #endif
    278 
    279   // Don't resolve the log path unless we need to. Otherwise we leave an open
    280   // ALPC handle after sandbox lockdown on Windows.
    281   if ((logging_dest & LOG_TO_FILE) != 0) {
    282     log_path = GetLogFileName();
    283 
    284 #if defined(OS_CHROMEOS)
    285     // For BWSI (Incognito) logins, we want to put the logs in the user
    286     // profile directory that is created for the temporary session instead
    287     // of in the system log directory, for privacy reasons.
    288     if (command_line.HasSwitch(chromeos::switches::kGuestSession))
    289       log_path = GetSessionLogFile(command_line);
    290 
    291     // On ChromeOS we log to the symlink.  We force creation of a new
    292     // symlink if we've been asked to delete the old log, since that
    293     // indicates the start of a new session.
    294     target_path = SetUpSymlinkIfNeeded(
    295         log_path, delete_old_log_file == logging::DELETE_OLD_LOG_FILE);
    296 
    297     // Because ChromeOS manages the move to a new session by redirecting
    298     // the link, it shouldn't remove the old file in the logging code,
    299     // since that will remove the newly created link instead.
    300     delete_old_log_file = logging::APPEND_TO_OLD_LOG_FILE;
    301 #endif
    302   } else {
    303     log_locking_state = DONT_LOCK_LOG_FILE;
    304   }
    305 
    306   logging::DcheckState dcheck_state =
    307       command_line.HasSwitch(switches::kEnableDCHECK) ?
    308       logging::ENABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS :
    309       logging::DISABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS;
    310 
    311   logging::LoggingSettings settings;
    312   settings.logging_dest = logging_dest;
    313   settings.log_file = log_path.value().c_str();
    314   settings.lock_log = log_locking_state;
    315   settings.delete_old = delete_old_log_file;
    316   settings.dcheck_state = dcheck_state;
    317   bool success = logging::InitLogging(settings);
    318 
    319 #if defined(OS_CHROMEOS)
    320   if (!success) {
    321     DPLOG(ERROR) << "Unable to initialize logging to " << log_path.value()
    322                 << " (which should be a link to " << target_path.value() << ")";
    323     RemoveSymlinkAndLog(log_path, target_path);
    324     chrome_logging_failed_ = true;
    325     return;
    326   }
    327 #else
    328   if (!success) {
    329     DPLOG(ERROR) << "Unable to initialize logging to " << log_path.value();
    330     chrome_logging_failed_ = true;
    331     return;
    332   }
    333 #endif
    334 
    335   // Default to showing error dialogs.
    336   if (!CommandLine::ForCurrentProcess()->HasSwitch(switches::kNoErrorDialogs))
    337     logging::SetShowErrorDialogs(true);
    338 
    339   // we want process and thread IDs because we have a lot of things running
    340   logging::SetLogItems(true,  // enable_process_id
    341                        true,  // enable_thread_id
    342                        true,  // enable_timestamp
    343                        false);  // enable_tickcount
    344 
    345   // We call running in unattended mode "headless", and allow
    346   // headless mode to be configured either by the Environment
    347   // Variable or by the Command Line Switch.  This is for
    348   // automated test purposes.
    349   scoped_ptr<base::Environment> env(base::Environment::Create());
    350   if (env->HasVar(env_vars::kHeadless) ||
    351       command_line.HasSwitch(switches::kNoErrorDialogs))
    352     SuppressDialogs();
    353 
    354   // Use a minimum log level if the command line asks for one,
    355   // otherwise leave it at the default level (INFO).
    356   if (command_line.HasSwitch(switches::kLoggingLevel)) {
    357     std::string log_level = command_line.GetSwitchValueASCII(
    358         switches::kLoggingLevel);
    359     int level = 0;
    360     if (base::StringToInt(log_level, &level) &&
    361         level >= 0 && level < LOG_NUM_SEVERITIES) {
    362       logging::SetMinLogLevel(level);
    363     } else {
    364       DLOG(WARNING) << "Bad log level: " << log_level;
    365     }
    366   }
    367 
    368 #if defined(OS_WIN)
    369   // Enable trace control and transport through event tracing for Windows.
    370   logging::LogEventProvider::Initialize(kChromeTraceProviderName);
    371 #endif
    372 
    373 #ifdef NDEBUG
    374   if (command_line.HasSwitch(switches::kSilentDumpOnDCHECK) &&
    375       command_line.HasSwitch(switches::kEnableDCHECK)) {
    376 #if defined(OS_WIN)
    377     logging::SetLogReportHandler(DumpProcessAssertHandler);
    378 #endif
    379   }
    380 #endif  // NDEBUG
    381 
    382   chrome_logging_initialized_ = true;
    383 }
    384 
    385 // This is a no-op, but we'll keep it around in case
    386 // we need to do more cleanup in the future.
    387 void CleanupChromeLogging() {
    388   if (chrome_logging_failed_)
    389     return;  // We failed to initiailize logging, no cleanup.
    390 
    391   DCHECK(chrome_logging_initialized_) <<
    392     "Attempted to clean up logging when it wasn't initialized.";
    393 
    394   CloseLogFile();
    395 
    396   chrome_logging_initialized_ = false;
    397   chrome_logging_redirected_ = false;
    398 }
    399 
    400 base::FilePath GetLogFileName() {
    401   std::string filename;
    402   scoped_ptr<base::Environment> env(base::Environment::Create());
    403   if (env->GetVar(env_vars::kLogFileName, &filename) && !filename.empty())
    404     return base::FilePath::FromUTF8Unsafe(filename);
    405 
    406   const base::FilePath log_filename(FILE_PATH_LITERAL("chrome_debug.log"));
    407   base::FilePath log_path;
    408 
    409   if (PathService::Get(chrome::DIR_LOGS, &log_path)) {
    410     log_path = log_path.Append(log_filename);
    411     return log_path;
    412   } else {
    413     // error with path service, just use some default file somewhere
    414     return log_filename;
    415   }
    416 }
    417 
    418 bool DialogsAreSuppressed() {
    419   return dialogs_are_suppressed_;
    420 }
    421 
    422 size_t GetFatalAssertions(AssertionList* assertions) {
    423   // In this function, we don't assume that assertions is non-null, so
    424   // that if you just want an assertion count, you can pass in NULL.
    425   if (assertions)
    426     assertions->clear();
    427   size_t assertion_count = 0;
    428 
    429   std::ifstream log_file;
    430   log_file.open(GetLogFileName().value().c_str());
    431   if (!log_file.is_open())
    432     return 0;
    433 
    434   std::string utf8_line;
    435   std::wstring wide_line;
    436   while (!log_file.eof()) {
    437     getline(log_file, utf8_line);
    438     if (utf8_line.find(":FATAL:") != std::string::npos) {
    439       wide_line = UTF8ToWide(utf8_line);
    440       if (assertions)
    441         assertions->push_back(wide_line);
    442       ++assertion_count;
    443     }
    444   }
    445   log_file.close();
    446 
    447   return assertion_count;
    448 }
    449 
    450 base::FilePath GenerateTimestampedName(const base::FilePath& base_path,
    451                                        base::Time timestamp) {
    452   base::Time::Exploded time_deets;
    453   timestamp.LocalExplode(&time_deets);
    454   std::string suffix = base::StringPrintf("_%02d%02d%02d-%02d%02d%02d",
    455                                           time_deets.year,
    456                                           time_deets.month,
    457                                           time_deets.day_of_month,
    458                                           time_deets.hour,
    459                                           time_deets.minute,
    460                                           time_deets.second);
    461   return base_path.InsertBeforeExtensionASCII(suffix);
    462 }
    463 
    464 }  // namespace logging
    465