From 1fd6883e242522d0b822baf280873ebf98fd1c51 Mon Sep 17 00:00:00 2001 From: Stefan Boberg Date: Wed, 25 Oct 2023 17:42:16 +0200 Subject: eliminate redundant logging code (#499) zenutil and zenserver both contain very similar logging setup code and this change aims to make them have most code in common. * fullformatter/jsonformatter/RotatingFileSink are moved into dedicated header files in zenutil * zenserver `InitializeLogging`/`ShutdownLogging` are renamed `InitializeServerLogging`/`InitializeServerLogging` * these now call into the common zenutil `BeginInitializeLogging`/`FinishInitializeLogging` in addition to setting up server custom logging * `std::filesystem::path` is now logged after stripping any `\\\\?\\` prefix for readability --- src/zenutil/logging.cpp | 502 +++++++++--------------------------------------- 1 file changed, 93 insertions(+), 409 deletions(-) (limited to 'src/zenutil/logging.cpp') 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 #include -#include #include -#include -#include #include -#include -#include -#if ZEN_USE_SENTRY -# include -#endif ZEN_THIRD_PARTY_INCLUDES_END +#include #include #include +#include +#include +#include #include #include -// 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 Epoch) : m_Epoch(Epoch), m_LogId(LogId) {} - - virtual std::unique_ptr clone() const override { return std::make_unique(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(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(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(msg.time); - fmt_helper::pad3(static_cast(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::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 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 clone() const override { return std::make_unique(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(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(msg.time); - fmt_helper::pad3(static_cast(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::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 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 +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::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( zen::PathToUtf8(GlobalOptions.AbsLogFile), - 0, - 0, - /* truncate */ false, - uint16_t(/* max files */ 14)); -#else - FileSink = std::make_shared(zen::PathToUtf8(LogOptions.AbsLogFile), - /* max size */ 128 * 1024 * 1024, - /* max files */ 16, - /* rotate on open */ true); -#endif + FileSink = std::make_shared(zen::PathToUtf8(LogOptions.AbsLogFile), + /* max size */ 128 * 1024 * 1024, + /* max files */ 16, + /* rotate on open */ true); } -#if ZEN_USE_SENTRY - SentrySink = std::make_shared(); -#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(); + 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(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(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(); } -- cgit v1.2.3