logging_chrome.cc revision eb525c5499e34cc9c4b825d6d9e75bb07cc06ace
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 63namespace { 64 65// When true, this means that error dialogs should not be shown. 66bool 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(). 70bool chrome_logging_initialized_ = false; 71 72// Set if we called InitChromeLogging() but failed to initialize. 73bool 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(). 77bool chrome_logging_redirected_ = false; 78 79#if defined(OS_WIN) 80// {7FE69228-633E-4f06-80C1-527FEA23E3A7} 81const 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. 89MSVC_DISABLE_OPTIMIZE(); 90void SilentRuntimeAssertHandler(const std::string& str) { 91 base::debug::BreakDebugger(); 92} 93void 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. 98void DumpProcessAssertHandler(const std::string& str) { 99 logging::DumpWithoutCrashing(); 100} 101#endif // OS_WIN 102MSVC_ENABLE_OPTIMIZE(); 103 104// Suppresses error/assertion dialogs and enables the logging of 105// those errors into silenced_errors_. 106void 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 128namespace logging { 129 130LoggingDestination 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) 160namespace { 161base::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 = file_util::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 (!file_util::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 (!file_util::ReadSymbolicLink(symlink_path, &target_path)) 185 DPLOG(ERROR) << "Unable to read symlink " << symlink_path.value(); 186 } 187 return target_path; 188} 189 190void 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 200base::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 if (command_line.HasSwitch(switches::kMultiProfiles)) { 211 // We could not use g_browser_process > profile_helper() here. 212 std::string profile_dir_str = chrome::kProfileDirPrefix; 213 profile_dir_str.append( 214 command_line.GetSwitchValueASCII(chromeos::switches::kLoginProfile)); 215 profile_dir = base::FilePath(profile_dir_str); 216 } else { 217 profile_dir = 218 command_line.GetSwitchValuePath(chromeos::switches::kLoginProfile); 219 } 220 log_dir = log_dir.Append(profile_dir); 221 } 222 return log_dir.Append(GetLogFileName().BaseName()); 223} 224 225void 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 267void 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. 387void 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 400base::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 418bool DialogsAreSuppressed() { 419 return dialogs_are_suppressed_; 420} 421 422size_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 450base::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