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

1 files changed, 93 insertions, 409 deletions

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