diff options
Diffstat (limited to 'src/zenutil/logging.cpp')
| -rw-r--r-- | src/zenutil/logging.cpp | 502 |
1 files changed, 93 insertions, 409 deletions
diff --git a/src/zenutil/logging.cpp b/src/zenutil/logging.cpp index c0a63cc71..3cd72eac9 100644 --- a/src/zenutil/logging.cpp +++ b/src/zenutil/logging.cpp @@ -2,413 +2,56 @@ #include "zenutil/logging.h" -#undef ZEN_USE_SENTRY -#define ZEN_USE_SENTRY 0 - -#if !defined(ZEN_USE_SENTRY) -# if ZEN_PLATFORM_MAC && ZEN_ARCH_ARM64 -// vcpkg's sentry-native port does not support Arm on Mac. -# define ZEN_USE_SENTRY 0 -# else -# define ZEN_USE_SENTRY 1 -# endif -#endif - ZEN_THIRD_PARTY_INCLUDES_START #include <spdlog/async.h> #include <spdlog/async_logger.h> -#include <spdlog/pattern_formatter.h> #include <spdlog/sinks/ansicolor_sink.h> -#include <spdlog/sinks/basic_file_sink.h> -#include <spdlog/sinks/daily_file_sink.h> #include <spdlog/sinks/msvc_sink.h> -#include <spdlog/sinks/rotating_file_sink.h> -#include <spdlog/sinks/stdout_color_sinks.h> -#if ZEN_USE_SENTRY -# include <sentry.h> -#endif ZEN_THIRD_PARTY_INCLUDES_END +#include <zencore/compactbinary.h> #include <zencore/filesystem.h> #include <zencore/string.h> +#include <zenutil/logging/fullformatter.h> +#include <zenutil/logging/jsonformatter.h> +#include <zenutil/logging/rotatingfilesink.h> #include <chrono> #include <memory> -// Custom logging -- test code, this should be tweaked - -namespace zen::logging { - -using namespace spdlog; -using namespace spdlog::details; -using namespace std::literals; - -class full_formatter final : public spdlog::formatter -{ -public: - full_formatter(std::string_view LogId, std::chrono::time_point<std::chrono::system_clock> Epoch) : m_Epoch(Epoch), m_LogId(LogId) {} - - virtual std::unique_ptr<formatter> clone() const override { return std::make_unique<full_formatter>(m_LogId, m_Epoch); } - - static constexpr bool UseDate = false; - - virtual void format(const details::log_msg& msg, memory_buf_t& dest) override - { - using std::chrono::duration_cast; - using std::chrono::milliseconds; - using std::chrono::seconds; - - if constexpr (UseDate) - { - auto secs = std::chrono::duration_cast<seconds>(msg.time.time_since_epoch()); - if (secs != m_LastLogSecs) - { - m_CachedTm = os::localtime(log_clock::to_time_t(msg.time)); - m_LastLogSecs = secs; - } - } - - const auto& tm_time = m_CachedTm; - - // cache the date/time part for the next second. - auto duration = msg.time - m_Epoch; - auto secs = duration_cast<seconds>(duration); - - if (m_CacheTimestamp != secs || m_CachedDatetime.size() == 0) - { - m_CachedDatetime.clear(); - m_CachedDatetime.push_back('['); - - if constexpr (UseDate) - { - fmt_helper::append_int(tm_time.tm_year + 1900, m_CachedDatetime); - m_CachedDatetime.push_back('-'); - - fmt_helper::pad2(tm_time.tm_mon + 1, m_CachedDatetime); - m_CachedDatetime.push_back('-'); - - fmt_helper::pad2(tm_time.tm_mday, m_CachedDatetime); - m_CachedDatetime.push_back(' '); - - fmt_helper::pad2(tm_time.tm_hour, m_CachedDatetime); - m_CachedDatetime.push_back(':'); - - fmt_helper::pad2(tm_time.tm_min, m_CachedDatetime); - m_CachedDatetime.push_back(':'); - - fmt_helper::pad2(tm_time.tm_sec, m_CachedDatetime); - } - else - { - int Count = int(secs.count()); - - const int LogSecs = Count % 60; - Count /= 60; - - const int LogMins = Count % 60; - Count /= 60; - - const int LogHours = Count; - - fmt_helper::pad2(LogHours, m_CachedDatetime); - m_CachedDatetime.push_back(':'); - fmt_helper::pad2(LogMins, m_CachedDatetime); - m_CachedDatetime.push_back(':'); - fmt_helper::pad2(LogSecs, m_CachedDatetime); - } - - m_CachedDatetime.push_back('.'); - - m_CacheTimestamp = secs; - } - - dest.append(m_CachedDatetime.begin(), m_CachedDatetime.end()); - - auto millis = fmt_helper::time_fraction<milliseconds>(msg.time); - fmt_helper::pad3(static_cast<uint32_t>(millis.count()), dest); - dest.push_back(']'); - dest.push_back(' '); - - if (!m_LogId.empty()) - { - dest.push_back('['); - fmt_helper::append_string_view(m_LogId, dest); - dest.push_back(']'); - dest.push_back(' '); - } - - // append logger name if exists - if (msg.logger_name.size() > 0) - { - dest.push_back('['); - fmt_helper::append_string_view(msg.logger_name, dest); - dest.push_back(']'); - dest.push_back(' '); - } - - dest.push_back('['); - // wrap the level name with color - msg.color_range_start = dest.size(); - fmt_helper::append_string_view(level::to_string_view(msg.level), dest); - msg.color_range_end = dest.size(); - dest.push_back(']'); - dest.push_back(' '); - - // add source location if present - if (!msg.source.empty()) - { - dest.push_back('['); - const char* filename = details::short_filename_formatter<details::null_scoped_padder>::basename(msg.source.filename); - fmt_helper::append_string_view(filename, dest); - dest.push_back(':'); - fmt_helper::append_int(msg.source.line, dest); - dest.push_back(']'); - dest.push_back(' '); - } - - fmt_helper::append_string_view(msg.payload, dest); - fmt_helper::append_string_view("\n"sv, dest); - } - -private: - std::chrono::time_point<std::chrono::system_clock> m_Epoch; - std::tm m_CachedTm; - std::chrono::seconds m_LastLogSecs; - std::chrono::seconds m_CacheTimestamp{0}; - memory_buf_t m_CachedDatetime; - std::string m_LogId; -}; - -class json_formatter final : public spdlog::formatter -{ -public: - json_formatter(std::string_view LogId) : m_LogId(LogId) {} - - virtual std::unique_ptr<formatter> clone() const override { return std::make_unique<json_formatter>(m_LogId); } - - virtual void format(const details::log_msg& msg, memory_buf_t& dest) override - { - using std::chrono::duration_cast; - using std::chrono::milliseconds; - using std::chrono::seconds; - - auto secs = std::chrono::duration_cast<seconds>(msg.time.time_since_epoch()); - if (secs != m_LastLogSecs) - { - m_CachedTm = os::localtime(log_clock::to_time_t(msg.time)); - m_LastLogSecs = secs; - } - - const auto& tm_time = m_CachedTm; - - // cache the date/time part for the next second. - - if (m_CacheTimestamp != secs || m_CachedDatetime.size() == 0) - { - m_CachedDatetime.clear(); - - fmt_helper::append_int(tm_time.tm_year + 1900, m_CachedDatetime); - m_CachedDatetime.push_back('-'); - - fmt_helper::pad2(tm_time.tm_mon + 1, m_CachedDatetime); - m_CachedDatetime.push_back('-'); - - fmt_helper::pad2(tm_time.tm_mday, m_CachedDatetime); - m_CachedDatetime.push_back(' '); - - fmt_helper::pad2(tm_time.tm_hour, m_CachedDatetime); - m_CachedDatetime.push_back(':'); - - fmt_helper::pad2(tm_time.tm_min, m_CachedDatetime); - m_CachedDatetime.push_back(':'); - - fmt_helper::pad2(tm_time.tm_sec, m_CachedDatetime); - - m_CachedDatetime.push_back('.'); - - m_CacheTimestamp = secs; - } - dest.append("{"sv); - dest.append("\"time\": \""sv); - dest.append(m_CachedDatetime.begin(), m_CachedDatetime.end()); - auto millis = fmt_helper::time_fraction<milliseconds>(msg.time); - fmt_helper::pad3(static_cast<uint32_t>(millis.count()), dest); - dest.append("\", "sv); - - dest.append("\"status\": \""sv); - dest.append(level::to_string_view(msg.level)); - dest.append("\", "sv); - - dest.append("\"source\": \""sv); - dest.append("zenserver"sv); - dest.append("\", "sv); - - dest.append("\"service\": \""sv); - dest.append("zencache"sv); - dest.append("\", "sv); - - if (!m_LogId.empty()) - { - dest.append("\"id\": \""sv); - dest.append(m_LogId); - dest.append("\", "sv); - } - - if (msg.logger_name.size() > 0) - { - dest.append("\"logger.name\": \""sv); - dest.append(msg.logger_name); - dest.append("\", "sv); - } - - if (msg.thread_id != 0) - { - dest.append("\"logger.thread_name\": \""sv); - fmt_helper::pad_uint(msg.thread_id, 0, dest); - dest.append("\", "sv); - } - - if (!msg.source.empty()) - { - dest.append("\"file\": \""sv); - WriteEscapedString(dest, details::short_filename_formatter<details::null_scoped_padder>::basename(msg.source.filename)); - dest.append("\","sv); - - dest.append("\"line\": \""sv); - dest.append(fmt::format("{}", msg.source.line)); - dest.append("\","sv); - - dest.append("\"logger.method_name\": \""sv); - WriteEscapedString(dest, msg.source.funcname); - dest.append("\", "sv); - } - - dest.append("\"message\": \""sv); - WriteEscapedString(dest, msg.payload); - dest.append("\""sv); - - dest.append("}\n"sv); - } +namespace zen { -private: - static inline const std::unordered_map<char, std::string_view> SpecialCharacterMap{{'\b', "\\b"sv}, - {'\f', "\\f"sv}, - {'\n', "\\n"sv}, - {'\r', "\\r"sv}, - {'\t', "\\t"sv}, - {'"', "\\\""sv}, - {'\\', "\\\\"sv}}; +spdlog::sink_ptr g_FileSink; - static void WriteEscapedString(memory_buf_t& dest, const spdlog::string_view_t& payload) - { - const char* RangeStart = payload.begin(); - for (const char* It = RangeStart; It != payload.end(); ++It) - { - if (auto SpecialIt = SpecialCharacterMap.find(*It); SpecialIt != SpecialCharacterMap.end()) - { - if (RangeStart != It) - { - dest.append(RangeStart, It); - } - dest.append(SpecialIt->second); - RangeStart = It + 1; - } - } - if (RangeStart != payload.end()) - { - dest.append(RangeStart, payload.end()); - } - }; - - std::tm m_CachedTm{0, 0, 0, 0, 0, 0, 0, 0, 0}; - std::chrono::seconds m_LastLogSecs{0}; - std::chrono::seconds m_CacheTimestamp{0}; - memory_buf_t m_CachedDatetime; - std::string m_LogId; -}; -} // namespace zen::logging - -bool -EnableVTMode() +spdlog::sink_ptr +GetFileSink() { -#if ZEN_PLATFORM_WINDOWS - // Set output mode to handle virtual terminal sequences - HANDLE hOut = GetStdHandle(STD_OUTPUT_HANDLE); - if (hOut == INVALID_HANDLE_VALUE) - { - return false; - } - - DWORD dwMode = 0; - if (!GetConsoleMode(hOut, &dwMode)) - { - return false; - } - - dwMode |= ENABLE_VIRTUAL_TERMINAL_PROCESSING; - if (!SetConsoleMode(hOut, dwMode)) - { - return false; - } -#endif - - return true; + return g_FileSink; } -#if ZEN_USE_SENTRY - -class sentry_sink final : public spdlog::sinks::base_sink<spdlog::details::null_mutex> +void +InitializeLogging(const LoggingOptions& LogOptions) { -public: - sentry_sink() {} - -protected: - static constexpr sentry_level_t MapToSentryLevel[spdlog::level::level_enum::n_levels] = {SENTRY_LEVEL_DEBUG, - SENTRY_LEVEL_DEBUG, - SENTRY_LEVEL_INFO, - SENTRY_LEVEL_WARNING, - SENTRY_LEVEL_ERROR, - SENTRY_LEVEL_FATAL, - SENTRY_LEVEL_DEBUG}; - - void sink_it_(const spdlog::details::log_msg& msg) override - { - if (msg.level >= SPDLOG_LEVEL_ERROR && msg.level <= SPDLOG_LEVEL_CRITICAL) - { - sentry_value_t event = sentry_value_new_message_event( - /* level */ MapToSentryLevel[msg.level], - /* logger */ nullptr, - /* message */ std::string(msg.payload.data(), msg.payload.size()).c_str()); - sentry_event_value_add_stacktrace(event, NULL, 0); - sentry_capture_event(event); - } - } - void flush_() override {} -}; -#endif - -namespace zen { + BeginInitializeLogging(LogOptions); + FinishInitializeLogging(LogOptions); +} void -InitializeLogging(const LoggingOptions& LogOptions) +BeginInitializeLogging(const LoggingOptions& LogOptions) { zen::logging::InitializeLogging(); + zen::logging::EnableVTMode(); - EnableVTMode(); - - bool IsAsync = true; - spdlog::level::level_enum LogLevel = spdlog::level::info; + bool IsAsync = true; if (LogOptions.IsDebug) { - LogLevel = spdlog::level::debug; - IsAsync = false; + IsAsync = false; } if (LogOptions.IsTest) { - LogLevel = spdlog::level::trace; - IsAsync = false; + IsAsync = false; } if (IsAsync) @@ -423,10 +66,7 @@ InitializeLogging(const LoggingOptions& LogOptions) // Sinks - auto ConsoleSink = std::make_shared<spdlog::sinks::ansicolor_stdout_sink_mt>(); - spdlog::sink_ptr FileSink; - spdlog::sink_ptr SentrySink; // spdlog can't create directories that starts with `\\?\` so we make sure the folder exists before creating the logger instance @@ -437,24 +77,12 @@ InitializeLogging(const LoggingOptions& LogOptions) zen::CreateDirectories(LogOptions.AbsLogFile.parent_path()); } -#if 0 - FileSink = std::make_shared<spdlog::sinks::daily_file_sink_mt>( zen::PathToUtf8(GlobalOptions.AbsLogFile), - 0, - 0, - /* truncate */ false, - uint16_t(/* max files */ 14)); -#else - FileSink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(zen::PathToUtf8(LogOptions.AbsLogFile), - /* max size */ 128 * 1024 * 1024, - /* max files */ 16, - /* rotate on open */ true); -#endif + FileSink = std::make_shared<zen::logging::RotatingFileSink>(zen::PathToUtf8(LogOptions.AbsLogFile), + /* max size */ 128 * 1024 * 1024, + /* max files */ 16, + /* rotate on open */ true); } -#if ZEN_USE_SENTRY - SentrySink = std::make_shared<sentry_sink>(); -#endif - std::set_terminate([]() { ZEN_CRITICAL("Program exited abnormally via std::terminate()"); }); // Default @@ -463,16 +91,20 @@ InitializeLogging(const LoggingOptions& LogOptions) auto& Sinks = DefaultLogger.sinks(); Sinks.clear(); - Sinks.push_back(ConsoleSink); - if (FileSink) + if (LogOptions.NoConsoleOutput) { - Sinks.push_back(FileSink); + zen::logging::SuppressConsoleLog(); + } + else + { + auto ConsoleSink = std::make_shared<spdlog::sinks::ansicolor_stdout_sink_mt>(); + Sinks.push_back(ConsoleSink); } - if (SentrySink) + if (FileSink) { - Sinks.push_back(SentrySink); + Sinks.push_back(FileSink); } #if ZEN_PLATFORM_WINDOWS @@ -484,13 +116,6 @@ InitializeLogging(const LoggingOptions& LogOptions) } #endif - // Configure all registered loggers according to settings - - spdlog::set_level(LogLevel); - spdlog::flush_on(spdlog::level::err); - spdlog::flush_every(std::chrono::seconds{2}); - spdlog::set_formatter(std::make_unique<logging::full_formatter>(LogOptions.LogId, std::chrono::system_clock::now())); - if (FileSink) { if (LogOptions.AbsLogFile.extension() == ".json") @@ -502,14 +127,73 @@ InitializeLogging(const LoggingOptions& LogOptions) FileSink->set_pattern("[%C-%m-%d.%e %T] [%n] [%l] %v"); } } - DefaultLogger.info("log starting at {:%FT%T%z}", std::chrono::system_clock::now()); + + spdlog::set_error_handler([](const std::string& msg) { + if (msg == std::bad_alloc().what()) + { + // Don't report out of memory in spdlog as we usually log in response to errors which will cause another OOM crashing the + // program + return; + } + // Bypass zen logging wrapping to reduce potential other error sources + if (auto ErrLogger = zen::logging::ErrorLog(); ErrLogger != nullptr) + { + try + { + ErrLogger->log(spdlog::level::err, msg); + } + catch (const std::exception&) + { + // Just ignore any errors when in error handler + } + } + try + { + Log().error(msg); + } + catch (const std::exception&) + { + // Just ignore any errors when in error handler + } + }); + + g_FileSink = std::move(FileSink); +} + +void +FinishInitializeLogging(const LoggingOptions& LogOptions) +{ + spdlog::level::level_enum LogLevel = spdlog::level::info; + + if (LogOptions.IsDebug) + { + LogLevel = spdlog::level::debug; + } + + if (LogOptions.IsTest) + { + LogLevel = spdlog::level::trace; + } + + // Configure all registered loggers according to settings + + spdlog::set_level(LogLevel); + spdlog::flush_on(spdlog::level::err); + spdlog::flush_every(std::chrono::seconds{2}); + spdlog::set_formatter(std::make_unique<logging::full_formatter>(LogOptions.LogId, std::chrono::system_clock::now())); + + const std::string StartLogTime = zen::DateTime::Now().ToIso8601(); + + spdlog::apply_all([&](auto Logger) { Logger->info("log starting at {}", StartLogTime); }); } void ShutdownLogging() { + g_FileSink.reset(); + auto& DefaultLogger = zen::logging::Default(); - DefaultLogger.info("log ending at {:%FT%T%z}", std::chrono::system_clock::now()); + DefaultLogger.info("log ending at {}", zen::DateTime::Now().ToIso8601()); zen::logging::ShutdownLogging(); } |