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