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/debug/dump_without_crashing.h"
37#include "base/environment.h"
38#include "base/files/file_path.h"
39#include "base/files/file_util.h"
40#include "base/logging.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 "base/time/time.h"
48#include "chrome/common/chrome_constants.h"
49#include "chrome/common/chrome_paths.h"
50#include "chrome/common/chrome_switches.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}
93MSVC_ENABLE_OPTIMIZE();
94
95// Suppresses error/assertion dialogs and enables the logging of
96// those errors into silenced_errors_.
97void SuppressDialogs() {
98  if (dialogs_are_suppressed_)
99    return;
100
101  logging::SetLogAssertHandler(SilentRuntimeAssertHandler);
102
103#if defined(OS_WIN)
104  UINT new_flags = SEM_FAILCRITICALERRORS |
105                   SEM_NOGPFAULTERRORBOX |
106                   SEM_NOOPENFILEERRORBOX;
107
108  // Preserve existing error mode, as discussed at http://t/dmea
109  UINT existing_flags = SetErrorMode(new_flags);
110  SetErrorMode(existing_flags | new_flags);
111#endif
112
113  dialogs_are_suppressed_ = true;
114}
115
116}  // anonymous namespace
117
118namespace logging {
119
120LoggingDestination DetermineLogMode(const CommandLine& command_line) {
121  // only use OutputDebugString in debug mode
122#ifdef NDEBUG
123  bool enable_logging = false;
124  const char *kInvertLoggingSwitch = switches::kEnableLogging;
125  const logging::LoggingDestination kDefaultLoggingMode = logging::LOG_TO_FILE;
126#else
127  bool enable_logging = true;
128  const char *kInvertLoggingSwitch = switches::kDisableLogging;
129  const logging::LoggingDestination kDefaultLoggingMode = logging::LOG_TO_ALL;
130#endif
131
132  if (command_line.HasSwitch(kInvertLoggingSwitch))
133    enable_logging = !enable_logging;
134
135  logging::LoggingDestination log_mode;
136  if (enable_logging) {
137    // Let --enable-logging=stderr force only stderr, particularly useful for
138    // non-debug builds where otherwise you can't get logs to stderr at all.
139    if (command_line.GetSwitchValueASCII(switches::kEnableLogging) == "stderr")
140      log_mode = logging::LOG_TO_SYSTEM_DEBUG_LOG;
141    else
142      log_mode = kDefaultLoggingMode;
143  } else {
144    log_mode = logging::LOG_NONE;
145  }
146  return log_mode;
147}
148
149#if defined(OS_CHROMEOS)
150namespace {
151base::FilePath SetUpSymlinkIfNeeded(const base::FilePath& symlink_path,
152                                    bool new_log) {
153  DCHECK(!symlink_path.empty());
154
155  // If not starting a new log, then just log through the existing
156  // symlink, but if the symlink doesn't exist, create it.  If
157  // starting a new log, then delete the old symlink and make a new
158  // one to a fresh log file.
159  base::FilePath target_path;
160  bool symlink_exists = base::PathExists(symlink_path);
161  if (new_log || !symlink_exists) {
162    target_path = GenerateTimestampedName(symlink_path, base::Time::Now());
163
164    // We don't care if the unlink fails; we're going to continue anyway.
165    if (::unlink(symlink_path.value().c_str()) == -1) {
166      if (symlink_exists) // only warn if we might expect it to succeed.
167        DPLOG(WARNING) << "Unable to unlink " << symlink_path.value();
168    }
169    if (!base::CreateSymbolicLink(target_path, symlink_path)) {
170      DPLOG(ERROR) << "Unable to create symlink " << symlink_path.value()
171                   << " pointing at " << target_path.value();
172    }
173  } else {
174    if (!base::ReadSymbolicLink(symlink_path, &target_path))
175      DPLOG(ERROR) << "Unable to read symlink " << symlink_path.value();
176  }
177  return target_path;
178}
179
180void RemoveSymlinkAndLog(const base::FilePath& link_path,
181                         const base::FilePath& target_path) {
182  if (::unlink(link_path.value().c_str()) == -1)
183    DPLOG(WARNING) << "Unable to unlink symlink " << link_path.value();
184  if (::unlink(target_path.value().c_str()) == -1)
185    DPLOG(WARNING) << "Unable to unlink log file " << target_path.value();
186}
187
188}  // anonymous namespace
189
190base::FilePath GetSessionLogDir(const CommandLine& command_line) {
191  base::FilePath log_dir;
192  std::string log_dir_str;
193  scoped_ptr<base::Environment> env(base::Environment::Create());
194  if (env->GetVar(env_vars::kSessionLogDir, &log_dir_str) &&
195      !log_dir_str.empty()) {
196    log_dir = base::FilePath(log_dir_str);
197  } else if (command_line.HasSwitch(chromeos::switches::kLoginProfile)) {
198    PathService::Get(chrome::DIR_USER_DATA, &log_dir);
199    base::FilePath profile_dir;
200    std::string login_profile_value =
201        command_line.GetSwitchValueASCII(chromeos::switches::kLoginProfile);
202    if (login_profile_value == chrome::kLegacyProfileDir ||
203        login_profile_value == chrome::kTestUserProfileDir) {
204      profile_dir = base::FilePath(login_profile_value);
205    } else {
206      // We could not use g_browser_process > profile_helper() here.
207      std::string profile_dir_str = chrome::kProfileDirPrefix;
208      profile_dir_str.append(login_profile_value);
209      profile_dir = base::FilePath(profile_dir_str);
210    }
211    log_dir = log_dir.Append(profile_dir);
212  }
213  return log_dir;
214}
215
216base::FilePath GetSessionLogFile(const CommandLine& command_line) {
217  return GetSessionLogDir(command_line).Append(GetLogFileName().BaseName());
218}
219
220void RedirectChromeLogging(const CommandLine& command_line) {
221  if (chrome_logging_redirected_) {
222    // TODO(nkostylev): Support multiple active users. http://crbug.com/230345
223    LOG(WARNING) << "NOT redirecting logging for multi-profiles case.";
224    return;
225  }
226
227  DCHECK(!chrome_logging_redirected_) <<
228    "Attempted to redirect logging when it was already initialized.";
229
230  // Redirect logs to the session log directory, if set.  Otherwise
231  // defaults to the profile dir.
232  base::FilePath log_path = GetSessionLogFile(command_line);
233
234  // Creating symlink causes us to do blocking IO on UI thread.
235  // Temporarily allow it until we fix http://crbug.com/61143
236  base::ThreadRestrictions::ScopedAllowIO allow_io;
237  // Always force a new symlink when redirecting.
238  base::FilePath target_path = SetUpSymlinkIfNeeded(log_path, true);
239
240  // ChromeOS always logs through the symlink, so it shouldn't be
241  // deleted if it already exists.
242  logging::LoggingSettings settings;
243  settings.logging_dest = DetermineLogMode(command_line);
244  settings.log_file = log_path.value().c_str();
245  if (!logging::InitLogging(settings)) {
246    DLOG(ERROR) << "Unable to initialize logging to " << log_path.value();
247    RemoveSymlinkAndLog(log_path, target_path);
248  } else {
249    chrome_logging_redirected_ = true;
250  }
251}
252
253#endif  // OS_CHROMEOS
254
255void InitChromeLogging(const CommandLine& command_line,
256                       OldFileDeletionState delete_old_log_file) {
257  DCHECK(!chrome_logging_initialized_) <<
258    "Attempted to initialize logging when it was already initialized.";
259
260  LoggingDestination logging_dest = DetermineLogMode(command_line);
261  LogLockingState log_locking_state = LOCK_LOG_FILE;
262  base::FilePath log_path;
263#if defined(OS_CHROMEOS)
264  base::FilePath target_path;
265#endif
266
267  // Don't resolve the log path unless we need to. Otherwise we leave an open
268  // ALPC handle after sandbox lockdown on Windows.
269  if ((logging_dest & LOG_TO_FILE) != 0) {
270    log_path = GetLogFileName();
271
272#if defined(OS_CHROMEOS)
273    // For BWSI (Incognito) logins, we want to put the logs in the user
274    // profile directory that is created for the temporary session instead
275    // of in the system log directory, for privacy reasons.
276    if (command_line.HasSwitch(chromeos::switches::kGuestSession))
277      log_path = GetSessionLogFile(command_line);
278
279    // On ChromeOS we log to the symlink.  We force creation of a new
280    // symlink if we've been asked to delete the old log, since that
281    // indicates the start of a new session.
282    target_path = SetUpSymlinkIfNeeded(
283        log_path, delete_old_log_file == logging::DELETE_OLD_LOG_FILE);
284
285    // Because ChromeOS manages the move to a new session by redirecting
286    // the link, it shouldn't remove the old file in the logging code,
287    // since that will remove the newly created link instead.
288    delete_old_log_file = logging::APPEND_TO_OLD_LOG_FILE;
289#endif
290  } else {
291    log_locking_state = DONT_LOCK_LOG_FILE;
292  }
293
294  logging::LoggingSettings settings;
295  settings.logging_dest = logging_dest;
296  settings.log_file = log_path.value().c_str();
297  settings.lock_log = log_locking_state;
298  settings.delete_old = delete_old_log_file;
299  bool success = logging::InitLogging(settings);
300
301#if defined(OS_CHROMEOS)
302  if (!success) {
303    DPLOG(ERROR) << "Unable to initialize logging to " << log_path.value()
304                << " (which should be a link to " << target_path.value() << ")";
305    RemoveSymlinkAndLog(log_path, target_path);
306    chrome_logging_failed_ = true;
307    return;
308  }
309#else
310  if (!success) {
311    DPLOG(ERROR) << "Unable to initialize logging to " << log_path.value();
312    chrome_logging_failed_ = true;
313    return;
314  }
315#endif
316
317  // Default to showing error dialogs.
318  if (!CommandLine::ForCurrentProcess()->HasSwitch(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,
337  // otherwise leave it at the default level (INFO).
338  if (command_line.HasSwitch(switches::kLoggingLevel)) {
339    std::string log_level = command_line.GetSwitchValueASCII(
340        switches::kLoggingLevel);
341    int level = 0;
342    if (base::StringToInt(log_level, &level) &&
343        level >= 0 && level < LOG_NUM_SEVERITIES) {
344      logging::SetMinLogLevel(level);
345    } else {
346      DLOG(WARNING) << "Bad log level: " << log_level;
347    }
348  }
349
350#if defined(OS_WIN)
351  // Enable trace control and transport through event tracing for Windows.
352  logging::LogEventProvider::Initialize(kChromeTraceProviderName);
353#endif
354
355  chrome_logging_initialized_ = true;
356}
357
358// This is a no-op, but we'll keep it around in case
359// we need to do more cleanup in the future.
360void CleanupChromeLogging() {
361  if (chrome_logging_failed_)
362    return;  // We failed to initiailize logging, no cleanup.
363
364  DCHECK(chrome_logging_initialized_) <<
365    "Attempted to clean up logging when it wasn't initialized.";
366
367  CloseLogFile();
368
369  chrome_logging_initialized_ = false;
370  chrome_logging_redirected_ = false;
371}
372
373base::FilePath GetLogFileName() {
374  std::string filename;
375  scoped_ptr<base::Environment> env(base::Environment::Create());
376  if (env->GetVar(env_vars::kLogFileName, &filename) && !filename.empty())
377    return base::FilePath::FromUTF8Unsafe(filename);
378
379  const base::FilePath log_filename(FILE_PATH_LITERAL("chrome_debug.log"));
380  base::FilePath log_path;
381
382  if (PathService::Get(chrome::DIR_LOGS, &log_path)) {
383    log_path = log_path.Append(log_filename);
384    return log_path;
385  } else {
386    // error with path service, just use some default file somewhere
387    return log_filename;
388  }
389}
390
391bool DialogsAreSuppressed() {
392  return dialogs_are_suppressed_;
393}
394
395size_t GetFatalAssertions(AssertionList* assertions) {
396  // In this function, we don't assume that assertions is non-null, so
397  // that if you just want an assertion count, you can pass in NULL.
398  if (assertions)
399    assertions->clear();
400  size_t assertion_count = 0;
401
402  std::ifstream log_file;
403  log_file.open(GetLogFileName().value().c_str());
404  if (!log_file.is_open())
405    return 0;
406
407  std::string utf8_line;
408  std::wstring wide_line;
409  while (!log_file.eof()) {
410    getline(log_file, utf8_line);
411    if (utf8_line.find(":FATAL:") != std::string::npos) {
412      wide_line = base::UTF8ToWide(utf8_line);
413      if (assertions)
414        assertions->push_back(wide_line);
415      ++assertion_count;
416    }
417  }
418  log_file.close();
419
420  return assertion_count;
421}
422
423base::FilePath GenerateTimestampedName(const base::FilePath& base_path,
424                                       base::Time timestamp) {
425  base::Time::Exploded time_deets;
426  timestamp.LocalExplode(&time_deets);
427  std::string suffix = base::StringPrintf("_%02d%02d%02d-%02d%02d%02d",
428                                          time_deets.year,
429                                          time_deets.month,
430                                          time_deets.day_of_month,
431                                          time_deets.hour,
432                                          time_deets.minute,
433                                          time_deets.second);
434  return base_path.InsertBeforeExtensionASCII(suffix);
435}
436
437}  // namespace logging
438