diff options
Diffstat (limited to 'src/zencore/logging')
| -rw-r--r-- | src/zencore/logging/ansicolorsink.cpp | 68 | ||||
| -rw-r--r-- | src/zencore/logging/logger.cpp | 61 | ||||
| -rw-r--r-- | src/zencore/logging/registry.cpp | 4 | ||||
| -rw-r--r-- | src/zencore/logging/tracelog.cpp | 800 | ||||
| -rw-r--r-- | src/zencore/logging/tracesink.cpp | 92 |
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 |