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
34static DWORD LogFlags = 0;
35static CQuickWSTR szLogFileName;
36static HANDLE LogFileHandle = INVALID_HANDLE_VALUE;
37static MUTEX_COOKIE LogFileMutex = 0;
38static DWORD LogFacilityMask = LF_ALL;
39static DWORD LogFacilityMask2 = 0;
40static DWORD LogVMLevel = LL_INFO100;
41 // <TODO>@todo FIX should probably only display warnings and above by default</TODO>
42
43
44VOID 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
160VOID 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
177VOID 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
190static bool bLoggingInitialized = false;
191VOID 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
202VOID 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
215VOID 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
228bool LoggingEnabled()
229{
230 STATIC_CONTRACT_LEAF;
231
232 return ((LogFlags & LOG_ENABLE) != 0);
233}
234
235
236bool 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
246bool 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//
259VOID 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
274VOID 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
289VOID 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
387VOID LogSpew(DWORD facility, DWORD level, const char *fmt, ... )
388{
389 STATIC_CONTRACT_WRAPPER;
390
391 ENTER_SO_NOT_MAINLINE_CODE;
392
393#ifdef SELF_NO_HOST
394 if (TRUE)
395#else //!SELF_NO_HOST
396 if (CanThisThreadCallIntoHost())
397#endif //!SELF_NO_HOST
398 {
399 va_list args;
400 va_start(args, fmt);
401 LogSpewValist (facility, level, fmt, args);
402 va_end(args);
403 }
404 else
405 {
406 // Cannot acquire the required lock, as this would call back
407 // into the host. Eat the log message.
408 }
409
410 LEAVE_SO_NOT_MAINLINE_CODE;
411}
412
413VOID LogSpew2(DWORD facility2, DWORD level, const char *fmt, ... )
414{
415 STATIC_CONTRACT_WRAPPER;
416
417 ENTER_SO_NOT_MAINLINE_CODE;
418
419#ifdef SELF_NO_HOST
420 if (TRUE)
421#else //!SELF_NO_HOST
422 if (CanThisThreadCallIntoHost())
423#endif //!SELF_NO_HOST
424 {
425 va_list args;
426 va_start(args, fmt);
427 LogSpew2Valist(facility2, level, fmt, args);
428 va_end(args);
429 }
430 else
431 {
432 // Cannot acquire the required lock, as this would call back
433 // into the host. Eat the log message.
434 }
435
436 LEAVE_SO_NOT_MAINLINE_CODE;
437}
438
439VOID LogSpewAlways (const char *fmt, ... )
440{
441 STATIC_CONTRACT_WRAPPER;
442
443 ENTER_SO_NOT_MAINLINE_CODE;
444
445#ifdef SELF_NO_HOST
446 if (TRUE)
447#else //!SELF_NO_HOST
448 if (CanThisThreadCallIntoHost())
449#endif //!SELF_NO_HOST
450 {
451 va_list args;
452 va_start(args, fmt);
453 LogSpewValist (LF_ALWAYS, LL_ALWAYS, fmt, args);
454 va_end(args);
455 }
456 else
457 {
458 // Cannot acquire the required lock, as this would call back
459 // into the host. Eat the log message.
460 }
461
462 LEAVE_SO_NOT_MAINLINE_CODE;
463}
464
465#endif // LOGGING
466
467