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. 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 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 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 154 void SetMinLogLevel(int level) { 155 min_log_level = level; 156 } 157 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 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 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. 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 227 LogMessage::LogMessage(const char* file, int line, LogSeverity severity, 228 int ctr) 229 : severity_(severity) { 230 Init(file, line); 231 } 232 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 239 LogMessage::LogMessage(const char* file, int line) 240 : severity_(LOG_INFO) { 241 Init(file, line); 242 } 243 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 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 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 356 void CloseLogFile() { 357 if (!log_file) 358 return; 359 360 CloseHandle(log_file); 361 log_file = NULL; 362 } 363 364 } // namespace logging 365 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