logging_chrome.cc 19 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514
  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. #include "build/build_config.h"
  5. // Need to include this before most other files because it defines
  6. // IPC_MESSAGE_LOG_ENABLED. We need to use it to define
  7. // IPC_MESSAGE_MACROS_LOG_ENABLED so render_messages.h will generate the
  8. // ViewMsgLog et al. functions.
  9. #include "ipc/ipc_buildflags.h"
  10. // On Windows, the about:ipc dialog shows IPCs; on POSIX, we hook up a
  11. // logger in this file. (We implement about:ipc on Mac but implement
  12. // the loggers here anyway). We need to do this real early to be sure
  13. // IPC_MESSAGE_MACROS_LOG_ENABLED doesn't get undefined.
  14. #if BUILDFLAG(IS_POSIX) && BUILDFLAG(IPC_MESSAGE_LOG_ENABLED)
  15. #define IPC_MESSAGE_MACROS_LOG_ENABLED
  16. #include "content/public/common/content_ipc_logging.h"
  17. #define IPC_LOG_TABLE_ADD_ENTRY(msg_id, logger) \
  18. content::RegisterIPCLogger(msg_id, logger)
  19. #include "chrome/common/all_messages.h"
  20. #endif
  21. #if BUILDFLAG(IS_WIN)
  22. #include <windows.h>
  23. #endif
  24. #include "chrome/common/logging_chrome.h"
  25. #include <fstream> // NOLINT
  26. #include <memory> // NOLINT
  27. #include <string> // NOLINT
  28. #include "base/base_switches.h"
  29. #include "base/bind.h"
  30. #include "base/command_line.h"
  31. #include "base/compiler_specific.h"
  32. #include "base/debug/debugger.h"
  33. #include "base/debug/dump_without_crashing.h"
  34. #include "base/environment.h"
  35. #include "base/files/file_path.h"
  36. #include "base/files/file_util.h"
  37. #include "base/metrics/statistics_recorder.h"
  38. #include "base/path_service.h"
  39. #include "base/strings/string_number_conversions.h"
  40. #include "base/strings/string_util.h"
  41. #include "base/strings/stringprintf.h"
  42. #include "base/strings/utf_string_conversions.h"
  43. #include "build/chromeos_buildflags.h"
  44. #include "chrome/common/chrome_constants.h"
  45. #include "chrome/common/chrome_paths.h"
  46. #include "chrome/common/chrome_switches.h"
  47. #include "chrome/common/env_vars.h"
  48. #include "content/public/common/content_switches.h"
  49. #include "ipc/ipc_logging.h"
  50. #if BUILDFLAG(IS_CHROMEOS_ASH)
  51. #include "ash/constants/ash_switches.h"
  52. #endif
  53. #if BUILDFLAG(IS_WIN)
  54. #include <initguid.h>
  55. #include "base/logging_win.h"
  56. #include "base/syslog_logging.h"
  57. #include "chrome/common/win/eventlog_messages.h"
  58. #include "chrome/install_static/install_details.h"
  59. #endif
  60. namespace logging {
  61. namespace {
  62. // When true, this means that error dialogs should not be shown.
  63. bool dialogs_are_suppressed_ = false;
  64. ScopedLogAssertHandler* assert_handler_ = nullptr;
  65. // This should be true for exactly the period between the end of
  66. // InitChromeLogging() and the beginning of CleanupChromeLogging().
  67. bool chrome_logging_initialized_ = false;
  68. // Set if we called InitChromeLogging() but failed to initialize.
  69. bool chrome_logging_failed_ = false;
  70. // This should be true for exactly the period between the end of
  71. // InitChromeLogging() and the beginning of CleanupChromeLogging().
  72. bool chrome_logging_redirected_ = false;
  73. // The directory on which we do rotation of log files instead of switching
  74. // with symlink. Because this directory doesn't support symlinks and the logic
  75. // doesn't work correctly.
  76. #if BUILDFLAG(IS_CHROMEOS_ASH)
  77. constexpr char kChronosHomeDir[] = "/home/chronos/user/";
  78. #endif // BUILDFLAG(IS_CHROMEOS_ASH)
  79. #if BUILDFLAG(IS_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. // 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. NOINLINE void SilentRuntimeAssertHandler(const char* file,
  89. int line,
  90. const base::StringPiece message,
  91. const base::StringPiece stack_trace) {
  92. base::debug::BreakDebugger();
  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. assert_handler_ = new ScopedLogAssertHandler(
  100. base::BindRepeating(SilentRuntimeAssertHandler));
  101. #if BUILDFLAG(IS_WIN)
  102. UINT new_flags =
  103. SEM_FAILCRITICALERRORS | SEM_NOGPFAULTERRORBOX | SEM_NOOPENFILEERRORBOX;
  104. // Preserve existing error mode, as discussed at http://t/dmea
  105. UINT existing_flags = SetErrorMode(new_flags);
  106. SetErrorMode(existing_flags | new_flags);
  107. #endif
  108. dialogs_are_suppressed_ = true;
  109. }
  110. } // anonymous namespace
  111. LoggingDestination DetermineLoggingDestination(
  112. const base::CommandLine& command_line) {
  113. #if BUILDFLAG(IS_FUCHSIA)
  114. // On Fuchsia, the default logging mode is the system log in both debug and
  115. // release mode.
  116. const LoggingDestination kDefaultLoggingMode = LOG_TO_SYSTEM_DEBUG_LOG;
  117. #elif NDEBUG
  118. const LoggingDestination kDefaultLoggingMode = LOG_TO_FILE;
  119. #else
  120. const LoggingDestination kDefaultLoggingMode = LOG_TO_ALL;
  121. #endif // BUILDFLAG(IS_FUCHSIA)
  122. #ifdef NDEBUG
  123. bool enable_logging = false;
  124. const char* kInvertLoggingSwitch = switches::kEnableLogging;
  125. #else
  126. bool enable_logging = true;
  127. const char* kInvertLoggingSwitch = switches::kDisableLogging;
  128. #endif
  129. if (command_line.HasSwitch(kInvertLoggingSwitch))
  130. enable_logging = !enable_logging;
  131. if (!enable_logging)
  132. return LOG_NONE;
  133. if (command_line.HasSwitch(switches::kEnableLogging)) {
  134. // Let --enable-logging=stderr force only stderr, particularly useful for
  135. // non-debug builds where otherwise you can't get logs to stderr at all.
  136. std::string logging_destination =
  137. command_line.GetSwitchValueASCII(switches::kEnableLogging);
  138. if (logging_destination == "stderr") {
  139. return LOG_TO_SYSTEM_DEBUG_LOG | LOG_TO_STDERR;
  140. } else if (logging_destination != "") {
  141. PLOG(ERROR) << "Invalid logging destination: " << logging_destination;
  142. }
  143. }
  144. return kDefaultLoggingMode;
  145. }
  146. #if BUILDFLAG(IS_CHROMEOS_ASH)
  147. bool RotateLogFile(const base::FilePath& target_path) {
  148. DCHECK(!target_path.empty());
  149. // If the old log file doesn't exist, do nothing.
  150. if (!base::PathExists(target_path)) {
  151. return true;
  152. }
  153. // Retrieve the creation time of the old log file.
  154. base::File::Info info;
  155. {
  156. // Opens a file, only if it exists.
  157. base::File fp(target_path, base::File::FLAG_OPEN | base::File::FLAG_READ);
  158. if (!fp.GetInfo(&info)) {
  159. // On failure, keep using the same file.
  160. return false;
  161. }
  162. }
  163. // Generate the rotated log path name from the creation time.
  164. // (eg. "/home/chrome/user/log/chrome_220102-030405")
  165. base::Time timestamp = info.creation_time;
  166. base::FilePath rotated_path = GenerateTimestampedName(target_path, timestamp);
  167. // Rare case: if the target path already exists, generate the alternative by
  168. // incrementing the timestamp. This may happen when the Chrome restarts
  169. // multiple times in a second.
  170. while (base::PathExists(rotated_path)) {
  171. timestamp += base::Seconds(1);
  172. rotated_path = GenerateTimestampedName(target_path, timestamp);
  173. }
  174. // Rename the old log file: |target_path| => |rotated_path|.
  175. // We don't use |base::Move|, since we don't consider the inter-filesystem
  176. // move in this logic. The current logic depends on the fact that the ctime
  177. // won't be changed after rotation, but ctime may be changed on
  178. // inter-filesystem move.
  179. if (!base::ReplaceFile(target_path, rotated_path, nullptr)) {
  180. PLOG(ERROR) << "Failed to rotate the log files: " << target_path << " => "
  181. << rotated_path;
  182. return false;
  183. }
  184. return true;
  185. }
  186. base::FilePath SetUpSymlinkIfNeeded(const base::FilePath& symlink_path,
  187. bool new_log) {
  188. DCHECK(!symlink_path.empty());
  189. // For backward compatibility, set up a .../chrome symlink to
  190. // .../chrome.LATEST as needed. This code needs to run only
  191. // after the migration (i.e. the addition of chrome.LATEST).
  192. if (symlink_path.Extension() == ".LATEST") {
  193. base::FilePath extensionless_path = symlink_path.ReplaceExtension("");
  194. base::FilePath target_path;
  195. bool extensionless_symlink_exists =
  196. base::ReadSymbolicLink(extensionless_path, &target_path);
  197. if (target_path != symlink_path) {
  198. // No link, or wrong link. Clean up. This should happen only once in
  199. // each log directory after the OS version update, but some of those
  200. // directories may not be accessed for a long time, so this code needs to
  201. // stay in forever :/
  202. if (extensionless_symlink_exists &&
  203. !base::DeleteFile(extensionless_path)) {
  204. DPLOG(WARNING) << "Cannot delete " << extensionless_path.value();
  205. }
  206. // After cleaning up, create the symlink.
  207. if (!base::CreateSymbolicLink(symlink_path, extensionless_path)) {
  208. DPLOG(ERROR) << "Cannot create " << extensionless_path.value();
  209. }
  210. }
  211. }
  212. // If not starting a new log, then just log through the existing symlink, but
  213. // if the symlink doesn't exist, create it.
  214. //
  215. // If starting a new log, then rename the old symlink as
  216. // symlink_path.PREVIOUS and make a new symlink to a fresh log file.
  217. // Check for existence of the symlink.
  218. base::FilePath target_path;
  219. bool symlink_exists = base::ReadSymbolicLink(symlink_path, &target_path);
  220. if (symlink_exists && !new_log)
  221. return target_path;
  222. // Remove any extension before time-stamping.
  223. target_path = GenerateTimestampedName(symlink_path.RemoveExtension(),
  224. base::Time::Now());
  225. if (symlink_exists) {
  226. base::FilePath previous_symlink_path =
  227. symlink_path.ReplaceExtension(".PREVIOUS");
  228. // Rename symlink to .PREVIOUS. This nukes an existing symlink just like
  229. // the rename(2) syscall does.
  230. if (!base::ReplaceFile(symlink_path, previous_symlink_path, nullptr)) {
  231. DPLOG(WARNING) << "Cannot rename " << symlink_path.value() << " to "
  232. << previous_symlink_path.value();
  233. }
  234. }
  235. // If all went well, the symlink no longer exists. Recreate it.
  236. base::FilePath relative_target_path = target_path.BaseName();
  237. if (!base::CreateSymbolicLink(relative_target_path, symlink_path)) {
  238. DPLOG(ERROR) << "Unable to create symlink " << symlink_path.value()
  239. << " pointing at " << relative_target_path.value();
  240. }
  241. return target_path;
  242. }
  243. void RemoveSymlinkAndLog(const base::FilePath& link_path,
  244. const base::FilePath& target_path) {
  245. if (::unlink(link_path.value().c_str()) == -1)
  246. DPLOG(WARNING) << "Unable to unlink symlink " << link_path.value();
  247. if (target_path != link_path && ::unlink(target_path.value().c_str()) == -1)
  248. DPLOG(WARNING) << "Unable to unlink log file " << target_path.value();
  249. }
  250. base::FilePath GetSessionLogDir(const base::CommandLine& command_line) {
  251. std::string log_dir;
  252. std::unique_ptr<base::Environment> env(base::Environment::Create());
  253. if (!env->GetVar(env_vars::kSessionLogDir, &log_dir))
  254. NOTREACHED();
  255. return base::FilePath(log_dir);
  256. }
  257. base::FilePath GetSessionLogFile(const base::CommandLine& command_line) {
  258. return GetSessionLogDir(command_line)
  259. .Append(GetLogFileName(command_line).BaseName());
  260. }
  261. base::FilePath SetUpLogFile(const base::FilePath& target_path, bool new_log) {
  262. const bool supports_symlinks =
  263. !(target_path.IsAbsolute() &&
  264. base::StartsWith(target_path.value(), kChronosHomeDir));
  265. // TODO(crbug.com/1326369): Remove the old symlink logic.
  266. if (supports_symlinks) {
  267. // As for now, we keep the original log rotation logic on the file system
  268. // which supports symlinks.
  269. return SetUpSymlinkIfNeeded(target_path, new_log);
  270. }
  271. // Chrome OS doesn't support symlinks on this file system, so that it uses
  272. // the rotation logic which doesn't use symlinks.
  273. if (!new_log) {
  274. // Keep using the same log file without doing anything.
  275. return target_path;
  276. }
  277. // For backward compatibility, ignore a ".LATEST" extension the way
  278. // |SetUpSymlinkIfNeeded()| does.
  279. base::FilePath bare_path = target_path;
  280. if (target_path.Extension() == ".LATEST") {
  281. bare_path = target_path.ReplaceExtension("");
  282. }
  283. // Try to rotate the log.
  284. if (!RotateLogFile(bare_path)) {
  285. DPLOG(ERROR) << "Failed to rotate the log file: " << bare_path.value()
  286. << ". Keeping using the same log file without rotating.";
  287. }
  288. return bare_path;
  289. }
  290. #endif // BUILDFLAG(IS_CHROMEOS_ASH)
  291. void InitChromeLogging(const base::CommandLine& command_line,
  292. OldFileDeletionState delete_old_log_file) {
  293. DCHECK(!chrome_logging_initialized_) <<
  294. "Attempted to initialize logging when it was already initialized.";
  295. LoggingDestination logging_dest = DetermineLoggingDestination(command_line);
  296. LogLockingState log_locking_state = LOCK_LOG_FILE;
  297. base::FilePath log_path;
  298. #if BUILDFLAG(IS_CHROMEOS_ASH)
  299. base::FilePath target_path;
  300. #endif
  301. // Don't resolve the log path unless we need to. Otherwise we leave an open
  302. // ALPC handle after sandbox lockdown on Windows.
  303. if ((logging_dest & LOG_TO_FILE) != 0) {
  304. log_path = GetLogFileName(command_line);
  305. #if BUILDFLAG(IS_CHROMEOS_ASH)
  306. // For BWSI (Incognito) logins, we want to put the logs in the user
  307. // profile directory that is created for the temporary session instead
  308. // of in the system log directory, for privacy reasons.
  309. if (command_line.HasSwitch(ash::switches::kGuestSession))
  310. log_path = GetSessionLogFile(command_line);
  311. // Prepares a log file. We rotate the previous log file and prepare a new
  312. // log file if we've been asked to delete the old log, since that
  313. // indicates the start of a new session.
  314. target_path =
  315. SetUpLogFile(log_path, delete_old_log_file == DELETE_OLD_LOG_FILE);
  316. // Because ChromeOS manages the move to a new session by redirecting
  317. // the link, it shouldn't remove the old file in the logging code,
  318. // since that will remove the newly created link instead.
  319. delete_old_log_file = APPEND_TO_OLD_LOG_FILE;
  320. #endif // BUILDFLAG(IS_CHROMEOS_ASH)
  321. } else {
  322. log_locking_state = DONT_LOCK_LOG_FILE;
  323. }
  324. LoggingSettings settings;
  325. settings.logging_dest = logging_dest;
  326. settings.log_file_path = log_path.value().c_str();
  327. settings.lock_log = log_locking_state;
  328. settings.delete_old = delete_old_log_file;
  329. bool success = InitLogging(settings);
  330. #if BUILDFLAG(IS_CHROMEOS_ASH)
  331. if (!success) {
  332. DPLOG(ERROR) << "Unable to initialize logging to " << log_path.value()
  333. << " (which should be a link to " << target_path.value() << ")";
  334. RemoveSymlinkAndLog(log_path, target_path);
  335. chrome_logging_failed_ = true;
  336. return;
  337. }
  338. #else // BUILDFLAG(IS_CHROMEOS_ASH)
  339. if (!success) {
  340. DPLOG(ERROR) << "Unable to initialize logging to " << log_path.value();
  341. chrome_logging_failed_ = true;
  342. return;
  343. }
  344. #endif // BUILDFLAG(IS_CHROMEOS_ASH)
  345. // We call running in unattended mode "headless", and allow headless mode to
  346. // be configured either by the Environment Variable or by the Command Line
  347. // Switch. This is for automated test purposes.
  348. std::unique_ptr<base::Environment> env(base::Environment::Create());
  349. const bool is_headless = env->HasVar(env_vars::kHeadless) ||
  350. command_line.HasSwitch(switches::kNoErrorDialogs);
  351. // Show fatal log messages in a dialog in debug builds when not headless.
  352. if (!is_headless)
  353. SetShowErrorDialogs(true);
  354. // we want process and thread IDs because we have a lot of things running
  355. SetLogItems(true, // enable_process_id
  356. true, // enable_thread_id
  357. true, // enable_timestamp
  358. false); // enable_tickcount
  359. // Suppress system error dialogs when headless.
  360. if (is_headless)
  361. SuppressDialogs();
  362. // Use a minimum log level if the command line asks for one. Ignore this
  363. // switch if there's vlog level switch present too (as both of these switches
  364. // refer to the same underlying log level, and the vlog level switch has
  365. // already been processed inside InitLogging). If there is neither
  366. // log level nor vlog level specified, then just leave the default level
  367. // (INFO).
  368. if (command_line.HasSwitch(switches::kLoggingLevel) &&
  369. GetMinLogLevel() >= 0) {
  370. std::string log_level =
  371. command_line.GetSwitchValueASCII(switches::kLoggingLevel);
  372. int level = 0;
  373. if (base::StringToInt(log_level, &level) && level >= 0 &&
  374. level < LOGGING_NUM_SEVERITIES) {
  375. SetMinLogLevel(level);
  376. } else {
  377. DLOG(WARNING) << "Bad log level: " << log_level;
  378. }
  379. }
  380. #if BUILDFLAG(IS_WIN)
  381. // Enable trace control and transport through event tracing for Windows.
  382. LogEventProvider::Initialize(kChromeTraceProviderName);
  383. // Enable logging to the Windows Event Log.
  384. SetEventSource(base::WideToASCII(
  385. install_static::InstallDetails::Get().install_full_name()),
  386. BROWSER_CATEGORY, MSG_LOG_MESSAGE);
  387. #endif
  388. base::StatisticsRecorder::InitLogOnShutdown();
  389. chrome_logging_initialized_ = true;
  390. }
  391. // This is a no-op, but we'll keep it around in case
  392. // we need to do more cleanup in the future.
  393. void CleanupChromeLogging() {
  394. if (chrome_logging_failed_)
  395. return; // We failed to initiailize logging, no cleanup.
  396. DCHECK(chrome_logging_initialized_)
  397. << "Attempted to clean up logging when it wasn't initialized.";
  398. CloseLogFile();
  399. chrome_logging_initialized_ = false;
  400. chrome_logging_redirected_ = false;
  401. }
  402. base::FilePath GetLogFileName(const base::CommandLine& command_line) {
  403. auto filename = command_line.GetSwitchValueNative(switches::kLogFile);
  404. if (!filename.empty())
  405. return base::FilePath(filename);
  406. std::string env_filename;
  407. base::Environment::Create()->GetVar(env_vars::kLogFileName, &env_filename);
  408. if (!env_filename.empty())
  409. return base::FilePath::FromUTF8Unsafe(env_filename);
  410. const base::FilePath log_filename(FILE_PATH_LITERAL("chrome_debug.log"));
  411. base::FilePath log_path;
  412. if (base::PathService::Get(chrome::DIR_LOGS, &log_path)) {
  413. log_path = log_path.Append(log_filename);
  414. return log_path;
  415. } else {
  416. // error with path service, just use some default file somewhere
  417. return log_filename;
  418. }
  419. }
  420. bool DialogsAreSuppressed() {
  421. return dialogs_are_suppressed_;
  422. }
  423. #if BUILDFLAG(IS_CHROMEOS_ASH)
  424. base::FilePath GenerateTimestampedName(const base::FilePath& base_path,
  425. base::Time timestamp) {
  426. base::Time::Exploded time_deets;
  427. timestamp.UTCExplode(&time_deets);
  428. std::string suffix = base::StringPrintf("_%02d%02d%02d-%02d%02d%02d",
  429. time_deets.year,
  430. time_deets.month,
  431. time_deets.day_of_month,
  432. time_deets.hour,
  433. time_deets.minute,
  434. time_deets.second);
  435. return base_path.InsertBeforeExtensionASCII(suffix);
  436. }
  437. #endif // BUILDFLAG(IS_CHROMEOS_ASH)
  438. } // namespace logging