path: root/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/rotating_file_sink.h>
#include <spdlog/sinks/stdout_color_sinks.h>
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 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 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;
}

void
InitializeLogging(const ZenServerOptions& GlobalOptions)
{
	zen::logging::InitializeLogging();

	EnableVTMode();

	std::filesystem::path LogPath =
		!GlobalOptions.AbsLogFile.empty() ? GlobalOptions.AbsLogFile : GlobalOptions.DataDir / "logs/zenserver.log";

	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

	auto ConsoleSink = std::make_shared<spdlog::sinks::ansicolor_stdout_sink_mt>();

#if 0
	auto FileSink	 = std::make_shared<spdlog::sinks::daily_file_sink_mt>(zen::PathToUtf8(LogPath),
																		   0,
																		   0,
																		   /* truncate */ false,
																		   uint16_t(/* max files */ 14));
#else
	auto FileSink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(zen::PathToUtf8(LogPath),
																		   /* max size */ 128 * 1024 * 1024,
																		   /* max files */ 16,
																		   /* rotate on open */ true);
#endif

	// Default

	auto& DefaultLogger = zen::logging::Default();
	auto& Sinks			= DefaultLogger.sinks();

	Sinks.clear();
	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

	// HTTP server request logging

	std::filesystem::path HttpLogPath = GlobalOptions.DataDir / "logs/http.log";

	auto HttpSink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(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);
	spdlog::register_logger(HttpLogger);

	// Jupiter - only log upstream HTTP traffic to file

	auto JupiterLogger = std::make_shared<spdlog::logger>("jupiter", FileSink);
	spdlog::register_logger(JupiterLogger);

	// Zen - only log upstream HTTP traffic to file

	auto ZenClientLogger = std::make_shared<spdlog::logger>("zenclient", FileSink);
	spdlog::register_logger(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()));

	FileSink->set_pattern("[%C-%m-%d.%e %T] [%n] [%l] %v");

	spdlog::info("log starting at {:%FT%T%z}", std::chrono::system_clock::now());
}

void
ShutdownLogging()
{
	zen::logging::ShutdownLogging();
}