1 // Copyright (c) 2011 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.
5 #include "base/logging.h"
10 typedef HANDLE FileHandle
;
11 typedef HANDLE MutexHandle
;
12 // Windows warns on using write(). It prefers _write().
13 #define write(fd, buf, count) _write(fd, buf, static_cast<unsigned int>(count))
14 // Windows doesn't define STDERR_FILENO. Define it here.
15 #define STDERR_FILENO 2
16 #elif defined(OS_MACOSX)
17 #include <mach/mach.h>
18 #include <mach/mach_time.h>
19 #include <mach-o/dyld.h>
20 #elif defined(OS_POSIX)
22 #include <sys/nacl_syscalls.h>
23 #include <sys/time.h> // timespec doesn't seem to be in <time.h>
25 #include <sys/syscall.h>
37 #define MAX_PATH PATH_MAX
38 typedef FILE* FileHandle
;
39 typedef pthread_mutex_t
* MutexHandle
;
48 #include "base/base_switches.h"
49 #include "base/command_line.h"
50 #include "base/debug/debugger.h"
51 #include "base/debug/stack_trace.h"
52 #include "base/eintr_wrapper.h"
53 #include "base/string_piece.h"
54 #include "base/synchronization/lock_impl.h"
55 #include "base/utf_string_conversions.h"
56 #include "base/vlog.h"
58 #include "base/safe_strerror_posix.h"
63 DcheckState g_dcheck_state
= DISABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS
;
64 VlogInfo
* g_vlog_info
= NULL
;
66 const char* const log_severity_names
[LOG_NUM_SEVERITIES
] = {
67 "INFO", "WARNING", "ERROR", "ERROR_REPORT", "FATAL" };
69 int min_log_level
= 0;
71 // The default set here for logging_destination will only be used if
72 // InitLogging is not called. On Windows, use a file next to the exe;
73 // on POSIX platforms, where it may not even be possible to locate the
74 // executable on disk, use stderr.
76 LoggingDestination logging_destination
= LOG_ONLY_TO_FILE
;
77 #elif defined(OS_POSIX)
78 LoggingDestination logging_destination
= LOG_ONLY_TO_SYSTEM_DEBUG_LOG
;
81 // For LOG_ERROR and above, always print to stderr.
82 const int kAlwaysPrintErrorLevel
= LOG_ERROR
;
84 // Which log file to use? This is initialized by InitLogging or
85 // will be lazily initialized to the default value when it is
88 typedef std::wstring PathString
;
90 typedef std::string PathString
;
92 PathString
* log_file_name
= NULL
;
94 // this file is lazily opened and the handle may be NULL
95 FileHandle log_file
= NULL
;
97 // what should be prepended to each message?
98 bool log_process_id
= false;
99 bool log_thread_id
= false;
100 bool log_timestamp
= true;
101 bool log_tickcount
= false;
103 // Should we pop up fatal debug messages in a dialog?
104 bool show_error_dialogs
= false;
106 // An assert handler override specified by the client to be called instead of
107 // the debug message dialog and process termination.
108 LogAssertHandlerFunction log_assert_handler
= NULL
;
109 // An report handler override specified by the client to be called instead of
110 // the debug message dialog.
111 LogReportHandlerFunction log_report_handler
= NULL
;
112 // A log message handler that gets notified of every log message we process.
113 LogMessageHandlerFunction log_message_handler
= NULL
;
115 // Helper functions to wrap platform differences.
117 int32
CurrentProcessId() {
119 return GetCurrentProcessId();
120 #elif defined(OS_POSIX)
125 int32
CurrentThreadId() {
127 return GetCurrentThreadId();
128 #elif defined(OS_MACOSX)
129 return mach_thread_self();
130 #elif defined(OS_LINUX)
131 return syscall(__NR_gettid
);
132 #elif defined(OS_FREEBSD)
133 // TODO(BSD): find a better thread ID
134 return reinterpret_cast<int64
>(pthread_self());
135 #elif defined(OS_NACL)
136 return pthread_self();
142 return GetTickCount();
143 #elif defined(OS_MACOSX)
144 return mach_absolute_time();
145 #elif defined(OS_NACL)
146 // NaCl sadly does not have _POSIX_TIMERS enabled in sys/features.h
147 // So we have to use clock() for now.
149 #elif defined(OS_POSIX)
151 clock_gettime(CLOCK_MONOTONIC
, &ts
);
153 uint64 absolute_micro
=
154 static_cast<int64
>(ts
.tv_sec
) * 1000000 +
155 static_cast<int64
>(ts
.tv_nsec
) / 1000;
157 return absolute_micro
;
161 void CloseFile(FileHandle log
) {
169 void DeleteFilePath(const PathString
& log_name
) {
171 DeleteFile(log_name
.c_str());
173 unlink(log_name
.c_str());
177 PathString
GetDefaultLogFile() {
179 // On Windows we use the same path as the exe.
180 wchar_t module_name
[MAX_PATH
];
181 GetModuleFileName(NULL
, module_name
, MAX_PATH
);
183 PathString log_file
= module_name
;
184 PathString::size_type last_backslash
=
185 log_file
.rfind('\\', log_file
.size());
186 if (last_backslash
!= PathString::npos
)
187 log_file
.erase(last_backslash
+ 1);
188 log_file
+= L
"debug.log";
190 #elif defined(OS_POSIX)
191 // On other platforms we just use the current directory.
192 return PathString("debug.log");
196 // This class acts as a wrapper for locking the logging files.
197 // LoggingLock::Init() should be called from the main thread before any logging
198 // is done. Then whenever logging, be sure to have a local LoggingLock
199 // instance on the stack. This will ensure that the lock is unlocked upon
200 // exiting the frame.
201 // LoggingLocks can not be nested.
212 static void Init(LogLockingState lock_log
, const PathChar
* new_log_file
) {
215 lock_log_file
= lock_log
;
216 if (lock_log_file
== LOCK_LOG_FILE
) {
219 std::wstring safe_name
;
221 safe_name
= new_log_file
;
223 safe_name
= GetDefaultLogFile();
224 // \ is not a legal character in mutex names so we replace \ with /
225 std::replace(safe_name
.begin(), safe_name
.end(), '\\', '/');
226 std::wstring
t(L
"Global\\");
228 log_mutex
= ::CreateMutex(NULL
, FALSE
, t
.c_str());
230 if (log_mutex
== NULL
) {
232 // Keep the error code for debugging
233 int error
= GetLastError(); // NOLINT
234 base::debug::BreakDebugger();
236 // Return nicely without putting initialized to true.
242 log_lock
= new base::internal::LockImpl();
248 static void LockLogging() {
249 if (lock_log_file
== LOCK_LOG_FILE
) {
251 ::WaitForSingleObject(log_mutex
, INFINITE
);
252 // WaitForSingleObject could have returned WAIT_ABANDONED. We don't
253 // abort the process here. UI tests might be crashy sometimes,
254 // and aborting the test binary only makes the problem worse.
255 // We also don't use LOG macros because that might lead to an infinite
256 // loop. For more info see http://crbug.com/18028.
257 #elif defined(OS_POSIX)
258 pthread_mutex_lock(&log_mutex
);
266 static void UnlockLogging() {
267 if (lock_log_file
== LOCK_LOG_FILE
) {
269 ReleaseMutex(log_mutex
);
270 #elif defined(OS_POSIX)
271 pthread_mutex_unlock(&log_mutex
);
278 // The lock is used if log file locking is false. It helps us avoid problems
279 // with multiple threads writing to the log file at the same time. Use
280 // LockImpl directly instead of using Lock, because Lock makes logging calls.
281 static base::internal::LockImpl
* log_lock
;
283 // When we don't use a lock, we are using a global mutex. We need to do this
284 // because LockFileEx is not thread safe.
286 static MutexHandle log_mutex
;
287 #elif defined(OS_POSIX)
288 static pthread_mutex_t log_mutex
;
291 static bool initialized
;
292 static LogLockingState lock_log_file
;
296 bool LoggingLock::initialized
= false;
298 base::internal::LockImpl
* LoggingLock::log_lock
= NULL
;
300 LogLockingState
LoggingLock::lock_log_file
= LOCK_LOG_FILE
;
304 MutexHandle
LoggingLock::log_mutex
= NULL
;
305 #elif defined(OS_POSIX)
306 pthread_mutex_t
LoggingLock::log_mutex
= PTHREAD_MUTEX_INITIALIZER
;
309 // Called by logging functions to ensure that debug_file is initialized
310 // and can be used for writing. Returns false if the file could not be
311 // initialized. debug_file will be NULL in this case.
312 bool InitializeLogFileHandle() {
316 if (!log_file_name
) {
317 // Nobody has called InitLogging to specify a debug log file, so here we
318 // initialize the log file name to a default.
319 log_file_name
= new PathString(GetDefaultLogFile());
322 if (logging_destination
== LOG_ONLY_TO_FILE
||
323 logging_destination
== LOG_TO_BOTH_FILE_AND_SYSTEM_DEBUG_LOG
) {
325 log_file
= CreateFile(log_file_name
->c_str(), GENERIC_WRITE
,
326 FILE_SHARE_READ
| FILE_SHARE_WRITE
, NULL
,
327 OPEN_ALWAYS
, FILE_ATTRIBUTE_NORMAL
, NULL
);
328 if (log_file
== INVALID_HANDLE_VALUE
|| log_file
== NULL
) {
329 // try the current directory
330 log_file
= CreateFile(L
".\\debug.log", GENERIC_WRITE
,
331 FILE_SHARE_READ
| FILE_SHARE_WRITE
, NULL
,
332 OPEN_ALWAYS
, FILE_ATTRIBUTE_NORMAL
, NULL
);
333 if (log_file
== INVALID_HANDLE_VALUE
|| log_file
== NULL
) {
338 SetFilePointer(log_file
, 0, 0, FILE_END
);
339 #elif defined(OS_POSIX)
340 log_file
= fopen(log_file_name
->c_str(), "a");
341 if (log_file
== NULL
)
349 bool BaseInitLoggingImpl(const PathChar
* new_log_file
,
350 LoggingDestination logging_dest
,
351 LogLockingState lock_log
,
352 OldFileDeletionState delete_old
,
353 DcheckState dcheck_state
) {
354 CommandLine
* command_line
= CommandLine::ForCurrentProcess();
355 g_dcheck_state
= dcheck_state
;
358 // Don't bother initializing g_vlog_info unless we use one of the
360 if (command_line
->HasSwitch(switches::kV
) ||
361 command_line
->HasSwitch(switches::kVModule
)) {
363 new VlogInfo(command_line
->GetSwitchValueASCII(switches::kV
),
364 command_line
->GetSwitchValueASCII(switches::kVModule
),
368 LoggingLock::Init(lock_log
, new_log_file
);
370 LoggingLock logging_lock
;
373 // calling InitLogging twice or after some log call has already opened the
374 // default log file will re-initialize to the new options
379 logging_destination
= logging_dest
;
381 // ignore file options if logging is disabled or only to system
382 if (logging_destination
== LOG_NONE
||
383 logging_destination
== LOG_ONLY_TO_SYSTEM_DEBUG_LOG
)
387 log_file_name
= new PathString();
388 *log_file_name
= new_log_file
;
389 if (delete_old
== DELETE_OLD_LOG_FILE
)
390 DeleteFilePath(*log_file_name
);
392 return InitializeLogFileHandle();
395 void SetMinLogLevel(int level
) {
396 min_log_level
= std::min(LOG_ERROR_REPORT
, level
);
399 int GetMinLogLevel() {
400 return min_log_level
;
403 int GetVlogVerbosity() {
404 return std::max(-1, LOG_INFO
- GetMinLogLevel());
407 int GetVlogLevelHelper(const char* file
, size_t N
) {
410 g_vlog_info
->GetVlogLevel(base::StringPiece(file
, N
- 1)) :
414 void SetLogItems(bool enable_process_id
, bool enable_thread_id
,
415 bool enable_timestamp
, bool enable_tickcount
) {
416 log_process_id
= enable_process_id
;
417 log_thread_id
= enable_thread_id
;
418 log_timestamp
= enable_timestamp
;
419 log_tickcount
= enable_tickcount
;
422 void SetShowErrorDialogs(bool enable_dialogs
) {
423 show_error_dialogs
= enable_dialogs
;
426 void SetLogAssertHandler(LogAssertHandlerFunction handler
) {
427 log_assert_handler
= handler
;
430 void SetLogReportHandler(LogReportHandlerFunction handler
) {
431 log_report_handler
= handler
;
434 void SetLogMessageHandler(LogMessageHandlerFunction handler
) {
435 log_message_handler
= handler
;
438 LogMessageHandlerFunction
GetLogMessageHandler() {
439 return log_message_handler
;
442 // MSVC doesn't like complex extern templates and DLLs.
443 #if !defined(COMPILER_MSVC)
444 // Explicit instantiations for commonly used comparisons.
445 template std::string
* MakeCheckOpString
<int, int>(
446 const int&, const int&, const char* names
);
447 template std::string
* MakeCheckOpString
<unsigned long, unsigned long>(
448 const unsigned long&, const unsigned long&, const char* names
);
449 template std::string
* MakeCheckOpString
<unsigned long, unsigned int>(
450 const unsigned long&, const unsigned int&, const char* names
);
451 template std::string
* MakeCheckOpString
<unsigned int, unsigned long>(
452 const unsigned int&, const unsigned long&, const char* names
);
453 template std::string
* MakeCheckOpString
<std::string
, std::string
>(
454 const std::string
&, const std::string
&, const char* name
);
457 // Displays a message box to the user with the error message in it.
458 // Used for fatal messages, where we close the app simultaneously.
459 // This is for developers only; we don't use this in circumstances
460 // (like release builds) where users could see it, since users don't
461 // understand these messages anyway.
462 void DisplayDebugMessageInDialog(const std::string
& str
) {
466 if (!show_error_dialogs
)
470 // For Windows programs, it's possible that the message loop is
471 // messed up on a fatal error, and creating a MessageBox will cause
472 // that message loop to be run. Instead, we try to spawn another
473 // process that displays its command line. We look for "Debug
474 // Message.exe" in the same directory as the application. If it
475 // exists, we use it, otherwise, we use a regular message box.
476 wchar_t prog_name
[MAX_PATH
];
477 GetModuleFileNameW(NULL
, prog_name
, MAX_PATH
);
478 wchar_t* backslash
= wcsrchr(prog_name
, '\\');
481 wcscat_s(prog_name
, MAX_PATH
, L
"debug_message.exe");
483 std::wstring cmdline
= UTF8ToWide(str
);
487 STARTUPINFO startup_info
;
488 memset(&startup_info
, 0, sizeof(startup_info
));
489 startup_info
.cb
= sizeof(startup_info
);
491 PROCESS_INFORMATION process_info
;
492 if (CreateProcessW(prog_name
, &cmdline
[0], NULL
, NULL
, false, 0, NULL
,
493 NULL
, &startup_info
, &process_info
)) {
494 WaitForSingleObject(process_info
.hProcess
, INFINITE
);
495 CloseHandle(process_info
.hThread
);
496 CloseHandle(process_info
.hProcess
);
498 // debug process broken, let's just do a message box
499 MessageBoxW(NULL
, &cmdline
[0], L
"Fatal error",
500 MB_OK
| MB_ICONHAND
| MB_TOPMOST
);
503 // We intentionally don't implement a dialog on other platforms.
504 // You can just look at stderr.
509 LogMessage::SaveLastError::SaveLastError() : last_error_(::GetLastError()) {
512 LogMessage::SaveLastError::~SaveLastError() {
513 ::SetLastError(last_error_
);
515 #endif // defined(OS_WIN)
517 LogMessage::LogMessage(const char* file
, int line
, LogSeverity severity
,
519 : severity_(severity
), file_(file
), line_(line
) {
523 LogMessage::LogMessage(const char* file
, int line
)
524 : severity_(LOG_INFO
), file_(file
), line_(line
) {
528 LogMessage::LogMessage(const char* file
, int line
, LogSeverity severity
)
529 : severity_(severity
), file_(file
), line_(line
) {
533 LogMessage::LogMessage(const char* file
, int line
, std::string
* result
)
534 : severity_(LOG_FATAL
), file_(file
), line_(line
) {
536 stream_
<< "Check failed: " << *result
;
540 LogMessage::LogMessage(const char* file
, int line
, LogSeverity severity
,
542 : severity_(severity
), file_(file
), line_(line
) {
544 stream_
<< "Check failed: " << *result
;
548 LogMessage::~LogMessage() {
550 if (severity_
== LOG_FATAL
) {
551 // Include a stack trace on a fatal.
552 base::debug::StackTrace trace
;
553 stream_
<< std::endl
; // Newline to separate from log message.
554 trace
.OutputToStream(&stream_
);
557 stream_
<< std::endl
;
558 std::string
str_newline(stream_
.str());
560 // Give any log message handler first dibs on the message.
561 if (log_message_handler
&& log_message_handler(severity_
, file_
, line_
,
562 message_start_
, str_newline
)) {
563 // The handler took care of it, no further processing.
567 if (logging_destination
== LOG_ONLY_TO_SYSTEM_DEBUG_LOG
||
568 logging_destination
== LOG_TO_BOTH_FILE_AND_SYSTEM_DEBUG_LOG
) {
570 OutputDebugStringA(str_newline
.c_str());
572 fprintf(stderr
, "%s", str_newline
.c_str());
574 } else if (severity_
>= kAlwaysPrintErrorLevel
) {
575 // When we're only outputting to a log file, above a certain log level, we
576 // should still output to stderr so that we can better detect and diagnose
577 // problems with unit tests, especially on the buildbots.
578 fprintf(stderr
, "%s", str_newline
.c_str());
582 // We can have multiple threads and/or processes, so try to prevent them
583 // from clobbering each other's writes.
584 // If the client app did not call InitLogging, and the lock has not
585 // been created do it now. We do this on demand, but if two threads try
586 // to do this at the same time, there will be a race condition to create
587 // the lock. This is why InitLogging should be called from the main
588 // thread at the beginning of execution.
589 LoggingLock::Init(LOCK_LOG_FILE
, NULL
);
591 if (logging_destination
!= LOG_NONE
&&
592 logging_destination
!= LOG_ONLY_TO_SYSTEM_DEBUG_LOG
) {
593 LoggingLock logging_lock
;
594 if (InitializeLogFileHandle()) {
596 SetFilePointer(log_file
, 0, 0, SEEK_END
);
599 static_cast<const void*>(str_newline
.c_str()),
600 static_cast<DWORD
>(str_newline
.length()),
604 fprintf(log_file
, "%s", str_newline
.c_str());
610 if (severity_
== LOG_FATAL
) {
611 // display a message or break into the debugger on a fatal error
612 if (base::debug::BeingDebugged()) {
613 base::debug::BreakDebugger();
615 if (log_assert_handler
) {
616 // make a copy of the string for the handler out of paranoia
617 log_assert_handler(std::string(stream_
.str()));
619 // Don't use the string with the newline, get a fresh version to send to
620 // the debug message process. We also don't display assertions to the
621 // user in release mode. The enduser can't do anything with this
622 // information, and displaying message boxes when the application is
623 // hosed can cause additional problems.
625 DisplayDebugMessageInDialog(stream_
.str());
627 // Crash the process to generate a dump.
628 base::debug::BreakDebugger();
631 } else if (severity_
== LOG_ERROR_REPORT
) {
632 // We are here only if the user runs with --enable-dcheck in release mode.
633 if (log_report_handler
) {
634 log_report_handler(std::string(stream_
.str()));
636 DisplayDebugMessageInDialog(stream_
.str());
641 // writes the common header info to the stream
642 void LogMessage::Init(const char* file
, int line
) {
643 base::StringPiece
filename(file
);
644 size_t last_slash_pos
= filename
.find_last_of("\\/");
645 if (last_slash_pos
!= base::StringPiece::npos
)
646 filename
.remove_prefix(last_slash_pos
+ 1);
648 // TODO(darin): It might be nice if the columns were fixed width.
652 stream_
<< CurrentProcessId() << ':';
654 stream_
<< CurrentThreadId() << ':';
656 time_t t
= time(NULL
);
657 struct tm local_time
= {0};
659 localtime_s(&local_time
, &t
);
661 localtime_r(&t
, &local_time
);
663 struct tm
* tm_time
= &local_time
;
664 stream_
<< std::setfill('0')
665 << std::setw(2) << 1 + tm_time
->tm_mon
666 << std::setw(2) << tm_time
->tm_mday
668 << std::setw(2) << tm_time
->tm_hour
669 << std::setw(2) << tm_time
->tm_min
670 << std::setw(2) << tm_time
->tm_sec
674 stream_
<< TickCount() << ':';
676 stream_
<< log_severity_names
[severity_
];
678 stream_
<< "VERBOSE" << -severity_
;
680 stream_
<< ":" << filename
<< "(" << line
<< ")] ";
682 message_start_
= stream_
.tellp();
686 // This has already been defined in the header, but defining it again as DWORD
687 // ensures that the type used in the header is equivalent to DWORD. If not,
688 // the redefinition is a compile error.
689 typedef DWORD SystemErrorCode
;
692 SystemErrorCode
GetLastSystemErrorCode() {
694 return ::GetLastError();
695 #elif defined(OS_POSIX)
698 #error Not implemented
703 Win32ErrorLogMessage::Win32ErrorLogMessage(const char* file
,
705 LogSeverity severity
,
710 log_message_(file
, line
, severity
) {
713 Win32ErrorLogMessage::Win32ErrorLogMessage(const char* file
,
715 LogSeverity severity
,
719 log_message_(file
, line
, severity
) {
722 Win32ErrorLogMessage::~Win32ErrorLogMessage() {
723 const int error_message_buffer_size
= 256;
724 char msgbuf
[error_message_buffer_size
];
725 DWORD flags
= FORMAT_MESSAGE_FROM_SYSTEM
| FORMAT_MESSAGE_IGNORE_INSERTS
;
728 hmod
= GetModuleHandleA(module_
);
730 flags
|= FORMAT_MESSAGE_FROM_HMODULE
;
732 // This makes a nested Win32ErrorLogMessage. It will have module_ of NULL
733 // so it will not call GetModuleHandle, so recursive errors are
735 DPLOG(WARNING
) << "Couldn't open module " << module_
736 << " for error message query";
741 DWORD len
= FormatMessageA(flags
,
746 sizeof(msgbuf
) / sizeof(msgbuf
[0]),
750 isspace(static_cast<unsigned char>(msgbuf
[len
- 1]))) {
753 stream() << ": " << msgbuf
;
755 stream() << ": Error " << GetLastError() << " while retrieving error "
759 #elif defined(OS_POSIX)
760 ErrnoLogMessage::ErrnoLogMessage(const char* file
,
762 LogSeverity severity
,
765 log_message_(file
, line
, severity
) {
768 ErrnoLogMessage::~ErrnoLogMessage() {
769 stream() << ": " << safe_strerror(err_
);
773 void CloseLogFile() {
774 LoggingLock logging_lock
;
783 void RawLog(int level
, const char* message
) {
784 if (level
>= min_log_level
) {
785 size_t bytes_written
= 0;
786 const size_t message_len
= strlen(message
);
788 while (bytes_written
< message_len
) {
790 write(STDERR_FILENO
, message
+ bytes_written
,
791 message_len
- bytes_written
));
793 // Give up, nothing we can do now.
799 if (message_len
> 0 && message
[message_len
- 1] != '\n') {
801 rv
= HANDLE_EINTR(write(STDERR_FILENO
, "\n", 1));
803 // Give up, nothing we can do now.
810 if (level
== LOG_FATAL
)
811 base::debug::BreakDebugger();
814 } // namespace logging
816 std::ostream
& operator<<(std::ostream
& out
, const wchar_t* wstr
) {
817 return out
<< WideToUTF8(std::wstring(wstr
));
822 // This was defined at the beginnig of this file.
825 std::ostream
& operator<<(std::ostream
& o
, const StringPiece
& piece
) {
826 o
.write(piece
.data(), static_cast<std::streamsize
>(piece
.size()));