spdlog implementation hiding (#498)

this change aims to hide logging internals from client code, in order to make it easier to extend and take more control over the logging process in the future. 

As a bonus side effect, the generated code is much tighter (net delta around 2.5% on the resulting executable which includes lots of thirdparty code) and should take less time to compile and link.

Client usage via macros is pretty much unchanged. The main exposure client code had to spdlog internals before was the use of custom loggers per subsystem, where it would be common to have `spdlog::logger` references to keep a reference to a logger within a class. This is now replaced by `zen::LoggerRef` which currently simply encapsulates an actual `spdlog::logger` instance, but this is intended to be an implementation detail which will change in the future.

The way the change works is that we now handle any formatting of log messages in the zencore logging subsystem instead of relying on `spdlog` to manage this. We use the `fmt` library to do the formatting which means the client usage is identical to using `spdlog`. The formatted message is then forwarded onto any sinks etc which are still implememted via `spdlog`.

3 files changed, 175 insertions, 37 deletions

diff --git a/src/zenutil/include/zenutil/logging/fullformatter.h b/src/zenutil/include/zenutil/logging/fullformatter.h
index 9ddb8067e..498ecd143 100644
--- a/src/zenutil/include/zenutil/logging/fullformatter.h
+++ b/src/zenutil/include/zenutil/logging/fullformatter.h
@@ -4,20 +4,15 @@
 
 #include <zencore/zencore.h>
 
-#include <spdlog/formatter.h>
-#include <spdlog/logger.h>
 #include <string_view>
 
 ZEN_THIRD_PARTY_INCLUDES_START
+#include <spdlog/formatter.h>
 #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:
@@ -27,18 +22,16 @@ public:
 
 	static constexpr bool UseDate = false;
 
-	virtual void format(const details::log_msg& msg, memory_buf_t& dest) override
+	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;
+		using namespace std::literals;
 
 		if constexpr (UseDate)
 		{
-			auto secs = std::chrono::duration_cast<seconds>(msg.time.time_since_epoch());
+			auto secs = std::chrono::duration_cast<std::chrono::seconds>(msg.time.time_since_epoch());
 			if (secs != m_LastLogSecs)
 			{
-				m_CachedTm	  = os::localtime(log_clock::to_time_t(msg.time));
+				m_CachedTm	  = spdlog::details::os::localtime(spdlog::log_clock::to_time_t(msg.time));
 				m_LastLogSecs = secs;
 			}
 		}
@@ -47,7 +40,7 @@ public:
 
 		// cache the date/time part for the next second.
 		auto duration = msg.time - m_Epoch;
-		auto secs	  = duration_cast<seconds>(duration);
+		auto secs	  = std::chrono::duration_cast<std::chrono::seconds>(duration);
 
 		if (m_CacheTimestamp != secs || m_CachedDatetime.size() == 0)
 		{
@@ -56,22 +49,22 @@ public:
 
 			if constexpr (UseDate)
 			{
-				fmt_helper::append_int(tm_time.tm_year + 1900, m_CachedDatetime);
+				spdlog::details::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);
+				spdlog::details::fmt_helper::pad2(tm_time.tm_mon + 1, m_CachedDatetime);
 				m_CachedDatetime.push_back('-');
 
-				fmt_helper::pad2(tm_time.tm_mday, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(tm_time.tm_mday, m_CachedDatetime);
 				m_CachedDatetime.push_back(' ');
 
-				fmt_helper::pad2(tm_time.tm_hour, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(tm_time.tm_hour, m_CachedDatetime);
 				m_CachedDatetime.push_back(':');
 
-				fmt_helper::pad2(tm_time.tm_min, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(tm_time.tm_min, m_CachedDatetime);
 				m_CachedDatetime.push_back(':');
 
-				fmt_helper::pad2(tm_time.tm_sec, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(tm_time.tm_sec, m_CachedDatetime);
 			}
 			else
 			{
@@ -85,11 +78,11 @@ public:
 
 				const int LogHours = Count;
 
-				fmt_helper::pad2(LogHours, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(LogHours, m_CachedDatetime);
 				m_CachedDatetime.push_back(':');
-				fmt_helper::pad2(LogMins, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(LogMins, m_CachedDatetime);
 				m_CachedDatetime.push_back(':');
-				fmt_helper::pad2(LogSecs, m_CachedDatetime);
+				spdlog::details::fmt_helper::pad2(LogSecs, m_CachedDatetime);
 			}
 
 			m_CachedDatetime.push_back('.');
@@ -99,15 +92,15 @@ public:
 
 		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);
+		auto millis = spdlog::details::fmt_helper::time_fraction<std::chrono::milliseconds>(msg.time);
+		spdlog::details::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);
+			spdlog::details::fmt_helper::append_string_view(m_LogId, dest);
 			dest.push_back(']');
 			dest.push_back(' ');
 		}
@@ -116,7 +109,7 @@ public:
 		if (msg.logger_name.size() > 0)
 		{
 			dest.push_back('[');
-			fmt_helper::append_string_view(msg.logger_name, dest);
+			spdlog::details::fmt_helper::append_string_view(msg.logger_name, dest);
 			dest.push_back(']');
 			dest.push_back(' ');
 		}
@@ -124,7 +117,7 @@ public:
 		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);
+		spdlog::details::fmt_helper::append_string_view(spdlog::level::to_string_view(msg.level), dest);
 		msg.color_range_end = dest.size();
 		dest.push_back(']');
 		dest.push_back(' ');
@@ -133,16 +126,17 @@ public:
 		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);
+			const char* filename =
+				spdlog::details::short_filename_formatter<spdlog::details::null_scoped_padder>::basename(msg.source.filename);
+			spdlog::details::fmt_helper::append_string_view(filename, dest);
 			dest.push_back(':');
-			fmt_helper::append_int(msg.source.line, dest);
+			spdlog::details::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);
+		spdlog::details::fmt_helper::append_string_view(msg.payload, dest);
+		spdlog::details::fmt_helper::append_string_view("\n"sv, dest);
 	}
 
 private:
