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 = base::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