1 // Copyright 2007, Google Inc.
2 // All rights reserved.
3 //
4 // Redistribution and use in source and binary forms, with or without
5 // modification, are permitted provided that the following conditions are
6 // met:
7 //
8 // * Redistributions of source code must retain the above copyright
9 // notice, this list of conditions and the following disclaimer.
10 // * Redistributions in binary form must reproduce the above
11 // copyright notice, this list of conditions and the following disclaimer
12 // in the documentation and/or other materials provided with the
13 // distribution.
14 // * Neither the name of Google Inc. nor the names of its
15 // contributors may be used to endorse or promote products derived from
16 // this software without specific prior written permission.
17 //
18 // THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
19 // "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
20 // LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
21 // A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
22 // OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
23 // SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
24 // LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
25 // DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
26 // THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
27 // (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
28 // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
29
30 #include <ctime>
31 #include <iomanip>
32 #include <cstring>
33 #include <windows.h>
34 #include <tchar.h>
35 #include <algorithm>
36 #include "base/logging.h"
37
38 namespace logging {
39
40 const char* const log_severity_names[LOG_NUM_SEVERITIES] = {
41 "INFO", "WARNING", "ERROR", "FATAL" };
42
43 int min_log_level = 0;
44 LogLockingState lock_log_file = LOCK_LOG_FILE;
45 LoggingDestination logging_destination = LOG_ONLY_TO_FILE;
46
47 const int kMaxFilteredLogLevel = LOG_WARNING;
48 char* log_filter_prefix = NULL;
49
50 // which log file to use? This is initialized by InitLogging or
51 // will be lazily initialized to the default value when it is
52 // first needed.
53 TCHAR log_file_name[MAX_PATH] = { 0 };
54
55 // this file is lazily opened and the handle may be NULL
56 HANDLE log_file = NULL;
57
58 // what should be prepended to each message?
59 bool log_process_id = false;
60 bool log_thread_id = false;
61 bool log_timestamp = true;
62 bool log_tickcount = false;
63
64 // An assert handler override specified by the client to be called instead of
65 // the debug message dialog.
66 LogAssertHandlerFunction log_assert_handler = NULL;
67
68 // The critical section is used if log file locking is false. It helps us
69 // avoid problems with multiple threads writing to the log file at the same
70 // time.
71 bool initialized_critical_section = false;
72 CRITICAL_SECTION log_critical_section;
73
74 // When we don't use a critical section, we are using a global mutex. We
75 // need to do this because LockFileEx is not thread safe
76 HANDLE log_mutex = NULL;
77
78 // Called by logging functions to ensure that debug_file is initialized
79 // and can be used for writing. Returns false if the file could not be
80 // initialized. debug_file will be NULL in this case.
InitializeLogFileHandle()81 bool InitializeLogFileHandle() {
82 if (log_file)
83 return true;
84
85 if (!log_file_name[0]) {
86 // nobody has called InitLogging to specify a debug log file, so here we
87 // initialize the log file name to the default
88 GetModuleFileName(NULL, log_file_name, MAX_PATH);
89 TCHAR* last_backslash = _tcsrchr(log_file_name, '\\');
90 if (last_backslash)
91 last_backslash[1] = 0; // name now ends with the backslash
92 _tcscat_s(log_file_name, _T("debug.log"));
93 }
94
95 log_file = CreateFile(log_file_name, GENERIC_WRITE,
96 FILE_SHARE_READ | FILE_SHARE_WRITE, NULL,
97 OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL);
98 if (log_file == INVALID_HANDLE_VALUE || log_file == NULL) {
99 // try the current directory
100 log_file = CreateFile(_T(".\\debug.log"), GENERIC_WRITE,
101 FILE_SHARE_READ | FILE_SHARE_WRITE, NULL,
102 OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL);
103 if (log_file == INVALID_HANDLE_VALUE || log_file == NULL) {
104 log_file = NULL;
105 return false;
106 }
107 }
108 SetFilePointer(log_file, 0, 0, FILE_END);
109 return true;
110 }
111
InitLogMutex()112 void InitLogMutex() {
113 if (!log_mutex) {
114 // \ is not a legal character in mutex names so we replace \ with /
115 std::wstring safe_name(log_file_name);
116 std::replace(safe_name.begin(), safe_name.end(), '\\', '/');
117 std::wstring t(L"Global\\");
118 t.append(safe_name);
119 log_mutex = ::CreateMutex(NULL, FALSE, t.c_str());
120 }
121 }
122
InitLogging(const TCHAR * new_log_file,LoggingDestination logging_dest,LogLockingState lock_log,OldFileDeletionState delete_old)123 void InitLogging(const TCHAR* new_log_file, LoggingDestination logging_dest,
124 LogLockingState lock_log, OldFileDeletionState delete_old) {
125 if (log_file) {
126 // calling InitLogging twice or after some log call has already opened the
127 // default log file will re-initialize to the new options
128 CloseHandle(log_file);
129 log_file = NULL;
130 }
131
132 lock_log_file = lock_log;
133 logging_destination = logging_dest;
134
135 // ignore file options if logging is only to system
136 if (logging_destination == LOG_ONLY_TO_SYSTEM_DEBUG_LOG)
137 return;
138
139 _tcscpy_s(log_file_name, MAX_PATH, new_log_file);
140 if (delete_old == DELETE_OLD_LOG_FILE)
141 DeleteFile(log_file_name);
142
143 if (lock_log_file == LOCK_LOG_FILE) {
144 InitLogMutex();
145 } else if (!initialized_critical_section) {
146 // initialize the critical section
147 InitializeCriticalSection(&log_critical_section);
148 initialized_critical_section = true;
149 }
150
151 InitializeLogFileHandle();
152 }
153
SetMinLogLevel(int level)154 void SetMinLogLevel(int level) {
155 min_log_level = level;
156 }
157
SetLogFilterPrefix(char * filter)158 void SetLogFilterPrefix(char* filter) {
159 if (log_filter_prefix) {
160 delete[] log_filter_prefix;
161 log_filter_prefix = NULL;
162 }
163
164 if (filter) {
165 size_t size = strlen(filter)+1;
166 log_filter_prefix = new char[size];
167 strcpy_s(log_filter_prefix, size, filter);
168 }
169 }
170
SetLogItems(bool enable_process_id,bool enable_thread_id,bool enable_timestamp,bool enable_tickcount)171 void SetLogItems(bool enable_process_id, bool enable_thread_id,
172 bool enable_timestamp, bool enable_tickcount) {
173 log_process_id = enable_process_id;
174 log_thread_id = enable_thread_id;
175 log_timestamp = enable_timestamp;
176 log_tickcount = enable_tickcount;
177 }
178
SetLogAssertHandler(LogAssertHandlerFunction handler)179 void SetLogAssertHandler(LogAssertHandlerFunction handler) {
180 log_assert_handler = handler;
181 }
182
183 // Displays a message box to the user with the error message in it. For
184 // Windows programs, it's possible that the message loop is messed up on
185 // a fatal error, and creating a MessageBox will cause that message loop
186 // to be run. Instead, we try to spawn another process that displays its
187 // command line. We look for "Debug Message.exe" in the same directory as
188 // the application. If it exists, we use it, otherwise, we use a regular
189 // message box.
DisplayDebugMessage(const std::string & str)190 void DisplayDebugMessage(const std::string& str) {
191 if (str.empty())
192 return;
193
194 // look for the debug dialog program next to our application
195 wchar_t prog_name[MAX_PATH];
196 GetModuleFileNameW(NULL, prog_name, MAX_PATH);
197 wchar_t* backslash = wcsrchr(prog_name, '\\');
198 if (backslash)
199 backslash[1] = 0;
200 wcscat_s(prog_name, MAX_PATH, L"debug_message.exe");
201
202 // stupid CreateProcess requires a non-const command line and may modify it.
203 // We also want to use the wide string
204 int charcount = MultiByteToWideChar(CP_UTF8, 0, str.c_str(), -1, NULL, 0);
205 if (!charcount)
206 return;
207 scoped_array<wchar_t> cmdline(new wchar_t[charcount]);
208 if (!MultiByteToWideChar(CP_UTF8, 0, str.c_str(), -1, cmdline.get(), charcount))
209 return;
210
211 STARTUPINFO startup_info;
212 memset(&startup_info, 0, sizeof(startup_info));
213 startup_info.cb = sizeof(startup_info);
214
215 PROCESS_INFORMATION process_info;
216 if (CreateProcessW(prog_name, cmdline.get(), NULL, NULL, false, 0, NULL,
217 NULL, &startup_info, &process_info)) {
218 WaitForSingleObject(process_info.hProcess, INFINITE);
219 CloseHandle(process_info.hThread);
220 CloseHandle(process_info.hProcess);
221 } else {
222 // debug process broken, let's just do a message box
223 MessageBoxW(NULL, cmdline.get(), L"Fatal error", MB_OK | MB_ICONHAND);
224 }
225 }
226
LogMessage(const char * file,int line,LogSeverity severity,int ctr)227 LogMessage::LogMessage(const char* file, int line, LogSeverity severity,
228 int ctr)
229 : severity_(severity) {
230 Init(file, line);
231 }
232
LogMessage(const char * file,int line,const CheckOpString & result)233 LogMessage::LogMessage(const char* file, int line, const CheckOpString& result)
234 : severity_(LOG_FATAL) {
235 Init(file, line);
236 stream_ << "Check failed: " << (*result.str_);
237 }
238
LogMessage(const char * file,int line)239 LogMessage::LogMessage(const char* file, int line)
240 : severity_(LOG_INFO) {
241 Init(file, line);
242 }
243
LogMessage(const char * file,int line,LogSeverity severity)244 LogMessage::LogMessage(const char* file, int line, LogSeverity severity)
245 : severity_(severity) {
246 Init(file, line);
247 }
248
249 // writes the common header info to the stream
Init(const char * file,int line)250 void LogMessage::Init(const char* file, int line) {
251 // log only the filename
252 const char* last_slash = strrchr(file, '\\');
253 if (last_slash)
254 file = last_slash + 1;
255
256 stream_ << '[';
257 if (log_process_id)
258 stream_ << GetCurrentProcessId() << ':';
259 if (log_thread_id)
260 stream_ << GetCurrentThreadId() << ':';
261 if (log_timestamp) {
262 time_t t = time(NULL);
263 struct tm tm_time;
264 localtime_s(&tm_time, &t);
265 stream_ << std::setfill('0')
266 << std::setw(2) << 1 + tm_time.tm_mon
267 << std::setw(2) << tm_time.tm_mday
268 << '/'
269 << std::setw(2) << tm_time.tm_hour
270 << std::setw(2) << tm_time.tm_min
271 << std::setw(2) << tm_time.tm_sec
272 << ':';
273 }
274 if (log_tickcount)
275 stream_ << GetTickCount() << ':';
276 stream_ << log_severity_names[severity_] << ":" << file << "(" << line << ")] ";
277
278 message_start_ = stream_.pcount();
279 }
280
~LogMessage()281 LogMessage::~LogMessage() {
282 if (severity_ < min_log_level)
283 return;
284
285 std::string str_newline(stream_.str(), stream_.pcount());
286 str_newline.append("\r\n");
287
288 if (log_filter_prefix && severity_ <= kMaxFilteredLogLevel &&
289 str_newline.compare(message_start_, strlen(log_filter_prefix),
290 log_filter_prefix) != 0) {
291 goto cleanup;
292 }
293
294 if (logging_destination != LOG_ONLY_TO_FILE)
295 OutputDebugStringA(str_newline.c_str());
296
297 // write to log file
298 if (logging_destination != LOG_ONLY_TO_SYSTEM_DEBUG_LOG &&
299 InitializeLogFileHandle()) {
300 // we can have multiple threads and/or processes, so try to prevent them from
301 // clobbering each other's writes
302 if (lock_log_file == LOCK_LOG_FILE) {
303 // Ensure that the mutex is initialized in case the client app did not
304 // call InitLogging. This is not thread safe. See below
305 InitLogMutex();
306
307 DWORD r = ::WaitForSingleObject(log_mutex, INFINITE);
308 DCHECK(r != WAIT_ABANDONED);
309 } else {
310 // use the critical section
311 if (!initialized_critical_section) {
312 // The client app did not call InitLogging, and so the critical section
313 // has not been created. We do this on demand, but if two threads try to
314 // do this at the same time, there will be a race condition to create
315 // the critical section. This is why InitLogging should be called from
316 // the main thread at the beginning of execution.
317 InitializeCriticalSection(&log_critical_section);
318 initialized_critical_section = true;
319 }
320 EnterCriticalSection(&log_critical_section);
321 }
322
323 SetFilePointer(log_file, 0, 0, SEEK_END);
324 DWORD num_written;
325 WriteFile(log_file, (void*)str_newline.c_str(), (DWORD)str_newline.length(), &num_written, NULL);
326
327 if (lock_log_file == LOCK_LOG_FILE) {
328 ReleaseMutex(log_mutex);
329 } else {
330 LeaveCriticalSection(&log_critical_section);
331 }
332 }
333
334 if (severity_ == LOG_FATAL) {
335 // display a message or break into the debugger on a fatal error
336 if (::IsDebuggerPresent()) {
337 DebugBreak();
338 } else {
339 if (log_assert_handler) {
340 log_assert_handler(std::string(stream_.str(), stream_.pcount()));
341 } else {
342 // don't use the string with the newline, get a fresh version to send to
343 // the debug message process
344 DisplayDebugMessage(std::string(stream_.str(), stream_.pcount()));
345 TerminateProcess(GetCurrentProcess(), 1);
346 }
347 }
348 }
349
350 cleanup:
351 // Calling stream_.str() freezes the stream buffer. A frozen buffer will
352 // not be freed during strstreambuf destruction.
353 stream_.freeze(false);
354 }
355
CloseLogFile()356 void CloseLogFile() {
357 if (!log_file)
358 return;
359
360 CloseHandle(log_file);
361 log_file = NULL;
362 }
363
364 } // namespace logging
365
operator <<(std::ostream & out,const wchar_t * wstr)366 std::ostream& operator<<(std::ostream& out, const wchar_t* wstr) {
367 if (!wstr || !wstr[0])
368 return out;
369
370 // compute the length of the buffer we'll need
371 int charcount = WideCharToMultiByte(CP_UTF8, 0, wstr, -1,
372 NULL, 0, NULL, NULL);
373 if (charcount == 0)
374 return out;
375
376 // convert
377 scoped_array<char> buf(new char[charcount]);
378 WideCharToMultiByte(CP_UTF8, 0, wstr, -1, buf.get(), charcount, NULL, NULL);
379 return out << buf.get();
380 }
381