chrome/common/logging_chrome.cc

   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/debug/dump_without_crashing.h"
  37 #include "base/environment.h"
  38 #include "base/file_util.h"
  39 #include "base/files/file_path.h"
  40 #include "base/logging.h"
  41 #include "base/path_service.h"
  42 #include "base/strings/string_number_conversions.h"
  43 #include "base/strings/string_util.h"
  44 #include "base/strings/stringprintf.h"
  45 #include "base/strings/utf_string_conversions.h"
  46 #include "base/threading/thread_restrictions.h"
  47 #include "base/time/time.h"
  48 #include "chrome/common/chrome_constants.h"
  49 #include "chrome/common/chrome_paths.h"
  50 #include "chrome/common/chrome_switches.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   base::debug::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 = base::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