// Copyright Epic Games, Inc. All Rights Reserved. #include "zenutil/logging.h" #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include namespace zen { static bool g_IsLoggingInitialized; logging::SinkPtr g_FileSink; Ref g_BroadcastSink; Ref g_BacklogSink; logging::SinkPtr GetFileSink() { return g_FileSink; } Ref GetDefaultBroadcastSink() { return g_BroadcastSink; } Ref 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(LogOptions.LogId)); } else { FileSink->SetFormatter(std::make_unique(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 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* Message = (fmt::basic_memory_buffer*)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 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(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(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( 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(LogOptions.LogId)); } else { g_FileSink->SetFormatter(std::make_unique(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