path: root/src/zenserver/diag/logging.cpp

// Copyright Epic Games, Inc. All Rights Reserved.

#include "logging.h"

#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

namespace zen {

void
InitializeLogging(const ZenServerOptions& GlobalOptions)
{
	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);
	}

	// Sinks

	// 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());

#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);
	};

	// 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
	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 HttpLogger = std::make_shared<spdlog::logger>("http_requests", HttpSink);
	RegisterLogger(HttpLogger);

	// Cache request logging
	std::filesystem::path CacheLogPath = GlobalOptions.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 CacheLogger = std::make_shared<spdlog::logger>("z$", CacheSink);
	RegisterLogger(CacheLogger);

	// Jupiter - only log upstream HTTP traffic to file

	auto JupiterLogger = std::make_shared<spdlog::logger>("jupiter", FileSink);
	RegisterLogger(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::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
		}
	});

	const std::string StartLogTime	  = zen::DateTime::Now().ToIso8601();
	const zen::Oid	  ServerSessionId = zen::GetSessionId();

	for (auto& Logger : KnownLoggers)
	{
		Logger->info("log starting at {}", StartLogTime);
		Logger->info("server session id: {}", ServerSessionId);
	}
}

void
ShutdownLogging()
{
	auto& DefaultLogger = zen::logging::Default();
	DefaultLogger.info("log ending at {}", zen::DateTime::Now().ToIso8601());
	zen::logging::ShutdownLogging();
}

}  // namespace zen