@@ -150,7 +144,7 @@ private:
 	std::tm											   m_CachedTm;
 	std::chrono::seconds							   m_LastLogSecs;
 	std::chrono::seconds							   m_CacheTimestamp{0};
-	memory_buf_t									   m_CachedDatetime;
+	spdlog::memory_buf_t							   m_CachedDatetime;
 	std::string										   m_LogId;
 };
 
diff --git a/src/zenutil/include/zenutil/logging/jsonformatter.h b/src/zenutil/include/zenutil/logging/jsonformatter.h
index 5f7d4853d..40fdb94e2 100644
--- a/src/zenutil/include/zenutil/logging/jsonformatter.h
+++ b/src/zenutil/include/zenutil/logging/jsonformatter.h
@@ -4,12 +4,10 @@
 
 #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>
+#include <spdlog/formatter.h>
 ZEN_THIRD_PARTY_INCLUDES_END
 
 namespace zen::logging {
@@ -166,4 +164,4 @@ private:
 	std::string			 m_LogId;
 };
 
-}  // namespace zen::logging
\ No newline at end of file
+}  // namespace zen::logging
diff --git a/src/zenutil/include/zenutil/logging/testformatter.h b/src/zenutil/include/zenutil/logging/testformatter.h
new file mode 100644
index 000000000..39fc44e75
--- /dev/null
+++ b/src/zenutil/include/zenutil/logging/testformatter.h
@@ -0,0 +1,146 @@
+// Copyright Epic Games, Inc. All Rights Reserved.
+
+#pragma once
+
+#include <spdlog/spdlog.h>
+
+namespace zen::logging {
+
+class full_test_formatter final : public spdlog::formatter
+{
+public:
+	full_test_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_test_formatter>(m_LogId, m_Epoch); }
+
+	static constexpr bool UseDate = false;
+
+	virtual void format(const spdlog::details::log_msg& msg, spdlog::memory_buf_t& dest) override
+	{
+		using namespace std::literals;
+
+		if constexpr (UseDate)
+		{
+			auto secs = std::chrono::duration_cast<std::chrono::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.
+		auto duration = msg.time - m_Epoch;
+		auto secs	  = std::chrono::duration_cast<std::chrono::seconds>(duration);
+
+		if (m_CacheTimestamp != secs || m_CachedDatetime.size() == 0)
+		{
+			m_CachedDatetime.clear();
+			m_CachedDatetime.push_back('[');
+
+			if constexpr (UseDate)
+			{
+				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);
+			}
+			else
+			{
+				int Count = int(secs.count());
+
+				const int LogSecs = Count % 60;
+				Count /= 60;
+
+				const int LogMins = Count % 60;
+				Count /= 60;
+
+				const int LogHours = Count;
+
+				spdlog::details::fmt_helper::pad2(LogHours, m_CachedDatetime);
+				m_CachedDatetime.push_back(':');
+				spdlog::details::fmt_helper::pad2(LogMins, m_CachedDatetime);
+				m_CachedDatetime.push_back(':');
+				spdlog::details::fmt_helper::pad2(LogSecs, m_CachedDatetime);
+			}
+
+			m_CachedDatetime.push_back('.');
+
+			m_CacheTimestamp = secs;
+		}
+
+		dest.append(m_CachedDatetime.begin(), m_CachedDatetime.end());
+
+		auto millis = spdlog::details::fmt_helper::time_fraction<std::chrono::milliseconds>(msg.time);
+		spdlog::details::fmt_helper::pad3(static_cast<uint32_t>(millis.count()), dest);
+		dest.push_back(']');
+		dest.push_back(' ');
+
+		if (!m_LogId.empty())
+		{
+			dest.push_back('[');
+			spdlog::details::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('[');
+			spdlog::details::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();
+		spdlog::details::fmt_helper::append_string_view(spdlog::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 =
+				spdlog::details::short_filename_formatter<spdlog::details::null_scoped_padder>::basename(msg.source.filename);
+			spdlog::details::fmt_helper::append_string_view(filename, dest);
+			dest.push_back(':');
+			spdlog::details::fmt_helper::append_int(msg.source.line, dest);
+			dest.push_back(']');
+			dest.push_back(' ');
+		}
+
+		spdlog::details::fmt_helper::append_string_view(msg.payload, dest);
+		spdlog::details::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};
+	spdlog::memory_buf_t							   m_CachedDatetime;
+	std::string										   m_LogId;
+};
+
+}  // namespace zen::logging
\ No newline at end of file