1//
2// Copyright (c) Microsoft. All rights reserved.
3// Licensed under the MIT license. See LICENSE file in the project root for full license information.
4//
5
6//----------------------------------------------------------
7// Logging.cpp - Common logging and console output infrastructure
8//----------------------------------------------------------
9
10#include "standardpch.h"
11#include "logging.h"
12#include "errorhandling.h"
13#include <time.h>
14
15//
16// NOTE: Since the logging system is at the core of the error handling infrastructure, any errors
17// that occur while logging will print a message to the console. Fatal errors trigger a debugbreak.
18//
19
20bool Logger::s_initialized = false;
21UINT32 Logger::s_logLevel = LOGMASK_DEFAULT;
22HANDLE Logger::s_logFile = INVALID_HANDLE_VALUE;
23char* Logger::s_logFilePath = nullptr;
24CRITICAL_SECTION Logger::s_critSec;
25
26//
27// Initializes the logging subsystem. This must be called before invoking any of the logging functionality.
28//
29/* static */
30void Logger::Initialize()
31{
32 if (!s_initialized)
33 {
34 InitializeCriticalSection(&s_critSec);
35 s_initialized = true;
36 }
37}
38
39//
40// Shuts down the logging subsystem, freeing resources, closing handles, and such.
41//
42/* static */
43void Logger::Shutdown()
44{
45 if (s_initialized)
46 {
47 DeleteCriticalSection(&s_critSec);
48 CloseLogFile();
49 s_initialized = false;
50 }
51}
52
53//
54// Opens a log file at the given path and enables file-based logging, if the given path is valid.
55//
56/* static */
57void Logger::OpenLogFile(char* logFilePath)
58{
59 if (s_logFile == INVALID_HANDLE_VALUE && logFilePath != nullptr)
60 {
61 s_logFile = CreateFileA(logFilePath, GENERIC_WRITE, FILE_SHARE_READ | FILE_SHARE_DELETE, NULL, CREATE_ALWAYS,
62 FILE_ATTRIBUTE_NORMAL | FILE_FLAG_SEQUENTIAL_SCAN, NULL);
63
64 if (s_logFile != INVALID_HANDLE_VALUE)
65 {
66 // We may need the file path later in order to delete the log file
67 s_logFilePath = _strdup(logFilePath);
68 }
69 else
70 {
71 fprintf(stderr, "WARNING: [Logger::OpenLogFile] Failed to open log file '%s'. GetLastError()=%u\n",
72 logFilePath, GetLastError());
73 }
74 }
75}
76
77//
78// Closes the currently open log file, if one is open.
79//
80/* static */
81void Logger::CloseLogFile()
82{
83 if (s_logFile != INVALID_HANDLE_VALUE)
84 {
85 // Avoid polluting the file system with empty log files
86 if (GetFileSize(s_logFile, nullptr) == 0 && s_logFilePath != nullptr)
87 {
88 // We can call this before closing the handle because DeleteFile just marks the file
89 // for deletion, i.e. it does not actually get deleted until its last handle is closed.
90 if (!DeleteFileA(s_logFilePath))
91 fprintf(stderr, "WARNING: [Logger::CloseLogFile] DeleteFile failed. GetLastError()=%u\n",
92 GetLastError());
93 }
94
95 if (!CloseHandle(s_logFile))
96 fprintf(stderr, "WARNING: [Logger::CloseLogFile] CloseHandle failed. GetLastError()=%u\n", GetLastError());
97
98 s_logFile = INVALID_HANDLE_VALUE;
99
100 free(s_logFilePath);
101 s_logFilePath = nullptr;
102 }
103}
104
105//
106// Returns a bitmask representing the logging levels that are specified by the given string. The string
107// format is described explicitly in the command-line usage documentation for SuperPMI and MCS.
108//
109// In essence, each log level has a corresponding character representing it, and the presence of that
110// character in the specifier string indicates that the log mask should include that log level. The
111// "quiet" level will override any other level specified: that is, if a "q" is present in the string,
112// all other levels specified will be disregarded.
113//
114// If "q" is not specified, and "a" is specified, then all log levels are enabled. This is a shorthand
115// to avoid looking up all the log levels and enabling them all by specifying all the individual characters.
116//
117/* static */
118UINT32 Logger::ParseLogLevelString(const char* specifierStr)
119{
120 UINT32 logLevelMask = LOGMASK_NONE;
121
122 if (strchr(specifierStr, 'q') == nullptr) // "Quiet" overrides all other specifiers
123 {
124 if (strchr(specifierStr, 'a') != nullptr) // "All" overrides the other specifiers
125 {
126 logLevelMask |= LOGMASK_ALL;
127 }
128 else
129 {
130 if (strchr(specifierStr, 'e') != nullptr)
131 logLevelMask |= LOGLEVEL_ERROR;
132
133 if (strchr(specifierStr, 'w') != nullptr)
134 logLevelMask |= LOGLEVEL_WARNING;
135
136 if (strchr(specifierStr, 'm') != nullptr)
137 logLevelMask |= LOGLEVEL_MISSING;
138
139 if (strchr(specifierStr, 'i') != nullptr)
140 logLevelMask |= LOGLEVEL_ISSUE;
141
142 if (strchr(specifierStr, 'n') != nullptr)
143 logLevelMask |= LOGLEVEL_INFO;
144
145 if (strchr(specifierStr, 'v') != nullptr)
146 logLevelMask |= LOGLEVEL_VERBOSE;
147
148 if (strchr(specifierStr, 'd') != nullptr)
149 logLevelMask |= LOGLEVEL_DEBUG;
150 }
151 }
152
153 return logLevelMask;
154}
155
156/* static */
157void Logger::LogPrintf(const char* function, const char* file, int line, LogLevel level, const char* msg, ...)
158{
159 va_list argList;
160 va_start(argList, msg);
161 LogVprintf(function, file, line, level, argList, msg);
162}
163
164//
165// Logs a message, if the given log level is enabled, to both the console and the log file. This is the
166// main logging function that all other logging functions eventually funnel into.
167//
168/* static */
169void Logger::LogVprintf(
170 const char* function, const char* file, int line, LogLevel level, va_list argList, const char* msg)
171{
172 if (!s_initialized)
173 {
174 fprintf(stderr, "ERROR: [Logger::LogVprintf] Invoked the logging system before initializing it.\n");
175 __debugbreak();
176 }
177
178 // Capture this first to make the timestamp more accurately reflect the actual time of logging
179 time_t timestamp = time(nullptr);
180
181 int fullMsgLen = _vscprintf(msg, argList) + 1; // This doesn't count the null terminator
182 char* fullMsg = new char[fullMsgLen];
183
184 _vsnprintf_s(fullMsg, fullMsgLen, fullMsgLen, msg, argList);
185 va_end(argList);
186
187 const char* logLevelStr = "INVALID_LOGLEVEL";
188 switch (level)
189 {
190 case LOGLEVEL_ERROR:
191 logLevelStr = "ERROR";
192 break;
193
194 case LOGLEVEL_WARNING:
195 logLevelStr = "WARNING";
196 break;
197
198 case LOGLEVEL_MISSING:
199 logLevelStr = "MISSING";
200 break;
201
202 case LOGLEVEL_ISSUE:
203 logLevelStr = "ISSUE";
204 break;
205
206 case LOGLEVEL_INFO:
207 logLevelStr = "INFO";
208 break;
209
210 case LOGLEVEL_VERBOSE:
211 logLevelStr = "VERBOSE";
212 break;
213
214 case LOGLEVEL_DEBUG:
215 logLevelStr = "DEBUG";
216 break;
217 }
218
219 // NOTE: This implementation doesn't guarantee that log messages will be written in chronological
220 // order, since Windows doesn't guarantee FIFO behavior when a thread relinquishes a lock. If
221 // maintaining chronological order is crucial, then we can implement a priority queueing system
222 // for log messages.
223
224 EnterCriticalSection(&s_critSec);
225
226 if (level & GetLogLevel())
227 {
228 // Sends error messages to stderr instead out stdout
229 FILE* dest = (level <= LOGLEVEL_WARNING) ? stderr : stdout;
230
231 if (level < LOGLEVEL_INFO)
232 fprintf(dest, "%s: ", logLevelStr);
233
234 fprintf(dest, "%s\n", fullMsg);
235
236 if (s_logFile != INVALID_HANDLE_VALUE)
237 {
238#ifndef FEATURE_PAL // TODO: no localtime_s() or strftime() in PAL
239 tm timeInfo;
240 errno_t err = localtime_s(&timeInfo, &timestamp);
241 if (err != 0)
242 {
243 fprintf(stderr, "WARNING: [Logger::LogVprintf] localtime failed with error %d.\n", err);
244 goto CleanUp;
245 }
246
247 size_t timeStrBuffSize = 20 * sizeof(char);
248 char* timeStr = (char*)malloc(timeStrBuffSize); // Use malloc so we can realloc if necessary
249
250 // This particular format string should always generate strings of the same size, but
251 // for the sake of robustness, we shouldn't rely on that assumption.
252 while (strftime(timeStr, timeStrBuffSize, "%Y-%m-%d %H:%M:%S", &timeInfo) == 0)
253 {
254 timeStrBuffSize *= 2;
255 timeStr = (char*)realloc(timeStr, timeStrBuffSize);
256 }
257#else // FEATURE_PAL
258 const char* timeStr = "";
259#endif // FEATURE_PAL
260
261 const char logEntryFmtStr[] = "%s - %s [%s:%d] - %s - %s\r\n";
262 size_t logEntryBuffSize = sizeof(logEntryFmtStr) + strlen(timeStr) + strlen(function) + strlen(file) + 10 +
263 strlen(logLevelStr) + strlen(fullMsg);
264
265 char* logEntry = new char[logEntryBuffSize];
266 sprintf_s(logEntry, logEntryBuffSize, logEntryFmtStr, timeStr, function, file, line, logLevelStr, fullMsg);
267
268 DWORD bytesWritten;
269
270 if (!WriteFile(s_logFile, logEntry, (DWORD)logEntryBuffSize - 1, &bytesWritten, nullptr))
271 fprintf(stderr, "WARNING: [Logger::LogVprintf] Failed to write to log file. GetLastError()=%u\n",
272 GetLastError());
273
274 if (!FlushFileBuffers(s_logFile))
275 fprintf(stderr, "WARNING: [Logger::LogVprintf] Failed to flush log file. GetLastError()=%u\n",
276 GetLastError());
277
278 delete[] logEntry;
279
280#ifndef FEATURE_PAL
281 free((void*)timeStr);
282#endif // !FEATURE_PAL
283 }
284 }
285
286#ifndef FEATURE_PAL
287CleanUp:
288#endif // !FEATURE_PAL
289
290 LeaveCriticalSection(&s_critSec);
291 delete[] fullMsg;
292}
293
294//
295// Special helper for logging exceptions. This logs the exception message given as a debug message.
296//
297/* static */
298void Logger::LogExceptionMessage(
299 const char* function, const char* file, int line, DWORD exceptionCode, const char* msg, ...)
300{
301 std::string fullMsg = "Exception thrown: ";
302 fullMsg += msg;
303
304 va_list argList;
305 va_start(argList, msg);
306 LogVprintf(function, file, line, LOGLEVEL_DEBUG, argList, fullMsg.c_str());
307}
308
309//
310// Logger for JIT issues. Identifies the issue type and logs the given message normally.
311//
312/* static */
313void IssueLogger::LogIssueHelper(
314 const char* function, const char* file, int line, IssueType issue, const char* msg, ...)
315{
316 std::string fullMsg;
317
318 switch (issue)
319 {
320 case ISSUE_ASSERT:
321 fullMsg += "<ASSERT>";
322 break;
323
324 case ISSUE_ASM_DIFF:
325 fullMsg += "<ASM_DIFF>";
326 break;
327
328 default:
329 fullMsg += "<UNKNOWN_ISSUE_TYPE>";
330 break;
331 }
332
333 fullMsg += " ";
334 fullMsg += msg;
335
336 va_list argList;
337 va_start(argList, msg);
338 Logger::LogVprintf(function, file, line, LOGLEVEL_ISSUE, argList, fullMsg.c_str());
339}
340