log.cpp (17679B)
1 // SPDX-FileCopyrightText: 2019-2022 Connor McLaughlin <stenzek@gmail.com> 2 // SPDX-License-Identifier: (GPL-3.0 OR CC-BY-NC-ND-4.0) 3 4 #include "log.h" 5 #include "assert.h" 6 #include "file_system.h" 7 #include "small_string.h" 8 #include "timer.h" 9 10 #include "fmt/format.h" 11 12 #include <cstdio> 13 #include <mutex> 14 #include <vector> 15 16 #if defined(_WIN32) 17 #include "windows_headers.h" 18 #elif defined(__ANDROID__) 19 #include <android/log.h> 20 #else 21 #include <unistd.h> 22 #endif 23 24 using namespace std::string_view_literals; 25 26 namespace Log { 27 namespace { 28 struct RegisteredCallback 29 { 30 Log::CallbackFunctionType Function; 31 void* Parameter; 32 }; 33 } // namespace 34 35 static void RegisterCallback(CallbackFunctionType callbackFunction, void* pUserParam, 36 const std::unique_lock<std::mutex>& lock); 37 static void UnregisterCallback(CallbackFunctionType callbackFunction, void* pUserParam, 38 const std::unique_lock<std::mutex>& lock); 39 static bool FilterTest(LOGLEVEL level, const char* channelName, const std::unique_lock<std::mutex>& lock); 40 static void ExecuteCallbacks(const char* channelName, const char* functionName, LOGLEVEL level, 41 std::string_view message, const std::unique_lock<std::mutex>& lock); 42 static void FormatLogMessageForDisplay(fmt::memory_buffer& buffer, const char* channelName, const char* functionName, 43 LOGLEVEL level, std::string_view message, bool timestamp, bool ansi_color_code, 44 bool newline); 45 static void ConsoleOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, 46 LOGLEVEL level, std::string_view message); 47 static void DebugOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, 48 std::string_view message); 49 static void FileOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, 50 std::string_view message); 51 template<typename T> 52 static void FormatLogMessageAndPrint(const char* channelName, const char* functionName, LOGLEVEL level, 53 std::string_view message, bool timestamp, bool ansi_color_code, bool newline, 54 const T& callback); 55 #ifdef _WIN32 56 template<typename T> 57 static void FormatLogMessageAndPrintW(const char* channelName, const char* functionName, LOGLEVEL level, 58 std::string_view message, bool timestamp, bool ansi_color_code, bool newline, 59 const T& callback); 60 #endif 61 62 static const char s_log_level_characters[LOGLEVEL_COUNT] = {'X', 'E', 'W', 'I', 'V', 'D', 'B', 'T'}; 63 64 static std::vector<RegisteredCallback> s_callbacks; 65 static std::mutex s_callback_mutex; 66 67 static Common::Timer::Value s_start_timestamp = Common::Timer::GetCurrentValue(); 68 69 static std::string s_log_filter; 70 static LOGLEVEL s_log_level = LOGLEVEL_TRACE; 71 static bool s_console_output_enabled = false; 72 static bool s_console_output_timestamps = true; 73 static bool s_file_output_enabled = false; 74 static bool s_file_output_timestamp = false; 75 static bool s_debug_output_enabled = false; 76 77 #ifdef _WIN32 78 static HANDLE s_hConsoleStdIn = NULL; 79 static HANDLE s_hConsoleStdOut = NULL; 80 static HANDLE s_hConsoleStdErr = NULL; 81 #endif 82 } // namespace Log 83 84 std::unique_ptr<std::FILE, void (*)(std::FILE*)> s_file_handle(nullptr, [](std::FILE* fp) { 85 if (fp) 86 { 87 std::fclose(fp); 88 } 89 }); 90 91 void Log::RegisterCallback(CallbackFunctionType callbackFunction, void* pUserParam) 92 { 93 std::unique_lock lock(s_callback_mutex); 94 RegisterCallback(callbackFunction, pUserParam, lock); 95 } 96 97 void Log::RegisterCallback(CallbackFunctionType callbackFunction, void* pUserParam, 98 const std::unique_lock<std::mutex>& lock) 99 { 100 RegisteredCallback Callback; 101 Callback.Function = callbackFunction; 102 Callback.Parameter = pUserParam; 103 104 s_callbacks.push_back(std::move(Callback)); 105 } 106 107 void Log::UnregisterCallback(CallbackFunctionType callbackFunction, void* pUserParam) 108 { 109 std::unique_lock lock(s_callback_mutex); 110 UnregisterCallback(callbackFunction, pUserParam, lock); 111 } 112 113 void Log::UnregisterCallback(CallbackFunctionType callbackFunction, void* pUserParam, 114 const std::unique_lock<std::mutex>& lock) 115 { 116 for (auto iter = s_callbacks.begin(); iter != s_callbacks.end(); ++iter) 117 { 118 if (iter->Function == callbackFunction && iter->Parameter == pUserParam) 119 { 120 s_callbacks.erase(iter); 121 break; 122 } 123 } 124 } 125 126 float Log::GetCurrentMessageTime() 127 { 128 return static_cast<float>(Common::Timer::ConvertValueToSeconds(Common::Timer::GetCurrentValue() - s_start_timestamp)); 129 } 130 131 bool Log::IsConsoleOutputEnabled() 132 { 133 return s_console_output_enabled; 134 } 135 136 bool Log::IsDebugOutputEnabled() 137 { 138 return s_debug_output_enabled; 139 } 140 141 void Log::ExecuteCallbacks(const char* channelName, const char* functionName, LOGLEVEL level, std::string_view message, 142 const std::unique_lock<std::mutex>& lock) 143 { 144 for (RegisteredCallback& callback : s_callbacks) 145 callback.Function(callback.Parameter, channelName, functionName, level, message); 146 } 147 148 ALWAYS_INLINE_RELEASE void Log::FormatLogMessageForDisplay(fmt::memory_buffer& buffer, const char* channelName, 149 const char* functionName, LOGLEVEL level, 150 std::string_view message, bool timestamp, 151 bool ansi_color_code, bool newline) 152 { 153 static constexpr std::string_view s_ansi_color_codes[LOGLEVEL_COUNT] = { 154 "\033[0m"sv, // NONE 155 "\033[1;31m"sv, // ERROR 156 "\033[1;33m"sv, // WARNING 157 "\033[1;37m"sv, // INFO 158 "\033[1;32m"sv, // VERBOSE 159 "\033[0;37m"sv, // DEV 160 "\033[0;32m"sv, // DEBUG 161 "\033[0;34m"sv, // TRACE 162 }; 163 164 std::string_view color_start = ansi_color_code ? s_ansi_color_codes[level] : ""sv; 165 std::string_view color_end = ansi_color_code ? s_ansi_color_codes[0] : ""sv; 166 std::string_view message_end = newline ? "\n"sv : ""sv; 167 168 auto appender = std::back_inserter(buffer); 169 170 if (timestamp) 171 { 172 // find time since start of process 173 const float message_time = Log::GetCurrentMessageTime(); 174 175 if (functionName) 176 { 177 fmt::format_to(appender, "[{:10.4f}] {}{}({}): {}{}{}", message_time, color_start, s_log_level_characters[level], 178 functionName, message, color_end, message_end); 179 } 180 else 181 { 182 fmt::format_to(appender, "[{:10.4f}] {}{}/{}: {}{}{}", message_time, color_start, s_log_level_characters[level], 183 channelName, message, color_end, message_end); 184 } 185 } 186 else 187 { 188 if (functionName) 189 { 190 fmt::format_to(appender, "{}{}({}): {}{}{}", color_start, s_log_level_characters[level], functionName, message, 191 color_end, message_end); 192 } 193 else 194 { 195 fmt::format_to(appender, "{}{}/{}: {}{}{}", color_start, s_log_level_characters[level], channelName, message, 196 color_end, message_end); 197 } 198 } 199 } 200 201 template<typename T> 202 ALWAYS_INLINE_RELEASE void Log::FormatLogMessageAndPrint(const char* channelName, const char* functionName, 203 LOGLEVEL level, std::string_view message, bool timestamp, 204 bool ansi_color_code, bool newline, const T& callback) 205 { 206 fmt::memory_buffer buffer; 207 Log::FormatLogMessageForDisplay(buffer, channelName, functionName, level, message, timestamp, ansi_color_code, 208 newline); 209 callback(std::string_view(buffer.data(), buffer.size())); 210 } 211 212 #ifdef _WIN32 213 214 template<typename T> 215 ALWAYS_INLINE_RELEASE void Log::FormatLogMessageAndPrintW(const char* channelName, const char* functionName, 216 LOGLEVEL level, std::string_view message, bool timestamp, 217 bool ansi_color_code, bool newline, const T& callback) 218 { 219 fmt::memory_buffer buffer; 220 Log::FormatLogMessageForDisplay(buffer, channelName, functionName, level, message, timestamp, ansi_color_code, 221 newline); 222 223 // Convert to UTF-16 first so unicode characters display correctly. NT is going to do it 224 // anyway... 225 wchar_t wbuf[512]; 226 wchar_t* wmessage_buf = wbuf; 227 int wmessage_buflen = static_cast<int>(std::size(wbuf) - 1); 228 if (buffer.size() >= std::size(wbuf)) 229 { 230 wmessage_buflen = static_cast<int>(buffer.size()); 231 wmessage_buf = static_cast<wchar_t*>(std::malloc((buffer.size() + 1) * sizeof(wchar_t))); 232 } 233 234 wmessage_buflen = 235 MultiByteToWideChar(CP_UTF8, 0, buffer.data(), static_cast<int>(buffer.size()), wmessage_buf, wmessage_buflen); 236 if (wmessage_buflen > 0) [[likely]] 237 { 238 wmessage_buf[wmessage_buflen] = '\0'; 239 callback(std::wstring_view(wmessage_buf, wmessage_buflen)); 240 } 241 242 if (wmessage_buf != wbuf) 243 std::free(wmessage_buf); 244 } 245 246 static bool EnableVirtualTerminalProcessing(HANDLE hConsole) 247 { 248 DWORD old_mode; 249 if (!GetConsoleMode(hConsole, &old_mode)) 250 return false; 251 252 // already enabled? 253 if (old_mode & ENABLE_VIRTUAL_TERMINAL_PROCESSING) 254 return true; 255 256 return SetConsoleMode(hConsole, old_mode | ENABLE_VIRTUAL_TERMINAL_PROCESSING); 257 } 258 259 #endif 260 261 void Log::ConsoleOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, 262 std::string_view message) 263 { 264 if (!s_console_output_enabled) 265 return; 266 267 #if defined(_WIN32) 268 FormatLogMessageAndPrintW(channelName, functionName, level, message, s_console_output_timestamps, true, true, 269 [level](const std::wstring_view& message) { 270 HANDLE hOutput = (level <= LOGLEVEL_WARNING) ? s_hConsoleStdErr : s_hConsoleStdOut; 271 DWORD chars_written; 272 WriteConsoleW(hOutput, message.data(), static_cast<DWORD>(message.length()), 273 &chars_written, nullptr); 274 }); 275 #elif !defined(__ANDROID__) 276 FormatLogMessageAndPrint(channelName, functionName, level, message, s_console_output_timestamps, true, true, 277 [level](std::string_view message) { 278 const int outputFd = (level <= LOGLEVEL_WARNING) ? STDERR_FILENO : STDOUT_FILENO; 279 write(outputFd, message.data(), message.length()); 280 }); 281 #endif 282 } 283 284 void Log::DebugOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, 285 std::string_view message) 286 { 287 if (!s_debug_output_enabled) 288 return; 289 290 #if defined(_WIN32) 291 FormatLogMessageAndPrintW(channelName, functionName, level, message, false, false, true, 292 [](const std::wstring_view& message) { OutputDebugStringW(message.data()); }); 293 #elif defined(__ANDROID__) 294 if (message.empty()) 295 return; 296 297 static constexpr int logPriority[LOGLEVEL_COUNT] = { 298 ANDROID_LOG_INFO, // NONE 299 ANDROID_LOG_ERROR, // ERROR 300 ANDROID_LOG_WARN, // WARNING 301 ANDROID_LOG_INFO, // PERF 302 ANDROID_LOG_INFO, // INFO 303 ANDROID_LOG_INFO, // VERBOSE 304 ANDROID_LOG_DEBUG, // DEV 305 ANDROID_LOG_DEBUG, // PROFILE 306 ANDROID_LOG_DEBUG, // DEBUG 307 ANDROID_LOG_DEBUG, // TRACE 308 }; 309 310 __android_log_print(logPriority[level], channelName, "%.*s", static_cast<int>(message.length()), message.data()); 311 #else 312 #endif 313 } 314 315 void Log::SetConsoleOutputParams(bool enabled, bool timestamps) 316 { 317 std::unique_lock lock(s_callback_mutex); 318 319 s_console_output_timestamps = timestamps; 320 if (s_console_output_enabled == enabled) 321 return; 322 323 s_console_output_enabled = enabled; 324 325 #if defined(_WIN32) 326 // On windows, no console is allocated by default on a windows based application 327 static bool console_was_allocated = false; 328 static HANDLE old_stdin = NULL; 329 static HANDLE old_stdout = NULL; 330 static HANDLE old_stderr = NULL; 331 332 if (enabled) 333 { 334 old_stdin = GetStdHandle(STD_INPUT_HANDLE); 335 old_stdout = GetStdHandle(STD_OUTPUT_HANDLE); 336 old_stderr = GetStdHandle(STD_ERROR_HANDLE); 337 338 if (!old_stdout) 339 { 340 // Attach to the parent console if we're running from a command window 341 if (!AttachConsole(ATTACH_PARENT_PROCESS) && !AllocConsole()) 342 return; 343 344 s_hConsoleStdIn = GetStdHandle(STD_INPUT_HANDLE); 345 s_hConsoleStdOut = GetStdHandle(STD_OUTPUT_HANDLE); 346 s_hConsoleStdErr = GetStdHandle(STD_ERROR_HANDLE); 347 348 EnableVirtualTerminalProcessing(s_hConsoleStdOut); 349 EnableVirtualTerminalProcessing(s_hConsoleStdErr); 350 351 std::FILE* fp; 352 freopen_s(&fp, "CONIN$", "r", stdin); 353 freopen_s(&fp, "CONOUT$", "w", stdout); 354 freopen_s(&fp, "CONOUT$", "w", stderr); 355 356 console_was_allocated = true; 357 } 358 else 359 { 360 s_hConsoleStdIn = old_stdin; 361 s_hConsoleStdOut = old_stdout; 362 s_hConsoleStdErr = old_stderr; 363 } 364 } 365 else 366 { 367 if (console_was_allocated) 368 { 369 console_was_allocated = false; 370 371 std::FILE* fp; 372 freopen_s(&fp, "NUL:", "w", stderr); 373 freopen_s(&fp, "NUL:", "w", stdout); 374 freopen_s(&fp, "NUL:", "w", stdin); 375 376 SetStdHandle(STD_ERROR_HANDLE, old_stderr); 377 SetStdHandle(STD_OUTPUT_HANDLE, old_stdout); 378 SetStdHandle(STD_INPUT_HANDLE, old_stdin); 379 380 s_hConsoleStdIn = NULL; 381 s_hConsoleStdOut = NULL; 382 s_hConsoleStdErr = NULL; 383 384 FreeConsole(); 385 } 386 } 387 #endif 388 389 if (enabled) 390 RegisterCallback(ConsoleOutputLogCallback, nullptr, lock); 391 else 392 UnregisterCallback(ConsoleOutputLogCallback, nullptr, lock); 393 } 394 395 void Log::SetDebugOutputParams(bool enabled) 396 { 397 std::unique_lock lock(s_callback_mutex); 398 if (s_debug_output_enabled == enabled) 399 return; 400 401 s_debug_output_enabled = enabled; 402 if (enabled) 403 RegisterCallback(DebugOutputLogCallback, nullptr, lock); 404 else 405 UnregisterCallback(DebugOutputLogCallback, nullptr, lock); 406 } 407 408 void Log::FileOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, 409 std::string_view message) 410 { 411 if (!s_file_output_enabled) 412 return; 413 414 FormatLogMessageAndPrint(channelName, functionName, level, message, true, false, true, [](std::string_view message) { 415 std::fwrite(message.data(), 1, message.size(), s_file_handle.get()); 416 std::fflush(s_file_handle.get()); 417 }); 418 } 419 420 void Log::SetFileOutputParams(bool enabled, const char* filename, bool timestamps /* = true */) 421 { 422 std::unique_lock lock(s_callback_mutex); 423 if (s_file_output_enabled == enabled) 424 return; 425 426 if (enabled) 427 { 428 s_file_handle.reset(FileSystem::OpenCFile(filename, "wb")); 429 if (!s_file_handle) [[unlikely]] 430 { 431 ExecuteCallbacks("Log", __FUNCTION__, LOGLEVEL_ERROR, 432 TinyString::from_format("Failed to open log file '{}'", filename), lock); 433 return; 434 } 435 436 RegisterCallback(FileOutputLogCallback, nullptr, lock); 437 } 438 else 439 { 440 UnregisterCallback(FileOutputLogCallback, nullptr, lock); 441 s_file_handle.reset(); 442 } 443 444 s_file_output_enabled = enabled; 445 s_file_output_timestamp = timestamps; 446 } 447 448 LOGLEVEL Log::GetLogLevel() 449 { 450 return s_log_level; 451 } 452 453 bool Log::IsLogVisible(LOGLEVEL level, const char* channelName) 454 { 455 if (level > s_log_level) 456 return false; 457 458 std::unique_lock lock(s_callback_mutex); 459 return FilterTest(level, channelName, lock); 460 } 461 462 void Log::SetLogLevel(LOGLEVEL level) 463 { 464 std::unique_lock lock(s_callback_mutex); 465 DebugAssert(level < LOGLEVEL_COUNT); 466 s_log_level = level; 467 } 468 469 void Log::SetLogFilter(std::string_view filter) 470 { 471 std::unique_lock lock(s_callback_mutex); 472 if (s_log_filter != filter) 473 s_log_filter = filter; 474 } 475 476 ALWAYS_INLINE_RELEASE bool Log::FilterTest(LOGLEVEL level, const char* channelName, 477 const std::unique_lock<std::mutex>& lock) 478 { 479 return (level <= s_log_level && s_log_filter.find(channelName) == std::string::npos); 480 } 481 482 void Log::Write(const char* channelName, LOGLEVEL level, std::string_view message) 483 { 484 std::unique_lock lock(s_callback_mutex); 485 if (!FilterTest(level, channelName, lock)) 486 return; 487 488 ExecuteCallbacks(channelName, nullptr, level, message, lock); 489 } 490 491 void Log::Write(const char* channelName, const char* functionName, LOGLEVEL level, std::string_view message) 492 { 493 std::unique_lock lock(s_callback_mutex); 494 if (!FilterTest(level, channelName, lock)) 495 return; 496 497 ExecuteCallbacks(channelName, functionName, level, message, lock); 498 } 499 500 void Log::WriteFmtArgs(const char* channelName, LOGLEVEL level, fmt::string_view fmt, fmt::format_args args) 501 { 502 std::unique_lock lock(s_callback_mutex); 503 if (!FilterTest(level, channelName, lock)) 504 return; 505 506 fmt::memory_buffer buffer; 507 fmt::vformat_to(std::back_inserter(buffer), fmt, args); 508 509 ExecuteCallbacks(channelName, nullptr, level, std::string_view(buffer.data(), buffer.size()), lock); 510 } 511 512 void Log::WriteFmtArgs(const char* channelName, const char* functionName, LOGLEVEL level, fmt::string_view fmt, 513 fmt::format_args args) 514 { 515 std::unique_lock lock(s_callback_mutex); 516 if (!FilterTest(level, channelName, lock)) 517 return; 518 519 fmt::memory_buffer buffer; 520 fmt::vformat_to(std::back_inserter(buffer), fmt, args); 521 522 ExecuteCallbacks(channelName, functionName, level, std::string_view(buffer.data(), buffer.size()), lock); 523 }