1#include "aio.h"
2#include "color.h"
3#include "dbg.h"
4#include "logger.h"
5#include "str.h"
6#include "time.h"
7#include "windows.h"
8
9#include <atomic>
10#include <cstdio>
11#include <memory>
12
13#if defined(CONF_FAMILY_WINDOWS)
14#include <fcntl.h>
15#include <io.h>
16#include <windows.h>
17#else
18#include "io.h"
19
20#include <unistd.h>
21#endif
22
23#if defined(CONF_PLATFORM_ANDROID)
24#include <android/log.h>
25#endif
26
27std::atomic<ILogger *> global_logger = nullptr;
28thread_local ILogger *scope_logger = nullptr;
29thread_local bool in_logger = false;
30
31void log_set_global_logger(ILogger *logger)
32{
33 ILogger *null = nullptr;
34 if(!global_logger.compare_exchange_strong(p1&: null, p2: logger, m: std::memory_order_acq_rel))
35 {
36 dbg_assert_failed("global logger has already been set and can only be set once");
37 }
38#if !defined(CONF_PLATFORM_EMSCRIPTEN)
39 // With Emscripten, when atexit calls log_global_logger_finish, which calls GlobalFinish, the
40 // Emscripten runtime has already exited, so we cannot wait for the AIO thread to finish and
41 // calling io_sync in the assertion logger is not possible. We instead finish the global logger
42 // manually in src/engine/client/client.cpp before exit.
43 atexit(func: log_global_logger_finish);
44#endif
45}
46
47void log_global_logger_finish()
48{
49 ILogger *logger = global_logger.load(m: std::memory_order_acquire);
50 if(logger)
51 logger->GlobalFinish();
52}
53
54void log_set_global_logger_default()
55{
56 log_set_global_logger(logger: log_logger_default().release());
57}
58
59ILogger *log_get_scope_logger()
60{
61 if(!scope_logger)
62 {
63 scope_logger = global_logger.load(m: std::memory_order_acquire);
64 }
65 return scope_logger;
66}
67
68void log_set_scope_logger(ILogger *logger)
69{
70 scope_logger = logger;
71 if(!scope_logger)
72 {
73 scope_logger = global_logger.load(m: std::memory_order_acquire);
74 }
75}
76
77[[gnu::format(printf, 5, 0)]] static void log_log_impl(LEVEL level, bool have_color, LOG_COLOR color, const char *sys, const char *fmt, va_list args)
78{
79 // Make sure we're not logging recursively.
80 if(in_logger)
81 {
82 return;
83 }
84 in_logger = true;
85 if(!scope_logger)
86 {
87 scope_logger = global_logger.load(m: std::memory_order_acquire);
88 }
89 if(!scope_logger)
90 {
91 in_logger = false;
92 return;
93 }
94
95 CLogMessage Msg;
96 Msg.m_Level = level;
97 Msg.m_HaveColor = have_color;
98 Msg.m_Color = color;
99 str_timestamp_format(buffer: Msg.m_aTimestamp, buffer_size: sizeof(Msg.m_aTimestamp), format: TimestampFormat::SPACE);
100 Msg.m_TimestampLength = str_length(str: Msg.m_aTimestamp);
101 str_copy(dst&: Msg.m_aSystem, src: sys);
102 Msg.m_SystemLength = str_length(str: Msg.m_aSystem);
103
104 str_format(buffer: Msg.m_aLine, buffer_size: sizeof(Msg.m_aLine), format: "%s %c %s: ", Msg.m_aTimestamp, "EWIDT"[level], Msg.m_aSystem);
105 Msg.m_LineMessageOffset = str_length(str: Msg.m_aLine);
106
107 char *pMessage = Msg.m_aLine + Msg.m_LineMessageOffset;
108 int MessageSize = sizeof(Msg.m_aLine) - Msg.m_LineMessageOffset;
109 str_format_v(buffer: pMessage, buffer_size: MessageSize, format: fmt, args);
110 Msg.m_LineLength = str_length(str: Msg.m_aLine);
111 scope_logger->Log(pMessage: &Msg);
112 in_logger = false;
113}
114
115void log_log_v(LEVEL level, const char *sys, const char *fmt, va_list args)
116{
117 log_log_impl(level, have_color: false, color: LOG_COLOR{.r: 0, .g: 0, .b: 0}, sys, fmt, args);
118}
119
120void log_log(LEVEL level, const char *sys, const char *fmt, ...)
121{
122 va_list args;
123 va_start(args, fmt);
124 log_log_impl(level, have_color: false, color: LOG_COLOR{.r: 0, .g: 0, .b: 0}, sys, fmt, args);
125 va_end(args);
126}
127
128void log_log_color_v(LEVEL level, LOG_COLOR color, const char *sys, const char *fmt, va_list args)
129{
130 log_log_impl(level, have_color: true, color, sys, fmt, args);
131}
132
133void log_log_color(LEVEL level, LOG_COLOR color, const char *sys, const char *fmt, ...)
134{
135 va_list args;
136 va_start(args, fmt);
137 log_log_impl(level, have_color: true, color, sys, fmt, args);
138 va_end(args);
139}
140
141bool CLogFilter::Filters(const CLogMessage *pMessage)
142{
143 return pMessage->m_Level > m_MaxLevel.load(m: std::memory_order_relaxed);
144}
145
146#if defined(CONF_PLATFORM_ANDROID)
147class CLoggerAndroid : public ILogger
148{
149public:
150 void Log(const CLogMessage *pMessage) override
151 {
152 if(m_Filter.Filters(pMessage))
153 {
154 return;
155 }
156 int AndroidLevel;
157 switch(pMessage->m_Level)
158 {
159 case LEVEL_TRACE: AndroidLevel = ANDROID_LOG_VERBOSE; break;
160 case LEVEL_DEBUG: AndroidLevel = ANDROID_LOG_DEBUG; break;
161 case LEVEL_INFO: AndroidLevel = ANDROID_LOG_INFO; break;
162 case LEVEL_WARN: AndroidLevel = ANDROID_LOG_WARN; break;
163 case LEVEL_ERROR: AndroidLevel = ANDROID_LOG_ERROR; break;
164 }
165 char aTag[64];
166 str_copy(aTag, ANDROID_PACKAGE_NAME "/");
167 str_append(aTag, pMessage->m_aSystem);
168 __android_log_write(AndroidLevel, aTag, pMessage->Message());
169 }
170};
171std::unique_ptr<ILogger> log_logger_android()
172{
173 return std::make_unique<CLoggerAndroid>();
174}
175#else
176std::unique_ptr<ILogger> log_logger_android()
177{
178 dbg_assert(0, "Android logger on non-Android");
179 return nullptr;
180}
181#endif
182
183class CLoggerCollection : public ILogger
184{
185 std::vector<std::shared_ptr<ILogger>> m_vpLoggers;
186
187public:
188 CLoggerCollection(std::vector<std::shared_ptr<ILogger>> &&vpLoggers) :
189 m_vpLoggers(std::move(vpLoggers))
190 {
191 m_Filter.m_MaxLevel.store(i: LEVEL_TRACE, m: std::memory_order_relaxed);
192 }
193 void Log(const CLogMessage *pMessage) override
194 {
195 if(m_Filter.Filters(pMessage))
196 {
197 return;
198 }
199 for(auto &pLogger : m_vpLoggers)
200 {
201 pLogger->Log(pMessage);
202 }
203 }
204 void GlobalFinish() override
205 {
206 for(auto &pLogger : m_vpLoggers)
207 {
208 pLogger->GlobalFinish();
209 }
210 }
211};
212
213std::unique_ptr<ILogger> log_logger_collection(std::vector<std::shared_ptr<ILogger>> &&vpLoggers)
214{
215 return std::make_unique<CLoggerCollection>(args: std::move(vpLoggers));
216}
217
218std::unique_ptr<ILogger> log_logger_default()
219{
220#if defined(CONF_PLATFORM_ANDROID)
221 std::unique_ptr<ILogger> logger = log_logger_android();
222#else
223 std::unique_ptr<ILogger> logger = log_logger_stdout();
224#endif
225 return logger == nullptr ? log_logger_noop() : std::move(logger);
226}
227
228class CLoggerAsync : public ILogger
229{
230 ASYNCIO *m_pAio;
231 bool m_AnsiTruecolor;
232 bool m_Close;
233
234public:
235 CLoggerAsync(IOHANDLE File, bool AnsiTruecolor, bool Close) :
236 m_pAio(aio_new(io: File)),
237 m_AnsiTruecolor(AnsiTruecolor),
238 m_Close(Close)
239 {
240 }
241 void Log(const CLogMessage *pMessage) override
242 {
243 if(m_Filter.Filters(pMessage))
244 {
245 return;
246 }
247 aio_lock(aio: m_pAio);
248 if(m_AnsiTruecolor && pMessage->m_HaveColor)
249 {
250 // https://en.wikipedia.org/w/index.php?title=ANSI_escape_code&oldid=1077146479#24-bit
251 char aAnsi[32];
252 str_format(buffer: aAnsi, buffer_size: sizeof(aAnsi),
253 format: "\x1b[38;2;%d;%d;%dm",
254 pMessage->m_Color.r,
255 pMessage->m_Color.g,
256 pMessage->m_Color.b);
257 aio_write_unlocked(aio: m_pAio, buffer: aAnsi, size: str_length(str: aAnsi));
258 }
259 aio_write_unlocked(aio: m_pAio, buffer: pMessage->m_aLine, size: pMessage->m_LineLength);
260 if(m_AnsiTruecolor && pMessage->m_HaveColor)
261 {
262 const char aResetColor[] = "\x1b[0m";
263 aio_write_unlocked(aio: m_pAio, buffer: aResetColor, size: str_length(str: aResetColor)); // reset
264 }
265 aio_write_newline_unlocked(aio: m_pAio);
266 aio_unlock(aio: m_pAio);
267 }
268 ~CLoggerAsync() override
269 {
270 if(m_Close)
271 {
272 aio_close(aio: m_pAio);
273 }
274 aio_wait(aio: m_pAio);
275 aio_free(aio: m_pAio);
276 }
277 void GlobalFinish() override
278 {
279 if(m_Close)
280 {
281 aio_close(aio: m_pAio);
282 }
283 aio_wait(aio: m_pAio);
284 }
285};
286
287std::unique_ptr<ILogger> log_logger_file(IOHANDLE logfile)
288{
289 return std::make_unique<CLoggerAsync>(args&: logfile, args: false, args: true);
290}
291
292#if defined(CONF_FAMILY_WINDOWS)
293static int color_hsv_to_windows_console_color(const ColorHSVA &Hsv)
294{
295 int h = Hsv.h * 255.0f;
296 int s = Hsv.s * 255.0f;
297 int v = Hsv.v * 255.0f;
298 if(s >= 0 && s <= 10)
299 {
300 if(v <= 150)
301 return FOREGROUND_INTENSITY;
302 return FOREGROUND_BLUE | FOREGROUND_GREEN | FOREGROUND_RED | FOREGROUND_INTENSITY;
303 }
304 if(h < 0)
305 return FOREGROUND_BLUE | FOREGROUND_GREEN | FOREGROUND_RED | FOREGROUND_INTENSITY;
306 else if(h < 15)
307 return FOREGROUND_RED | FOREGROUND_INTENSITY;
308 else if(h < 30)
309 return FOREGROUND_GREEN | FOREGROUND_RED;
310 else if(h < 60)
311 return FOREGROUND_GREEN | FOREGROUND_RED | FOREGROUND_INTENSITY;
312 else if(h < 110)
313 return FOREGROUND_GREEN | FOREGROUND_INTENSITY;
314 else if(h < 140)
315 return FOREGROUND_BLUE | FOREGROUND_GREEN | FOREGROUND_INTENSITY;
316 else if(h < 170)
317 return FOREGROUND_BLUE | FOREGROUND_INTENSITY;
318 else if(h < 195)
319 return FOREGROUND_BLUE | FOREGROUND_RED;
320 else if(h < 240)
321 return FOREGROUND_BLUE | FOREGROUND_RED | FOREGROUND_INTENSITY;
322 else
323 return FOREGROUND_RED | FOREGROUND_INTENSITY;
324}
325
326class CWindowsConsoleLogger : public ILogger
327{
328 HANDLE m_pConsole;
329 bool m_EnableColor;
330 int m_BackgroundColor;
331 int m_ForegroundColor;
332 CLock m_OutputLock;
333 bool m_Finished = false;
334
335public:
336 CWindowsConsoleLogger(HANDLE pConsole, bool EnableColor) :
337 m_pConsole(pConsole),
338 m_EnableColor(EnableColor)
339 {
340 CONSOLE_SCREEN_BUFFER_INFO ConsoleInfo;
341 if(GetConsoleScreenBufferInfo(pConsole, &ConsoleInfo))
342 {
343 m_BackgroundColor = ConsoleInfo.wAttributes & (BACKGROUND_BLUE | BACKGROUND_GREEN | BACKGROUND_RED | BACKGROUND_INTENSITY);
344 m_ForegroundColor = ConsoleInfo.wAttributes & (FOREGROUND_BLUE | FOREGROUND_GREEN | FOREGROUND_RED | FOREGROUND_INTENSITY);
345 }
346 else
347 {
348 m_BackgroundColor = 0;
349 m_ForegroundColor = FOREGROUND_BLUE | FOREGROUND_GREEN | FOREGROUND_RED | FOREGROUND_INTENSITY;
350 }
351 }
352 void Log(const CLogMessage *pMessage) override REQUIRES(!m_OutputLock)
353 {
354 if(m_Filter.Filters(pMessage))
355 {
356 return;
357 }
358 const std::wstring WideMessage = windows_utf8_to_wide(pMessage->m_aLine);
359
360 int Color = m_BackgroundColor;
361 if(m_EnableColor && pMessage->m_HaveColor)
362 {
363 const ColorRGBA Rgba(pMessage->m_Color.r / 255.0f, pMessage->m_Color.g / 255.0f, pMessage->m_Color.b / 255.0f);
364 Color |= color_hsv_to_windows_console_color(color_cast<ColorHSVA>(Rgba));
365 }
366 else
367 Color |= FOREGROUND_BLUE | FOREGROUND_GREEN | FOREGROUND_RED | FOREGROUND_INTENSITY;
368
369 const CLockScope LockScope(m_OutputLock);
370 if(!m_Finished)
371 {
372 SetConsoleTextAttribute(m_pConsole, Color);
373 WriteConsoleW(m_pConsole, WideMessage.c_str(), WideMessage.length(), nullptr, nullptr);
374 WriteConsoleW(m_pConsole, L"\r\n", 2, nullptr, nullptr);
375 }
376 }
377 void GlobalFinish() override REQUIRES(!m_OutputLock)
378 {
379 // Restore original color
380 const CLockScope LockScope(m_OutputLock);
381 SetConsoleTextAttribute(m_pConsole, m_BackgroundColor | m_ForegroundColor);
382 m_Finished = true;
383 }
384};
385
386static IOHANDLE ConvertWindowsHandle(HANDLE pHandle, int OpenFlags)
387{
388 int FileDescriptor = _open_osfhandle(reinterpret_cast<intptr_t>(pHandle), OpenFlags);
389 dbg_assert(FileDescriptor != -1, "_open_osfhandle failure");
390 IOHANDLE FileStream = _wfdopen(FileDescriptor, L"w");
391 dbg_assert(FileStream != nullptr, "_wfdopen failure");
392 return FileStream;
393}
394#endif
395
396std::unique_ptr<ILogger> log_logger_stdout()
397{
398#if !defined(CONF_FAMILY_WINDOWS)
399 // TODO: Only enable true color when COLORTERM contains "truecolor".
400 // https://github.com/termstandard/colors/tree/65bf0cd1ece7c15fa33a17c17528b02c99f1ae0b#checking-for-colorterm
401 const bool Colors = getenv(name: "NO_COLOR") == nullptr && isatty(STDOUT_FILENO);
402 return std::make_unique<CLoggerAsync>(args: io_stdout(), args: Colors, args: false);
403#else
404 // If we currently have no stdout (console, file, pipe),
405 // try to attach to the console of the parent process.
406 if(GetFileType(GetStdHandle(STD_OUTPUT_HANDLE)) == FILE_TYPE_UNKNOWN)
407 {
408 AttachConsole(ATTACH_PARENT_PROCESS);
409 }
410
411 HANDLE pOutput = GetStdHandle(STD_OUTPUT_HANDLE);
412 if(pOutput == nullptr)
413 {
414 // There is no console, file or pipe that we can output to.
415 return nullptr;
416 }
417 dbg_assert(pOutput != INVALID_HANDLE_VALUE, "GetStdHandle failure");
418
419 const DWORD OutputType = GetFileType(pOutput);
420 if(OutputType == FILE_TYPE_CHAR)
421 {
422 DWORD OldConsoleMode = 0;
423 if(!GetConsoleMode(pOutput, &OldConsoleMode))
424 {
425 // GetConsoleMode can fail with ERROR_INVALID_HANDLE when redirecting output to "nul",
426 // which is considered a character file but cannot be used as a console.
427 dbg_assert(GetLastError() == ERROR_INVALID_HANDLE, "GetConsoleMode failure");
428 return nullptr;
429 }
430
431 const bool Colors = _wgetenv(L"NO_COLOR") == nullptr;
432
433 // Try to enable virtual terminal processing in the Windows console.
434 // See https://learn.microsoft.com/en-us/windows/console/console-virtual-terminal-sequences
435 if(!SetConsoleMode(pOutput, OldConsoleMode | ENABLE_VIRTUAL_TERMINAL_PROCESSING | DISABLE_NEWLINE_AUTO_RETURN))
436 {
437 // Try to downgrade mode gracefully when failing to set both.
438 if(!SetConsoleMode(pOutput, OldConsoleMode | ENABLE_VIRTUAL_TERMINAL_PROCESSING))
439 {
440 // Fallback to old, slower Windows logging API, when failing to enable virtual terminal processing.
441 return std::make_unique<CWindowsConsoleLogger>(pOutput, Colors);
442 }
443 }
444
445 // Virtual terminal processing was enabled successfully. We can
446 // use the async logger with ANSI escape codes for colors now.
447 // We need to set the output encoding to UTF-8 manually and
448 // convert the HANDLE to an IOHANDLE to use the async logger.
449 // We assume UTF-8 is available when virtual terminal processing is.
450 dbg_assert(SetConsoleOutputCP(CP_UTF8) != 0, "SetConsoleOutputCP failure");
451 return std::make_unique<CLoggerAsync>(ConvertWindowsHandle(pOutput, _O_TEXT), Colors, false);
452 }
453 else if(OutputType == FILE_TYPE_DISK || OutputType == FILE_TYPE_PIPE)
454 {
455 // Writing to a pipe works the same as writing to a file.
456 // We can use the async logger to write to files and pipes
457 // by converting the HANDLE to an IOHANDLE.
458 // For pipes there does not seem to be any way to determine
459 // whether the console supports ANSI escape codes.
460 return std::make_unique<CLoggerAsync>(ConvertWindowsHandle(pOutput, _O_APPEND), false, false);
461 }
462 else
463 {
464 dbg_assert_failed("GetFileType failure");
465 }
466#endif
467}
468
469#if defined(CONF_FAMILY_WINDOWS)
470class CLoggerWindowsDebugger : public ILogger
471{
472public:
473 void Log(const CLogMessage *pMessage) override
474 {
475 if(m_Filter.Filters(pMessage))
476 {
477 return;
478 }
479 const std::wstring WideMessage = windows_utf8_to_wide(pMessage->m_aLine);
480 OutputDebugStringW(WideMessage.c_str());
481 }
482};
483std::unique_ptr<ILogger> log_logger_windows_debugger()
484{
485 return std::make_unique<CLoggerWindowsDebugger>();
486}
487#else
488std::unique_ptr<ILogger> log_logger_windows_debugger()
489{
490 dbg_assert(0, "Windows Debug logger on non-Windows");
491 return nullptr;
492}
493#endif
494
495class CLoggerNoOp : public ILogger
496{
497public:
498 void Log(const CLogMessage *pMessage) override
499 {
500 // no-op
501 }
502};
503std::unique_ptr<ILogger> log_logger_noop()
504{
505 return std::make_unique<CLoggerNoOp>();
506}
507
508#ifdef __GNUC__
509// atomic_compare_exchange_strong_explicit is deprecated
510#pragma GCC diagnostic push
511#pragma GCC diagnostic ignored "-Wdeprecated-declarations"
512#endif
513void CFutureLogger::Set(std::shared_ptr<ILogger> pLogger)
514{
515 const CLockScope LockScope(m_PendingLock);
516 std::shared_ptr<ILogger> pNullLogger;
517 if(!std::atomic_compare_exchange_strong_explicit(p: &m_pLogger, v: &pNullLogger, w: pLogger, std::memory_order_acq_rel, std::memory_order_acq_rel))
518 {
519 dbg_assert_failed("future logger has already been set and can only be set once");
520 }
521 m_pLogger = std::move(pLogger);
522
523 for(const auto &Pending : m_vPending)
524 {
525 m_pLogger->Log(pMessage: &Pending);
526 }
527 m_vPending.clear();
528 m_vPending.shrink_to_fit();
529}
530
531void CFutureLogger::Log(const CLogMessage *pMessage)
532{
533 auto pLogger = std::atomic_load_explicit(p: &m_pLogger, std::memory_order_acquire);
534 if(pLogger)
535 {
536 pLogger->Log(pMessage);
537 return;
538 }
539 const CLockScope LockScope(m_PendingLock);
540 pLogger = std::atomic_load_explicit(p: &m_pLogger, std::memory_order_relaxed);
541 if(pLogger)
542 {
543 pLogger->Log(pMessage);
544 return;
545 }
546 m_vPending.push_back(x: *pMessage);
547}
548
549void CFutureLogger::GlobalFinish()
550{
551 auto pLogger = std::atomic_load_explicit(p: &m_pLogger, std::memory_order_acquire);
552 if(pLogger)
553 {
554 pLogger->GlobalFinish();
555 }
556}
557
558void CFutureLogger::OnFilterChange()
559{
560 auto pLogger = std::atomic_load_explicit(p: &m_pLogger, std::memory_order_acquire);
561 if(pLogger)
562 {
563 pLogger->SetFilter(m_Filter);
564 }
565}
566
567#ifdef __GNUC__
568#pragma GCC diagnostic pop
569#endif
570
571void CMemoryLogger::Log(const CLogMessage *pMessage)
572{
573 if(m_pParentLogger)
574 {
575 m_pParentLogger->Log(pMessage);
576 }
577 if(m_Filter.Filters(pMessage))
578 {
579 return;
580 }
581 const CLockScope LockScope(m_MessagesMutex);
582 m_vMessages.push_back(x: *pMessage);
583}
584
585std::vector<CLogMessage> CMemoryLogger::Lines()
586{
587 const CLockScope LockScope(m_MessagesMutex);
588 return m_vMessages;
589}
590
591std::string CMemoryLogger::ConcatenatedLines()
592{
593 const CLockScope LockScope(m_MessagesMutex);
594 std::string Result;
595 for(const CLogMessage &Message : m_vMessages)
596 {
597 if(!Result.empty())
598 {
599 Result += '\n';
600 }
601 Result += Message.m_aLine;
602 }
603 return Result;
604}
605