diff options
| author | Stefan Boberg <[email protected]> | 2023-10-25 17:42:16 +0200 |
|---|---|---|
| committer | GitHub <[email protected]> | 2023-10-25 17:42:16 +0200 |
| commit | 1fd6883e242522d0b822baf280873ebf98fd1c51 (patch) | |
| tree | 58650cb932e4a470042a5a3534e699b39536b5f3 /src | |
| parent | statsd metrics reporting (#496) (diff) | |
| download | zen-1fd6883e242522d0b822baf280873ebf98fd1c51.tar.xz zen-1fd6883e242522d0b822baf280873ebf98fd1c51.zip | |
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
Diffstat (limited to 'src')
| -rw-r--r-- | src/zencore/include/zencore/fmtutils.h | 11 | ||||
| -rw-r--r-- | src/zencore/logging.cpp | 4 | ||||
| -rw-r--r-- | src/zenserver/diag/logging.cpp | 750 | ||||
| -rw-r--r-- | src/zenserver/diag/logging.h | 4 | ||||
| -rw-r--r-- | src/zenserver/main.cpp | 4 | ||||
| -rw-r--r-- | src/zenutil/include/zenutil/logging.h | 21 | ||||
| -rw-r--r-- | src/zenutil/include/zenutil/logging/fullformatter.h | 157 | ||||
| -rw-r--r-- | src/zenutil/include/zenutil/logging/jsonformatter.h | 169 | ||||
| -rw-r--r-- | src/zenutil/include/zenutil/logging/rotatingfilesink.h | 273 | ||||
| -rw-r--r-- | src/zenutil/logging.cpp | 502 |
10 files changed, 759 insertions, 1136 deletions
diff --git a/src/zencore/include/zencore/fmtutils.h b/src/zencore/include/zencore/fmtutils.h index a927df866..3d29625be 100644 --- a/src/zencore/include/zencore/fmtutils.h +++ b/src/zencore/include/zencore/fmtutils.h @@ -58,9 +58,18 @@ struct fmt::formatter<std::filesystem::path> : formatter<string_view> template<typename FormatContext> auto format(const std::filesystem::path& Path, FormatContext& ctx) { + using namespace std::literals; + zen::ExtendableStringBuilder<128> String; String << Path.u8string(); - return fmt::formatter<string_view>::format(String.ToView(), ctx); + std::string_view PathView = String.ToView(); + + if (PathView.starts_with("\\\\?\\"sv)) + { + PathView.remove_prefix(4); + } + + return fmt::formatter<string_view>::format(PathView, ctx); } }; diff --git a/src/zencore/logging.cpp b/src/zencore/logging.cpp index ff37af368..c366df812 100644 --- a/src/zencore/logging.cpp +++ b/src/zencore/logging.cpp @@ -20,12 +20,14 @@ namespace zen::logging { spdlog::logger& Default() { + ZEN_ASSERT(TheDefaultLogger); return *TheDefaultLogger; } void SetDefault(std::shared_ptr<spdlog::logger> NewDefaultLogger) { + ZEN_ASSERT(NewDefaultLogger); spdlog::set_default_logger(NewDefaultLogger); TheDefaultLogger = spdlog::default_logger_raw(); } @@ -73,6 +75,7 @@ std::shared_ptr<spdlog::logger> TheErrorLogger; spdlog::logger* ErrorLog() { + // This may return nullptr return TheErrorLogger.get(); } @@ -93,6 +96,7 @@ ShutdownLogging() { spdlog::drop_all(); spdlog::shutdown(); + TheDefaultLogger = nullptr; } bool diff --git a/src/zenserver/diag/logging.cpp b/src/zenserver/diag/logging.cpp index a8e8fa38e..6a27ea13e 100644 --- a/src/zenserver/diag/logging.cpp +++ b/src/zenserver/diag/logging.cpp @@ -4,762 +4,74 @@ #include "config.h" -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/stdout_color_sinks.h> -ZEN_THIRD_PARTY_INCLUDES_END - -#include <zencore/compactbinary.h> #include <zencore/filesystem.h> #include <zencore/fmtutils.h> #include <zencore/session.h> #include <zencore/string.h> -#include <zenutil/basicfile.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); - } - -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}}; - - 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; -}; - -// Basically the same functionality as spdlog::sinks::rotating_file_sink with the biggest difference -// being that it just ignores any errors when writing/rotating files and keeps chugging on. -// It will keep trying to log, and if it starts to work it will continue to log. -class RotatingFileSink : public spdlog::sinks::sink -{ -public: - RotatingFileSink(const std::filesystem::path& BaseFilename, std::size_t MaxSize, std::size_t MaxFiles, bool RotateOnOpen = false) - : m_BasePath(BaseFilename.parent_path()) - , m_Stem(BaseFilename.stem().string()) - , m_Extension(BaseFilename.extension().string()) - , m_MaxSize(MaxSize) - , m_MaxFiles(MaxFiles) - { - std::filesystem::path RootFileName = GetFileName(0); - std::error_code Ec; - if (RotateOnOpen) - { - RwLock::ExclusiveLockScope RotateLock(m_Lock); - Rotate(RotateLock, Ec); - } - else - { - m_CurrentFile.Open(RootFileName, BasicFile::Mode::kWrite, Ec); - if (!Ec) - { - m_CurrentSize = m_CurrentFile.FileSize(Ec); - } - if (!Ec) - { - if (m_CurrentSize > m_MaxSize) - { - RwLock::ExclusiveLockScope RotateLock(m_Lock); - Rotate(RotateLock, Ec); - } - } - } - - if (Ec) - { - throw std::system_error(Ec, fmt::format("Failed to open log file '{}'", RootFileName.string())); - } - } - - virtual ~RotatingFileSink() - { - try - { - RwLock::ExclusiveLockScope RotateLock(m_Lock); - m_CurrentFile.Close(); - } - catch (std::exception&) - { - } - } - - RotatingFileSink(const RotatingFileSink&) = delete; - RotatingFileSink(RotatingFileSink&&) = delete; - - RotatingFileSink& operator=(const RotatingFileSink&) = delete; - RotatingFileSink& operator=(RotatingFileSink&&) = delete; - - virtual void log(const details::log_msg& msg) override - { - try - { - memory_buf_t Formatted; - if (TrySinkIt(msg, Formatted)) - { - return; - } - while (true) - { - { - RwLock::ExclusiveLockScope RotateLock(m_Lock); - // Only rotate if no-one else has rotated before us - if (m_CurrentSize > m_MaxSize || !m_CurrentFile.IsOpen()) - { - std::error_code Ec; - Rotate(RotateLock, Ec); - if (Ec) - { - return; - } - } - } - if (TrySinkIt(Formatted)) - { - return; - } - } - } - catch (std::exception&) - { - // Silently eat errors - } - } - virtual void flush() override - { - try - { - RwLock::SharedLockScope Lock(m_Lock); - if (m_CurrentFile.IsOpen()) - { - m_CurrentFile.Flush(); - } - } - catch (std::exception&) - { - // Silently eat errors - } - } - - virtual void set_pattern(const std::string& pattern) override - { - try - { - RwLock::ExclusiveLockScope _(m_Lock); - m_Formatter = details::make_unique<spdlog::pattern_formatter>(pattern); - } - catch (std::exception&) - { - // Silently eat errors - } - } - virtual void set_formatter(std::unique_ptr<spdlog::formatter> sink_formatter) override - { - try - { - RwLock::ExclusiveLockScope _(m_Lock); - m_Formatter = std::move(sink_formatter); - } - catch (std::exception&) - { - // Silently eat errors - } - } - -private: - static bool IsEmpty(const std::filesystem::path& Path, std::error_code& Ec) - { - bool Exists = std::filesystem::exists(Path, Ec); - if (Ec) - { - return false; - } - if (!Exists) - { - return true; - } - uintmax_t Size = std::filesystem::file_size(Path, Ec); - if (Ec) - { - return false; - } - return Size == 0; - } - - void Rotate(RwLock::ExclusiveLockScope&, std::error_code& OutEc) - { - m_CurrentFile.Close(); - bool BaseIsEmpty = IsEmpty(GetFileName(0), OutEc); - if (OutEc) - { - return; - } - if (!BaseIsEmpty) - { - // We try our best to rotate the logs, if we fail we fail and will try to open the base log file anyway - for (auto i = m_MaxFiles; i > 0; i--) - { - std::filesystem::path src = GetFileName(i - 1); - if (!std::filesystem::exists(src)) - { - continue; - } - std::error_code DummyEc; - std::filesystem::path target = GetFileName(i); - if (std::filesystem::exists(target, DummyEc)) - { - std::filesystem::remove(target, DummyEc); - } - std::filesystem::rename(src, target, DummyEc); - } - } - m_CurrentFile.Open(GetFileName(0), BasicFile::Mode::kWrite, OutEc); - if (OutEc) - { - return; - } - // If we fail to rotate, try extending the current log file - m_CurrentSize = m_CurrentFile.FileSize(OutEc); - } - - bool TrySinkIt(const details::log_msg& msg, memory_buf_t& OutFormatted) - { - RwLock::SharedLockScope Lock(m_Lock); - if (!m_CurrentFile.IsOpen()) - { - return false; - } - m_Formatter->format(msg, OutFormatted); - size_t add_size = OutFormatted.size(); - size_t write_pos = m_CurrentSize.fetch_add(add_size); - if (write_pos + add_size > m_MaxSize) - { - return false; - } - std::error_code Ec; - m_CurrentFile.Write(OutFormatted.data(), OutFormatted.size(), write_pos, Ec); - if (Ec) - { - return false; - } - return true; - } - - bool TrySinkIt(const memory_buf_t& Formatted) - { - RwLock::SharedLockScope Lock(m_Lock); - if (!m_CurrentFile.IsOpen()) - { - return false; - } - size_t add_size = Formatted.size(); - size_t write_pos = m_CurrentSize.fetch_add(add_size); - if (write_pos + add_size > m_MaxSize) - { - return false; - } - - std::error_code Ec; - m_CurrentFile.Write(Formatted.data(), Formatted.size(), write_pos, Ec); - if (Ec) - { - return false; - } - return true; - } - - std::filesystem::path GetFileName(size_t Index) const - { - if (Index == 0) - { - return m_BasePath / (m_Stem + m_Extension); - } - return m_BasePath / fmt::format("{}.{}{}", m_Stem, Index, m_Extension); - } - - RwLock m_Lock; - const std::filesystem::path m_BasePath; - const std::string m_Stem; - const std::string m_Extension; - std::unique_ptr<spdlog::formatter> m_Formatter; - std::atomic_size_t m_CurrentSize; - const std::size_t m_MaxSize; - const std::size_t m_MaxFiles; - BasicFile m_CurrentFile; -}; - -} // namespace zen::logging +#include <zenutil/logging.h> +#include <zenutil/logging/rotatingfilesink.h> namespace zen { void -InitializeLogging(const ZenServerOptions& GlobalOptions) +InitializeServerLogging(const ZenServerOptions& InOptions) { - zen::logging::InitializeLogging(); - zen::logging::EnableVTMode(); - - bool IsAsync = true; - spdlog::level::level_enum LogLevel = spdlog::level::info; - - if (GlobalOptions.IsDebug) - { - LogLevel = spdlog::level::debug; - IsAsync = false; - } - - if (GlobalOptions.IsTest) - { - LogLevel = spdlog::level::trace; - IsAsync = false; - } - - if (IsAsync) - { - const int QueueSize = 8192; - const int ThreadCount = 1; - spdlog::init_thread_pool(QueueSize, ThreadCount); - - auto AsyncLogger = spdlog::create_async<spdlog::sinks::ansicolor_stdout_sink_mt>("main"); - zen::logging::SetDefault(AsyncLogger); - } + const LoggingOptions LogOptions = {.IsDebug = InOptions.IsDebug, + .IsVerbose = false, + .IsTest = InOptions.IsTest, + .NoConsoleOutput = InOptions.NoConsoleOutput, + .AbsLogFile = InOptions.AbsLogFile, + .LogId = InOptions.LogId}; - // Sinks + BeginInitializeLogging(LogOptions); - // spdlog can't create directories that starts with `\\?\` so we make sure the folder exists before creating the logger instance - zen::CreateDirectories(GlobalOptions.AbsLogFile.parent_path()); + // Initialize loggers -#if 0 - auto FileSink = std::make_shared<spdlog::sinks::daily_file_sink_mt>(zen::PathToUtf8(GlobalOptions.AbsLogFile), - 0, - 0, - /* truncate */ false, - uint16_t(/* max files */ 14)); -#else - auto FileSink = std::make_shared<zen::logging::RotatingFileSink>(zen::PathToUtf8(GlobalOptions.AbsLogFile), - /* max size */ 128 * 1024 * 1024, - /* max files */ 16, - /* rotate on open */ true); -#endif - - std::set_terminate([]() { ZEN_CRITICAL("Program exited abnormally via std::terminate()"); }); - - // Default - - auto& DefaultLogger = zen::logging::Default(); - auto& Sinks = DefaultLogger.sinks(); - - Sinks.clear(); - - if (GlobalOptions.NoConsoleOutput) - { - zen::logging::SuppressConsoleLog(); - } - else - { - auto ConsoleSink = std::make_shared<spdlog::sinks::ansicolor_stdout_sink_mt>(); - Sinks.push_back(ConsoleSink); - } - - Sinks.push_back(FileSink); - -#if ZEN_PLATFORM_WINDOWS - if (zen::IsDebuggerPresent() && GlobalOptions.IsDebug) - { - auto DebugSink = std::make_shared<spdlog::sinks::msvc_sink_mt>(); - DebugSink->set_level(spdlog::level::debug); - Sinks.push_back(DebugSink); - } -#endif - - std::vector<std::shared_ptr<spdlog::logger>> KnownLoggers{spdlog::default_logger()}; - - auto RegisterLogger = [&](std::shared_ptr<spdlog::logger> Logger) { - spdlog::register_logger(Logger); - KnownLoggers.push_back(Logger); - }; + auto FileSink = GetFileSink(); // HTTP server request logging - std::filesystem::path HttpLogPath = GlobalOptions.DataDir / "logs" / "http.log"; - // spdlog can't create directories that starts with `\\?\` so we make sure the folder exists before creating the logger instance + std::filesystem::path HttpLogPath = InOptions.DataDir / "logs" / "http.log"; zen::CreateDirectories(HttpLogPath.parent_path()); - auto HttpSink = std::make_shared<zen::logging::RotatingFileSink>(zen::PathToUtf8(HttpLogPath), - /* max size */ 128 * 1024 * 1024, - /* max files */ 16, - /* rotate on open */ true); + auto HttpSink = std::make_shared<zen::logging::RotatingFileSink>(zen::PathToUtf8(HttpLogPath), + /* max size */ 128 * 1024 * 1024, + /* max files */ 16, + /* rotate on open */ true); auto HttpLogger = std::make_shared<spdlog::logger>("http_requests", HttpSink); - RegisterLogger(HttpLogger); + spdlog::register_logger(HttpLogger); // Cache request logging - std::filesystem::path CacheLogPath = GlobalOptions.DataDir / "logs" / "z$.log"; + std::filesystem::path CacheLogPath = InOptions.DataDir / "logs" / "z$.log"; zen::CreateDirectories(CacheLogPath.parent_path()); - auto CacheSink = std::make_shared<zen::logging::RotatingFileSink>(zen::PathToUtf8(CacheLogPath), - /* max size */ 128 * 1024 * 1024, - /* max files */ 16, - /* rotate on open */ false); + auto CacheSink = std::make_shared<zen::logging::RotatingFileSink>(zen::PathToUtf8(CacheLogPath), + /* max size */ 128 * 1024 * 1024, + /* max files */ 16, + /* rotate on open */ false); auto CacheLogger = std::make_shared<spdlog::logger>("z$", CacheSink); - RegisterLogger(CacheLogger); + spdlog::register_logger(CacheLogger); // Jupiter - only log upstream HTTP traffic to file auto JupiterLogger = std::make_shared<spdlog::logger>("jupiter", FileSink); - RegisterLogger(JupiterLogger); + spdlog::register_logger(JupiterLogger); // Zen - only log upstream HTTP traffic to file auto ZenClientLogger = std::make_shared<spdlog::logger>("zenclient", FileSink); - RegisterLogger(ZenClientLogger); - - // 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>(GlobalOptions.LogId, std::chrono::system_clock::now())); - - if (GlobalOptions.AbsLogFile.extension() == ".json") - { - FileSink->set_formatter(std::make_unique<logging::json_formatter>(GlobalOptions.LogId)); - } - else - { - FileSink->set_pattern("[%C-%m-%d.%e %T] [%n] [%l] %v"); - } + spdlog::register_logger(ZenClientLogger); - 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 - } - }); + FinishInitializeLogging(LogOptions); - const std::string StartLogTime = zen::DateTime::Now().ToIso8601(); - const zen::Oid ServerSessionId = zen::GetSessionId(); + const zen::Oid ServerSessionId = zen::GetSessionId(); - for (auto& Logger : KnownLoggers) - { - Logger->info("log starting at {}", StartLogTime); - Logger->info("server session id: {}", ServerSessionId); - } + spdlog::apply_all([&](auto Logger) { Logger->info("server session id: {}", ServerSessionId); }); } void -ShutdownLogging() +ShutdownServerLogging() { - auto& DefaultLogger = zen::logging::Default(); - DefaultLogger.info("log ending at {}", zen::DateTime::Now().ToIso8601()); - zen::logging::ShutdownLogging(); + zen::ShutdownLogging(); } } // namespace zen diff --git a/src/zenserver/diag/logging.h b/src/zenserver/diag/logging.h index 91b74a094..46aab100f 100644 --- a/src/zenserver/diag/logging.h +++ b/src/zenserver/diag/logging.h @@ -8,7 +8,7 @@ namespace zen { struct ZenServerOptions; -void InitializeLogging(const ZenServerOptions& GlobalOptions); -void ShutdownLogging(); +void InitializeServerLogging(const ZenServerOptions& LogOptions); +void ShutdownServerLogging(); } // namespace zen diff --git a/src/zenserver/main.cpp b/src/zenserver/main.cpp index f482e6737..b83964319 100644 --- a/src/zenserver/main.cpp +++ b/src/zenserver/main.cpp @@ -150,7 +150,7 @@ ZenEntryPoint::Run() std::exit(99); } - InitializeLogging(m_ServerOptions); + InitializeServerLogging(m_ServerOptions); #if ZEN_USE_SENTRY Sentry.LogStartupInformation(); @@ -251,7 +251,7 @@ ZenEntryPoint::Run() } } - ShutdownLogging(); + ShutdownServerLogging(); return ApplicationExitCode(); } diff --git a/src/zenutil/include/zenutil/logging.h b/src/zenutil/include/zenutil/logging.h index 6f408f512..ebf6372fc 100644 --- a/src/zenutil/include/zenutil/logging.h +++ b/src/zenutil/include/zenutil/logging.h @@ -5,8 +5,17 @@ #include <zencore/logging.h> #include <filesystem> +#include <memory> #include <string> +namespace spdlog::sinks { +class sink; +} + +namespace spdlog { +using sink_ptr = std::shared_ptr<sinks::sink>; +} + ////////////////////////////////////////////////////////////////////////// // // Logging utilities @@ -20,14 +29,20 @@ namespace zen { struct LoggingOptions { - bool IsDebug = false; - bool IsVerbose = false; - bool IsTest = false; + bool IsDebug = false; + bool IsVerbose = false; + bool IsTest = false; + bool NoConsoleOutput = false; std::filesystem::path AbsLogFile; // Absolute path to main log file std::string LogId; }; +void BeginInitializeLogging(const LoggingOptions& LoggingOptions); +void FinishInitializeLogging(const LoggingOptions& LoggingOptions); + void InitializeLogging(const LoggingOptions& LoggingOptions); void ShutdownLogging(); +spdlog::sink_ptr GetFileSink(); + } // namespace zen diff --git a/src/zenutil/include/zenutil/logging/fullformatter.h b/src/zenutil/include/zenutil/logging/fullformatter.h new file mode 100644 index 000000000..9ddb8067e --- /dev/null +++ b/src/zenutil/include/zenutil/logging/fullformatter.h @@ -0,0 +1,157 @@ +// Copyright Epic Games, Inc. All Rights Reserved. + +#pragma once + +#include <zencore/zencore.h> + +#include <spdlog/formatter.h> +#include <spdlog/logger.h> +#include <string_view> + +ZEN_THIRD_PARTY_INCLUDES_START +#include <spdlog/pattern_formatter.h> +ZEN_THIRD_PARTY_INCLUDES_END + +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; +}; + +} // namespace zen::logging diff --git a/src/zenutil/include/zenutil/logging/jsonformatter.h b/src/zenutil/include/zenutil/logging/jsonformatter.h new file mode 100644 index 000000000..5f7d4853d --- /dev/null +++ b/src/zenutil/include/zenutil/logging/jsonformatter.h @@ -0,0 +1,169 @@ +// Copyright Epic Games, Inc. All Rights Reserved. + +#pragma once + +#include <zencore/zencore.h> + +#include <spdlog/formatter.h> +#include <spdlog/logger.h> +#include <string_view> + +ZEN_THIRD_PARTY_INCLUDES_START +#include <spdlog/pattern_formatter.h> +ZEN_THIRD_PARTY_INCLUDES_END + +namespace zen::logging { + +using namespace std::literals; + +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 spdlog::details::log_msg& msg, spdlog::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 = spdlog::details::os::localtime(spdlog::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(); + + spdlog::details::fmt_helper::append_int(tm_time.tm_year + 1900, m_CachedDatetime); + m_CachedDatetime.push_back('-'); + + spdlog::details::fmt_helper::pad2(tm_time.tm_mon + 1, m_CachedDatetime); + m_CachedDatetime.push_back('-'); + + spdlog::details::fmt_helper::pad2(tm_time.tm_mday, m_CachedDatetime); + m_CachedDatetime.push_back(' '); + + spdlog::details::fmt_helper::pad2(tm_time.tm_hour, m_CachedDatetime); + m_CachedDatetime.push_back(':'); + + spdlog::details::fmt_helper::pad2(tm_time.tm_min, m_CachedDatetime); + m_CachedDatetime.push_back(':'); + + spdlog::details::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 = spdlog::details::fmt_helper::time_fraction<milliseconds>(msg.time); + spdlog::details::fmt_helper::pad3(static_cast<uint32_t>(millis.count()), dest); + dest.append("\", "sv); + + dest.append("\"status\": \""sv); + dest.append(spdlog::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); + spdlog::details::fmt_helper::pad_uint(msg.thread_id, 0, dest); + dest.append("\", "sv); + } + + if (!msg.source.empty()) + { + dest.append("\"file\": \""sv); + WriteEscapedString( + dest, + spdlog::details::short_filename_formatter<spdlog::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); + } + +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}}; + + static void WriteEscapedString(spdlog::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}; + spdlog::memory_buf_t m_CachedDatetime; + std::string m_LogId; +}; + +} // namespace zen::logging
\ No newline at end of file diff --git a/src/zenutil/include/zenutil/logging/rotatingfilesink.h b/src/zenutil/include/zenutil/logging/rotatingfilesink.h new file mode 100644 index 000000000..9468addee --- /dev/null +++ b/src/zenutil/include/zenutil/logging/rotatingfilesink.h @@ -0,0 +1,273 @@ +// Copyright Epic Games, Inc. All Rights Reserved. + +#pragma once + +#include <zenutil/basicfile.h> + +#include <spdlog/details/log_msg.h> +#include <spdlog/sinks/base_sink.h> + +#include <filesystem> + +namespace zen::logging { + +// Basically the same functionality as spdlog::sinks::rotating_file_sink with the biggest difference +// being that it just ignores any errors when writing/rotating files and keeps chugging on. +// It will keep trying to log, and if it starts to work it will continue to log. +class RotatingFileSink : public spdlog::sinks::sink +{ +public: + RotatingFileSink(const std::filesystem::path& BaseFilename, std::size_t MaxSize, std::size_t MaxFiles, bool RotateOnOpen = false) + : m_BasePath(BaseFilename.parent_path()) + , m_Stem(BaseFilename.stem().string()) + , m_Extension(BaseFilename.extension().string()) + , m_MaxSize(MaxSize) + , m_MaxFiles(MaxFiles) + { + std::filesystem::path RootFileName = GetFileName(0); + std::error_code Ec; + if (RotateOnOpen) + { + RwLock::ExclusiveLockScope RotateLock(m_Lock); + Rotate(RotateLock, Ec); + } + else + { + m_CurrentFile.Open(RootFileName, BasicFile::Mode::kWrite, Ec); + if (!Ec) + { + m_CurrentSize = m_CurrentFile.FileSize(Ec); + } + if (!Ec) + { + if (m_CurrentSize > m_MaxSize) + { + RwLock::ExclusiveLockScope RotateLock(m_Lock); + Rotate(RotateLock, Ec); + } + } + } + + if (Ec) + { + throw std::system_error(Ec, fmt::format("Failed to open log file '{}'", RootFileName.string())); + } + } + + virtual ~RotatingFileSink() + { + try + { + RwLock::ExclusiveLockScope RotateLock(m_Lock); + m_CurrentFile.Close(); + } + catch (std::exception&) + { + } + } + + RotatingFileSink(const RotatingFileSink&) = delete; + RotatingFileSink(RotatingFileSink&&) = delete; + + RotatingFileSink& operator=(const RotatingFileSink&) = delete; + RotatingFileSink& operator=(RotatingFileSink&&) = delete; + + virtual void log(const spdlog::details::log_msg& msg) override + { + try + { + spdlog::memory_buf_t Formatted; + if (TrySinkIt(msg, Formatted)) + { + return; + } + while (true) + { + { + RwLock::ExclusiveLockScope RotateLock(m_Lock); + // Only rotate if no-one else has rotated before us + if (m_CurrentSize > m_MaxSize || !m_CurrentFile.IsOpen()) + { + std::error_code Ec; + Rotate(RotateLock, Ec); + if (Ec) + { + return; + } + } + } + if (TrySinkIt(Formatted)) + { + return; + } + } + } + catch (std::exception&) + { + // Silently eat errors + } + } + virtual void flush() override + { + try + { + RwLock::SharedLockScope Lock(m_Lock); + if (m_CurrentFile.IsOpen()) + { + m_CurrentFile.Flush(); + } + } + catch (std::exception&) + { + // Silently eat errors + } + } + + virtual void set_pattern(const std::string& pattern) override + { + try + { + RwLock::ExclusiveLockScope _(m_Lock); + m_Formatter = spdlog::details::make_unique<spdlog::pattern_formatter>(pattern); + } + catch (std::exception&) + { + // Silently eat errors + } + } + virtual void set_formatter(std::unique_ptr<spdlog::formatter> sink_formatter) override + { + try + { + RwLock::ExclusiveLockScope _(m_Lock); + m_Formatter = std::move(sink_formatter); + } + catch (std::exception&) + { + // Silently eat errors + } + } + +private: + static bool IsEmpty(const std::filesystem::path& Path, std::error_code& Ec) + { + bool Exists = std::filesystem::exists(Path, Ec); + if (Ec) + { + return false; + } + if (!Exists) + { + return true; + } + uintmax_t Size = std::filesystem::file_size(Path, Ec); + if (Ec) + { + return false; + } + return Size == 0; + } + + void Rotate(RwLock::ExclusiveLockScope&, std::error_code& OutEc) + { + m_CurrentFile.Close(); + bool BaseIsEmpty = IsEmpty(GetFileName(0), OutEc); + if (OutEc) + { + return; + } + if (!BaseIsEmpty) + { + // We try our best to rotate the logs, if we fail we fail and will try to open the base log file anyway + for (auto i = m_MaxFiles; i > 0; i--) + { + std::filesystem::path src = GetFileName(i - 1); + if (!std::filesystem::exists(src)) + { + continue; + } + std::error_code DummyEc; + std::filesystem::path target = GetFileName(i); + if (std::filesystem::exists(target, DummyEc)) + { + std::filesystem::remove(target, DummyEc); + } + std::filesystem::rename(src, target, DummyEc); + } + } + m_CurrentFile.Open(GetFileName(0), BasicFile::Mode::kWrite, OutEc); + if (OutEc) + { + return; + } + // If we fail to rotate, try extending the current log file + m_CurrentSize = m_CurrentFile.FileSize(OutEc); + } + + bool TrySinkIt(const spdlog::details::log_msg& msg, spdlog::memory_buf_t& OutFormatted) + { + RwLock::SharedLockScope Lock(m_Lock); + if (!m_CurrentFile.IsOpen()) + { + return false; + } + m_Formatter->format(msg, OutFormatted); + size_t add_size = OutFormatted.size(); + size_t write_pos = m_CurrentSize.fetch_add(add_size); + if (write_pos + add_size > m_MaxSize) + { + return false; + } + std::error_code Ec; + m_CurrentFile.Write(OutFormatted.data(), OutFormatted.size(), write_pos, Ec); + if (Ec) + { + return false; + } + return true; + } + + bool TrySinkIt(const spdlog::memory_buf_t& Formatted) + { + RwLock::SharedLockScope Lock(m_Lock); + if (!m_CurrentFile.IsOpen()) + { + return false; + } + size_t add_size = Formatted.size(); + size_t write_pos = m_CurrentSize.fetch_add(add_size); + if (write_pos + add_size > m_MaxSize) + { + return false; + } + + std::error_code Ec; + m_CurrentFile.Write(Formatted.data(), Formatted.size(), write_pos, Ec); + if (Ec) + { + return false; + } + return true; + } + + std::filesystem::path GetFileName(size_t Index) const + { + if (Index == 0) + { + return m_BasePath / (m_Stem + m_Extension); + } + return m_BasePath / fmt::format("{}.{}{}", m_Stem, Index, m_Extension); + } + + RwLock m_Lock; + const std::filesystem::path m_BasePath; + const std::string m_Stem; + const std::string m_Extension; + std::unique_ptr<spdlog::formatter> m_Formatter; + std::atomic_size_t m_CurrentSize; + const std::size_t m_MaxSize; + const std::size_t m_MaxFiles; + BasicFile m_CurrentFile; +}; + +} // namespace zen::logging 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(); } |