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

4 files changed, 617 insertions, 3 deletions

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