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.
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/time.h> // timespec doesn't seem to be in <time.h>
24 #include <sys/syscall.h>
36 #define MAX_PATH PATH_MAX
37 typedef FILE* FileHandle
;
38 typedef pthread_mutex_t
* MutexHandle
;
48 #include "base/base_switches.h"
49 #include "base/command_line.h"
50 #include "base/debug/alias.h"
51 #include "base/debug/debugger.h"
52 #include "base/debug/stack_trace.h"
53 #include "base/posix/eintr_wrapper.h"
54 #include "base/strings/string_piece.h"
55 #include "base/strings/string_util.h"
56 #include "base/strings/stringprintf.h"
57 #include "base/strings/utf_string_conversions.h"
58 #include "base/synchronization/lock_impl.h"
59 #include "base/threading/platform_thread.h"
60 #include "base/vlog.h"
62 #include "base/safe_strerror_posix.h"
65 #if defined(OS_ANDROID)
66 #include <android/log.h>
73 VlogInfo
* g_vlog_info
= nullptr;
74 VlogInfo
* g_vlog_info_prev
= nullptr;
76 const char* const log_severity_names
[LOG_NUM_SEVERITIES
] = {
77 "INFO", "WARNING", "ERROR", "FATAL" };
79 const char* log_severity_name(int severity
) {
80 if (severity
>= 0 && severity
< LOG_NUM_SEVERITIES
)
81 return log_severity_names
[severity
];
85 int g_min_log_level
= 0;
87 LoggingDestination g_logging_destination
= LOG_DEFAULT
;
89 // For LOG_ERROR and above, always print to stderr.
90 const int kAlwaysPrintErrorLevel
= LOG_ERROR
;
92 // Which log file to use? This is initialized by InitLogging or
93 // will be lazily initialized to the default value when it is
96 typedef std::wstring PathString
;
98 typedef std::string PathString
;
100 PathString
* g_log_file_name
= nullptr;
102 // This file is lazily opened and the handle may be nullptr
103 FileHandle g_log_file
= nullptr;
105 // What should be prepended to each message?
106 bool g_log_process_id
= false;
107 bool g_log_thread_id
= false;
108 bool g_log_timestamp
= true;
109 bool g_log_tickcount
= false;
111 // Should we pop up fatal debug messages in a dialog?
112 bool show_error_dialogs
= false;
114 // An assert handler override specified by the client to be called instead of
115 // the debug message dialog and process termination.
116 LogAssertHandlerFunction log_assert_handler
= nullptr;
117 // A log message handler that gets notified of every log message we process.
118 LogMessageHandlerFunction log_message_handler
= nullptr;
120 // Helper functions to wrap platform differences.
122 int32
CurrentProcessId() {
124 return GetCurrentProcessId();
125 #elif defined(OS_POSIX)
132 return GetTickCount();
133 #elif defined(OS_MACOSX)
134 return mach_absolute_time();
135 #elif defined(OS_NACL)
136 // NaCl sadly does not have _POSIX_TIMERS enabled in sys/features.h
137 // So we have to use clock() for now.
139 #elif defined(OS_POSIX)
141 clock_gettime(CLOCK_MONOTONIC
, &ts
);
143 uint64 absolute_micro
=
144 static_cast<int64
>(ts
.tv_sec
) * 1000000 +
145 static_cast<int64
>(ts
.tv_nsec
) / 1000;
147 return absolute_micro
;
151 void DeleteFilePath(const PathString
& log_name
) {
153 DeleteFile(log_name
.c_str());
154 #elif defined(OS_NACL)
155 // Do nothing; unlink() isn't supported on NaCl.
157 unlink(log_name
.c_str());
161 PathString
GetDefaultLogFile() {
163 // On Windows we use the same path as the exe.
164 wchar_t module_name
[MAX_PATH
];
165 GetModuleFileName(nullptr, module_name
, MAX_PATH
);
167 PathString log_name
= module_name
;
168 PathString::size_type last_backslash
= log_name
.rfind('\\', log_name
.size());
169 if (last_backslash
!= PathString::npos
)
170 log_name
.erase(last_backslash
+ 1);
171 log_name
+= L
"debug.log";
173 #elif defined(OS_POSIX)
174 // On other platforms we just use the current directory.
175 return PathString("debug.log");
179 // This class acts as a wrapper for locking the logging files.
180 // LoggingLock::Init() should be called from the main thread before any logging
181 // is done. Then whenever logging, be sure to have a local LoggingLock
182 // instance on the stack. This will ensure that the lock is unlocked upon
183 // exiting the frame.
184 // LoggingLocks can not be nested.
195 static void Init(LogLockingState lock_log
, const PathChar
* new_log_file
) {
198 lock_log_file
= lock_log
;
199 if (lock_log_file
== LOCK_LOG_FILE
) {
202 std::wstring safe_name
;
204 safe_name
= new_log_file
;
206 safe_name
= GetDefaultLogFile();
207 // \ is not a legal character in mutex names so we replace \ with /
208 std::replace(safe_name
.begin(), safe_name
.end(), '\\', '/');
209 std::wstring
t(L
"Global\\");
211 log_mutex
= ::CreateMutex(nullptr, FALSE
, t
.c_str());
213 if (log_mutex
== nullptr) {
215 // Keep the error code for debugging
216 int error
= GetLastError(); // NOLINT
217 base::debug::BreakDebugger();
219 // Return nicely without putting initialized to true.
225 log_lock
= new base::internal::LockImpl();
231 static void LockLogging() {
232 if (lock_log_file
== LOCK_LOG_FILE
) {
234 ::WaitForSingleObject(log_mutex
, INFINITE
);
235 // WaitForSingleObject could have returned WAIT_ABANDONED. We don't
236 // abort the process here. UI tests might be crashy sometimes,
237 // and aborting the test binary only makes the problem worse.
238 // We also don't use LOG macros because that might lead to an infinite
239 // loop. For more info see http://crbug.com/18028.
240 #elif defined(OS_POSIX)
241 pthread_mutex_lock(&log_mutex
);
249 static void UnlockLogging() {
250 if (lock_log_file
== LOCK_LOG_FILE
) {
252 ReleaseMutex(log_mutex
);
253 #elif defined(OS_POSIX)
254 pthread_mutex_unlock(&log_mutex
);
261 // The lock is used if log file locking is false. It helps us avoid problems
262 // with multiple threads writing to the log file at the same time. Use
263 // LockImpl directly instead of using Lock, because Lock makes logging calls.
264 static base::internal::LockImpl
* log_lock
;
266 // When we don't use a lock, we are using a global mutex. We need to do this
267 // because LockFileEx is not thread safe.
269 static MutexHandle log_mutex
;
270 #elif defined(OS_POSIX)
271 static pthread_mutex_t log_mutex
;
274 static bool initialized
;
275 static LogLockingState lock_log_file
;
279 bool LoggingLock::initialized
= false;
281 base::internal::LockImpl
* LoggingLock::log_lock
= nullptr;
283 LogLockingState
LoggingLock::lock_log_file
= LOCK_LOG_FILE
;
287 MutexHandle
LoggingLock::log_mutex
= nullptr;
288 #elif defined(OS_POSIX)
289 pthread_mutex_t
LoggingLock::log_mutex
= PTHREAD_MUTEX_INITIALIZER
;
292 // Called by logging functions to ensure that |g_log_file| is initialized
293 // and can be used for writing. Returns false if the file could not be
294 // initialized. |g_log_file| will be nullptr in this case.
295 bool InitializeLogFileHandle() {
299 if (!g_log_file_name
) {
300 // Nobody has called InitLogging to specify a debug log file, so here we
301 // initialize the log file name to a default.
302 g_log_file_name
= new PathString(GetDefaultLogFile());
305 if ((g_logging_destination
& LOG_TO_FILE
) != 0) {
307 g_log_file
= CreateFile(g_log_file_name
->c_str(), GENERIC_WRITE
,
308 FILE_SHARE_READ
| FILE_SHARE_WRITE
, nullptr,
309 OPEN_ALWAYS
, FILE_ATTRIBUTE_NORMAL
, nullptr);
310 if (g_log_file
== INVALID_HANDLE_VALUE
|| g_log_file
== nullptr) {
311 // try the current directory
312 g_log_file
= CreateFile(L
".\\debug.log", GENERIC_WRITE
,
313 FILE_SHARE_READ
| FILE_SHARE_WRITE
, nullptr,
314 OPEN_ALWAYS
, FILE_ATTRIBUTE_NORMAL
, nullptr);
315 if (g_log_file
== INVALID_HANDLE_VALUE
|| g_log_file
== nullptr) {
316 g_log_file
= nullptr;
320 SetFilePointer(g_log_file
, 0, 0, FILE_END
);
321 #elif defined(OS_POSIX)
322 g_log_file
= fopen(g_log_file_name
->c_str(), "a");
323 if (g_log_file
== nullptr)
331 void CloseFile(FileHandle log
) {
339 void CloseLogFileUnlocked() {
343 CloseFile(g_log_file
);
344 g_log_file
= nullptr;
349 LoggingSettings::LoggingSettings()
350 : logging_dest(LOG_DEFAULT
),
352 lock_log(LOCK_LOG_FILE
),
353 delete_old(APPEND_TO_OLD_LOG_FILE
) {}
355 bool BaseInitLoggingImpl(const LoggingSettings
& settings
) {
357 // Can log only to the system debug log.
358 CHECK_EQ(settings
.logging_dest
& ~LOG_TO_SYSTEM_DEBUG_LOG
, 0);
360 base::CommandLine
* command_line
= base::CommandLine::ForCurrentProcess();
361 // Don't bother initializing |g_vlog_info| unless we use one of the
363 if (command_line
->HasSwitch(switches::kV
) ||
364 command_line
->HasSwitch(switches::kVModule
)) {
365 // NOTE: If |g_vlog_info| has already been initialized, it might be in use
366 // by another thread. Don't delete the old VLogInfo, just create a second
367 // one. We keep track of both to avoid memory leak warnings.
368 CHECK(!g_vlog_info_prev
);
369 g_vlog_info_prev
= g_vlog_info
;
372 new VlogInfo(command_line
->GetSwitchValueASCII(switches::kV
),
373 command_line
->GetSwitchValueASCII(switches::kVModule
),
377 g_logging_destination
= settings
.logging_dest
;
379 // ignore file options unless logging to file is set.
380 if ((g_logging_destination
& LOG_TO_FILE
) == 0)
383 LoggingLock::Init(settings
.lock_log
, settings
.log_file
);
384 LoggingLock logging_lock
;
386 // Calling InitLogging twice or after some log call has already opened the
387 // default log file will re-initialize to the new options.
388 CloseLogFileUnlocked();
390 if (!g_log_file_name
)
391 g_log_file_name
= new PathString();
392 *g_log_file_name
= settings
.log_file
;
393 if (settings
.delete_old
== DELETE_OLD_LOG_FILE
)
394 DeleteFilePath(*g_log_file_name
);
396 return InitializeLogFileHandle();
399 void SetMinLogLevel(int level
) {
400 g_min_log_level
= std::min(LOG_FATAL
, level
);
403 int GetMinLogLevel() {
404 return g_min_log_level
;
407 int GetVlogVerbosity() {
408 return std::max(-1, LOG_INFO
- GetMinLogLevel());
411 int GetVlogLevelHelper(const char* file
, size_t N
) {
413 // Note: |g_vlog_info| may change on a different thread during startup
414 // (but will always be valid or nullptr).
415 VlogInfo
* vlog_info
= g_vlog_info
;
417 vlog_info
->GetVlogLevel(base::StringPiece(file
, N
- 1)) :
421 void SetLogItems(bool enable_process_id
, bool enable_thread_id
,
422 bool enable_timestamp
, bool enable_tickcount
) {
423 g_log_process_id
= enable_process_id
;
424 g_log_thread_id
= enable_thread_id
;
425 g_log_timestamp
= enable_timestamp
;
426 g_log_tickcount
= enable_tickcount
;
429 void SetShowErrorDialogs(bool enable_dialogs
) {
430 show_error_dialogs
= enable_dialogs
;
433 void SetLogAssertHandler(LogAssertHandlerFunction handler
) {
434 log_assert_handler
= handler
;
437 void SetLogMessageHandler(LogMessageHandlerFunction handler
) {
438 log_message_handler
= handler
;
441 LogMessageHandlerFunction
GetLogMessageHandler() {
442 return log_message_handler
;
445 // Explicit instantiations for commonly used comparisons.
446 template std::string
* MakeCheckOpString
<int, int>(
447 const int&, const int&, const char* names
);
448 template std::string
* MakeCheckOpString
<unsigned long, unsigned long>(
449 const unsigned long&, const unsigned long&, const char* names
);
450 template std::string
* MakeCheckOpString
<unsigned long, unsigned int>(
451 const unsigned long&, const unsigned int&, const char* names
);
452 template std::string
* MakeCheckOpString
<unsigned int, unsigned long>(
453 const unsigned int&, const unsigned long&, const char* names
);
454 template std::string
* MakeCheckOpString
<std::string
, std::string
>(
455 const std::string
&, const std::string
&, const char* name
);
458 // Displays a message box to the user with the error message in it.
459 // Used for fatal messages, where we close the app simultaneously.
460 // This is for developers only; we don't use this in circumstances
461 // (like release builds) where users could see it, since users don't
462 // understand these messages anyway.
463 void DisplayDebugMessageInDialog(const std::string
& str
) {
467 if (!show_error_dialogs
)
471 // For Windows programs, it's possible that the message loop is
472 // messed up on a fatal error, and creating a MessageBox will cause
473 // that message loop to be run. Instead, we try to spawn another
474 // process that displays its command line. We look for "Debug
475 // Message.exe" in the same directory as the application. If it
476 // exists, we use it, otherwise, we use a regular message box.
477 wchar_t prog_name
[MAX_PATH
];
478 GetModuleFileNameW(nullptr, prog_name
, MAX_PATH
);
479 wchar_t* backslash
= wcsrchr(prog_name
, '\\');
482 wcscat_s(prog_name
, MAX_PATH
, L
"debug_message.exe");
484 std::wstring cmdline
= base::UTF8ToWide(str
);
488 STARTUPINFO startup_info
;
489 memset(&startup_info
, 0, sizeof(startup_info
));
490 startup_info
.cb
= sizeof(startup_info
);
492 PROCESS_INFORMATION process_info
;
493 if (CreateProcessW(prog_name
, &cmdline
[0], nullptr, nullptr, false, 0,
494 nullptr, nullptr, &startup_info
, &process_info
)) {
495 WaitForSingleObject(process_info
.hProcess
, INFINITE
);
496 CloseHandle(process_info
.hThread
);
497 CloseHandle(process_info
.hProcess
);
499 // debug process broken, let's just do a message box
500 MessageBoxW(nullptr, &cmdline
[0], L
"Fatal error",
501 MB_OK
| MB_ICONHAND
| MB_TOPMOST
);
504 // We intentionally don't implement a dialog on other platforms.
505 // You can just look at stderr.
506 #endif // defined(OS_WIN)
508 #endif // !defined(NDEBUG)
511 LogMessage::SaveLastError::SaveLastError() : last_error_(::GetLastError()) {
514 LogMessage::SaveLastError::~SaveLastError() {
515 ::SetLastError(last_error_
);
517 #endif // defined(OS_WIN)
519 LogMessage::LogMessage(const char* file
, int line
, LogSeverity severity
)
520 : severity_(severity
), file_(file
), line_(line
) {
524 LogMessage::LogMessage(const char* file
, int line
, std::string
* result
)
525 : severity_(LOG_FATAL
), file_(file
), line_(line
) {
527 stream_
<< "Check failed: " << *result
;
531 LogMessage::LogMessage(const char* file
, int line
, LogSeverity severity
,
533 : severity_(severity
), file_(file
), line_(line
) {
535 stream_
<< "Check failed: " << *result
;
539 LogMessage::~LogMessage() {
540 #if !defined(NDEBUG) && !defined(OS_NACL) && !defined(__UCLIBC__)
541 if (severity_
== LOG_FATAL
) {
542 // Include a stack trace on a fatal.
543 base::debug::StackTrace trace
;
544 stream_
<< std::endl
; // Newline to separate from log message.
545 trace
.OutputToStream(&stream_
);
548 stream_
<< std::endl
;
549 std::string
str_newline(stream_
.str());
551 // Give any log message handler first dibs on the message.
552 if (log_message_handler
&&
553 log_message_handler(severity_
, file_
, line_
,
554 message_start_
, str_newline
)) {
555 // The handler took care of it, no further processing.
559 if ((g_logging_destination
& LOG_TO_SYSTEM_DEBUG_LOG
) != 0) {
561 OutputDebugStringA(str_newline
.c_str());
562 #elif defined(OS_ANDROID)
563 android_LogPriority priority
=
564 (severity_
< 0) ? ANDROID_LOG_VERBOSE
: ANDROID_LOG_UNKNOWN
;
567 priority
= ANDROID_LOG_INFO
;
570 priority
= ANDROID_LOG_WARN
;
573 priority
= ANDROID_LOG_ERROR
;
576 priority
= ANDROID_LOG_FATAL
;
579 __android_log_write(priority
, "chromium", str_newline
.c_str());
581 ignore_result(fwrite(str_newline
.data(), str_newline
.size(), 1, stderr
));
583 } else if (severity_
>= kAlwaysPrintErrorLevel
) {
584 // When we're only outputting to a log file, above a certain log level, we
585 // should still output to stderr so that we can better detect and diagnose
586 // problems with unit tests, especially on the buildbots.
587 ignore_result(fwrite(str_newline
.data(), str_newline
.size(), 1, stderr
));
592 if ((g_logging_destination
& LOG_TO_FILE
) != 0) {
593 // We can have multiple threads and/or processes, so try to prevent them
594 // from clobbering each other's writes.
595 // If the client app did not call InitLogging, and the lock has not
596 // been created do it now. We do this on demand, but if two threads try
597 // to do this at the same time, there will be a race condition to create
598 // the lock. This is why InitLogging should be called from the main
599 // thread at the beginning of execution.
600 LoggingLock::Init(LOCK_LOG_FILE
, nullptr);
601 LoggingLock logging_lock
;
602 if (InitializeLogFileHandle()) {
604 SetFilePointer(g_log_file
, 0, 0, SEEK_END
);
606 WriteFile(g_log_file
,
607 static_cast<const void*>(str_newline
.c_str()),
608 static_cast<DWORD
>(str_newline
.length()),
612 ignore_result(fwrite(
613 str_newline
.data(), str_newline
.size(), 1, g_log_file
));
619 if (severity_
== LOG_FATAL
) {
620 // Ensure the first characters of the string are on the stack so they
621 // are contained in minidumps for diagnostic purposes.
622 char str_stack
[1024];
623 str_newline
.copy(str_stack
, arraysize(str_stack
));
624 base::debug::Alias(str_stack
);
626 if (log_assert_handler
) {
627 // Make a copy of the string for the handler out of paranoia.
628 log_assert_handler(std::string(stream_
.str()));
630 // Don't use the string with the newline, get a fresh version to send to
631 // the debug message process. We also don't display assertions to the
632 // user in release mode. The enduser can't do anything with this
633 // information, and displaying message boxes when the application is
634 // hosed can cause additional problems.
636 DisplayDebugMessageInDialog(stream_
.str());
638 // Crash the process to generate a dump.
639 base::debug::BreakDebugger();
644 // writes the common header info to the stream
645 void LogMessage::Init(const char* file
, int line
) {
646 base::StringPiece
filename(file
);
647 size_t last_slash_pos
= filename
.find_last_of("\\/");
648 if (last_slash_pos
!= base::StringPiece::npos
)
649 filename
.remove_prefix(last_slash_pos
+ 1);
651 // TODO(darin): It might be nice if the columns were fixed width.
654 if (g_log_process_id
)
655 stream_
<< CurrentProcessId() << ':';
657 stream_
<< base::PlatformThread::CurrentId() << ':';
658 if (g_log_timestamp
) {
659 time_t t
= time(nullptr);
660 struct tm local_time
= {0};
662 localtime_s(&local_time
, &t
);
664 localtime_r(&t
, &local_time
);
666 struct tm
* tm_time
= &local_time
;
667 stream_
<< std::setfill('0')
668 << std::setw(2) << 1 + tm_time
->tm_mon
669 << std::setw(2) << tm_time
->tm_mday
671 << std::setw(2) << tm_time
->tm_hour
672 << std::setw(2) << tm_time
->tm_min
673 << std::setw(2) << tm_time
->tm_sec
677 stream_
<< TickCount() << ':';
679 stream_
<< log_severity_name(severity_
);
681 stream_
<< "VERBOSE" << -severity_
;
683 stream_
<< ":" << filename
<< "(" << line
<< ")] ";
685 message_start_
= stream_
.str().length();
689 // This has already been defined in the header, but defining it again as DWORD
690 // ensures that the type used in the header is equivalent to DWORD. If not,
691 // the redefinition is a compile error.
692 typedef DWORD SystemErrorCode
;
695 SystemErrorCode
GetLastSystemErrorCode() {
697 return ::GetLastError();
698 #elif defined(OS_POSIX)
701 #error Not implemented
706 BASE_EXPORT
std::string
SystemErrorCodeToString(SystemErrorCode error_code
) {
707 const int kErrorMessageBufferSize
= 256;
708 char msgbuf
[kErrorMessageBufferSize
];
709 DWORD flags
= FORMAT_MESSAGE_FROM_SYSTEM
| FORMAT_MESSAGE_IGNORE_INSERTS
;
710 DWORD len
= FormatMessageA(flags
, nullptr, error_code
, 0, msgbuf
,
711 arraysize(msgbuf
), nullptr);
713 // Messages returned by system end with line breaks.
714 return base::CollapseWhitespaceASCII(msgbuf
, true) +
715 base::StringPrintf(" (0x%X)", error_code
);
717 return base::StringPrintf("Error (0x%X) while retrieving error. (0x%X)",
718 GetLastError(), error_code
);
720 #elif defined(OS_POSIX)
721 BASE_EXPORT
std::string
SystemErrorCodeToString(SystemErrorCode error_code
) {
722 return safe_strerror(error_code
);
725 #error Not implemented
726 #endif // defined(OS_WIN)
730 Win32ErrorLogMessage::Win32ErrorLogMessage(const char* file
,
732 LogSeverity severity
,
735 log_message_(file
, line
, severity
) {
738 Win32ErrorLogMessage::~Win32ErrorLogMessage() {
739 stream() << ": " << SystemErrorCodeToString(err_
);
740 // We're about to crash (CHECK). Put |err_| on the stack (by placing it in a
741 // field) and use Alias in hopes that it makes it into crash dumps.
742 DWORD last_error
= err_
;
743 base::debug::Alias(&last_error
);
745 #elif defined(OS_POSIX)
746 ErrnoLogMessage::ErrnoLogMessage(const char* file
,
748 LogSeverity severity
,
751 log_message_(file
, line
, severity
) {
754 ErrnoLogMessage::~ErrnoLogMessage() {
755 stream() << ": " << SystemErrorCodeToString(err_
);
757 #endif // defined(OS_WIN)
759 void CloseLogFile() {
760 LoggingLock logging_lock
;
761 CloseLogFileUnlocked();
764 void RawLog(int level
, const char* message
) {
765 if (level
>= g_min_log_level
) {
766 size_t bytes_written
= 0;
767 const size_t message_len
= strlen(message
);
769 while (bytes_written
< message_len
) {
771 write(STDERR_FILENO
, message
+ bytes_written
,
772 message_len
- bytes_written
));
774 // Give up, nothing we can do now.
780 if (message_len
> 0 && message
[message_len
- 1] != '\n') {
782 rv
= HANDLE_EINTR(write(STDERR_FILENO
, "\n", 1));
784 // Give up, nothing we can do now.
791 if (level
== LOG_FATAL
)
792 base::debug::BreakDebugger();
795 // This was defined at the beginning of this file.
799 std::wstring
GetLogFileFullPath() {
801 return *g_log_file_name
;
802 return std::wstring();
806 } // namespace logging
808 std::ostream
& std::operator<<(std::ostream
& out
, const wchar_t* wstr
) {
809 return out
<< base::WideToUTF8(wstr
);