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 "chrome/common/logging_chrome.h"
  30
  31 #include <fstream>  // NOLINT
  32 #include <string>  // NOLINT
  33
  34 #include "base/command_line.h"
  35 #include "base/compiler_specific.h"
  36 #include "base/debug/debugger.h"
  37 #include "base/debug/dump_without_crashing.h"
  38 #include "base/environment.h"
  39 #include "base/files/file_path.h"
  40 #include "base/files/file_util.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 "chrome/common/chrome_constants.h"
  48 #include "chrome/common/chrome_paths.h"
  49 #include "chrome/common/chrome_switches.h"
  50 #include "chrome/common/env_vars.h"
  51 #include "ipc/ipc_logging.h"
  52
  53 #if defined(OS_CHROMEOS)
  54 #include "chromeos/chromeos_switches.h"
  55 #endif
  56
  57 #if defined(OS_WIN)
  58 #include <initguid.h>
  59 #include "base/logging_win.h"
  60 #endif
  61
  62 namespace {
  63
  64 // When true, this means that error dialogs should not be shown.
  65 bool dialogs_are_suppressed_ = false;
  66
  67 // This should be true for exactly the period between the end of
  68 // InitChromeLogging() and the beginning of CleanupChromeLogging().
  69 bool chrome_logging_initialized_ = false;
  70
  71 // Set if we called InitChromeLogging() but failed to initialize.
  72 bool chrome_logging_failed_ = false;
  73
  74 // This should be true for exactly the period between the end of
  75 // InitChromeLogging() and the beginning of CleanupChromeLogging().
  76 bool chrome_logging_redirected_ = false;
  77
  78 #if defined(OS_WIN)
  79 // {7FE69228-633E-4f06-80C1-527FEA23E3A7}
  80 const GUID kChromeTraceProviderName = {
  81     0x7fe69228, 0x633e, 0x4f06,
  82         { 0x80, 0xc1, 0x52, 0x7f, 0xea, 0x23, 0xe3, 0xa7 } };
  83 #endif
  84
  85 // Assertion handler for logging errors that occur when dialogs are
  86 // silenced.  To record a new error, pass the log string associated
  87 // with that error in the str parameter.
  88 MSVC_DISABLE_OPTIMIZE();
  89 void SilentRuntimeAssertHandler(const std::string& str) {
  90   base::debug::BreakDebugger();
  91 }
  92 MSVC_ENABLE_OPTIMIZE();
  93
  94 // Suppresses error/assertion dialogs and enables the logging of
  95 // those errors into silenced_errors_.
  96 void SuppressDialogs() {
  97   if (dialogs_are_suppressed_)
  98     return;
  99
 100   logging::SetLogAssertHandler(SilentRuntimeAssertHandler);
 101
 102 #if defined(OS_WIN)
 103   UINT new_flags = SEM_FAILCRITICALERRORS |
 104                    SEM_NOGPFAULTERRORBOX |
 105                    SEM_NOOPENFILEERRORBOX;
 106
 107   // Preserve existing error mode, as discussed at http://t/dmea
 108   UINT existing_flags = SetErrorMode(new_flags);
 109   SetErrorMode(existing_flags | new_flags);
 110 #endif
 111
 112   dialogs_are_suppressed_ = true;
 113 }
 114
 115 }  // anonymous namespace
 116
 117 namespace logging {
 118
 119 LoggingDestination DetermineLogMode(const base::CommandLine& command_line) {
 120   // only use OutputDebugString in debug mode
 121 #ifdef NDEBUG
 122   bool enable_logging = false;
 123   const char *kInvertLoggingSwitch = switches::kEnableLogging;
 124   const logging::LoggingDestination kDefaultLoggingMode = logging::LOG_TO_FILE;
 125 #else
 126   bool enable_logging = true;
 127   const char *kInvertLoggingSwitch = switches::kDisableLogging;
 128   const logging::LoggingDestination kDefaultLoggingMode = logging::LOG_TO_ALL;
 129 #endif
 130
 131   if (command_line.HasSwitch(kInvertLoggingSwitch))
 132     enable_logging = !enable_logging;
 133
 134   logging::LoggingDestination log_mode;
 135   if (enable_logging) {
 136     // Let --enable-logging=stderr force only stderr, particularly useful for
 137     // non-debug builds where otherwise you can't get logs to stderr at all.
 138     if (command_line.GetSwitchValueASCII(switches::kEnableLogging) == "stderr")
 139       log_mode = logging::LOG_TO_SYSTEM_DEBUG_LOG;
 140     else
 141       log_mode = kDefaultLoggingMode;
 142   } else {
 143     log_mode = logging::LOG_NONE;
 144   }
 145   return log_mode;
 146 }
 147
 148 #if defined(OS_CHROMEOS)
 149 namespace {
 150 base::FilePath SetUpSymlinkIfNeeded(const base::FilePath& symlink_path,
 151                                     bool new_log) {
 152   DCHECK(!symlink_path.empty());
 153
 154   // If not starting a new log, then just log through the existing
 155   // symlink, but if the symlink doesn't exist, create it.  If
 156   // starting a new log, then delete the old symlink and make a new
 157   // one to a fresh log file.
 158   base::FilePath target_path;
 159   bool symlink_exists = base::PathExists(symlink_path);
 160   if (new_log || !symlink_exists) {
 161     target_path = GenerateTimestampedName(symlink_path, base::Time::Now());
 162
 163     // We don't care if the unlink fails; we're going to continue anyway.
 164     if (::unlink(symlink_path.value().c_str()) == -1) {
 165       if (symlink_exists) // only warn if we might expect it to succeed.
 166         DPLOG(WARNING) << "Unable to unlink " << symlink_path.value();
 167     }
 168     if (!base::CreateSymbolicLink(target_path, symlink_path)) {
 169       DPLOG(ERROR) << "Unable to create symlink " << symlink_path.value()
 170                    << " pointing at " << target_path.value();
 171     }
 172   } else {
 173     if (!base::ReadSymbolicLink(symlink_path, &target_path))
 174       DPLOG(ERROR) << "Unable to read symlink " << symlink_path.value();
 175   }
 176   return target_path;
 177 }
 178
 179 void RemoveSymlinkAndLog(const base::FilePath& link_path,
 180                          const base::FilePath& target_path) {
 181   if (::unlink(link_path.value().c_str()) == -1)
 182     DPLOG(WARNING) << "Unable to unlink symlink " << link_path.value();
 183   if (::unlink(target_path.value().c_str()) == -1)
 184     DPLOG(WARNING) << "Unable to unlink log file " << target_path.value();
 185 }
 186
 187 }  // anonymous namespace
 188
 189 base::FilePath GetSessionLogDir(const base::CommandLine& command_line) {
 190   base::FilePath log_dir;
 191   std::string log_dir_str;
 192   scoped_ptr<base::Environment> env(base::Environment::Create());
 193   if (env->GetVar(env_vars::kSessionLogDir, &log_dir_str) &&
 194       !log_dir_str.empty()) {
 195     log_dir = base::FilePath(log_dir_str);
 196   } else if (command_line.HasSwitch(chromeos::switches::kLoginProfile)) {
 197     PathService::Get(chrome::DIR_USER_DATA, &log_dir);
 198     base::FilePath profile_dir;
 199     std::string login_profile_value =
 200         command_line.GetSwitchValueASCII(chromeos::switches::kLoginProfile);
 201     if (login_profile_value == chrome::kLegacyProfileDir ||
 202         login_profile_value == chrome::kTestUserProfileDir) {
 203       profile_dir = base::FilePath(login_profile_value);
 204     } else {
 205       // We could not use g_browser_process > profile_helper() here.
 206       std::string profile_dir_str = chrome::kProfileDirPrefix;
 207       profile_dir_str.append(login_profile_value);
 208       profile_dir = base::FilePath(profile_dir_str);
 209     }
 210     log_dir = log_dir.Append(profile_dir);
 211   }
 212   return log_dir;
 213 }
 214
 215 base::FilePath GetSessionLogFile(const base::CommandLine& command_line) {
 216   return GetSessionLogDir(command_line).Append(GetLogFileName().BaseName());
 217 }
 218
 219 void RedirectChromeLogging(const base::CommandLine& command_line) {
 220   if (chrome_logging_redirected_) {
 221     // TODO(nkostylev): Support multiple active users. http://crbug.com/230345
 222     LOG(WARNING) << "NOT redirecting logging for multi-profiles case.";
 223     return;
 224   }
 225
 226   DCHECK(!chrome_logging_redirected_) <<
 227     "Attempted to redirect logging when it was already initialized.";
 228
 229   // Redirect logs to the session log directory, if set.  Otherwise
 230   // defaults to the profile dir.
 231   base::FilePath log_path = GetSessionLogFile(command_line);
 232
 233   // Creating symlink causes us to do blocking IO on UI thread.
 234   // Temporarily allow it until we fix http://crbug.com/61143
 235   base::ThreadRestrictions::ScopedAllowIO allow_io;
 236   // Always force a new symlink when redirecting.
 237   base::FilePath target_path = SetUpSymlinkIfNeeded(log_path, true);
 238
 239   // ChromeOS always logs through the symlink, so it shouldn't be
 240   // deleted if it already exists.
 241   logging::LoggingSettings settings;
 242   settings.logging_dest = DetermineLogMode(command_line);
 243   settings.log_file = log_path.value().c_str();
 244   if (!logging::InitLogging(settings)) {
 245     DLOG(ERROR) << "Unable to initialize logging to " << log_path.value();
 246     RemoveSymlinkAndLog(log_path, target_path);
 247   } else {
 248     chrome_logging_redirected_ = true;
 249   }
 250 }
 251
 252 #endif  // OS_CHROMEOS
 253
 254 void InitChromeLogging(const base::CommandLine& command_line,
 255                        OldFileDeletionState delete_old_log_file) {
 256   DCHECK(!chrome_logging_initialized_) <<
 257     "Attempted to initialize logging when it was already initialized.";
 258
 259   LoggingDestination logging_dest = DetermineLogMode(command_line);
 260   LogLockingState log_locking_state = LOCK_LOG_FILE;
 261   base::FilePath log_path;
 262 #if defined(OS_CHROMEOS)
 263   base::FilePath target_path;
 264 #endif
 265
 266   // Don't resolve the log path unless we need to. Otherwise we leave an open
 267   // ALPC handle after sandbox lockdown on Windows.
 268   if ((logging_dest & LOG_TO_FILE) != 0) {
 269     log_path = GetLogFileName();
 270
 271 #if defined(OS_CHROMEOS)
 272     // For BWSI (Incognito) logins, we want to put the logs in the user
 273     // profile directory that is created for the temporary session instead
 274     // of in the system log directory, for privacy reasons.
 275     if (command_line.HasSwitch(chromeos::switches::kGuestSession))
 276       log_path = GetSessionLogFile(command_line);
 277
 278     // On ChromeOS we log to the symlink.  We force creation of a new
 279     // symlink if we've been asked to delete the old log, since that
 280     // indicates the start of a new session.
 281     target_path = SetUpSymlinkIfNeeded(
 282         log_path, delete_old_log_file == logging::DELETE_OLD_LOG_FILE);
 283
 284     // Because ChromeOS manages the move to a new session by redirecting
 285     // the link, it shouldn't remove the old file in the logging code,
 286     // since that will remove the newly created link instead.
 287     delete_old_log_file = logging::APPEND_TO_OLD_LOG_FILE;
 288 #endif
 289   } else {
 290     log_locking_state = DONT_LOCK_LOG_FILE;
 291   }
 292
 293   logging::LoggingSettings settings;
 294   settings.logging_dest = logging_dest;
 295   settings.log_file = log_path.value().c_str();
 296   settings.lock_log = log_locking_state;
 297   settings.delete_old = delete_old_log_file;
 298   bool success = logging::InitLogging(settings);
 299
 300 #if defined(OS_CHROMEOS)
 301   if (!success) {
 302     DPLOG(ERROR) << "Unable to initialize logging to " << log_path.value()
 303                 << " (which should be a link to " << target_path.value() << ")";
 304     RemoveSymlinkAndLog(log_path, target_path);
 305     chrome_logging_failed_ = true;
 306     return;
 307   }
 308 #else
 309   if (!success) {
 310     DPLOG(ERROR) << "Unable to initialize logging to " << log_path.value();
 311     chrome_logging_failed_ = true;
 312     return;
 313   }
 314 #endif
 315
 316   // Default to showing error dialogs.
 317   if (!base::CommandLine::ForCurrentProcess()->HasSwitch(
 318           switches::kNoErrorDialogs))
 319     logging::SetShowErrorDialogs(true);
 320
 321   // we want process and thread IDs because we have a lot of things running
 322   logging::SetLogItems(true,  // enable_process_id
 323                        true,  // enable_thread_id
 324                        true,  // enable_timestamp
 325                        false);  // enable_tickcount
 326
 327   // We call running in unattended mode "headless", and allow
 328   // headless mode to be configured either by the Environment
 329   // Variable or by the Command Line Switch.  This is for
 330   // automated test purposes.
 331   scoped_ptr<base::Environment> env(base::Environment::Create());
 332   if (env->HasVar(env_vars::kHeadless) ||
 333       command_line.HasSwitch(switches::kNoErrorDialogs))
 334     SuppressDialogs();
 335
 336   // Use a minimum log level if the command line asks for one. Ignore this
 337   // switch if there's vlog level switch present too (as both of these switches
 338   // refer to the same underlying log level, and the vlog level switch has
 339   // already been processed inside logging::InitLogging). If there is neither
 340   // log level nor vlog level specified, then just leave the default level
 341   // (INFO).
 342   if (command_line.HasSwitch(switches::kLoggingLevel) &&
 343       logging::GetMinLogLevel() >= 0) {
 344     std::string log_level =
 345         command_line.GetSwitchValueASCII(switches::kLoggingLevel);
 346     int level = 0;
 347     if (base::StringToInt(log_level, &level) && level >= 0 &&
 348         level < LOG_NUM_SEVERITIES) {
 349       logging::SetMinLogLevel(level);
 350     } else {
 351       DLOG(WARNING) << "Bad log level: " << log_level;
 352     }
 353   }
 354
 355 #if defined(OS_WIN)
 356   // Enable trace control and transport through event tracing for Windows.
 357   logging::LogEventProvider::Initialize(kChromeTraceProviderName);
 358 #endif
 359
 360   chrome_logging_initialized_ = true;
 361 }
 362
 363 // This is a no-op, but we'll keep it around in case
 364 // we need to do more cleanup in the future.
 365 void CleanupChromeLogging() {
 366   if (chrome_logging_failed_)
 367     return;  // We failed to initiailize logging, no cleanup.
 368
 369   DCHECK(chrome_logging_initialized_) <<
 370     "Attempted to clean up logging when it wasn't initialized.";
 371
 372   CloseLogFile();
 373
 374   chrome_logging_initialized_ = false;
 375   chrome_logging_redirected_ = false;
 376 }
 377
 378 base::FilePath GetLogFileName() {
 379   std::string filename;
 380   scoped_ptr<base::Environment> env(base::Environment::Create());
 381   if (env->GetVar(env_vars::kLogFileName, &filename) && !filename.empty())
 382     return base::FilePath::FromUTF8Unsafe(filename);
 383
 384   const base::FilePath log_filename(FILE_PATH_LITERAL("chrome_debug.log"));
 385   base::FilePath log_path;
 386
 387   if (PathService::Get(chrome::DIR_LOGS, &log_path)) {
 388     log_path = log_path.Append(log_filename);
 389     return log_path;
 390   } else {
 391     // error with path service, just use some default file somewhere
 392     return log_filename;
 393   }
 394 }
 395
 396 bool DialogsAreSuppressed() {
 397   return dialogs_are_suppressed_;
 398 }
 399 base::FilePath GenerateTimestampedName(const base::FilePath& base_path,
 400                                        base::Time timestamp) {
 401   base::Time::Exploded time_deets;
 402   timestamp.LocalExplode(&time_deets);
 403   std::string suffix = base::StringPrintf("_%02d%02d%02d-%02d%02d%02d",
 404                                           time_deets.year,
 405                                           time_deets.month,
 406                                           time_deets.day_of_month,
 407                                           time_deets.hour,
 408                                           time_deets.minute,
 409                                           time_deets.second);
 410   return base_path.InsertBeforeExtensionASCII(suffix);
 411 }
 412
 413 }  // namespace logging