added logging utility functions (from sb/proto) (#469)

these allow standalone programs to share much of the logging setup from zenserver

1 files changed, 516 insertions, 0 deletions

diff --git a/src/zenutil/logging.cpp b/src/zenutil/logging.cpp
new file mode 100644
index 000000000..c0a63cc71
--- /dev/null
+++ b/src/zenutil/logging.cpp
@@ -0,0 +1,516 @@
+// Copyright Epic Games, Inc. All Rights Reserved.
+
+#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/filesystem.h>
+#include <zencore/string.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;
+};
+}  // namespace zen::logging
+
+bool
+EnableVTMode()
+{
+#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;
+}
+
+#if ZEN_USE_SENTRY
+
+class sentry_sink final : public spdlog::sinks::base_sink<spdlog::details::null_mutex>
+{
+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 {
+
+void
+InitializeLogging(const LoggingOptions& LogOptions)
+{
+	zen::logging::InitializeLogging();
+
+	EnableVTMode();
+
+	bool					  IsAsync  = true;
+	spdlog::level::level_enum LogLevel = spdlog::level::info;
+
+	if (LogOptions.IsDebug)
+	{
+		LogLevel = spdlog::level::debug;
+		IsAsync	 = false;
+	}
+
+	if (LogOptions.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);
+	}
+
+	// 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
+
+	if (!LogOptions.AbsLogFile.empty())
+	{
+		if (LogOptions.AbsLogFile.has_parent_path())
+		{
+			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
+	}
+
+#if ZEN_USE_SENTRY
+	SentrySink = std::make_shared<sentry_sink>();
+#endif
+
+	std::set_terminate([]() { ZEN_CRITICAL("Program exited abnormally via std::terminate()"); });
+
+	// Default
+
+	auto& DefaultLogger = zen::logging::Default();
+	auto& Sinks			= DefaultLogger.sinks();
+
+	Sinks.clear();
+	Sinks.push_back(ConsoleSink);
+
+	if (FileSink)
+	{
+		Sinks.push_back(FileSink);
+	}
+
+	if (SentrySink)
+	{
+		Sinks.push_back(SentrySink);
+	}
+
+#if ZEN_PLATFORM_WINDOWS
+	if (zen::IsDebuggerPresent() && LogOptions.IsDebug)
+	{
+		auto DebugSink = std::make_shared<spdlog::sinks::msvc_sink_mt>();
+		DebugSink->set_level(spdlog::level::debug);
+		Sinks.push_back(DebugSink);
+	}
+#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")
+		{
+			FileSink->set_formatter(std::make_unique<logging::json_formatter>(LogOptions.LogId));
+		}
+		else
+		{
+			FileSink->set_pattern("[%C-%m-%d.%e %T] [%n] [%l] %v");
+		}
+	}
+	DefaultLogger.info("log starting at {:%FT%T%z}", std::chrono::system_clock::now());
+}
+
+void
+ShutdownLogging()
+{
+	auto& DefaultLogger = zen::logging::Default();
+	DefaultLogger.info("log ending at {:%FT%T%z}", std::chrono::system_clock::now());
+	zen::logging::ShutdownLogging();
+}
+
+}  // namespace zen