src/utilcode/log.cpp

   1 // Licensed to the .NET Foundation under one or more agreements.
   2 // The .NET Foundation licenses this file to you under the MIT license.
   3 // See the LICENSE file in the project root for more information.
   4
   5 //
   6 // Simple Logging Facility
   7 //
   8 #include "stdafx.h"
   9
  10 //
  11 // Define LOGGING by default in a checked build. If you want to log in a free
  12 // build, define logging independent of _DEBUG here and each place you want
  13 // to use it.
  14 //
  15 #ifdef _DEBUG
  16 #define LOGGING
  17 #endif
  18
  19 #include "log.h"
  20 #include "utilcode.h"
  21
  22 #ifdef LOGGING
  23
  24 #define DEFAULT_LOGFILE_NAME    W("COMPLUS.LOG")
  25
  26 #define LOG_ENABLE_FILE_LOGGING         0x0001
  27 #define LOG_ENABLE_FLUSH_FILE           0x0002
  28 #define LOG_ENABLE_CONSOLE_LOGGING      0x0004
  29 #define LOG_ENABLE_APPEND_FILE          0x0010
  30 #define LOG_ENABLE_DEBUGGER_LOGGING     0x0020
  31 #define LOG_ENABLE                      0x0040
  32
  33
  34 static DWORD    LogFlags                    = 0;
  35 static CQuickWSTR     szLogFileName;
  36 static HANDLE   LogFileHandle               = INVALID_HANDLE_VALUE;
  37 static MUTEX_COOKIE   LogFileMutex                = 0;
  38 static DWORD    LogFacilityMask             = LF_ALL;
  39 static DWORD    LogFacilityMask2            = 0;
  40 static DWORD    LogVMLevel                  = LL_INFO100;
  41         // <TODO>@todo FIX should probably only display warnings and above by default</TODO>
  42
  43
  44 VOID InitLogging()
  45 {
  46     STATIC_CONTRACT_NOTHROW;
  47
  48         // <TODO>FIX bit of a workaround for now, check for the log file in the
  49         // registry and if there, turn on file logging VPM</TODO>
  50
  51     LogFlags |= REGUTIL::GetConfigFlag_DontUse_(CLRConfig::INTERNAL_LogEnable, LOG_ENABLE);
  52     LogFacilityMask = REGUTIL::GetConfigDWORD_DontUse_(CLRConfig::INTERNAL_LogFacility, LogFacilityMask) | LF_ALWAYS;
  53     LogVMLevel = REGUTIL::GetConfigDWORD_DontUse_(CLRConfig::EXTERNAL_LogLevel, LogVMLevel);
  54     LogFlags |= REGUTIL::GetConfigFlag_DontUse_(CLRConfig::INTERNAL_LogFileAppend, LOG_ENABLE_APPEND_FILE);
  55     LogFlags |= REGUTIL::GetConfigFlag_DontUse_(CLRConfig::INTERNAL_LogFlushFile,  LOG_ENABLE_FLUSH_FILE);
  56     LogFlags |= REGUTIL::GetConfigFlag_DontUse_(CLRConfig::INTERNAL_LogToDebugger, LOG_ENABLE_DEBUGGER_LOGGING);
  57     LogFlags |= REGUTIL::GetConfigFlag_DontUse_(CLRConfig::INTERNAL_LogToFile,     LOG_ENABLE_FILE_LOGGING);
  58     LogFlags |= REGUTIL::GetConfigFlag_DontUse_(CLRConfig::INTERNAL_LogToConsole,  LOG_ENABLE_CONSOLE_LOGGING);
  59
  60     LogFacilityMask2 = REGUTIL::GetConfigDWORD_DontUse_(CLRConfig::INTERNAL_LogFacility2, LogFacilityMask2) | LF_ALWAYS;
  61
  62     if (SUCCEEDED(szLogFileName.ReSizeNoThrow(MAX_LONGPATH)))
  63     {
  64         wcscpy_s(szLogFileName.Ptr(), szLogFileName.Size(), DEFAULT_LOGFILE_NAME);
  65     }
  66
  67     LPWSTR fileName = CLRConfig::GetConfigValue(CLRConfig::INTERNAL_LogFile);
  68     if (fileName != 0)
  69     {
  70         if (SUCCEEDED(szLogFileName.ReSizeNoThrow(wcslen(fileName) + 32)))
  71         {
  72             wcscpy_s(szLogFileName.Ptr(), szLogFileName.Size(), fileName);
  73         }
  74         delete fileName;
  75     }
  76
  77     if (REGUTIL::GetConfigDWORD_DontUse_(CLRConfig::INTERNAL_LogWithPid, FALSE))
  78     {
  79         WCHAR szPid[20];
  80         swprintf_s(szPid, COUNTOF(szPid), W(".%d"), GetCurrentProcessId());
  81         wcscat_s(szLogFileName.Ptr(), szLogFileName.Size(), szPid);
  82     }
  83
  84     if ((LogFlags & LOG_ENABLE) &&
  85         (LogFlags & LOG_ENABLE_FILE_LOGGING) &&
  86         (szLogFileName.Size() > 0) &&
  87         (LogFileHandle == INVALID_HANDLE_VALUE))
  88     {
  89         DWORD fdwCreate = (LogFlags & LOG_ENABLE_APPEND_FILE) ? OPEN_ALWAYS : CREATE_ALWAYS;
  90         LogFileHandle = WszCreateFile(
  91             szLogFileName.Ptr(),
  92             GENERIC_WRITE,
  93             FILE_SHARE_READ,
  94             NULL,
  95             fdwCreate,
  96             FILE_ATTRIBUTE_NORMAL | FILE_FLAG_SEQUENTIAL_SCAN |  ((LogFlags & LOG_ENABLE_FLUSH_FILE) ? FILE_FLAG_WRITE_THROUGH : 0),
  97             NULL);
  98
  99         if(0 == LogFileMutex)
 100         {
 101             LogFileMutex = ClrCreateMutex(
 102                 NULL,
 103                 FALSE,
 104                 NULL);
 105             _ASSERTE(LogFileMutex != 0);
 106         }
 107
 108             // Some other logging may be going on, try again with another file name
 109         if (LogFileHandle == INVALID_HANDLE_VALUE && wcslen(szLogFileName.Ptr()) + 3 <= szLogFileName.Size())
 110         {
 111             WCHAR* ptr = szLogFileName.Ptr() + wcslen(szLogFileName.Ptr()) + 1;
 112             ptr[-1] = W('.');
 113             ptr[0] = W('0');
 114             ptr[1] = 0;
 115
 116             for(int i = 0; i < 10; i++)
 117             {
 118                 LogFileHandle = WszCreateFile(
 119                     szLogFileName.Ptr(),
 120                     GENERIC_WRITE,
 121                     FILE_SHARE_READ,
 122                     NULL,
 123                     fdwCreate,
 124                     FILE_ATTRIBUTE_NORMAL | FILE_FLAG_SEQUENTIAL_SCAN |  ((LogFlags & LOG_ENABLE_FLUSH_FILE) ? FILE_FLAG_WRITE_THROUGH : 0),
 125                     NULL);
 126                 if (LogFileHandle != INVALID_HANDLE_VALUE)
 127                     break;
 128                 *ptr = *ptr + 1;
 129             }
 130             if (LogFileHandle == INVALID_HANDLE_VALUE) {
 131                 int ret = WszWideCharToMultiByte(CP_ACP, 0, szLogFileName.Ptr(), -1, NULL, 0, NULL, NULL);
 132                 const char *msg = "Could not open log file, logging to ";
 133                 DWORD msgLen = (DWORD)strlen(msg);
 134                 CQuickSTR buff;
 135                 if (SUCCEEDED(buff.ReSizeNoThrow(ret + msgLen)))
 136                 {
 137                     strcpy_s(buff.Ptr(), buff.Size(), msg);
 138                     WszWideCharToMultiByte(CP_ACP, 0, szLogFileName.Ptr(), -1, buff.Ptr() + msgLen, ret, NULL, NULL);
 139                     msg = buff.Ptr();
 140                 }
 141                 else
 142                 {
 143                     msg = "Could not open log file";
 144                 }
 145                 DWORD       written;
 146                 WriteFile(GetStdHandle(STD_OUTPUT_HANDLE), msg, (DWORD)strlen(msg), &written, 0);
 147             }
 148         }
 149         if (LogFileHandle == INVALID_HANDLE_VALUE)
 150             UtilMessageBoxNonLocalized(NULL, W("Could not open log file"), W("CLR logging"), MB_OK | MB_ICONINFORMATION, FALSE, TRUE);
 151         if (LogFileHandle != INVALID_HANDLE_VALUE)
 152         {
 153             if (LogFlags & LOG_ENABLE_APPEND_FILE)
 154                 SetFilePointer(LogFileHandle, 0, NULL, FILE_END);
 155             LogSpew( LF_ALWAYS, FATALERROR, "************************ New Output *****************\n" );
 156         }
 157     }
 158 }
 159
 160 VOID EnterLogLock()
 161 {
 162     STATIC_CONTRACT_NOTHROW;
 163     STATIC_CONTRACT_GC_NOTRIGGER;
 164
 165     // We don't care about violating CANNOT_TAKE_LOCK in debug-only builds, and it's
 166     // rather hard to care about this, as we LOG all over the place.
 167     CONTRACT_VIOLATION(TakesLockViolation);
 168
 169     if(LogFileMutex != 0)
 170     {
 171         DWORD status;
 172         status = ClrWaitForMutex(LogFileMutex, INFINITE, FALSE);
 173         _ASSERTE(WAIT_OBJECT_0 == status);
 174     }
 175 }
 176
 177 VOID LeaveLogLock()
 178 {
 179     STATIC_CONTRACT_NOTHROW;
 180     STATIC_CONTRACT_GC_NOTRIGGER;
 181
 182     if(LogFileMutex != 0)
 183     {
 184         BOOL success;
 185         success = ClrReleaseMutex(LogFileMutex);
 186         _ASSERTE(success);
 187     }
 188 }
 189
 190 static bool bLoggingInitialized = false;
 191 VOID InitializeLogging()
 192 {
 193     STATIC_CONTRACT_NOTHROW;
 194
 195     if (bLoggingInitialized)
 196         return;
 197     bLoggingInitialized = true;
 198
 199     InitLogging();      // You can call this in the debugger to fetch new settings
 200 }
 201
 202 VOID FlushLogging() {
 203     STATIC_CONTRACT_NOTHROW;
 204
 205     if (LogFileHandle != INVALID_HANDLE_VALUE)
 206     {
 207         // We must take the lock, as an OS deadlock can occur between
 208         // FlushFileBuffers and WriteFile.
 209         EnterLogLock();
 210         FlushFileBuffers( LogFileHandle );
 211         LeaveLogLock();
 212     }
 213 }
 214
 215 VOID ShutdownLogging()
 216 {
 217     STATIC_CONTRACT_NOTHROW;
 218
 219     if (LogFileHandle != INVALID_HANDLE_VALUE) {
 220         LogSpew( LF_ALWAYS, FATALERROR, "Logging shutting down\n");
 221         CloseHandle( LogFileHandle );
 222     }
 223     LogFileHandle = INVALID_HANDLE_VALUE;
 224     bLoggingInitialized = false;
 225 }
 226
 227
 228 bool LoggingEnabled()
 229 {
 230     STATIC_CONTRACT_LEAF;
 231
 232     return ((LogFlags & LOG_ENABLE) != 0);
 233 }
 234
 235
 236 bool LoggingOn(DWORD facility, DWORD level) {
 237     STATIC_CONTRACT_LEAF;
 238
 239     _ASSERTE(LogFacilityMask & LF_ALWAYS); // LF_ALWAYS should always be enabled
 240
 241     return((LogFlags & LOG_ENABLE) &&
 242            level <= LogVMLevel &&
 243            (facility & LogFacilityMask));
 244 }
 245
 246 bool Logging2On(DWORD facility2, DWORD level) {
 247     STATIC_CONTRACT_LEAF;
 248
 249     _ASSERTE(LogFacilityMask2 & LF_ALWAYS); // LF_ALWAYS should always be enabled
 250
 251     return((LogFlags & LOG_ENABLE) &&
 252            level <= LogVMLevel &&
 253            (facility2 & LogFacilityMask2));
 254 }
 255
 256 //
 257 // Don't use me directly, use the macros in log.h
 258 //
 259 VOID LogSpewValist(DWORD facility, DWORD level, const char *fmt, va_list args)
 260 {
 261     SCAN_IGNORE_FAULT;  // calls to new (nothrow) in logging code are OK
 262     STATIC_CONTRACT_NOTHROW;
 263     STATIC_CONTRACT_GC_NOTRIGGER;
 264
 265     if (!LoggingOn(facility, level))
 266         return;
 267
 268     DEBUG_ONLY_FUNCTION;
 269
 270     LogSpewAlwaysValist(fmt, args);
 271 }
 272
 273
 274 VOID LogSpew2Valist(DWORD facility2, DWORD level, const char *fmt, va_list args)
 275 {
 276     SCAN_IGNORE_FAULT;  // calls to new (nothrow) in logging code are OK
 277     STATIC_CONTRACT_NOTHROW;
 278     STATIC_CONTRACT_GC_NOTRIGGER;
 279
 280     if (!Logging2On(facility2, level))
 281         return;
 282
 283     DEBUG_ONLY_FUNCTION;
 284
 285     LogSpewAlwaysValist(fmt, args);
 286 }
 287
 288
 289 VOID LogSpewAlwaysValist(const char *fmt, va_list args)
 290 {
 291     SCAN_IGNORE_FAULT;  // calls to new (nothrow) in logging code are OK
 292     STATIC_CONTRACT_NOTHROW;
 293     STATIC_CONTRACT_GC_NOTRIGGER;
 294
 295     DEBUG_ONLY_FUNCTION;
 296
 297     // We can't do heap allocations at all.  The current thread may have
 298     // suspended another thread, and the suspended thread may be inside of the
 299     // heap lock.
 300     //
 301     // (Some historical comments:)
 302     //
 303     // We must operate with a very small stack (in case we're logging durring
 304     // a stack overflow)
 305     //
 306     // We're going to bypass our debug memory allocator and just allocate memory from
 307     // the process heap. Why? Because our debug memory allocator will log out of memory
 308     // conditions. If we're low on memory, and we try to log an out of memory condition, and we try
 309     // and allocate memory again using the debug allocator, we could (and probably will) hit
 310     // another low memory condition, try to log it, and we spin indefinately until we hit a stack overflow.
 311
 312     const int BUFFERSIZE = 1000;
 313     static char rgchBuffer[BUFFERSIZE];
 314
 315     EnterLogLock();
 316
 317     char *  pBuffer      = &rgchBuffer[0];
 318     DWORD       buflen       = 0;
 319     DWORD       written;
 320
 321     static bool needsPrefix = true;
 322
 323     if (needsPrefix)
 324         buflen = sprintf_s(pBuffer, COUNTOF(rgchBuffer), "TID %04x: ", GetCurrentThreadId());
 325
 326     needsPrefix = (fmt[strlen(fmt)-1] == '\n');
 327
 328     int cCountWritten = _vsnprintf_s(&pBuffer[buflen], BUFFERSIZE-buflen, _TRUNCATE, fmt, args );
 329     pBuffer[BUFFERSIZE-1] = 0;
 330     if (cCountWritten < 0) {
 331         buflen = BUFFERSIZE - 1;
 332     } else {
 333         buflen += cCountWritten;
 334     }
 335
 336     // Its a little late for this, but at least you wont continue
 337     // trashing your program...
 338     _ASSERTE((buflen < (DWORD) BUFFERSIZE) && "Log text is too long!") ;
 339
 340 #if !PLATFORM_UNIX
 341     //convert NL's to CR NL to fixup notepad
 342     const int BUFFERSIZE2 = BUFFERSIZE + 500;
 343     char rgchBuffer2[BUFFERSIZE2];
 344     char * pBuffer2 = &rgchBuffer2[0];
 345
 346     char *d = pBuffer2;
 347     for (char *p = pBuffer; *p != '\0'; p++)
 348     {
 349         if (*p == '\n') {
 350             _ASSERTE(d < pBuffer2 + BUFFERSIZE2);
 351             *(d++) = '\r';
 352         }
 353
 354         _ASSERTE(d < pBuffer2 + BUFFERSIZE2);
 355         *(d++) = *p;
 356     }
 357     *d = 0;
 358
 359     buflen = (DWORD)(d - pBuffer2);
 360     pBuffer = pBuffer2;
 361 #endif // PLATFORM_UNIX
 362
 363     if (LogFlags & LOG_ENABLE_FILE_LOGGING && LogFileHandle != INVALID_HANDLE_VALUE)
 364     {
 365         WriteFile(LogFileHandle, pBuffer, buflen, &written, NULL);
 366         if (LogFlags & LOG_ENABLE_FLUSH_FILE) {
 367             FlushFileBuffers( LogFileHandle );
 368         }
 369     }
 370
 371     if (LogFlags & LOG_ENABLE_CONSOLE_LOGGING)
 372     {
 373         WriteFile(GetStdHandle(STD_OUTPUT_HANDLE), pBuffer, buflen, &written, 0);
 374         //<TODO>@TODO ...Unnecessary to flush console?</TODO>
 375         if (LogFlags & LOG_ENABLE_FLUSH_FILE)
 376             FlushFileBuffers( GetStdHandle(STD_OUTPUT_HANDLE) );
 377     }
 378
 379     if (LogFlags & LOG_ENABLE_DEBUGGER_LOGGING)
 380     {
 381         OutputDebugStringA(pBuffer);
 382     }
 383
 384     LeaveLogLock();
 385 }
 386
 387 VOID LogSpew(DWORD facility, DWORD level, const char *fmt, ... )
 388 {
 389     STATIC_CONTRACT_WRAPPER;
 390
 391 #ifdef SELF_NO_HOST
 392     if (TRUE)
 393 #else //!SELF_NO_HOST
 394     if (CanThisThreadCallIntoHost())
 395 #endif //!SELF_NO_HOST
 396     {
 397         va_list     args;
 398         va_start(args, fmt);
 399         LogSpewValist (facility, level, fmt, args);
 400         va_end(args);
 401     }
 402     else
 403     {
 404         // Cannot acquire the required lock, as this would call back
 405         // into the host.  Eat the log message.
 406     }
 407 }
 408
 409 VOID LogSpew2(DWORD facility2, DWORD level, const char *fmt, ... )
 410 {
 411     STATIC_CONTRACT_WRAPPER;
 412
 413 #ifdef SELF_NO_HOST
 414     if (TRUE)
 415 #else //!SELF_NO_HOST
 416     if (CanThisThreadCallIntoHost())
 417 #endif //!SELF_NO_HOST
 418     {
 419         va_list     args;
 420         va_start(args, fmt);
 421         LogSpew2Valist(facility2, level, fmt, args);
 422         va_end(args);
 423     }
 424     else
 425     {
 426         // Cannot acquire the required lock, as this would call back
 427         // into the host.  Eat the log message.
 428     }
 429 }
 430
 431 VOID LogSpewAlways (const char *fmt, ... )
 432 {
 433     STATIC_CONTRACT_WRAPPER;
 434
 435 #ifdef SELF_NO_HOST
 436     if (TRUE)
 437 #else //!SELF_NO_HOST
 438     if (CanThisThreadCallIntoHost())
 439 #endif //!SELF_NO_HOST
 440     {
 441         va_list     args;
 442         va_start(args, fmt);
 443         LogSpewValist (LF_ALWAYS, LL_ALWAYS, fmt, args);
 444         va_end(args);
 445     }
 446     else
 447     {
 448         // Cannot acquire the required lock, as this would call back
 449         // into the host.  Eat the log message.
 450     }
 451 }
 452
 453 #endif // LOGGING
 454