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/render_messages.h"
21 #include "content/common/plugin_messages.h"
22 #include "content/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
57 namespace {
58
59 // When true, this means that error dialogs should not be shown.
60 bool 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().
64 bool chrome_logging_initialized_ = false;
65
66 // Set if we caled InitChromeLogging() but failed to initialize.
67 bool 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().
71 bool chrome_logging_redirected_ = false;
72
73 #if defined(OS_WIN)
74 // {7FE69228-633E-4f06-80C1-527FEA23E3A7}
75 const 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.
83 MSVC_DISABLE_OPTIMIZE();
SilentRuntimeAssertHandler(const std::string & str)84 void SilentRuntimeAssertHandler(const std::string& str) {
85 base::debug::BreakDebugger();
86 }
SilentRuntimeReportHandler(const std::string & str)87 void 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.
DumpProcessAssertHandler(const std::string & str)92 void 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
102 MSVC_ENABLE_OPTIMIZE();
103
104 // Suppresses error/assertion dialogs and enables the logging of
105 // those errors into silenced_errors_.
SuppressDialogs()106 void 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
128 namespace logging {
129
DetermineLogMode(const CommandLine & command_line)130 LoggingDestination 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)
162 namespace {
GenerateTimestampedName(const FilePath & base_path,base::Time timestamp)163 FilePath 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
SetUpSymlinkIfNeeded(const FilePath & symlink_path,bool new_log)177 FilePath 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
RemoveSymlinkAndLog(const FilePath & link_path,const FilePath & target_path)205 void 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
GetSessionLogFile(const CommandLine & command_line)215 FilePath 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
RedirectChromeLogging(const CommandLine & command_line)231 void 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
InitChromeLogging(const CommandLine & command_line,OldFileDeletionState delete_old_log_file)267 void 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.
CleanupChromeLogging()377 void 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
GetLogFileName()390 FilePath 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
DialogsAreSuppressed()413 bool DialogsAreSuppressed() {
414 return dialogs_are_suppressed_;
415 }
416
GetFatalAssertions(AssertionList * assertions)417 size_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