aboutsummaryrefslogtreecommitdiff
path: root/src/zencore/logging
diff options
context:
space:
mode:
Diffstat (limited to 'src/zencore/logging')
-rw-r--r--src/zencore/logging/ansicolorsink.cpp68
-rw-r--r--src/zencore/logging/logger.cpp61
-rw-r--r--src/zencore/logging/registry.cpp4
-rw-r--r--src/zencore/logging/tracelog.cpp800
-rw-r--r--src/zencore/logging/tracesink.cpp92
5 files changed, 866 insertions, 159 deletions
diff --git a/src/zencore/logging/ansicolorsink.cpp b/src/zencore/logging/ansicolorsink.cpp
index 03aae068a..fb127bede 100644
--- a/src/zencore/logging/ansicolorsink.cpp
+++ b/src/zencore/logging/ansicolorsink.cpp
@@ -5,6 +5,7 @@
#include <zencore/logging/messageonlyformatter.h>
#include <zencore/thread.h>
+#include <zencore/timer.h>
#include <cstdio>
#include <cstdlib>
@@ -22,48 +23,37 @@
namespace zen::logging {
-// Default formatter replicating spdlog's %+ pattern:
-// [YYYY-MM-DD HH:MM:SS.mmm] [logger_name] [level] message\n
+// Default formatter for console output:
+// [HH:MM:SS.mmm] [logger_name] [level] message\n
+// Timestamps show elapsed time since process launch.
class DefaultConsoleFormatter : public Formatter
{
public:
+ DefaultConsoleFormatter() : m_Epoch(std::chrono::system_clock::now() - std::chrono::milliseconds(GetTimeSinceProcessStart())) {}
+
void Format(const LogMessage& Msg, MemoryBuffer& Dest) override
{
- // timestamp
- auto Secs = std::chrono::duration_cast<std::chrono::seconds>(Msg.GetTime().time_since_epoch());
- if (Secs != m_LastLogSecs)
- {
- m_LastLogSecs = Secs;
- m_CachedLocalTm = helpers::SafeLocaltime(LogClock::to_time_t(Msg.GetTime()));
- }
+ // Elapsed time since process launch
+ auto Elapsed = Msg.GetTime() - m_Epoch;
+ auto TotalSecs = std::chrono::duration_cast<std::chrono::seconds>(Elapsed);
+ int Count = static_cast<int>(TotalSecs.count());
+ int LogSecs = Count % 60;
+ Count /= 60;
+ int LogMins = Count % 60;
+ int LogHours = Count / 60;
Dest.push_back('[');
- helpers::AppendInt(m_CachedLocalTm.tm_year + 1900, Dest);
- Dest.push_back('-');
- helpers::Pad2(m_CachedLocalTm.tm_mon + 1, Dest);
- Dest.push_back('-');
- helpers::Pad2(m_CachedLocalTm.tm_mday, Dest);
- Dest.push_back(' ');
- helpers::Pad2(m_CachedLocalTm.tm_hour, Dest);
+ helpers::Pad2(LogHours, Dest);
Dest.push_back(':');
- helpers::Pad2(m_CachedLocalTm.tm_min, Dest);
+ helpers::Pad2(LogMins, Dest);
Dest.push_back(':');
- helpers::Pad2(m_CachedLocalTm.tm_sec, Dest);
+ helpers::Pad2(LogSecs, Dest);
Dest.push_back('.');
auto Millis = helpers::TimeFraction<std::chrono::milliseconds>(Msg.GetTime());
helpers::Pad3(static_cast<uint32_t>(Millis.count()), Dest);
Dest.push_back(']');
Dest.push_back(' ');
- // logger name
- if (Msg.GetLoggerName().size() > 0)
- {
- Dest.push_back('[');
- helpers::AppendStringView(Msg.GetLoggerName(), Dest);
- Dest.push_back(']');
- Dest.push_back(' ');
- }
-
// level
Dest.push_back('[');
if (IsColorEnabled())
@@ -78,6 +68,25 @@ public:
Dest.push_back(']');
Dest.push_back(' ');
+ using namespace std::literals;
+
+ // logger name
+ if (Msg.GetLoggerName().size() > 0)
+ {
+ if (IsColorEnabled())
+ {
+ Dest.append("\033[97m"sv);
+ }
+ Dest.push_back('[');
+ helpers::AppendStringView(Msg.GetLoggerName(), Dest);
+ Dest.push_back(']');
+ if (IsColorEnabled())
+ {
+ Dest.append("\033[0m"sv);
+ }
+ Dest.push_back(' ');
+ }
+
// message (align continuation lines with the first line)
size_t AnsiBytes = IsColorEnabled() ? (helpers::AnsiColorForLevel(Msg.GetLevel()).size() + helpers::kAnsiReset.size()) : 0;
size_t LinePrefixCount = Dest.size() - AnsiBytes;
@@ -128,8 +137,7 @@ public:
}
private:
- std::chrono::seconds m_LastLogSecs{0};
- std::tm m_CachedLocalTm{};
+ LogClock::time_point m_Epoch;
};
bool
@@ -197,7 +205,7 @@ IsColorTerminal()
// Windows console supports ANSI color by default in modern versions
return true;
#else
- // Unknown terminal — be conservative
+ // Unknown terminal - be conservative
return false;
#endif
}
diff --git a/src/zencore/logging/logger.cpp b/src/zencore/logging/logger.cpp
index dd1675bb1..830d2b611 100644
--- a/src/zencore/logging/logger.cpp
+++ b/src/zencore/logging/logger.cpp
@@ -1,30 +1,24 @@
// Copyright Epic Games, Inc. All Rights Reserved.
#include <zencore/logging/logger.h>
+#include <zencore/logging/tracelog.h>
#include <zencore/thread.h>
#include <string>
-#include <vector>
namespace zen::logging {
struct Logger::Impl
{
- std::string m_Name;
- std::vector<SinkPtr> m_Sinks;
- ErrorHandler* m_ErrorHandler = nullptr;
+ std::string m_Name;
+ SinkPtr m_Sink;
+ ErrorHandler* m_ErrorHandler = nullptr;
};
Logger::Logger(std::string_view InName, SinkPtr InSink) : m_Impl(std::make_unique<Impl>())
{
m_Impl->m_Name = InName;
- m_Impl->m_Sinks.push_back(std::move(InSink));
-}
-
-Logger::Logger(std::string_view InName, std::span<const SinkPtr> InSinks) : m_Impl(std::make_unique<Impl>())
-{
- m_Impl->m_Name = InName;
- m_Impl->m_Sinks.assign(InSinks.begin(), InSinks.end());
+ m_Impl->m_Sink = std::move(InSink);
}
Logger::~Logger() = default;
@@ -40,6 +34,12 @@ Logger::Log(const LogPoint& Point, fmt::format_args Args)
fmt::basic_memory_buffer<char, 250> Buffer;
fmt::vformat_to(fmt::appender(Buffer), Point.FormatString, Args);
+#if ZEN_WITH_TRACE
+ // Forward the typed argument pack to the trace system while we still have
+ // it - sinks are invoked below with the already-rendered payload.
+ TraceLogTyped(*this, Point, Args);
+#endif
+
LogMessage LogMsg(Point, m_Impl->m_Name, std::string_view(Buffer.data(), Buffer.size()));
LogMsg.SetThreadId(GetCurrentThreadId());
SinkIt(LogMsg);
@@ -49,20 +49,17 @@ Logger::Log(const LogPoint& Point, fmt::format_args Args)
void
Logger::SinkIt(const LogMessage& Msg)
{
- for (auto& CurrentSink : m_Impl->m_Sinks)
+ if (m_Impl->m_Sink && m_Impl->m_Sink->ShouldLog(Msg.GetLevel()))
{
- if (CurrentSink->ShouldLog(Msg.GetLevel()))
+ try
{
- try
- {
- CurrentSink->Log(Msg);
- }
- catch (const std::exception& Ex)
+ m_Impl->m_Sink->Log(Msg);
+ }
+ catch (const std::exception& Ex)
+ {
+ if (m_Impl->m_ErrorHandler)
{
- if (m_Impl->m_ErrorHandler)
- {
- m_Impl->m_ErrorHandler->HandleError(Ex.what());
- }
+ m_Impl->m_ErrorHandler->HandleError(Ex.what());
}
}
}
@@ -80,11 +77,11 @@ Logger::FlushIfNeeded(LogLevel InLevel)
void
Logger::Flush()
{
- for (auto& CurrentSink : m_Impl->m_Sinks)
+ if (m_Impl->m_Sink)
{
try
{
- CurrentSink->Flush();
+ m_Impl->m_Sink->Flush();
}
catch (const std::exception& Ex)
{
@@ -97,15 +94,9 @@ Logger::Flush()
}
void
-Logger::SetSinks(std::vector<SinkPtr> InSinks)
-{
- m_Impl->m_Sinks = std::move(InSinks);
-}
-
-void
-Logger::AddSink(SinkPtr InSink)
+Logger::SetSink(SinkPtr InSink)
{
- m_Impl->m_Sinks.push_back(std::move(InSink));
+ m_Impl->m_Sink = std::move(InSink);
}
void
@@ -117,9 +108,9 @@ Logger::SetErrorHandler(ErrorHandler* Handler)
void
Logger::SetFormatter(std::unique_ptr<Formatter> InFormatter)
{
- for (auto& CurrentSink : m_Impl->m_Sinks)
+ if (m_Impl->m_Sink)
{
- CurrentSink->SetFormatter(InFormatter->Clone());
+ m_Impl->m_Sink->SetFormatter(std::move(InFormatter));
}
}
@@ -132,7 +123,7 @@ Logger::Name() const
Ref<Logger>
Logger::Clone(std::string_view NewName) const
{
- Ref<Logger> Cloned(new Logger(NewName, m_Impl->m_Sinks));
+ Ref<Logger> Cloned(new Logger(NewName, m_Impl->m_Sink));
Cloned->SetLevel(m_Level.load(std::memory_order_relaxed));
Cloned->SetFlushLevel(m_FlushLevel.load(std::memory_order_relaxed));
Cloned->SetErrorHandler(m_Impl->m_ErrorHandler);
diff --git a/src/zencore/logging/registry.cpp b/src/zencore/logging/registry.cpp
index 383a5d8ba..0f552aced 100644
--- a/src/zencore/logging/registry.cpp
+++ b/src/zencore/logging/registry.cpp
@@ -137,7 +137,7 @@ struct Registry::Impl
{
if (Pattern.find_first_of("*?") == std::string::npos)
{
- // Exact match — fast path via map lookup.
+ // Exact match - fast path via map lookup.
auto It = m_Loggers.find(Pattern);
if (It != m_Loggers.end())
{
@@ -146,7 +146,7 @@ struct Registry::Impl
}
else
{
- // Wildcard pattern — iterate all loggers.
+ // Wildcard pattern - iterate all loggers.
for (auto& [Name, CurLogger] : m_Loggers)
{
if (MatchLoggerPattern(Pattern, Name))
diff --git a/src/zencore/logging/tracelog.cpp b/src/zencore/logging/tracelog.cpp
new file mode 100644
index 000000000..d90b07f02
--- /dev/null
+++ b/src/zencore/logging/tracelog.cpp
@@ -0,0 +1,800 @@
+// Copyright Epic Games, Inc. All Rights Reserved.
+
+#include <zencore/logbase.h>
+#include <zencore/logging/logger.h>
+#include <zencore/logging/tracelog.h>
+#include <zencore/testing.h>
+#include <zencore/thread.h>
+#include <zencore/timer.h>
+#include <zencore/trace.h>
+
+#if ZEN_WITH_TRACE
+
+ZEN_THIRD_PARTY_INCLUDES_START
+# include <EASTL/fixed_vector.h>
+# include <fmt/args.h>
+# include <fmt/format.h>
+ZEN_THIRD_PARTY_INCLUDES_END
+
+# include <cstring>
+# include <limits>
+# include <unordered_set>
+
+namespace zen::logging {
+
+UE_TRACE_CHANNEL_DEFINE(ZenLogChannel)
+
+// A zen-specific log event schema. The field layout is deliberately close to
+// UE's Logging.* events so the analyzer's plumbing looks familiar, but the
+// event names are distinct because our FormatArgs blob is formatted against
+// an fmt-style `{}` template instead of a printf-style `%d`/`%s`/... template,
+// and Insights' current log analyzer can't render the former.
+UE_TRACE_EVENT_BEGIN(ZenLog, Category, NoSync | Important)
+ UE_TRACE_EVENT_FIELD(const void*, CategoryPointer)
+ UE_TRACE_EVENT_FIELD(uint8_t, DefaultVerbosity)
+ UE_TRACE_EVENT_FIELD(UE::Trace::AnsiString, Name)
+UE_TRACE_EVENT_END()
+
+UE_TRACE_EVENT_BEGIN(ZenLog, MessageSpec, NoSync | Important)
+ UE_TRACE_EVENT_FIELD(const void*, LogPoint)
+ UE_TRACE_EVENT_FIELD(const void*, CategoryPointer)
+ UE_TRACE_EVENT_FIELD(int32_t, Line)
+ UE_TRACE_EVENT_FIELD(uint8_t, Verbosity)
+ UE_TRACE_EVENT_FIELD(UE::Trace::AnsiString, FileName)
+ UE_TRACE_EVENT_FIELD(UE::Trace::AnsiString, FormatString)
+UE_TRACE_EVENT_END()
+
+UE_TRACE_EVENT_BEGIN(ZenLog, Message, NoSync)
+ UE_TRACE_EVENT_FIELD(const void*, LogPoint)
+ UE_TRACE_EVENT_FIELD(uint64_t, Cycle)
+ UE_TRACE_EVENT_FIELD(uint8_t[], FormatArgs)
+UE_TRACE_EVENT_END()
+
+namespace {
+
+ // Translate zen's LogLevel to UE's ELogVerbosity convention, which is what
+ // trace consumers (Unreal Insights, the zen viewer, ...) expect on the wire.
+ // zen: Trace=0, Debug=1, Info=2, Warn=3, Err=4, Critical=5, Off=6
+ // UE: NoLogging=0, Fatal=1, Error=2, Warning=3, Display=4, Log=5, Verbose=6, VeryVerbose=7
+ uint8_t ToUeVerbosity(LogLevel Level)
+ {
+ switch (Level)
+ {
+ case Trace:
+ return 7; // VeryVerbose
+ case Debug:
+ return 6; // Verbose
+ case Info:
+ return 5; // Log
+ case Warn:
+ return 3; // Warning
+ case Err:
+ return 2; // Error
+ case Critical:
+ return 1; // Fatal
+ case Off:
+ default:
+ return 0; // NoLogging
+ }
+ }
+
+ // Descriptor byte layout: top 3 bits are a category tag, bottom 5 bits are
+ // the payload size in bytes (for strings, the per-character width). Sizes
+ // are always <= 8 in practice, so 5 bits is plenty; the extra category
+ // bit leaves room for future types (timestamps, blobs, compact integers,
+ // ...) without another wire-format break.
+ //
+ // Note: this is the ZenLog-specific descriptor encoding. UE's upstream
+ // Logging.* events (decoded by FormatLogMessage in trace_model.cpp) use a
+ // 2-bit category / 6-bit size layout, which is a separate wire format.
+ //
+ // Bool category (0x00): size = 1, payload byte is 0 or 1
+ // Signed int category (0x20): size = 1/2/4/8, payload is two's complement
+ // Unsigned int category(0x40): size = 1/2/4/8, payload is unsigned
+ // Float category (0x60): float/double, size = 4/8
+ // String category (0x80): size = 1 (ANSI char), payload is null-terminated
+ // Pointer category (0xA0): size = 8, payload is the raw address
+ // (0xC0, 0xE0 are reserved for future types)
+ constexpr uint8_t kCatMask = 0xE0;
+ constexpr uint8_t kSizeMask = 0x1F;
+ constexpr uint8_t kCatBool = 0x00;
+ constexpr uint8_t kCatSInt = 0x20;
+ constexpr uint8_t kCatUInt = 0x40;
+ constexpr uint8_t kCatFloat = 0x60;
+ constexpr uint8_t kCatString = 0x80;
+ constexpr uint8_t kCatPointer = 0xA0;
+
+ // A single byte in the wire header holds the argument count, so 255 is the
+ // hard cap. Any log site emitting more args is truncated silently; no real
+ // log line should come close.
+ constexpr size_t kMaxEncodedArgCount = 0xff;
+
+ struct ArgEncoder
+ {
+ // Descriptors and payload are built side by side and spliced together by
+ // the caller once all args have been visited: the wire format wants all
+ // descriptors before any payload bytes, but we only learn each arg's
+ // size as we visit it.
+ eastl::fixed_vector<uint8_t, 64> Descriptors;
+ eastl::fixed_vector<uint8_t, 512> Payload;
+
+ void PushBool(bool Value)
+ {
+ Descriptors.push_back(uint8_t(kCatBool | 1));
+ Payload.push_back(Value ? uint8_t(1) : uint8_t(0));
+ }
+
+ void PushSInt(uint64_t RawBits, uint8_t ByteSize)
+ {
+ Descriptors.push_back(uint8_t(kCatSInt | ByteSize));
+ AppendRaw(&RawBits, ByteSize);
+ }
+
+ void PushUInt(uint64_t RawBits, uint8_t ByteSize)
+ {
+ Descriptors.push_back(uint8_t(kCatUInt | ByteSize));
+ AppendRaw(&RawBits, ByteSize);
+ }
+
+ void PushFloat(const void* Src, uint8_t ByteSize)
+ {
+ Descriptors.push_back(uint8_t(kCatFloat | ByteSize));
+ AppendRaw(Src, ByteSize);
+ }
+
+ void PushString(std::string_view Str)
+ {
+ Descriptors.push_back(uint8_t(kCatString | 1));
+ const uint8_t* Begin = reinterpret_cast<const uint8_t*>(Str.data());
+ Payload.insert(Payload.end(), Begin, Begin + Str.size());
+ Payload.push_back(uint8_t(0));
+ }
+
+ void PushPointer(const void* Ptr)
+ {
+ Descriptors.push_back(uint8_t(kCatPointer | 8));
+ uint64_t Raw = uint64_t(reinterpret_cast<uintptr_t>(Ptr));
+ AppendRaw(&Raw, sizeof(Raw));
+ }
+
+ void AppendRaw(const void* Src, size_t Size)
+ {
+ const uint8_t* Bytes = static_cast<const uint8_t*>(Src);
+ Payload.insert(Payload.end(), Bytes, Bytes + Size);
+ }
+
+ // fmt::basic_format_arg::visit dispatches on these overloads.
+ void operator()(fmt::monostate) {}
+ void operator()(bool v) { PushBool(v); }
+ void operator()(char v) { PushSInt(uint64_t(int8_t(v)), 1); }
+ void operator()(int v) { PushSInt(uint64_t(int64_t(v)), 4); }
+ void operator()(unsigned v) { PushUInt(uint64_t(v), 4); }
+ void operator()(long long v) { PushSInt(uint64_t(v), 8); }
+ void operator()(unsigned long long v) { PushUInt(v, 8); }
+# if FMT_USE_INT128
+ // Trace wire format tops out at 64-bit ints; truncate. Without these,
+ // overload resolution on __int128_t is ambiguous between long long and
+ // unsigned long long under clang's fmt::visit dispatch.
+ void operator()(fmt::detail::int128_opt v) { PushSInt(uint64_t(int64_t(v)), 8); }
+ void operator()(fmt::detail::uint128_opt v) { PushUInt(uint64_t(v), 8); }
+# endif
+ void operator()(float v) { PushFloat(&v, 4); }
+ void operator()(double v) { PushFloat(&v, 8); }
+ void operator()(long double v)
+ {
+ // Down-cast to double: the trace decoder only knows 4/8-byte floats,
+ // and long double is rare in log sites.
+ double d = double(v);
+ PushFloat(&d, 8);
+ }
+ void operator()(const char* v) { PushString(v ? std::string_view(v) : std::string_view{}); }
+ void operator()(fmt::string_view v) { PushString({v.data(), v.size()}); }
+ void operator()(const void* v) { PushPointer(v); }
+ void operator()(fmt::basic_format_arg<fmt::context>::handle CustomHandle)
+ {
+ // fmt has no public way to inspect a custom-formatted value's type,
+ // so for user-defined formatters we render via fmt itself and ship
+ // the result as a string argument. This preserves message fidelity
+ // at the cost of losing typed-arg introspection for custom types.
+ //
+ // vformat_to will already have rendered this arg successfully for the
+ // regular sinks above us, so the formatter is expected to succeed here
+ // too. The try/catch is defensive: a custom formatter that relies on
+ // something unusual in its context could still misbehave, and a stray
+ // exception here would unwind through every ZEN_LOG caller.
+ fmt::memory_buffer Scratch;
+ fmt::parse_context<char> ParseCtx{fmt::string_view("")};
+ fmt::context FmtCtx{fmt::appender(Scratch), fmt::format_args{}};
+ try
+ {
+ CustomHandle.format(ParseCtx, FmtCtx);
+ PushString({Scratch.data(), Scratch.size()});
+ }
+ catch (...)
+ {
+ PushString("<handle error>");
+ }
+ }
+ };
+
+ // Dedupe state for the Important events. Both LogCategory and MessageSpec are
+ // cached by the trace runtime and replayed to consumers that connect later,
+ // so we only want to emit them once per distinct (logger, point) pair.
+ struct EmitState
+ {
+ RwLock Lock;
+ std::unordered_set<const void*> EmittedCategories;
+ std::unordered_set<const void*> EmittedSpecs;
+ };
+
+ EmitState& GetEmitState()
+ {
+ static EmitState State;
+ return State;
+ }
+
+ void EmitCategory(const void* CategoryPtr, std::string_view Name, LogLevel DefaultVerbosity)
+ {
+ const uint16_t NameLen = uint16_t(Name.size());
+ UE_TRACE_LOG(ZenLog, Category, ZenLogChannel, NameLen * sizeof(ANSICHAR))
+ << Category.CategoryPointer(CategoryPtr) << Category.DefaultVerbosity(ToUeVerbosity(DefaultVerbosity))
+ << Category.Name(Name.data(), NameLen);
+ }
+
+ void EmitMessageSpec(const void* Point,
+ const void* CategoryPtr,
+ LogLevel Verbosity,
+ std::string_view File,
+ int32_t Line,
+ std::string_view Format)
+ {
+ const uint16_t FileNameLen = uint16_t(File.size());
+ const uint16_t FormatStringLen = uint16_t(Format.size());
+ const uint32_t DataSize = (FileNameLen + FormatStringLen) * sizeof(ANSICHAR);
+ UE_TRACE_LOG(ZenLog, MessageSpec, ZenLogChannel, DataSize)
+ << MessageSpec.LogPoint(Point) << MessageSpec.CategoryPointer(CategoryPtr) << MessageSpec.Line(Line)
+ << MessageSpec.Verbosity(ToUeVerbosity(Verbosity)) << MessageSpec.FileName(File.data(), FileNameLen)
+ << MessageSpec.FormatString(Format.data(), FormatStringLen);
+ }
+
+ void EmitMessage(const void* Point, const uint8_t* EncodedArgs, int32_t EncodedSize)
+ {
+ UE_TRACE_LOG(ZenLog, Message, ZenLogChannel)
+ << Message.LogPoint(Point) << Message.Cycle(GetHifreqTimerValue()) << Message.FormatArgs(EncodedArgs, EncodedSize);
+ }
+
+ // Visit every arg in the pack (up to the 255-arg wire cap) and feed them
+ // into the encoder. Factored out so both the hot path (TraceLogTyped, with
+ // a stack buffer) and the public EncodeLogArgs (with a std::vector) share
+ // a single arg-walking implementation.
+ void VisitAllArgs(fmt::format_args Args, ArgEncoder& Enc)
+ {
+ const int ArgLimit = std::min<int>(Args.max_size(), int(kMaxEncodedArgCount));
+ for (int i = 0; i < ArgLimit; ++i)
+ {
+ fmt::basic_format_arg<fmt::context> Arg = Args.get(i);
+ if (!Arg)
+ {
+ break;
+ }
+ Arg.visit(Enc);
+ }
+ }
+
+} // namespace
+
+void
+TraceLogTyped(const Logger& InLogger, const LogPoint& Point, fmt::format_args Args)
+{
+ if (!UE_TRACE_CHANNELEXPR_IS_ENABLED(ZenLogChannel))
+ {
+ return;
+ }
+
+ // The logger's name is stored in a std::string that's written once in the
+ // constructor and never reassigned, so its .data() pointer is stable for
+ // the logger's lifetime and is unique per Logger instance - exactly what
+ // we need to identify a category on the wire.
+ const std::string_view LoggerName = InLogger.Name();
+ const void* CategoryPtr = LoggerName.data();
+ if (CategoryPtr == nullptr)
+ {
+ return;
+ }
+
+ EmitState& State = GetEmitState();
+
+ bool NeedsEmit = false;
+ {
+ RwLock::SharedLockScope Read(State.Lock);
+ NeedsEmit = State.EmittedCategories.find(CategoryPtr) == State.EmittedCategories.end() ||
+ State.EmittedSpecs.find(&Point) == State.EmittedSpecs.end();
+ }
+ if (NeedsEmit)
+ {
+ RwLock::ExclusiveLockScope Write(State.Lock);
+ if (State.EmittedCategories.insert(CategoryPtr).second)
+ {
+ EmitCategory(CategoryPtr, LoggerName, Point.Level);
+ }
+ if (State.EmittedSpecs.insert(&Point).second)
+ {
+ const std::string_view File = Point.Filename ? std::string_view(Point.Filename) : std::string_view{};
+ EmitMessageSpec(&Point, CategoryPtr, Point.Level, File, Point.Line, Point.FormatString);
+ }
+ }
+
+ ArgEncoder Enc;
+ VisitAllArgs(Args, Enc);
+
+ // Splice the wire layout: [ArgumentCount:uint8][Descriptors...][Payload...].
+ // Sized to cover the common case without touching the heap; oversize args
+ // spill to the fixed_vector's fallback allocator.
+ eastl::fixed_vector<uint8_t, 1 + 64 + 512> Blob;
+ Blob.reserve(1 + Enc.Descriptors.size() + Enc.Payload.size());
+ Blob.push_back(uint8_t(Enc.Descriptors.size()));
+ Blob.insert(Blob.end(), Enc.Descriptors.begin(), Enc.Descriptors.end());
+ Blob.insert(Blob.end(), Enc.Payload.begin(), Enc.Payload.end());
+
+ EmitMessage(&Point, Blob.data(), int32_t(Blob.size()));
+}
+
+void
+EncodeLogArgs(fmt::format_args Args, std::vector<uint8_t>& Out)
+{
+ ArgEncoder Enc;
+ VisitAllArgs(Args, Enc);
+
+ // Wire layout: [ArgumentCount:uint8][Descriptors:count][Payload:variable].
+ // VisitAllArgs breaks at the first arg of type none_type (what `!Arg`
+ // tests), which is how fmt signals "past the end" of the pack. Every other
+ // overload pushes exactly one descriptor, so the descriptor count is the
+ // authoritative argument count for the wire.
+ Out.clear();
+ Out.reserve(1 + Enc.Descriptors.size() + Enc.Payload.size());
+ Out.push_back(uint8_t(Enc.Descriptors.size()));
+ Out.insert(Out.end(), Enc.Descriptors.begin(), Enc.Descriptors.end());
+ Out.insert(Out.end(), Enc.Payload.begin(), Enc.Payload.end());
+}
+
+namespace {
+
+ // Cursor over a ZenLog FormatArgs blob. The layout is
+ // `[count:uint8][descriptors:count][payload]` - see EncodeLogArgs.
+ struct ArgDecoder
+ {
+ const uint8_t* Descriptors = nullptr;
+ const uint8_t* Payload = nullptr;
+ uint8_t Remaining = 0;
+
+ bool HasNext() const { return Remaining > 0; }
+ uint8_t PeekCategory() const { return (*Descriptors) & kCatMask; }
+ uint8_t PeekSize() const { return (*Descriptors) & kSizeMask; }
+
+ void Advance(size_t PayloadBytes)
+ {
+ Payload += PayloadBytes;
+ ++Descriptors;
+ --Remaining;
+ }
+
+ // On success, wires up the cursor into Data. On a null/truncated blob,
+ // leaves Dec in its default state (Remaining == 0) so the decode loop
+ // becomes a no-op and the caller just renders the format template
+ // against an empty arg store.
+ static void Init(ArgDecoder& Dec, const uint8_t* Data, size_t Size)
+ {
+ if (!Data || Size == 0)
+ {
+ return;
+ }
+ const uint8_t Count = Data[0];
+ if (size_t(1) + Count > Size)
+ {
+ return;
+ }
+ Dec.Descriptors = Data + 1;
+ Dec.Payload = Data + 1 + Count;
+ Dec.Remaining = Count;
+ }
+ };
+
+} // namespace
+
+std::string
+FormatLogArgs(std::string_view Format, const uint8_t* Data, size_t Size)
+{
+ using namespace std::literals;
+
+ ArgDecoder Stream;
+ ArgDecoder::Init(Stream, Data, Size);
+
+ // Payload bytes (including inlined null-terminated strings) live in the
+ // caller-owned Data buffer for the duration of this call, so we can hand
+ // fmt std::string_views that point straight into it rather than copying.
+ fmt::dynamic_format_arg_store<fmt::format_context> Store;
+ Store.reserve(Stream.Remaining, /*named*/ 0);
+
+ while (Stream.HasNext())
+ {
+ const uint8_t Category = Stream.PeekCategory();
+ const uint8_t ArgSize = Stream.PeekSize();
+
+ if (Category == kCatBool)
+ {
+ bool Value = (ArgSize == 1) && (Stream.Payload[0] != 0);
+ // Pushing as bool rather than int means fmt renders `{}` as
+ // `true`/`false` and `{:d}` as `1`/`0`, matching what the
+ // console/file sinks showed.
+ Store.push_back(Value);
+ Stream.Advance(ArgSize);
+ }
+ else if (Category == kCatSInt)
+ {
+ uint64_t Raw = 0;
+ if (ArgSize > 0 && ArgSize <= sizeof(Raw))
+ {
+ std::memcpy(&Raw, Stream.Payload, ArgSize);
+ }
+ // Sign-extend from the stored width so narrower negative values
+ // round-trip correctly.
+ int64_t Signed = 0;
+ switch (ArgSize)
+ {
+ case 1:
+ Signed = int8_t(Raw & 0xff);
+ break;
+ case 2:
+ Signed = int16_t(Raw & 0xffff);
+ break;
+ case 4:
+ Signed = int32_t(Raw & 0xffffffff);
+ break;
+ case 8:
+ default:
+ Signed = int64_t(Raw);
+ break;
+ }
+ Store.push_back(Signed);
+ Stream.Advance(ArgSize);
+ }
+ else if (Category == kCatUInt)
+ {
+ uint64_t Raw = 0;
+ if (ArgSize > 0 && ArgSize <= sizeof(Raw))
+ {
+ std::memcpy(&Raw, Stream.Payload, ArgSize);
+ }
+ Store.push_back(Raw);
+ Stream.Advance(ArgSize);
+ }
+ else if (Category == kCatFloat)
+ {
+ if (ArgSize == 4)
+ {
+ // Preserve float-vs-double distinction so fmt's default `{}`
+ // rendering matches what a direct fmt::format call would show
+ // (double's default precision differs from float's).
+ float F = 0.0f;
+ std::memcpy(&F, Stream.Payload, 4);
+ Store.push_back(F);
+ }
+ else if (ArgSize == 8)
+ {
+ double D = 0.0;
+ std::memcpy(&D, Stream.Payload, 8);
+ Store.push_back(D);
+ }
+ Stream.Advance(ArgSize);
+ }
+ else if (Category == kCatString)
+ {
+ if (ArgSize == 1)
+ {
+ const char* S = reinterpret_cast<const char*>(Stream.Payload);
+ const size_t Len = std::strlen(S);
+ Store.push_back(std::string_view(S, Len));
+ Stream.Advance(Len + 1);
+ }
+ else
+ {
+ // Wider strings (e.g. UTF-16) aren't emitted by the current
+ // encoder and we have no way to tell how many payload bytes
+ // to skip, so further decoding would read garbage. Surface a
+ // placeholder and stop - partial output is better than mis-
+ // aligned output.
+ Store.push_back("<?>"sv);
+ Stream.Remaining = 0;
+ }
+ }
+ else if (Category == kCatPointer)
+ {
+ uint64_t Raw = 0;
+ if (ArgSize > 0 && ArgSize <= sizeof(Raw))
+ {
+ std::memcpy(&Raw, Stream.Payload, ArgSize);
+ }
+ // Round-trip as void* so fmt's default `{}` renders "0x..." hex,
+ // matching a direct fmt::format call against the original pointer.
+ Store.push_back(reinterpret_cast<const void*>(static_cast<uintptr_t>(Raw)));
+ Stream.Advance(ArgSize);
+ }
+ else
+ {
+ // Unknown category: ArgSize is untrustworthy (it may not correspond
+ // to real payload bytes), so trying to continue past this point
+ // would desync the cursor. Stop with a placeholder.
+ Store.push_back("<arg>"sv);
+ Stream.Remaining = 0;
+ }
+ }
+
+ try
+ {
+ return fmt::vformat(fmt::string_view(Format.data(), Format.size()), Store);
+ }
+ catch (const fmt::format_error& Ex)
+ {
+ // A mismatched format spec shouldn't wedge the whole trace view -
+ // surface the template and the error to the reader instead.
+ return fmt::format("<fmt error: {}> {}", Ex.what(), Format);
+ }
+}
+
+} // namespace zen::logging
+
+# if ZEN_WITH_TESTS
+
+namespace zen::logging::tests {
+
+// Round-trip an argument pack through EncodeLogArgs -> FormatLogArgs and
+// compare against a direct fmt::format call against the same template.
+template<typename... Args>
+static void
+CheckRoundtrip(std::string_view Spec, const Args&... InArgs)
+{
+ const std::string Direct = fmt::format(fmt::runtime(Spec), InArgs...);
+
+ std::vector<uint8_t> Blob;
+ EncodeLogArgs(fmt::make_format_args(InArgs...), Blob);
+ const std::string Decoded = FormatLogArgs(Spec, Blob.data(), Blob.size());
+
+ CHECK_MESSAGE(Decoded == Direct, "spec=\"", Spec, "\" direct=\"", Direct, "\" decoded=\"", Decoded, "\"");
+}
+
+TEST_SUITE_BEGIN("core.tracelog");
+
+TEST_CASE("encode.plain_args")
+{
+ CheckRoundtrip("{}", 42);
+ CheckRoundtrip("{}", -42);
+ CheckRoundtrip("{}", 0);
+ CheckRoundtrip("{}", int64_t(0x7fffffffffffffffLL));
+ CheckRoundtrip("{}", std::numeric_limits<int64_t>::min());
+ CheckRoundtrip("{}", uint32_t(4000000000u)); // top bit set - splits signed/unsigned paths
+ CheckRoundtrip("{}", uint64_t(0xffffffffffffffffull));
+ CheckRoundtrip("{}", true);
+ CheckRoundtrip("{}", false);
+ CheckRoundtrip("{}", std::string_view("hello"));
+ CheckRoundtrip("{}", std::string_view(""));
+}
+
+TEST_CASE("encode.width_and_precision")
+{
+ CheckRoundtrip("{:10}", 42);
+ CheckRoundtrip("{:>10}", 42);
+ CheckRoundtrip("{:<10}", 42);
+ CheckRoundtrip("{:^10}", 42);
+ CheckRoundtrip("{:_>10}", 42);
+ CheckRoundtrip("{:*<8}", std::string_view("hi"));
+ CheckRoundtrip("{:.3}", std::string_view("hello"));
+ CheckRoundtrip("{:10.3}", std::string_view("hello"));
+ CheckRoundtrip("{:>10.3}", std::string_view("hello"));
+}
+
+TEST_CASE("encode.type_specs")
+{
+ CheckRoundtrip("{:x}", 255);
+ CheckRoundtrip("{:X}", 255);
+ CheckRoundtrip("{:#x}", 255);
+ CheckRoundtrip("{:b}", 13);
+ CheckRoundtrip("{:#b}", 13);
+ CheckRoundtrip("{:o}", 8);
+ CheckRoundtrip("{:d}", 42);
+ CheckRoundtrip("{:08x}", 0xabc);
+ CheckRoundtrip("{:+d}", 42);
+ CheckRoundtrip("{:+d}", -42);
+ CheckRoundtrip("{: d}", 42);
+}
+
+TEST_CASE("encode.bool_type_specs")
+{
+ // Bool roundtrips as bool (not int), so `{}` gives true/false and `{:d}`
+ // gives 1/0. This is zen-specific vs upstream UE's Logging.* printf path.
+ CheckRoundtrip("{}", true);
+ CheckRoundtrip("{}", false);
+ CheckRoundtrip("{:d}", true);
+ CheckRoundtrip("{:d}", false);
+ CheckRoundtrip("{:s}", true);
+}
+
+TEST_CASE("encode.float_specs")
+{
+ CheckRoundtrip("{}", 3.14);
+ CheckRoundtrip("{}", -3.14);
+ CheckRoundtrip("{}", 0.0);
+ CheckRoundtrip("{:.3f}", 3.14159);
+ CheckRoundtrip("{:10.3f}", 3.14159);
+ CheckRoundtrip("{:>10.3f}", 3.14159);
+ CheckRoundtrip("{:e}", 1234.5678);
+ CheckRoundtrip("{:.2e}", 1234.5678);
+ CheckRoundtrip("{:g}", 1234.5678);
+ CheckRoundtrip("{:+.3f}", 3.14);
+
+ // Float vs double are distinct on the wire so default `{}` renders match
+ CheckRoundtrip("{}", 3.14f);
+ CheckRoundtrip("{:.3f}", 3.14f);
+}
+
+TEST_CASE("encode.nested_widths")
+{
+ // Width/precision passed as separate positional args
+ CheckRoundtrip("{:>{}}", std::string_view("hi"), 8);
+ CheckRoundtrip("{:<{}}", 42, 6);
+ CheckRoundtrip("{:{}}", 42, 8);
+ CheckRoundtrip("{:.{}}", std::string_view("hello"), 3);
+ CheckRoundtrip("{:{}.{}f}", 3.14159, 10, 2);
+}
+
+TEST_CASE("encode.dynamic_width_from_stream")
+{
+ SUBCASE("width only")
+ {
+ // fmt consumes a second arg from the stream for `{}` width. The decoder
+ // must preserve arg ordering and integer type for dynamic specs to work.
+ CheckRoundtrip("{:{}}", 42, 0);
+ CheckRoundtrip("{:{}}", 42, 1); // width narrower than value -> no padding
+ CheckRoundtrip("{:{}}", 42, 12); // wide padding
+ CheckRoundtrip("{:>{}}", std::string_view("x"), 0);
+ CheckRoundtrip("{:>{}}", std::string_view("x"), 16);
+ CheckRoundtrip("{:_^{}}", std::string_view("hi"), 10);
+ }
+ SUBCASE("precision only")
+ {
+ CheckRoundtrip("{:.{}}", std::string_view("abcdef"), 0);
+ CheckRoundtrip("{:.{}}", std::string_view("abcdef"), 3);
+ CheckRoundtrip("{:.{}}", std::string_view("abcdef"), 100);
+ CheckRoundtrip("{:.{}f}", 1.0 / 3.0, 0);
+ CheckRoundtrip("{:.{}f}", 1.0 / 3.0, 6);
+ CheckRoundtrip("{:.{}f}", 1.0 / 3.0, 15);
+ CheckRoundtrip("{:.{}e}", 1234567.89, 3);
+ }
+ SUBCASE("width and precision both dynamic")
+ {
+ CheckRoundtrip("{:{}.{}f}", 3.14159, 10, 2);
+ CheckRoundtrip("{:>{}.{}f}", 3.14159, 14, 4);
+ CheckRoundtrip("{:*>{}.{}}", std::string_view("hello world"), 20, 7);
+ }
+ SUBCASE("positional dynamic width")
+ {
+ // `{0}` / `{1}` / `{2}` refer to specific arg indices; widths sourced
+ // from one index while the value comes from another exercises arg
+ // reordering through the decoder's Store.
+ CheckRoundtrip("{1:>{0}}", 10, std::string_view("xyz"));
+ CheckRoundtrip("{2:{0}.{1}f}", 12, 3, 1.61803);
+ }
+ SUBCASE("multiple values sharing a dynamic width")
+ {
+ // Same width arg consumed by two format specs - every spec needs its
+ // own `{n}` reference to the width.
+ CheckRoundtrip("[{0:>{2}}][{1:>{2}}]", 1, 2, 6);
+ }
+ SUBCASE("dynamic width on unsigned")
+ {
+ // Covers the kCatUInt decoding path in combination with nested specs.
+ CheckRoundtrip("{:{}}", uint32_t(4000000000u), 12);
+ CheckRoundtrip("{:>{}x}", uint64_t(0xdeadbeefcafeull), 16);
+ }
+ SUBCASE("dynamic width of zero")
+ {
+ // fmt treats width=0 as "no minimum width", not as truncation -
+ // ensure the decoder doesn't accidentally special-case it.
+ CheckRoundtrip("[{:>{}}]", std::string_view("hello"), 0);
+ CheckRoundtrip("[{:{}}]", 42, 0);
+ }
+}
+
+TEST_CASE("encode.multiple_args")
+{
+ CheckRoundtrip("{} + {} = {}", 1, 2, 3);
+ CheckRoundtrip("{} {} {} {}", 42, 3.14, std::string_view("str"), true);
+ CheckRoundtrip("[{:>4}] [{:<4}] [{:^4}]", 1, 2, 3);
+}
+
+TEST_CASE("encode.positional_args")
+{
+ CheckRoundtrip("{0} {1} {0}", std::string_view("a"), std::string_view("b"));
+ CheckRoundtrip("{1:<{0}}", 8, std::string_view("hi"));
+}
+
+TEST_CASE("encode.empty_args")
+{
+ std::vector<uint8_t> Blob;
+ EncodeLogArgs(fmt::format_args{}, Blob);
+ REQUIRE(!Blob.empty());
+ CHECK_EQ(Blob[0], uint8_t(0)); // arg count = 0
+ CHECK_EQ(FormatLogArgs("no args here", Blob.data(), Blob.size()), "no args here");
+ CHECK_EQ(FormatLogArgs("literal {{braces}}", Blob.data(), Blob.size()), "literal {braces}");
+}
+
+TEST_CASE("encode.mismatched_format_is_soft_error")
+{
+ // Arg count mismatches shouldn't crash - the decoder surfaces the error in
+ // the rendered message rather than throwing.
+ int Arg = 42;
+
+ std::vector<uint8_t> Blob;
+ EncodeLogArgs(fmt::make_format_args(Arg), Blob);
+ const std::string Out = FormatLogArgs("{} {} {}", Blob.data(), Blob.size());
+ CHECK_MESSAGE(Out.find("fmt error") != std::string::npos, "expected soft error, got: ", Out);
+}
+
+TEST_CASE("encode.pointer")
+{
+ // Pointers are encoded as uint64 and render identically via `{}`.
+ int Local = 0;
+ const void* P = &Local;
+ CheckRoundtrip("{}", P);
+ CheckRoundtrip("{}", static_cast<const void*>(nullptr));
+}
+
+// Minimal user-defined type with a custom fmt formatter, to exercise the
+// handle path in ArgEncoder without pulling in fmt/chrono.h here.
+struct Point2D
+{
+ int X;
+ int Y;
+};
+
+} // namespace zen::logging::tests
+
+template<>
+struct fmt::formatter<zen::logging::tests::Point2D> : fmt::formatter<std::string_view>
+{
+ auto format(const zen::logging::tests::Point2D& P, fmt::format_context& Ctx) const
+ {
+ return fmt::format_to(Ctx.out(), "({},{})", P.X, P.Y);
+ }
+};
+
+namespace zen::logging::tests {
+
+TEST_CASE("encode.custom_formatter_renders_as_string")
+{
+ // Custom-formatted types take the handle path in ArgEncoder, which
+ // pre-renders them to a string using an *empty* parse context. The
+ // decoder then receives a string, so the original `{}` works but any
+ // spec that only makes sense for the original type would fail.
+ Point2D P{3, 4};
+
+ std::vector<uint8_t> Blob;
+ EncodeLogArgs(fmt::make_format_args(P), Blob);
+
+ // Plain `{}` against the pre-rendered string works fine.
+ CHECK_EQ(FormatLogArgs("{}", Blob.data(), Blob.size()), "(3,4)");
+
+ // A type-specific spec against the decoded string surfaces a soft fmt
+ // error (simulating e.g. chrono `{:%Y-%m-%d}` against a time_point).
+ const std::string BadOut = FormatLogArgs("{:d}", Blob.data(), Blob.size());
+ CHECK_MESSAGE(BadOut.find("fmt error") != std::string::npos,
+ "type-specific spec against flattened string should soft-fail, got: ",
+ BadOut);
+}
+
+TEST_SUITE_END();
+
+} // namespace zen::logging::tests
+
+# endif // ZEN_WITH_TESTS
+
+#endif // ZEN_WITH_TRACE
diff --git a/src/zencore/logging/tracesink.cpp b/src/zencore/logging/tracesink.cpp
deleted file mode 100644
index 8a6f4e40c..000000000
--- a/src/zencore/logging/tracesink.cpp
+++ /dev/null
@@ -1,92 +0,0 @@
-
-// Copyright Epic Games, Inc. All Rights Reserved.
-
-#include <zencore/logbase.h>
-#include <zencore/logging/tracesink.h>
-#include <zencore/string.h>
-#include <zencore/timer.h>
-#include <zencore/trace.h>
-
-#if ZEN_WITH_TRACE
-
-namespace zen::logging {
-
-UE_TRACE_CHANNEL_DEFINE(LogChannel)
-
-UE_TRACE_EVENT_BEGIN(Logging, LogCategory, NoSync | Important)
- UE_TRACE_EVENT_FIELD(const void*, CategoryPointer)
- UE_TRACE_EVENT_FIELD(uint8_t, DefaultVerbosity)
- UE_TRACE_EVENT_FIELD(UE::Trace::AnsiString, Name)
-UE_TRACE_EVENT_END()
-
-UE_TRACE_EVENT_BEGIN(Logging, LogMessageSpec, NoSync | Important)
- UE_TRACE_EVENT_FIELD(const void*, LogPoint)
- UE_TRACE_EVENT_FIELD(const void*, CategoryPointer)
- UE_TRACE_EVENT_FIELD(int32_t, Line)
- UE_TRACE_EVENT_FIELD(uint8_t, Verbosity)
- UE_TRACE_EVENT_FIELD(UE::Trace::AnsiString, FileName)
- UE_TRACE_EVENT_FIELD(UE::Trace::AnsiString, FormatString)
-UE_TRACE_EVENT_END()
-
-UE_TRACE_EVENT_BEGIN(Logging, LogMessage, NoSync)
- UE_TRACE_EVENT_FIELD(const void*, LogPoint)
- UE_TRACE_EVENT_FIELD(uint64_t, Cycle)
- UE_TRACE_EVENT_FIELD(uint8_t[], FormatArgs)
-UE_TRACE_EVENT_END()
-
-void
-TraceLogCategory(const logging::Logger* Category, const char* Name, logging::LogLevel DefaultVerbosity)
-{
- uint16_t NameLen = uint16_t(strlen(Name));
- UE_TRACE_LOG(Logging, LogCategory, LogChannel, NameLen * sizeof(ANSICHAR))
- << LogCategory.CategoryPointer(Category) << LogCategory.DefaultVerbosity(uint8_t(DefaultVerbosity))
- << LogCategory.Name(Name, NameLen);
-}
-
-void
-TraceLogMessageSpec(const void* LogPoint,
- const logging::Logger* Category,
- logging::LogLevel Verbosity,
- const std::string_view File,
- int32_t Line,
- const std::string_view Format)
-{
- uint16_t FileNameLen = uint16_t(File.size());
- uint16_t FormatStringLen = uint16_t(Format.size());
- uint32_t DataSize = (FileNameLen * sizeof(ANSICHAR)) + (FormatStringLen * sizeof(ANSICHAR));
- UE_TRACE_LOG(Logging, LogMessageSpec, LogChannel, DataSize)
- << LogMessageSpec.LogPoint(LogPoint) << LogMessageSpec.CategoryPointer(Category) << LogMessageSpec.Line(Line)
- << LogMessageSpec.Verbosity(uint8_t(Verbosity)) << LogMessageSpec.FileName(File.data(), FileNameLen)
- << LogMessageSpec.FormatString(Format.data(), FormatStringLen);
-}
-
-void
-TraceLogMessageInternal(const void* LogPoint, int32_t EncodedFormatArgsSize, const uint8_t* EncodedFormatArgs)
-{
- UE_TRACE_LOG(Logging, LogMessage, LogChannel) << LogMessage.LogPoint(LogPoint) << LogMessage.Cycle(GetHifreqTimerValue())
- << LogMessage.FormatArgs(EncodedFormatArgs, EncodedFormatArgsSize);
-}
-
-//////////////////////////////////////////////////////////////////////////
-
-void
-TraceSink::Log(const LogMessage& Msg)
-{
- ZEN_UNUSED(Msg);
-}
-
-void
-TraceSink::Flush()
-{
-}
-
-void
-TraceSink::SetFormatter(std::unique_ptr<Formatter> /*InFormatter*/)
-{
- // This sink doesn't use a formatter since it just forwards the raw format
- // args to the trace system
-}
-
-} // namespace zen::logging
-
-#endif