Home | History | Annotate | Download | only in base
      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