path: root/src/zenutil/logging/logging.cpp

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

#include "zenutil/logging.h"

#include <zencore/callstack.h>
#include <zencore/compactbinary.h>
#include <zencore/filesystem.h>
#include <zencore/logging.h>
#include <zencore/logging/ansicolorsink.h>
#include <zencore/logging/asyncsink.h>
#include <zencore/logging/backlogsink.h>
#include <zencore/logging/broadcastsink.h>
#include <zencore/logging/logger.h>
#include <zencore/logging/msvcsink.h>
#include <zencore/logging/registry.h>
#include <zencore/memory/llm.h>
#include <zencore/string.h>
#include <zencore/timer.h>
#include <zenutil/logging/fullformatter.h>
#include <zenutil/logging/jsonformatter.h>
#include <zenutil/logging/rotatingfilesink.h>

#include <chrono>
#include <memory>

namespace zen {

static bool					g_IsLoggingInitialized;
logging::SinkPtr			g_FileSink;
Ref<logging::BroadcastSink> g_BroadcastSink;
Ref<logging::BacklogSink>	g_BacklogSink;

logging::SinkPtr
GetFileSink()
{
	return g_FileSink;
}

Ref<logging::BroadcastSink>
GetDefaultBroadcastSink()
{
	return g_BroadcastSink;
}

Ref<logging::BacklogSink>
GetLogBacklogSink()
{
	return g_BacklogSink;
}

void
AttachSinkWithBacklogReplay(logging::SinkPtr Sink)
{
	if (!Sink)
	{
		return;
	}
	// Drain any AsyncSink queue first so messages emitted just before this
	// call have a chance to land in the backlog before we snapshot its
	// cursor. Without this we'd still be correct (AsyncSink would deliver
	// the queued lines to the new sink directly via the broadcast after
	// AddSink runs), but the new sink would observe them out of timestamp
	// order — replayed history first, then late drains interleaved with
	// fresh post-attach messages.
	zen::logging::FlushLogging();

	if (!g_BroadcastSink)
	{
		return;
	}

	// Subscribe Sink to the broadcast and snapshot the backlog cursor
	// atomically. The broadcast's exclusive lock blocks fanout while it's
	// held, so during the callback no thread can be inside backlog.Log()
	// and the cursor we capture is exact w.r.t. the moment Sink became
	// visible to fanout.
	//
	// After the callback returns and the lock is released, two things are
	// true:
	//  - Any backlog entry at index < Cursor was added before Sink became
	//    a fanout target, so Sink did NOT receive it via Log() — Replay
	//    must deliver it.
	//  - Any backlog entry at index >= Cursor was added after Sink became
	//    a fanout target, so Sink already received it via Log() — Replay
	//    must skip it.
	// This closes the prior race where a message arriving between Replay
	// and AddSink would land in the backlog only and be lost on
	// DisableLogBacklog.
	size_t Cursor = 0;
	g_BroadcastSink->AddSinkAtomic(Sink, [&]() {
		if (g_BacklogSink && g_BacklogSink->IsEnabled())
		{
			Cursor = g_BacklogSink->Size();
		}
	});

	if (Cursor > 0)
	{
		g_BacklogSink->Replay(*Sink, Cursor);
	}
}

void
DisableLogBacklog()
{
	if (!g_BacklogSink)
	{
		return;
	}
	// Remove from the broadcast first so subsequent log lines don't even
	// fan out to a now-no-op sink — one fewer per-log overhead for the
	// rest of the process lifetime. Disable() then frees the arena, and
	// dropping our own Ref releases the object.
	if (g_BroadcastSink)
	{
		g_BroadcastSink->RemoveSink(logging::SinkPtr(g_BacklogSink.Get()));
	}
	g_BacklogSink->Disable();
	g_BacklogSink = nullptr;
}

void
InitializeLogging(const LoggingOptions& LogOptions)
{
	BeginInitializeLogging(LogOptions);
	FinishInitializeLogging(LogOptions);
}

static std::terminate_handler OldTerminateHandler = nullptr;

void
BeginInitializeLogging(const LoggingOptions& LogOptions)
{
	ZEN_MEMSCOPE(ELLMTag::Logging);

	zen::logging::InitializeLogging();

	// Sinks

	logging::SinkPtr FileSink;

	if (!LogOptions.AbsLogFile.empty())
	{
		if (LogOptions.AbsLogFile.has_parent_path())
		{
			zen::CreateDirectories(LogOptions.AbsLogFile.parent_path());
		}

		FileSink = logging::SinkPtr(new zen::logging::RotatingFileSink(LogOptions.AbsLogFile,
																	   /* max size */ 128 * 1024 * 1024,
																	   /* max files */ 16,
																	   /* rotate on open */ true));
		if (LogOptions.AbsLogFile.extension() == ".json")
		{
			FileSink->SetFormatter(std::make_unique<logging::JsonFormatter>(LogOptions.LogId));
		}
		else
		{
			FileSink->SetFormatter(std::make_unique<logging::FullFormatter>(LogOptions.LogId));	 // this will have a date prefix
		}
	}

	OldTerminateHandler = std::set_terminate([]() {
		try
		{
			constexpr int	 SkipFrameCount = 4;
			constexpr int	 FrameCount		= 8;
			uint8_t			 CallstackBuffer[CallstackRawMemorySize(SkipFrameCount, FrameCount)];
			CallstackFrames* Callstack = GetCallstackRaw(&CallstackBuffer[0], SkipFrameCount, FrameCount);

			fmt::basic_memory_buffer<char, 2048> Message;
			auto								 Appender = fmt::appender(Message);
			fmt::format_to(Appender, "Program exited abnormally via std::terminate()");

			if (Callstack->FrameCount > 0)
			{
				fmt::format_to(Appender, "\n");

				CallstackToStringRaw(Callstack, &Message, [](void* UserData, uint32_t FrameIndex, const char* FrameText) {
					ZEN_UNUSED(FrameIndex);
					fmt::basic_memory_buffer<char, 2048>* Message  = (fmt::basic_memory_buffer<char, 2048>*)UserData;
					auto								  Appender = fmt::appender(*Message);
					fmt::format_to(Appender, "  {}\n", FrameText);
				});
			}
			Message.push_back('\0');

			// We use direct ZEN_LOG here instead of ZEN_ERROR as we don't care about *this* code location in the log
			ZEN_LOG(Log(), zen::logging::Critical, "{}", Message.data());
			zen::logging::FlushLogging();
		}
		catch (const std::exception&)
		{
			// Ignore any exceptions in terminate callback
		}
		if (OldTerminateHandler)
		{
			OldTerminateHandler();
		}
	});

	// Default

	LoggerRef DefaultLogger = zen::logging::Default();

	// Build the broadcast sink - a shared indirection point that all
	// loggers cloned from the default will share.  Adding or removing
	// a child sink later is immediately visible to every logger.
	std::vector<logging::SinkPtr> BroadcastChildren;

	// Install the backlog sink as the first broadcast child so it sees
	// every line emitted from this point until the bootstrap window
	// closes (DisableLogBacklog at server-run-loop / CLI-dispatch). Sinks
	// attached later via AttachSinkWithBacklogReplay can replay the
	// captured window into themselves so they don't miss the early logs.
	g_BacklogSink = Ref<logging::BacklogSink>(new logging::BacklogSink());
	BroadcastChildren.push_back(logging::SinkPtr(g_BacklogSink.Get()));

	if (LogOptions.NoConsoleOutput)
	{
		zen::logging::SuppressConsoleLog();
	}
	else
	{
		logging::SinkPtr ConsoleSink(
			new logging::AnsiColorStdoutSink(LogOptions.ForceColor ? logging::ColorMode::On : logging::ColorMode::Auto));
		if (LogOptions.QuietConsole)
		{
			ConsoleSink->SetLevel(logging::Warn);
		}
		BroadcastChildren.push_back(ConsoleSink);
	}

	if (FileSink)
	{
		BroadcastChildren.push_back(FileSink);
	}

#if ZEN_PLATFORM_WINDOWS
	if (zen::IsDebuggerPresent() && LogOptions.IsDebug)
	{
		logging::SinkPtr DebugSink(new logging::MsvcSink());
		DebugSink->SetLevel(logging::Debug);
		BroadcastChildren.push_back(DebugSink);
	}
#endif

	// Trace forwarding is installed at a lower level (in Logger::Log itself)
	// so it can see the typed fmt argument pack before vformat collapses it
	// to a string - see src/zencore/logging/tracelog.cpp.

	g_BroadcastSink = Ref<logging::BroadcastSink>(new logging::BroadcastSink(std::move(BroadcastChildren)));

	bool IsAsync = LogOptions.AllowAsync && !LogOptions.IsDebug && !LogOptions.IsTest;

	if (IsAsync)
	{
		DefaultLogger->SetSink(logging::SinkPtr(new logging::AsyncSink({logging::SinkPtr(g_BroadcastSink.Get())})));
	}
	else
	{
		DefaultLogger->SetSink(logging::SinkPtr(g_BroadcastSink.Get()));
	}

	static struct : logging::ErrorHandler
	{
		void HandleError(const std::string_view& ErrorMsg) override
		{
			if (ErrorMsg == std::bad_alloc().what())
			{
				return;
			}
			static constinit logging::LogPoint ErrorPoint{0, 0, logging::Err, "{}"};
			if (auto ErrLogger = zen::logging::ErrorLog())
			{
				try
				{
					ErrLogger->Log(ErrorPoint, fmt::make_format_args(ErrorMsg));
				}
				catch (const std::exception&)
				{
				}
			}
			try
			{
				Log()->Log(ErrorPoint, fmt::make_format_args(ErrorMsg));
			}
			catch (const std::exception&)
			{
			}
		}
	} s_ErrorHandler;
	logging::Registry::Instance().SetErrorHandler(&s_ErrorHandler);

	g_FileSink = std::move(FileSink);
}

void
FinishInitializeLogging(const LoggingOptions& LogOptions)
{
	ZEN_MEMSCOPE(ELLMTag::Logging);

	logging::LogLevel LogLevel = logging::Info;

	if (LogOptions.IsDebug)
	{
		LogLevel = logging::Debug;
	}

	if (LogOptions.IsTest || LogOptions.IsVerbose)
	{
		LogLevel = logging::Trace;
	}

	// Configure all registered loggers according to settings

	logging::RefreshLogLevels(LogLevel);
	logging::Registry::Instance().FlushOn(logging::Err);
	logging::Registry::Instance().FlushEvery(std::chrono::seconds{2});
	logging::Registry::Instance().SetFormatter(std::make_unique<logging::FullFormatter>(
		LogOptions.LogId,
		std::chrono::system_clock::now() - std::chrono::milliseconds(GetTimeSinceProcessStart())));	 // default to duration prefix

	// If the console logger was initialized before, the above will change the output format
	// so we need to reset it

	logging::ResetConsoleLog();

	if (g_FileSink)
	{
		if (LogOptions.AbsLogFile.extension() == ".json")
		{
			g_FileSink->SetFormatter(std::make_unique<logging::JsonFormatter>(LogOptions.LogId));
		}
		else
		{
			g_FileSink->SetFormatter(std::make_unique<logging::FullFormatter>(LogOptions.LogId));  // this will have a date prefix
		}

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

		logging::Registry::Instance().ApplyAll([&](auto Logger) {
			static constinit logging::LogPoint LogStartPoint{0, 0, logging::Info, "log starting at {}"};
			Logger->Log(LogStartPoint, fmt::make_format_args(StartLogTime));
		});
	}

	g_IsLoggingInitialized = true;
}

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

	zen::logging::ShutdownLogging();

	g_FileSink		= nullptr;
	g_BroadcastSink = nullptr;
	g_BacklogSink	= nullptr;
}

}  // namespace zen