aboutsummaryrefslogtreecommitdiff
path: root/src
diff options
context:
space:
mode:
authorStefan Boberg <[email protected]>2023-10-25 17:42:16 +0200
committerGitHub <[email protected]>2023-10-25 17:42:16 +0200
commit1fd6883e242522d0b822baf280873ebf98fd1c51 (patch)
tree58650cb932e4a470042a5a3534e699b39536b5f3 /src
parentstatsd metrics reporting (#496) (diff)
downloadzen-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.h11
-rw-r--r--src/zencore/logging.cpp4
-rw-r--r--src/zenserver/diag/logging.cpp750
-rw-r--r--src/zenserver/diag/logging.h4
-rw-r--r--src/zenserver/main.cpp4
-rw-r--r--src/zenutil/include/zenutil/logging.h21
-rw-r--r--src/zenutil/include/zenutil/logging/fullformatter.h157
-rw-r--r--src/zenutil/include/zenutil/logging/jsonformatter.h169
-rw-r--r--src/zenutil/include/zenutil/logging/rotatingfilesink.h273
-rw-r--r--src/zenutil/logging.cpp502
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();
}