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