diff options
Diffstat (limited to 'library/cpp/yt/logging')
21 files changed, 1960 insertions, 273 deletions
diff --git a/library/cpp/yt/logging/backends/arcadia/backend.cpp b/library/cpp/yt/logging/backends/arcadia/backend.cpp index 3c6ff9f5f58..5878ba52be3 100644 --- a/library/cpp/yt/logging/backends/arcadia/backend.cpp +++ b/library/cpp/yt/logging/backends/arcadia/backend.cpp @@ -57,7 +57,7 @@ public: // Use low-level api, because it is more convinient here. auto loggingContext = GetLoggingContext(); auto event = NDetail::CreateLogEvent(loggingContext, Logger_, logLevel); - event.MessageRef = NDetail::BuildLogMessage(loggingContext, Logger_, message).MessageRef; + event.Payload = NDetail::BuildLogMessage(loggingContext, Logger_, message).Payload; event.Family = ELogFamily::PlainText; Logger_.Write(std::move(event)); } diff --git a/library/cpp/yt/logging/benchmark/logging.cpp b/library/cpp/yt/logging/benchmark/logging.cpp new file mode 100644 index 00000000000..8745511f2bd --- /dev/null +++ b/library/cpp/yt/logging/benchmark/logging.cpp @@ -0,0 +1,167 @@ +#include <benchmark/benchmark.h> + +#include <library/cpp/yt/logging/logger.h> + +#include <atomic> + +namespace NYT::NLogging { +namespace { + +//////////////////////////////////////////////////////////////////////////////// + +// A log manager whose Enqueue is essentially free, so that the benchmark measures +// only the producer-side cost (building the event payload), not the logging thread. +class TBenchmarkLogManager + : public ILogManager +{ +public: + void RegisterStaticAnchor(TLoggingAnchor* anchor, ::TSourceLocation /*sourceLocation*/, TStringBuf /*message*/) override + { + anchor->Registered.store(true); + } + + void UpdateAnchor(TLoggingAnchor* anchor) override + { + anchor->CurrentVersion.store(ActualVersion_.load()); + } + + void Enqueue(TLogEvent&& event) override + { + // Keep the produced payload observable so the build is not optimized away; + // the event is then destroyed (freeing its chunk slice) -- same for both APIs. + benchmark::DoNotOptimize(std::get<TTaggedLogEventPayload>(event.Payload).Underlying().Begin()); + } + + const TLoggingCategory* GetCategory(TStringBuf /*categoryName*/) override + { + return &Category_; + } + + void UpdateCategory(TLoggingCategory* category) override + { + category->CurrentVersion.store(ActualVersion_.load()); + } + + bool GetAbortOnAlert() const override + { + return false; + } + +private: + std::atomic<int> ActualVersion_ = 1; + TLoggingCategory Category_ = { + .Name = "Bench", + .MinPlainTextLevel = ELogLevel::Minimum, + .CurrentVersion = 0, + .ActualVersion = &ActualVersion_, + }; +}; + +//////////////////////////////////////////////////////////////////////////////// +// No tags. + +void BM_Log_NoTags(benchmark::State& state) +{ + TBenchmarkLogManager manager; + TLogger Logger(&manager, "Bench"); + for (auto _ : state) { + YT_LOG_INFO("This is a log message of a typical length without tags"); + } +} +BENCHMARK(BM_Log_NoTags); + +void BM_TLog_NoTags(benchmark::State& state) +{ + TBenchmarkLogManager manager; + TLogger Logger(&manager, "Bench"); + for (auto _ : state) { + YT_TLOG_INFO("This is a log message of a typical length without tags"); + } +} +BENCHMARK(BM_TLog_NoTags); + +//////////////////////////////////////////////////////////////////////////////// +// One int tag. + +void BM_Log_OneTag(benchmark::State& state) +{ + TBenchmarkLogManager manager; + TLogger Logger(&manager, "Bench"); + for (auto _ : state) { + YT_LOG_INFO("This is a log message of a typical length (TagName: %v)", + 123); + } +} +BENCHMARK(BM_Log_OneTag); + +void BM_TLog_OneTag(benchmark::State& state) +{ + TBenchmarkLogManager manager; + TLogger Logger(&manager, "Bench"); + for (auto _ : state) { + YT_TLOG_INFO("This is a log message of a typical length") + .With("TagName", 123); + } +} +BENCHMARK(BM_TLog_OneTag); + +//////////////////////////////////////////////////////////////////////////////// +// Two tags (int + string). + +void BM_Log_TwoTags(benchmark::State& state) +{ + TBenchmarkLogManager manager; + TLogger Logger(&manager, "Bench"); + for (auto _ : state) { + YT_LOG_INFO("This is a log message of a typical length (TagName1: %v, TagName2: %v)", + 123, + "this-is-a-string"); + } +} +BENCHMARK(BM_Log_TwoTags); + +void BM_TLog_TwoTags(benchmark::State& state) +{ + TBenchmarkLogManager manager; + TLogger Logger(&manager, "Bench"); + for (auto _ : state) { + YT_TLOG_INFO("This is a log message of a typical length") + .With("TagName1", 123) + .With("TagName2", "this-is-a-string"); + } +} +BENCHMARK(BM_TLog_TwoTags); + +//////////////////////////////////////////////////////////////////////////////// +// Three tags (int + string + double). + +void BM_Log_ThreeTags(benchmark::State& state) +{ + TBenchmarkLogManager manager; + TLogger Logger(&manager, "Bench"); + for (auto _ : state) { + YT_LOG_INFO("This is a log message of a typical length (TagName1: %v, TagName2: %v, TagName3: %v)", + 123, + "this-is-a-string", + 3.14); + } +} +BENCHMARK(BM_Log_ThreeTags); + +void BM_TLog_ThreeTags(benchmark::State& state) +{ + TBenchmarkLogManager manager; + TLogger Logger(&manager, "Bench"); + for (auto _ : state) { + YT_TLOG_INFO("This is a log message of a typical length") + .With("TagName1", 123) + .With("TagName2", "this-is-a-string") + .With("TagName3", 3.14); + } +} +BENCHMARK(BM_TLog_ThreeTags); + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace +} // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/benchmark/ya.make b/library/cpp/yt/logging/benchmark/ya.make index 61fd0b49276..a7a23128cdf 100644 --- a/library/cpp/yt/logging/benchmark/ya.make +++ b/library/cpp/yt/logging/benchmark/ya.make @@ -4,6 +4,7 @@ INCLUDE(${ARCADIA_ROOT}/library/cpp/yt/ya_cpp.make.inc) SRCS( logger_tag.cpp + logging.cpp ) PEERDIR( diff --git a/library/cpp/yt/logging/logger-inl.h b/library/cpp/yt/logging/logger-inl.h index fa20fb06489..ff4d6d81bbe 100644 --- a/library/cpp/yt/logging/logger-inl.h +++ b/library/cpp/yt/logging/logger-inl.h @@ -4,6 +4,8 @@ #include "logger.h" #endif +#include "tagged_payload.h" + #include <library/cpp/yt/yson_string/convert.h> #include <library/cpp/yt/yson_string/string.h> @@ -107,33 +109,6 @@ Y_FORCE_INLINE const TLogger& TLogger::operator()() const namespace NDetail { -struct TMessageStringBuilderContext -{ - TSharedMutableRef Chunk; -}; - -struct TMessageBufferTag -{ }; - -class TMessageStringBuilder - : public TStringBuilderBase -{ -public: - TSharedRef Flush(); - - // For testing only. - static void DisablePerThreadCache(); - -protected: - void DoReset() override; - void DoReserve(size_t newLength) override; - -private: - TSharedMutableRef Buffer_; - - static constexpr size_t ChunkSize = 128_KB - 64; -}; - inline bool HasMessageTags( const TLoggingContext& loggingContext, const TLogger& logger) @@ -162,14 +137,14 @@ inline void AppendMessageTags( } if (const auto& traceLoggingTag = loggingContext.TraceLoggingTag; !traceLoggingTag.empty()) { if (printComma) { - builder->AppendString(TStringBuf(", ")); + builder->AppendString(", "_sb); } builder->AppendString(traceLoggingTag); printComma = true; } if (const auto& threadMessageTag = GetThreadMessageTag(); !threadMessageTag.empty()) { if (printComma) { - builder->AppendString(TStringBuf(", ")); + builder->AppendString(", "_sb); } builder->AppendString(threadMessageTag); printComma = true; @@ -185,10 +160,10 @@ inline void AppendLogMessage( if (HasMessageTags(loggingContext, logger)) { if (message.Size() >= 1 && message[message.Size() - 1] == ')') { builder->AppendString(TStringBuf(message.Begin(), message.Size() - 1)); - builder->AppendString(TStringBuf(", ")); + builder->AppendString(", "_sb); } else { builder->AppendString(TStringBuf(message.Begin(), message.Size())); - builder->AppendString(TStringBuf(" (")); + builder->AppendString(" ("_sb); } AppendMessageTags(builder, loggingContext, logger); builder->AppendChar(')'); @@ -208,10 +183,10 @@ void AppendLogMessageWithFormat( if (HasMessageTags(loggingContext, logger)) { if (format.size() >= 2 && format[format.size() - 1] == ')') { builder->AppendFormat(TRuntimeFormat{format.substr(0, format.size() - 1)}, std::forward<TArgs>(args)...); - builder->AppendString(TStringBuf(", ")); + builder->AppendString(", "_sb); } else { builder->AppendFormat(TRuntimeFormat{format}, std::forward<TArgs>(args)...); - builder->AppendString(TStringBuf(" (")); + builder->AppendString(" ("_sb); } AppendMessageTags(builder, loggingContext, logger); builder->AppendChar(')'); @@ -222,7 +197,7 @@ void AppendLogMessageWithFormat( struct TLogMessage { - TSharedRef MessageRef; + TTaggedLogEventPayload Payload; TStringBuf Anchor; }; @@ -233,9 +208,10 @@ TLogMessage BuildLogMessage( TFormatString<TArgs...> format, TArgs&&... args) { - TMessageStringBuilder builder; - AppendLogMessageWithFormat(&builder, loggingContext, logger, format.Get(), std::forward<TArgs>(args)...); - return {builder.Flush(), format.Get()}; + TTaggedPayloadWriter writer; + AppendLogMessageWithFormat(writer.BeginMessage(), loggingContext, logger, format.Get(), std::forward<TArgs>(args)...); + writer.EndMessage(); + return {writer.Finish(), format.Get()}; } template <CFormattable T> @@ -245,13 +221,15 @@ TLogMessage BuildLogMessage( const TLogger& logger, const T& obj) { - TMessageStringBuilder builder; - FormatValue(&builder, obj, TStringBuf("v")); + TTaggedPayloadWriter writer; + auto* builder = writer.BeginMessage(); + FormatValue(builder, obj, "v"_sb); if (HasMessageTags(loggingContext, logger)) { - builder.AppendString(TStringBuf(" (")); - AppendMessageTags(&builder, loggingContext, logger); - builder.AppendChar(')'); + builder->AppendString(" ("_sb); + AppendMessageTags(builder, loggingContext, logger); + builder->AppendChar(')'); } + writer.EndMessage(); if constexpr (std::same_as<TStringBuf, std::remove_cvref_t<T>>) { // NB(arkady-e1ppa): This is the overload where TStringBuf @@ -262,9 +240,9 @@ TLogMessage BuildLogMessage( // us having overload for TStringBuf (both have implicit ctors from // string literals) thus we have to accommodate TStringBuf specifics // in this if constexpr part. - return {builder.Flush(), obj}; + return {writer.Finish(), obj}; } else { - return {builder.Flush(), TStringBuf()}; + return {writer.Finish(), TStringBuf()}; } } @@ -295,13 +273,10 @@ inline TLogMessage BuildLogMessage( const TLogger& logger, TSharedRef&& message) { - if (HasMessageTags(loggingContext, logger)) { - TMessageStringBuilder builder; - AppendLogMessage(&builder, loggingContext, logger, message); - return {builder.Flush(), TStringBuf()}; - } else { - return {std::move(message), TStringBuf()}; - } + TTaggedPayloadWriter writer; + AppendLogMessage(writer.BeginMessage(), loggingContext, logger, message); + writer.EndMessage(); + return {writer.Finish(), TStringBuf()}; } inline TLogEvent CreateLogEvent( @@ -310,10 +285,10 @@ inline TLogEvent CreateLogEvent( ELogLevel level) { TLogEvent event; - event.Instant = loggingContext.Instant; event.Category = logger.GetCategory(); - event.Essential = logger.IsEssential(); event.Level = level; + event.Essential = logger.IsEssential(); + event.Instant = loggingContext.Instant; event.ThreadId = loggingContext.ThreadId; event.ThreadName = loggingContext.ThreadName; event.FiberId = loggingContext.FiberId; @@ -332,15 +307,24 @@ inline void LogEventImpl( ELogLevel level, ::TSourceLocation sourceLocation, TLoggingAnchor* anchor, - TSharedRef message) + TTaggedLogEventPayload payload) { - auto event = CreateLogEvent(loggingContext, logger, level); - event.MessageKind = ELogMessageKind::Unstructured; - event.MessageRef = std::move(message); - event.Family = ELogFamily::PlainText; - event.SourceFile = sourceLocation.File; - event.SourceLine = sourceLocation.Line; - event.Anchor = anchor; + auto event = TLogEvent{ + .Category = logger.GetCategory(), + .Level = level, + .Family = ELogFamily::PlainText, + .Essential = logger.IsEssential(), + .Payload = std::move(payload), + .Instant = loggingContext.Instant, + .ThreadId = loggingContext.ThreadId, + .ThreadName = loggingContext.ThreadName, + .FiberId = loggingContext.FiberId, + .TraceId = loggingContext.TraceId, + .RequestId = loggingContext.RequestId, + .SourceFile = sourceLocation.File, + .SourceLine = sourceLocation.Line, + .Anchor = anchor, + }; if (Y_UNLIKELY(event.Level >= ELogLevel::Alert)) { logger.Write(TLogEvent(event)); OnCriticalLogEvent(logger, event); @@ -349,6 +333,299 @@ inline void LogEventImpl( } } +//////////////////////////////////////////////////////////////////////////////// + +//! References the per-call-site static anchor and its one-shot registration flag. +//! Produced by the lambda embedded in the fluent |YT_TLOG_*| macros. +struct TStaticAnchorRef +{ + TLoggingAnchor* Anchor; + std::atomic<bool>* Registered; +}; + +//! Wraps the format spec passed to |TTaggedLoggingGuard::With| and validates at compile +//! time that it is a |%|-prefixed string literal (e.g. |"%v"|, |"%08x"|). The stored +//! spec has the leading |%| stripped, as expected by |FormatValue|. +class TLoggingTagSpec +{ +public: + template <size_t N> + consteval TLoggingTagSpec(const char (&spec)[N]) + : Spec_(spec + 1, N - 2) + { + static_assert(N >= 2, "Logging tag format spec must be a non-empty string literal"); + if (spec[0] != '%') { + TheLoggingTagFormatSpecMustStartWithPercentSign(); + } + } + + TStringBuf Get() const + { + return Spec_; + } + +private: + const TStringBuf Spec_; + + // Undefined on purpose: calling it from the |consteval| ctor turns a missing + // leading |%| into a compile error that names the violated rule. + static void TheLoggingTagFormatSpecMustStartWithPercentSign(); +}; + +class TWellKnownTaggedLoggingGuard; + +//! Accumulates a tagged log message via a fluent |.With| chain and emits the event in +//! its destructor. Instantiated by the fluent |YT_TLOG_*| macros, which guarantee that +//! the chain is reached only when the level is enabled (so tag value expressions are +//! not evaluated otherwise). +//! +//! The user message -- with the logger's contextual (logger/trace/thread) tags folded +//! in -- goes to the payload message field; each |.With(key, value)| becomes a +//! structured payload tag (see #TTaggedPayloadWriter). +class TTaggedLoggingGuard +{ +public: + TTaggedLoggingGuard( + const TLogger& logger, + ELogLevel level, + ::TSourceLocation sourceLocation, + TStaticAnchorRef anchorRef, + TStringBuf message) + : TTaggedLoggingGuard( + logger, + level, + sourceLocation, + anchorRef, + message, + /*alwaysBuildMessage*/ false) + { } + + TTaggedLoggingGuard(const TTaggedLoggingGuard&) = delete; + TTaggedLoggingGuard& operator=(const TTaggedLoggingGuard&) = delete; + + bool IsEnabled() const + { + return Enabled_; + } + + template <class TValue> + TTaggedLoggingGuard& With(TStringBuf tag, const TValue& value) & + { + return DoWith(tag, value, "v"_sb); + } + + template <class TValue> + TTaggedLoggingGuard& With(TStringBuf tag, const TValue& value, TLoggingTagSpec spec) & + { + return DoWith(tag, value, spec.Get()); + } + + //! Attaches a well-known tag whose key is resolved from #value's type via the + //! |GetWellKnownLoggingTag| ADL point (the type must opt in, e.g. errors). + //! + //! Returns a #TWellKnownTaggedLoggingGuard, which exposes only further well-known + //! tags: the payload contract requires well-known tags to come last (so + //! #FormatTaggedPayload can stay single-pass), so a keyed |.With(key, value)| after a + //! well-known tag must not compile. + template <class TValue> + TWellKnownTaggedLoggingGuard With(const TValue& value) &; + + ~TTaggedLoggingGuard() + { + if (!Enabled_) { + return; + } + LogEventImpl( + LoggingContext_, + Logger_, + EffectiveLevel_, + SourceLocation_, + Anchor_, + Writer_.Finish()); + } + +protected: + const TLogger& Logger_; + const ::TSourceLocation SourceLocation_; + TLoggingAnchor* const Anchor_; + + bool Enabled_ = false; + ELogLevel EffectiveLevel_ = ELogLevel::Minimum; + TLoggingContext LoggingContext_; + TTaggedPayloadWriter Writer_; + + //! Shared constructor. When #alwaysBuildMessage is set the payload message is built + //! even if the level is disabled (so a terminal guard can still recover it); #Enabled_ + //! continues to gate whether the destructor emits the event. + TTaggedLoggingGuard( + const TLogger& logger, + ELogLevel level, + ::TSourceLocation sourceLocation, + TStaticAnchorRef anchorRef, + TStringBuf message, + bool alwaysBuildMessage) + : Logger_(logger) + , SourceLocation_(sourceLocation) + , Anchor_(anchorRef.Anchor) + { + if (!Logger_.IsAnchorUpToDate(*Anchor_)) [[unlikely]] { + Logger_.UpdateStaticAnchor(Anchor_, anchorRef.Registered, sourceLocation, message); + } + + EffectiveLevel_ = TLogger::GetEffectiveLoggingLevel(level, *Anchor_); + Enabled_ = Logger_.IsLevelEnabled(EffectiveLevel_); + if (!Enabled_ && !alwaysBuildMessage) { + return; + } + + LoggingContext_ = GetLoggingContext(); + + auto* builder = Writer_.BeginMessage(); + builder->AppendString(message); + if (HasMessageTags(LoggingContext_, Logger_)) { + builder->AppendString(" ("_sb); + AppendMessageTags(builder, LoggingContext_, Logger_); + builder->AppendChar(')'); + } + Writer_.EndMessage(); + } + +private: + template <class TValue> + TTaggedLoggingGuard& DoWith(TStringBuf tag, const TValue& value, TStringBuf spec) & + { + // Format the value straight into the payload buffer; no temporary. + FormatValue(Writer_.BeginTag(tag), value, spec); + Writer_.EndTag(); + return *this; + } +}; + +//! Restricts the fluent |.With| chain once a well-known tag has been attached. The +//! payload contract requires well-known tags to come last (#FormatTaggedPayload is +//! single-pass), so only further well-known |.With(value)| calls are exposed -- a keyed +//! |.With(key, value)| after a well-known tag fails to compile. +class TWellKnownTaggedLoggingGuard +{ +public: + explicit TWellKnownTaggedLoggingGuard(TTaggedLoggingGuard& guard) + : Guard_(guard) + { } + + template <class TValue> + TWellKnownTaggedLoggingGuard With(const TValue& value) && + { + return Guard_.With(value); + } + +private: + TTaggedLoggingGuard& Guard_; +}; + +template <class TValue> +TWellKnownTaggedLoggingGuard TTaggedLoggingGuard::With(const TValue& value) & +{ + FormatValue(Writer_.BeginWellKnownTag(GetWellKnownLoggingTag(value)), value, "v"_sb); + Writer_.EndTag(); + return TWellKnownTaggedLoggingGuard(*this); +} + +//! Terminal guard for the fluent |YT_TLOG_FATAL| macros. Builds the message +//! unconditionally and, once the |.With| chain completes, emits the event at |Fatal| +//! level -- which aborts the process. The enclosing |for| invokes #Commit in its step. +class TTaggedFatalLoggingGuard + : public TTaggedLoggingGuard +{ +public: + TTaggedFatalLoggingGuard( + const TLogger& logger, + ::TSourceLocation sourceLocation, + TStaticAnchorRef anchorRef, + TStringBuf message) + : TTaggedLoggingGuard(logger, ELogLevel::Fatal, sourceLocation, anchorRef, message, /*alwaysBuildMessage*/ true) + { } + + //! Returns true exactly once, so the enclosing |for| runs the |.With| chain a single + //! time before its step expression commits the event. + bool TryEnter() + { + bool pending = Pending_; + Pending_ = false; + return pending; + } + + //! Emits the event at |Fatal| level; the log manager aborts the process. + [[noreturn]] void Commit() & + { + Enabled_ = false; // The event is emitted here, not from the base destructor. + LogEventImpl(LoggingContext_, Logger_, ELogLevel::Fatal, SourceLocation_, Anchor_, Writer_.Finish()); + Y_UNREACHABLE(); + } + +private: + bool Pending_ = true; +}; + +//! Terminal guard for the fluent |YT_TLOG_ALERT_AND_THROW| macros. Builds the message +//! unconditionally; once the |.With| chain completes, #Commit emits the event at |Alert| +//! level (when enabled) and returns the message so the macro can attach it to the thrown +//! error. The throw lives in the macro -- the logging library must not depend on the +//! error library, and a destructor must not throw. +class TTaggedThrowingLoggingGuard + : public TTaggedLoggingGuard +{ +public: + TTaggedThrowingLoggingGuard( + const TLogger& logger, + ::TSourceLocation sourceLocation, + TStaticAnchorRef anchorRef, + TStringBuf message) + : TTaggedLoggingGuard(logger, ELogLevel::Alert, sourceLocation, anchorRef, message, /*alwaysBuildMessage*/ true) + { } + + //! Returns true exactly once, so the enclosing |for| runs the |.With| chain a single + //! time before its step expression commits the event and throws. + bool TryEnter() + { + bool pending = Pending_; + Pending_ = false; + return pending; + } + + //! Emits the alert event (when enabled) and returns its message for the error payload. + std::string Commit() & + { + auto payload = Writer_.Finish(); + std::string message(GetMessageFromTaggedPayload(payload)); + if (Enabled_) { + Enabled_ = false; // The event is emitted here, not from the base destructor. + LogEventImpl(LoggingContext_, Logger_, EffectiveLevel_, SourceLocation_, Anchor_, std::move(payload)); + } + return message; + } + +private: + bool Pending_ = true; +}; + +//! A no-op stand-in for #TTaggedLoggingGuard used by compile-time-disabled trace logging: +//! it swallows the |.With| chain without evaluating it. +class TNullTaggedLoggingGuard +{ +public: + template <class... TArgs> + TNullTaggedLoggingGuard& With(TArgs&&...) + { + return *this; + } +}; + +template <class TMessage> +TNullTaggedLoggingGuard MakeNullTaggedLoggingGuard(const TMessage&) +{ + return {}; +} + } // namespace NDetail //////////////////////////////////////////////////////////////////////////////// diff --git a/library/cpp/yt/logging/logger.cpp b/library/cpp/yt/logging/logger.cpp index 64d8b06fa7e..5359c1cd141 100644 --- a/library/cpp/yt/logging/logger.cpp +++ b/library/cpp/yt/logging/logger.cpp @@ -1,9 +1,13 @@ #include "logger.h" +#include "structured_payload.h" + #include <library/cpp/yt/assert/assert.h> #include <library/cpp/yt/cpu_clock/clock.h> +#include <library/cpp/yt/memory/leaky_singleton.h> + #include <library/cpp/yt/system/thread_name.h> #include <util/system/compiler.h> @@ -23,98 +27,13 @@ void OnCriticalLogEvent( event.Level == ELogLevel::Alert && logger.GetAbortOnAlert()) { fprintf(stderr, "*** Aborting on critical log event\n"); - fwrite(event.MessageRef.begin(), 1, event.MessageRef.size(), stderr); + auto message = FormatTaggedPayload(std::get<TTaggedLogEventPayload>(event.Payload)); + fwrite(message.data(), 1, message.size(), stderr); fprintf(stderr, "\n"); YT_ABORT(); } } -TSharedRef TMessageStringBuilder::Flush() -{ - return Buffer_.Slice(0, GetLength()); -} - -void TMessageStringBuilder::DoReset() -{ - Buffer_.Reset(); -} - -struct TPerThreadCache; - -YT_DEFINE_THREAD_LOCAL(TPerThreadCache*, Cache); -YT_DEFINE_THREAD_LOCAL(bool, CacheDestroyed); - -struct TPerThreadCache -{ - TSharedMutableRef Chunk; - size_t ChunkOffset = 0; - - ~TPerThreadCache() - { - TMessageStringBuilder::DisablePerThreadCache(); - } - - static YT_PREVENT_TLS_CACHING TPerThreadCache* GetCache() - { - auto& cache = Cache(); - if (Y_LIKELY(cache)) { - return cache; - } - if (CacheDestroyed()) { - return nullptr; - } - static thread_local TPerThreadCache CacheData; - cache = &CacheData; - return cache; - } -}; - -void TMessageStringBuilder::DisablePerThreadCache() -{ - Cache() = nullptr; - CacheDestroyed() = true; -} - -void TMessageStringBuilder::DoReserve(size_t newCapacity) -{ - auto oldLength = GetLength(); - newCapacity = FastClp2(newCapacity); - - auto newChunkSize = std::max(ChunkSize, newCapacity); - // Hold the old buffer until the data is copied. - auto oldBuffer = std::move(Buffer_); - auto* cache = TPerThreadCache::GetCache(); - if (Y_LIKELY(cache)) { - auto oldCapacity = End_ - Begin_; - auto deltaCapacity = newCapacity - oldCapacity; - if (End_ == cache->Chunk.Begin() + cache->ChunkOffset && - cache->ChunkOffset + deltaCapacity <= cache->Chunk.Size()) - { - // Resize inplace. - Buffer_ = cache->Chunk.Slice(cache->ChunkOffset - oldCapacity, cache->ChunkOffset + deltaCapacity); - cache->ChunkOffset += deltaCapacity; - End_ = Begin_ + newCapacity; - return; - } - - if (Y_UNLIKELY(cache->ChunkOffset + newCapacity > cache->Chunk.Size())) { - cache->Chunk = TSharedMutableRef::Allocate<TMessageBufferTag>(newChunkSize, {.InitializeStorage = false}); - cache->ChunkOffset = 0; - } - - Buffer_ = cache->Chunk.Slice(cache->ChunkOffset, cache->ChunkOffset + newCapacity); - cache->ChunkOffset += newCapacity; - } else { - Buffer_ = TSharedMutableRef::Allocate<TMessageBufferTag>(newChunkSize, {.InitializeStorage = false}); - newCapacity = newChunkSize; - } - if (oldLength > 0) { - ::memcpy(Buffer_.Begin(), Begin_, oldLength); - } - Begin_ = Buffer_.Begin(); - End_ = Begin_ + newCapacity; -} - } // namespace NDetail //////////////////////////////////////////////////////////////////////////////// @@ -149,16 +68,34 @@ ELogLevel GetThreadMinLogLevel() //////////////////////////////////////////////////////////////////////////////// -YT_DEFINE_THREAD_LOCAL(std::string, ThreadMessageTag); +YT_DEFINE_THREAD_LOCAL(bool, ThreadMessageTagDestroyed, false); + +struct TThreadMessageTagStorage +{ + std::string Tag; + + ~TThreadMessageTagStorage() + { + ThreadMessageTagDestroyed() = true; + } +}; + +YT_DEFINE_THREAD_LOCAL(TThreadMessageTagStorage, ThreadMessageTag); void SetThreadMessageTag(std::string messageTag) { - ThreadMessageTag() = std::move(messageTag); + if (Y_UNLIKELY(ThreadMessageTagDestroyed())) { + return; + } + ThreadMessageTag().Tag = std::move(messageTag); } std::string& GetThreadMessageTag() { - return ThreadMessageTag(); + if (Y_UNLIKELY(ThreadMessageTagDestroyed())) { + return *LeakySingleton<std::string>(); + } + return ThreadMessageTag().Tag; } //////////////////////////////////////////////////////////////////////////////// @@ -350,8 +287,7 @@ void LogStructuredEvent( loggingContext, logger, level); - event.MessageKind = ELogMessageKind::Structured; - event.MessageRef = message.ToSharedRef(); + event.Payload = MakeStructuredPayloadFromYson(message); event.Family = ELogFamily::Structured; logger.Write(std::move(event)); } diff --git a/library/cpp/yt/logging/logger.h b/library/cpp/yt/logging/logger.h index d781326e88d..0f29b6f7376 100644 --- a/library/cpp/yt/logging/logger.h +++ b/library/cpp/yt/logging/logger.h @@ -80,11 +80,6 @@ using TRequestId = TGuid; //////////////////////////////////////////////////////////////////////////////// -DEFINE_ENUM(ELogMessageKind, - (Unstructured) - (Structured) -); - struct TLogEvent { const TLoggingCategory* Category = nullptr; @@ -92,8 +87,9 @@ struct TLogEvent ELogFamily Family = ELogFamily::PlainText; bool Essential = false; - ELogMessageKind MessageKind = ELogMessageKind::Unstructured; - TSharedRef MessageRef; + //! The active alternative identifies the event kind (tagged plain-text vs + //! structured) and determines how the bytes are decoded. + TLogEventPayload Payload; TCpuInstant Instant = 0; @@ -327,10 +323,10 @@ void LogStructuredEvent( #define YT_LOG_ALERT_IF(condition, ...) if (condition) YT_LOG_ALERT(__VA_ARGS__) #define YT_LOG_ALERT_UNLESS(condition, ...) if (!(condition)) YT_LOG_ALERT(__VA_ARGS__) -#define YT_LOG_FATAL(...) \ - do { \ +#define YT_LOG_FATAL(...) \ + do { \ YT_LOG_EVENT(Logger, ::NYT::NLogging::ELogLevel::Fatal, __VA_ARGS__); \ - Y_UNREACHABLE(); \ + Y_UNREACHABLE(); \ } while(false) #define YT_LOG_FATAL_IF(condition, ...) if (Y_UNLIKELY(condition)) YT_LOG_FATAL(__VA_ARGS__) #define YT_LOG_FATAL_UNLESS(condition, ...) if (!Y_LIKELY(condition)) YT_LOG_FATAL(__VA_ARGS__) @@ -346,126 +342,233 @@ void LogStructuredEvent( * 4. The exception is raised regardless of the logging level configured for the |Logger| and * and the currently active message suppressions. */ -#define YT_LOG_ALERT_AND_THROW(...) \ - do { \ - /* NOLINTBEGIN(bugprone-reserved-identifier, readability-identifier-naming) */ \ - const auto& logger__ = Logger(); \ - auto level__ = ::NYT::NLogging::ELogLevel::Alert; \ - auto location__ = __LOCATION__; \ - \ - auto loggingContext__ = ::NYT::NLogging::GetLoggingContext(); \ - auto message__ = ::NYT::NLogging::NDetail::BuildLogMessage(loggingContext__, logger__, __VA_ARGS__); \ - auto messageStr__ = ::std::string(message__.MessageRef.ToStringBuf()); \ - \ - static ::NYT::TLeakyStorage<::NYT::NLogging::TLoggingAnchor> anchorStorage__; \ - auto* anchor__ = anchorStorage__.Get(); \ - \ - bool anchorUpToDate__ = logger__.IsAnchorUpToDate(*anchor__); \ - if (!anchorUpToDate__) [[unlikely]] { \ - static std::atomic<bool> anchorRegistered__; \ - logger__.UpdateStaticAnchor(anchor__, &anchorRegistered__, location__, message__.Anchor); \ - } \ - \ - auto effectiveLevel__ = ::NYT::NLogging::TLogger::GetEffectiveLoggingLevel(level__, *anchor__); \ - if (logger__.IsLevelEnabled(effectiveLevel__)) { \ - ::NYT::NLogging::NDetail::LogEventImpl( \ - loggingContext__, \ - logger__, \ - effectiveLevel__, \ - location__, \ - anchor__, \ - std::move(message__.MessageRef)); \ - } \ - \ - THROW_ERROR_EXCEPTION( \ - ::NYT::EErrorCode::Fatal, \ - "Malformed request or incorrect state detected") \ - << ::NYT::TErrorAttribute("message", std::move(messageStr__)); \ - /* NOLINTEND(bugprone-reserved-identifier, readability-identifier-naming) */ \ +#define YT_LOG_ALERT_AND_THROW(...) \ + do { \ + /* NOLINTBEGIN(bugprone-reserved-identifier, readability-identifier-naming) */ \ + const auto& logger__ = Logger(); \ + auto level__ = ::NYT::NLogging::ELogLevel::Alert; \ + auto location__ = __LOCATION__; \ + \ + auto loggingContext__ = ::NYT::NLogging::GetLoggingContext(); \ + auto message__ = ::NYT::NLogging::NDetail::BuildLogMessage(loggingContext__, logger__, __VA_ARGS__); \ + /* Copy the message out before the payload is moved into the log event below. */ \ + auto messageStr__ = ::std::string(::NYT::NLogging::GetMessageFromTaggedPayload(message__.Payload)); \ + \ + static ::NYT::TLeakyStorage<::NYT::NLogging::TLoggingAnchor> anchorStorage__; \ + auto* anchor__ = anchorStorage__.Get(); \ + \ + bool anchorUpToDate__ = logger__.IsAnchorUpToDate(*anchor__); \ + if (!anchorUpToDate__) [[unlikely]] { \ + static std::atomic<bool> anchorRegistered__; \ + logger__.UpdateStaticAnchor(anchor__, &anchorRegistered__, location__, message__.Anchor); \ + } \ + \ + auto effectiveLevel__ = ::NYT::NLogging::TLogger::GetEffectiveLoggingLevel(level__, *anchor__); \ + if (logger__.IsLevelEnabled(effectiveLevel__)) { \ + ::NYT::NLogging::NDetail::LogEventImpl( \ + loggingContext__, \ + logger__, \ + effectiveLevel__, \ + location__, \ + anchor__, \ + std::move(message__.Payload)); \ + } \ + \ + THROW_ERROR_EXCEPTION( \ + ::NYT::EErrorCode::Fatal, \ + "Malformed request or incorrect state detected") \ + << ::NYT::TErrorAttribute("message", std::move(messageStr__)); \ + /* NOLINTEND(bugprone-reserved-identifier, readability-identifier-naming) */ \ } while (false) #define YT_LOG_ALERT_AND_THROW_IF(condition, ...) \ - if (Y_UNLIKELY(condition)) { \ - YT_LOG_ALERT_AND_THROW(__VA_ARGS__); \ - } \ + if (Y_UNLIKELY(condition)) { \ + YT_LOG_ALERT_AND_THROW(__VA_ARGS__); \ + } \ static_assert(true) #define YT_LOG_ALERT_AND_THROW_UNLESS(condition, ...) \ - if (!Y_UNLIKELY(condition)) { \ - YT_LOG_ALERT_AND_THROW(__VA_ARGS__); \ - } \ + if (!Y_UNLIKELY(condition)) { \ + YT_LOG_ALERT_AND_THROW(__VA_ARGS__); \ + } \ static_assert(true) -#define YT_LOG_EVENT(logger, level, ...) \ - do { \ - /* NOLINTBEGIN(bugprone-reserved-identifier, readability-identifier-naming) */ \ - const auto& logger__ = (logger)(); \ - auto level__ = (level); \ - auto location__ = __LOCATION__; \ - static ::NYT::TLeakyStorage<::NYT::NLogging::TLoggingAnchor> anchorStorage__; \ - auto* anchor__ = anchorStorage__.Get(); \ - \ - bool anchorUpToDate__ = logger__.IsAnchorUpToDate(*anchor__); \ - if (anchorUpToDate__) [[likely]] { \ - auto effectiveLevel__ = ::NYT::NLogging::TLogger::GetEffectiveLoggingLevel(level__, *anchor__); \ - if (!logger__.IsLevelEnabled(effectiveLevel__)) { \ - break; \ - } \ - } \ - \ - auto loggingContext__ = ::NYT::NLogging::GetLoggingContext(); \ +#define YT_LOG_EVENT(logger, level, ...) \ + do { \ + /* NOLINTBEGIN(bugprone-reserved-identifier, readability-identifier-naming) */ \ + const auto& logger__ = (logger)(); \ + auto level__ = (level); \ + auto location__ = __LOCATION__; \ + static ::NYT::TLeakyStorage<::NYT::NLogging::TLoggingAnchor> anchorStorage__; \ + auto* anchor__ = anchorStorage__.Get(); \ + \ + bool anchorUpToDate__ = logger__.IsAnchorUpToDate(*anchor__); \ + if (anchorUpToDate__) [[likely]] { \ + auto effectiveLevel__ = ::NYT::NLogging::TLogger::GetEffectiveLoggingLevel(level__, *anchor__); \ + if (!logger__.IsLevelEnabled(effectiveLevel__)) { \ + break; \ + } \ + } \ + \ + auto loggingContext__ = ::NYT::NLogging::GetLoggingContext(); \ auto message__ = ::NYT::NLogging::NDetail::BuildLogMessage(loggingContext__, logger__, __VA_ARGS__); \ - \ - if (!anchorUpToDate__) [[unlikely]] { \ - static std::atomic<bool> anchorRegistered__; \ - logger__.UpdateStaticAnchor(anchor__, &anchorRegistered__, location__, message__.Anchor); \ - } \ - \ - auto effectiveLevel__ = ::NYT::NLogging::TLogger::GetEffectiveLoggingLevel(level__, *anchor__); \ - if (!logger__.IsLevelEnabled(effectiveLevel__)) { \ - break; \ - } \ - \ - ::NYT::NLogging::NDetail::LogEventImpl( \ - loggingContext__, \ - logger__, \ - effectiveLevel__, \ - location__, \ - anchor__, \ - std::move(message__.MessageRef)); \ - /* NOLINTEND(bugprone-reserved-identifier, readability-identifier-naming) */ \ + \ + if (!anchorUpToDate__) [[unlikely]] { \ + static std::atomic<bool> anchorRegistered__; \ + logger__.UpdateStaticAnchor(anchor__, &anchorRegistered__, location__, message__.Anchor); \ + } \ + \ + auto effectiveLevel__ = ::NYT::NLogging::TLogger::GetEffectiveLoggingLevel(level__, *anchor__); \ + if (!logger__.IsLevelEnabled(effectiveLevel__)) { \ + break; \ + } \ + \ + ::NYT::NLogging::NDetail::LogEventImpl( \ + loggingContext__, \ + logger__, \ + effectiveLevel__, \ + location__, \ + anchor__, \ + std::move(message__.Payload)); \ + /* NOLINTEND(bugprone-reserved-identifier, readability-identifier-naming) */ \ } while (false) -#define YT_LOG_EVENT_WITH_DYNAMIC_ANCHOR(logger, level, anchor, ...) \ - do { \ - const auto& logger__ = (logger)(); \ - auto level__ = (level); \ - auto location__ = __LOCATION__; \ - auto* anchor__ = (anchor); \ - \ - bool anchorUpToDate__ = logger__.IsAnchorUpToDate(*anchor__); \ - if (!anchorUpToDate__) [[unlikely]] { \ - logger__.UpdateDynamicAnchor(anchor__); \ - } \ - \ - auto effectiveLevel__ = ::NYT::NLogging::TLogger::GetEffectiveLoggingLevel(level__, *anchor__); \ - if (!logger__.IsLevelEnabled(effectiveLevel__)) { \ - break; \ - } \ - \ - auto loggingContext__ = ::NYT::NLogging::GetLoggingContext(); \ +#define YT_LOG_EVENT_WITH_DYNAMIC_ANCHOR(logger, level, anchor, ...) \ + do { \ + const auto& logger__ = (logger)(); \ + auto level__ = (level); \ + auto location__ = __LOCATION__; \ + auto* anchor__ = (anchor); \ + \ + bool anchorUpToDate__ = logger__.IsAnchorUpToDate(*anchor__); \ + if (!anchorUpToDate__) [[unlikely]] { \ + logger__.UpdateDynamicAnchor(anchor__); \ + } \ + \ + auto effectiveLevel__ = ::NYT::NLogging::TLogger::GetEffectiveLoggingLevel(level__, *anchor__); \ + if (!logger__.IsLevelEnabled(effectiveLevel__)) { \ + break; \ + } \ + \ + auto loggingContext__ = ::NYT::NLogging::GetLoggingContext(); \ auto message__ = ::NYT::NLogging::NDetail::BuildLogMessage(loggingContext__, logger__, __VA_ARGS__); \ - \ - ::NYT::NLogging::NDetail::LogEventImpl( \ - loggingContext__, \ - logger__, \ - effectiveLevel__, \ - location__, \ - anchor__, \ - std::move(message__.MessageRef)); \ + \ + ::NYT::NLogging::NDetail::LogEventImpl( \ + loggingContext__, \ + logger__, \ + effectiveLevel__, \ + location__, \ + anchor__, \ + std::move(message__.Payload)); \ } while (false) //////////////////////////////////////////////////////////////////////////////// +// Tagged logging +// +// Tags are supplied via a fluent |.With(name, value)| (or |.With(name, value, "%spec")|) +// chain; they are carried as structured key/value pairs in the event payload. A single- +// argument |.With(value)| attaches the value under a statically known key resolved by ADL +// (e.g. |.With(error)| under the "Error" key): +// +// YT_TLOG_INFO("Message") +// .With("Key", value) +// .With("Count", count, "%08x") +// .With(error); +// +// If the message is not logged then the |.With| chain is not evaluated, so tag value +// expressions cost nothing. + +//! Yields a #TStaticAnchorRef for the expansion site: a per-call-site leaky anchor and +//! its one-shot registration flag, produced via an immediately-invoked lambda. +#define YT_TLOG_STATIC_ANCHOR_REF() \ + [] { \ + /* NOLINTBEGIN(bugprone-reserved-identifier, readability-identifier-naming) */ \ + static ::NYT::TLeakyStorage<::NYT::NLogging::TLoggingAnchor> anchorStorage__; \ + static std::atomic<bool> anchorRegistered__; \ + return ::NYT::NLogging::NDetail::TStaticAnchorRef{anchorStorage__.Get(), &anchorRegistered__}; \ + /* NOLINTEND(bugprone-reserved-identifier, readability-identifier-naming) */ \ + }() + +#define YT_TLOG_EVENT_FLUENT(logger, level, message) \ + if (::NYT::NLogging::NDetail::TTaggedLoggingGuard loggingGuard__( \ + (logger)(), \ + (level), \ + __LOCATION__, \ + YT_TLOG_STATIC_ANCHOR_REF(), \ + (message)); \ + !loggingGuard__.IsEnabled()) \ + { } else \ + loggingGuard__ + +#ifdef YT_ENABLE_TRACE_LOGGING +#define YT_TLOG_TRACE(message) YT_TLOG_EVENT_FLUENT(Logger, ::NYT::NLogging::ELogLevel::Trace, message) +#define YT_TLOG_TRACE_IF(condition, message) if (condition) YT_TLOG_TRACE(message) +#define YT_TLOG_TRACE_UNLESS(condition, message) if (!(condition)) YT_TLOG_TRACE(message) +#else +#define YT_TLOG_UNUSED(message) if (true) { } else ::NYT::NLogging::NDetail::MakeNullTaggedLoggingGuard(message) +#define YT_TLOG_TRACE(message) YT_TLOG_UNUSED(message) +#define YT_TLOG_TRACE_IF(condition, message) YT_TLOG_UNUSED(message) +#define YT_TLOG_TRACE_UNLESS(condition, message) YT_TLOG_UNUSED(message) +#endif + +#define YT_TLOG_DEBUG(message) YT_TLOG_EVENT_FLUENT(Logger, ::NYT::NLogging::ELogLevel::Debug, message) +#define YT_TLOG_DEBUG_IF(condition, message) if (condition) YT_TLOG_DEBUG(message) +#define YT_TLOG_DEBUG_UNLESS(condition, message) if (!(condition)) YT_TLOG_DEBUG(message) + +#define YT_TLOG_INFO(message) YT_TLOG_EVENT_FLUENT(Logger, ::NYT::NLogging::ELogLevel::Info, message) +#define YT_TLOG_INFO_IF(condition, message) if (condition) YT_TLOG_INFO(message) +#define YT_TLOG_INFO_UNLESS(condition, message) if (!(condition)) YT_TLOG_INFO(message) + +#define YT_TLOG_WARNING(message) YT_TLOG_EVENT_FLUENT(Logger, ::NYT::NLogging::ELogLevel::Warning, message) +#define YT_TLOG_WARNING_IF(condition, message) if (condition) YT_TLOG_WARNING(message) +#define YT_TLOG_WARNING_UNLESS(condition, message) if (!(condition)) YT_TLOG_WARNING(message) + +#define YT_TLOG_ERROR(message) YT_TLOG_EVENT_FLUENT(Logger, ::NYT::NLogging::ELogLevel::Error, message) +#define YT_TLOG_ERROR_IF(condition, message) if (condition) YT_TLOG_ERROR(message) +#define YT_TLOG_ERROR_UNLESS(condition, message) if (!(condition)) YT_TLOG_ERROR(message) + +#define YT_TLOG_ALERT(message) YT_TLOG_EVENT_FLUENT(Logger, ::NYT::NLogging::ELogLevel::Alert, message) +#define YT_TLOG_ALERT_IF(condition, message) if (condition) YT_TLOG_ALERT(message) +#define YT_TLOG_ALERT_UNLESS(condition, message) if (!(condition)) YT_TLOG_ALERT(message) + +// The terminal action of |YT_TLOG_FATAL|/|YT_TLOG_ALERT_AND_THROW| (aborting or throwing) +// must run *after* the |.With| chain, which the user appends to the macro. A guard cannot +// do it in its destructor -- that would run mid-chain on a temporary, and a throwing +// destructor terminates. So both expand to a single-iteration |for| whose step expression +// fires once the chain (the loop body) has completed. + +#define YT_TLOG_FATAL(message) \ + for (::NYT::NLogging::NDetail::TTaggedFatalLoggingGuard loggingGuard__( \ + Logger(), \ + __LOCATION__, \ + YT_TLOG_STATIC_ANCHOR_REF(), \ + (message)); \ + loggingGuard__.TryEnter(); \ + loggingGuard__.Commit()) \ + loggingGuard__ +#define YT_TLOG_FATAL_IF(condition, message) if (condition) [[unlikely]] YT_TLOG_FATAL(message) +#define YT_TLOG_FATAL_UNLESS(condition, message) if (!(condition)) [[unlikely]] YT_TLOG_FATAL(message) + +// See #YT_LOG_ALERT_AND_THROW for the rationale. The throw lives here -- not in the guard +// -- because the logging library must not depend on the error library. The guard's +// |Commit| logs the alert (when enabled) and returns the message for the |"message"| +// attribute. +#define YT_TLOG_ALERT_AND_THROW(message) \ + for (::NYT::NLogging::NDetail::TTaggedThrowingLoggingGuard loggingGuard__( \ + Logger(), \ + __LOCATION__, \ + YT_TLOG_STATIC_ANCHOR_REF(), \ + (message)); \ + loggingGuard__.TryEnter(); \ + THROW_ERROR_EXCEPTION( \ + ::NYT::EErrorCode::Fatal, \ + "Malformed request or incorrect state detected") \ + << ::NYT::TErrorAttribute("message", loggingGuard__.Commit())) \ + loggingGuard__ +#define YT_TLOG_ALERT_AND_THROW_IF(condition, message) if (condition) [[unlikely]] YT_TLOG_ALERT_AND_THROW(message) +#define YT_TLOG_ALERT_AND_THROW_UNLESS(condition, message) if (!(condition)) [[unlikely]] YT_TLOG_ALERT_AND_THROW(message) + +//////////////////////////////////////////////////////////////////////////////// } // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/plain_text_formatter/formatter.cpp b/library/cpp/yt/logging/plain_text_formatter/formatter.cpp index ab2181113dd..85f0889fa9b 100644 --- a/library/cpp/yt/logging/plain_text_formatter/formatter.cpp +++ b/library/cpp/yt/logging/plain_text_formatter/formatter.cpp @@ -1,9 +1,13 @@ #include "formatter.h" +#include <library/cpp/yt/logging/structured_payload.h> + #include <library/cpp/yt/cpu_clock/clock.h> #include <library/cpp/yt/misc/port.h> +#include <variant> + #ifdef YT_USE_SSE42 #include <emmintrin.h> #include <pmmintrin.h> @@ -146,6 +150,37 @@ void FormatMessage(TBaseFormatter* out, TStringBuf message) } } +// Formats |Message (Key: Value, ...)|, with well-known tags (e.g. an error) appended +// after the |(...)| group. Well-known tags are always written last, so a single pass +// suffices. Every piece -- message, tag keys/values, and the newline separating a +// well-known tag -- goes through FormatMessage and is escaped, so the rendered payload +// stays on a single physical line (a newline is emitted as the literal "\n"). +void FormatPayload(TBaseFormatter* out, const TTaggedLogEventPayload& payload) +{ + TTaggedPayloadReader reader(payload); + FormatMessage(out, reader.ReadMessage()); + bool parenOpen = false; + while (auto tag = reader.TryReadTag()) { + if (tag->IsWellKnown) { + if (parenOpen) { + out->AppendChar(')'); + parenOpen = false; + } + FormatMessage(out, "\n"_sb); + FormatMessage(out, tag->Value); + } else { + out->AppendString(parenOpen ? ", "_sb : " ("_sb); + parenOpen = true; + FormatMessage(out, tag->Key); + out->AppendString(": "_sb); + FormatMessage(out, tag->Value); + } + } + if (parenOpen) { + out->AppendChar(')'); + } +} + //////////////////////////////////////////////////////////////////////////////// void TCachingDateFormatter::Format(TBaseFormatter* buffer, TInstant dateTime, bool printMicroseconds) @@ -186,7 +221,13 @@ void TPlainTextEventFormatter::Format(TBaseFormatter* buffer, const TLogEvent& e buffer->AppendChar('\t'); - FormatMessage(buffer, event.MessageRef.ToStringBuf()); + if (const auto* tagged = std::get_if<TTaggedLogEventPayload>(&event.Payload)) { + FormatPayload(buffer, *tagged); + } else { + // A structured event routed to a plain-text writer: emit its raw YSON fragment + // (escaped, so the record stays a single physical line). + FormatMessage(buffer, GetYsonFromStructuredPayload(std::get<TStructuredLogEventPayload>(event.Payload)).AsStringBuf()); + } buffer->AppendChar('\t'); diff --git a/library/cpp/yt/logging/private.h b/library/cpp/yt/logging/private.h new file mode 100644 index 00000000000..b80f0488048 --- /dev/null +++ b/library/cpp/yt/logging/private.h @@ -0,0 +1,15 @@ +#pragma once + +#include "public.h" + +namespace NYT::NLogging::NDetail { + +//////////////////////////////////////////////////////////////////////////////// + +//! Ref-counted memory tag for payload buffers; used for memory accounting. +struct TMessageBufferTag +{ }; + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace NYT::NLogging::NDetail diff --git a/library/cpp/yt/logging/public.h b/library/cpp/yt/logging/public.h index 1e2b59ca0d3..17f8998f1af 100644 --- a/library/cpp/yt/logging/public.h +++ b/library/cpp/yt/logging/public.h @@ -1,6 +1,11 @@ #pragma once #include <library/cpp/yt/misc/enum.h> +#include <library/cpp/yt/misc/strong_typedef.h> + +#include <library/cpp/yt/memory/ref.h> + +#include <variant> namespace NYT::NLogging { @@ -36,4 +41,18 @@ struct ILogManager; //////////////////////////////////////////////////////////////////////////////// +//! Opaque payload of a plain-text log event: a message plus optional key/value tags, +//! framed by #TTaggedPayloadWriter. Produced by the YT_LOG_*/YT_TLOG_* macros. +YT_DEFINE_STRONG_TYPEDEF(TTaggedLogEventPayload, TSharedRef); + +//! Opaque payload of a structured log event: a raw YSON map fragment. +//! Produced by #LogStructuredEvent. +YT_DEFINE_STRONG_TYPEDEF(TStructuredLogEventPayload, TSharedRef); + +//! The payload carried by a #TLogEvent: exactly one of the encodings above. The active +//! alternative both identifies the event kind and determines how the payload is decoded. +using TLogEventPayload = std::variant<TTaggedLogEventPayload, TStructuredLogEventPayload>; + +//////////////////////////////////////////////////////////////////////////////// + } // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/structured_payload.cpp b/library/cpp/yt/logging/structured_payload.cpp new file mode 100644 index 00000000000..1a6ce5ea370 --- /dev/null +++ b/library/cpp/yt/logging/structured_payload.cpp @@ -0,0 +1,19 @@ +#include "structured_payload.h" + +namespace NYT::NLogging { + +//////////////////////////////////////////////////////////////////////////////// + +TStructuredLogEventPayload MakeStructuredPayloadFromYson(const NYson::TYsonString& message) +{ + return TStructuredLogEventPayload(message.ToSharedRef()); +} + +NYson::TYsonStringBuf GetYsonFromStructuredPayload(const TStructuredLogEventPayload& payload) +{ + return NYson::TYsonStringBuf(payload.Underlying().ToStringBuf(), NYson::EYsonType::MapFragment); +} + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/structured_payload.h b/library/cpp/yt/logging/structured_payload.h new file mode 100644 index 00000000000..81464f4aa92 --- /dev/null +++ b/library/cpp/yt/logging/structured_payload.h @@ -0,0 +1,25 @@ +#pragma once + +#include "public.h" + +#include <library/cpp/yt/memory/ref.h> + +#include <library/cpp/yt/yson_string/string.h> + +namespace NYT::NLogging { + +//////////////////////////////////////////////////////////////////////////////// + +// Structured events carry the raw YSON map fragment as their opaque payload, with no +// framing. These helpers isolate that representation from callers. + +//! Producer: wraps #message into a payload (zero-copy). +TStructuredLogEventPayload MakeStructuredPayloadFromYson(const NYson::TYsonString& message); + +//! Consumer: views the payload as the YSON map fragment it carries. The result views +//! into #payload, which must outlive it. +NYson::TYsonStringBuf GetYsonFromStructuredPayload(const TStructuredLogEventPayload& payload); + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/tagged_payload-inl.h b/library/cpp/yt/logging/tagged_payload-inl.h new file mode 100644 index 00000000000..4b71a5bebef --- /dev/null +++ b/library/cpp/yt/logging/tagged_payload-inl.h @@ -0,0 +1,108 @@ +#ifndef TAGGED_PAYLOAD_INL_H_ +#error "Direct inclusion of this file is not allowed, include tagged_payload.h" +// For the sake of sane code completion. +#include "tagged_payload.h" +#endif + +#include <library/cpp/yt/assert/assert.h> + +#include <cstring> + +namespace NYT::NLogging { + +//////////////////////////////////////////////////////////////////////////////// + +inline TSharedRef TTaggedPayloadBuilder::Flush() +{ + return Buffer_.Slice(0, GetLength()); +} + +template <class T> +void TTaggedPayloadBuilder::AppendPod(const T& value) +{ + ::memcpy(Preallocate(sizeof(value)), &value, sizeof(value)); + Advance(sizeof(value)); +} + +template <class T> +void TTaggedPayloadBuilder::WritePodAt(size_t offset, const T& value) +{ + YT_ASSERT(offset + sizeof(value) <= GetLength()); + ::memcpy(Begin_ + offset, &value, sizeof(value)); +} + +//////////////////////////////////////////////////////////////////////////////// + +inline TStringBuilderBase* TTaggedPayloadWriter::BeginMessage() & +{ + YT_ASSERT(!MessageStarted_); + MessageStarted_ = true; + ReserveLengthPrefix(); + return &Builder_; +} + +inline TTaggedPayloadWriter& TTaggedPayloadWriter::EndMessage() & +{ + YT_ASSERT(MessageStarted_ && !MessageEnded_); + MessageEnded_ = true; + BackpatchLengthPrefix(); + return *this; +} + +inline TStringBuilderBase* TTaggedPayloadWriter::BeginTag(TStringBuf key) & +{ + return DoBeginTag(key, /*wellKnown*/ false); +} + +inline TStringBuilderBase* TTaggedPayloadWriter::BeginWellKnownTag(TStringBuf key) & +{ + return DoBeginTag(key, /*wellKnown*/ true); +} + +inline TStringBuilderBase* TTaggedPayloadWriter::DoBeginTag(TStringBuf key, bool wellKnown) +{ + YT_ASSERT(MessageEnded_ && !InTag_); + // High bit reserved for the well-known flag. + YT_ASSERT(key.size() < WellKnownTagFlag); + InTag_ = true; + // Reserve the key-size prefix, the key bytes, and the value-size prefix in a single + // capacity check; the value is then formatted in place and EndTag backpatches its size. + auto keySize = static_cast<ui32>(key.size()) | (wellKnown ? WellKnownTagFlag : 0); + char* ptr = Builder_.Preallocate(2 * sizeof(ui32) + key.size()); + PrefixOffset_ = Builder_.GetLength() + sizeof(ui32) + key.size(); + ::memcpy(ptr, &keySize, sizeof(keySize)); + ::memcpy(ptr + sizeof(keySize), key.data(), key.size()); + // The value-size prefix is left uninitialized; EndTag overwrites it. + Builder_.Advance(2 * sizeof(ui32) + key.size()); + return &Builder_; +} + +inline TTaggedPayloadWriter& TTaggedPayloadWriter::EndTag() & +{ + YT_ASSERT(InTag_); + InTag_ = false; + BackpatchLengthPrefix(); + return *this; +} + +inline TTaggedLogEventPayload TTaggedPayloadWriter::Finish() & +{ + YT_ASSERT(MessageEnded_ && !InTag_); + return TTaggedLogEventPayload(Builder_.Flush()); +} + +inline void TTaggedPayloadWriter::ReserveLengthPrefix() +{ + PrefixOffset_ = Builder_.GetLength(); + // Reserve a zeroed ui32; backpatched by BackpatchLengthPrefix. + Builder_.AppendPod<ui32>(0); +} + +inline void TTaggedPayloadWriter::BackpatchLengthPrefix() +{ + Builder_.WritePodAt<ui32>(PrefixOffset_, Builder_.GetLength() - PrefixOffset_ - sizeof(ui32)); +} + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/tagged_payload.cpp b/library/cpp/yt/logging/tagged_payload.cpp new file mode 100644 index 00000000000..4133cc0bd55 --- /dev/null +++ b/library/cpp/yt/logging/tagged_payload.cpp @@ -0,0 +1,214 @@ +#include "tagged_payload.h" +#include "private.h" + +#include <library/cpp/yt/assert/assert.h> + +#include <library/cpp/yt/misc/tls.h> + +#include <util/system/compiler.h> +#include <util/system/types.h> + +#include <util/generic/bitops.h> + +#include <algorithm> + +namespace NYT::NLogging { + +//////////////////////////////////////////////////////////////////////////////// + +namespace { + +struct TPerThreadCache; + +YT_DEFINE_THREAD_LOCAL(TPerThreadCache*, Cache); +YT_DEFINE_THREAD_LOCAL(bool, CacheDestroyed); + +struct TPerThreadCache +{ + TSharedMutableRef Chunk; + size_t ChunkOffset = 0; + + ~TPerThreadCache() + { + TTaggedPayloadBuilder::DisablePerThreadCache(); + } + + static YT_PREVENT_TLS_CACHING TPerThreadCache* GetCache() + { + auto& cache = Cache(); + [[likely]] if (cache) { + return cache; + } + if (CacheDestroyed()) { + return nullptr; + } + static thread_local TPerThreadCache CacheData; + cache = &CacheData; + return cache; + } +}; + +TSharedMutableRef AllocateChunk(size_t size) +{ + return TSharedMutableRef::Allocate<::NYT::NLogging::NDetail::TMessageBufferTag>(size, {.InitializeStorage = false}); +} + +} // namespace + +//////////////////////////////////////////////////////////////////////////////// + +void TTaggedPayloadBuilder::DisablePerThreadCache() +{ + Cache() = nullptr; + CacheDestroyed() = true; +} + +void TTaggedPayloadBuilder::DoReset() +{ + Buffer_.Reset(); +} + +void TTaggedPayloadBuilder::DoReserve(size_t newCapacity) +{ + auto oldLength = GetLength(); + newCapacity = FastClp2(newCapacity); + + auto newChunkSize = std::max(ChunkSize, newCapacity); + // Hold the old buffer until the data is copied. + auto oldBuffer = std::move(Buffer_); + auto* cache = TPerThreadCache::GetCache(); + [[likely]] if (cache) { + auto oldCapacity = End_ - Begin_; + auto deltaCapacity = newCapacity - oldCapacity; + if (End_ == cache->Chunk.Begin() + cache->ChunkOffset && + cache->ChunkOffset + deltaCapacity <= cache->Chunk.Size()) + { + // Resize inplace. + Buffer_ = cache->Chunk.Slice(cache->ChunkOffset - oldCapacity, cache->ChunkOffset + deltaCapacity); + cache->ChunkOffset += deltaCapacity; + End_ = Begin_ + newCapacity; + return; + } + + [[unlikely]] if (cache->ChunkOffset + newCapacity > cache->Chunk.Size()) { + cache->Chunk = AllocateChunk(newChunkSize); + cache->ChunkOffset = 0; + } + + Buffer_ = cache->Chunk.Slice(cache->ChunkOffset, cache->ChunkOffset + newCapacity); + cache->ChunkOffset += newCapacity; + } else { + Buffer_ = AllocateChunk(newChunkSize); + newCapacity = newChunkSize; + } + if (oldLength > 0) { + ::memcpy(Buffer_.Begin(), Begin_, oldLength); + } + Begin_ = Buffer_.Begin(); + End_ = Begin_ + newCapacity; +} + +//////////////////////////////////////////////////////////////////////////////// + +void TTaggedPayloadWriter::DisablePerThreadCache() +{ + TTaggedPayloadBuilder::DisablePerThreadCache(); +} + +//////////////////////////////////////////////////////////////////////////////// + +TTaggedPayloadReader::TTaggedPayloadReader(const TTaggedLogEventPayload& payload) + : Current_(payload.Underlying().Begin()) + , End_(payload.Underlying().End()) +{ } + +TStringBuf TTaggedPayloadReader::ReadMessage() +{ + YT_ASSERT(!MessageRead_); + MessageRead_ = true; + return ReadString(); +} + +std::optional<TTaggedPayloadReader::TTag> TTaggedPayloadReader::TryReadTag() +{ + YT_ASSERT(MessageRead_); + if (Current_ == End_) { + return std::nullopt; + } + auto keySize = ReadLength(); + bool wellKnown = (keySize & WellKnownTagFlag) != 0; + auto key = ReadBytes(keySize & ~WellKnownTagFlag); + auto value = ReadString(); + return TTag{.IsWellKnown = wellKnown, .Key = key, .Value = value}; +} + +ui32 TTaggedPayloadReader::ReadLength() +{ + YT_ASSERT(Current_ + sizeof(ui32) <= End_); + ui32 size; + ::memcpy(&size, Current_, sizeof(size)); + Current_ += sizeof(size); + return size; +} + +TStringBuf TTaggedPayloadReader::ReadBytes(ui32 size) +{ + YT_ASSERT(Current_ + size <= End_); + TStringBuf result(Current_, size); + Current_ += size; + return result; +} + +TStringBuf TTaggedPayloadReader::ReadString() +{ + return ReadBytes(ReadLength()); +} + +//////////////////////////////////////////////////////////////////////////////// + +TTaggedLogEventPayload MakeTaggedPayloadFromMessage(TStringBuf message) +{ + TTaggedPayloadWriter writer; + writer.BeginMessage()->AppendString(message); + writer.EndMessage(); + return writer.Finish(); +} + +TStringBuf GetMessageFromTaggedPayload(const TTaggedLogEventPayload& payload) +{ + return TTaggedPayloadReader(payload).ReadMessage(); +} + +std::string FormatTaggedPayload(const TTaggedLogEventPayload& payload) +{ + TTaggedPayloadReader reader(payload); + std::string result(reader.ReadMessage()); + // Well-known tags (e.g. an error) are always written last -- the fluent |.With| chain + // enforces this at the type level (see #TWellKnownTaggedLoggingGuard) -- so they render + // after the |(...)| group on trailing lines in a single pass. + bool parenOpen = false; + while (auto tag = reader.TryReadTag()) { + if (tag->IsWellKnown) { + if (parenOpen) { + result += ')'; + parenOpen = false; + } + result += '\n'; + result += tag->Value; + } else { + result += parenOpen ? ", " : " ("; + parenOpen = true; + result += tag->Key; + result += ": "; + result += tag->Value; + } + } + if (parenOpen) { + result += ')'; + } + return result; +} + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/tagged_payload.h b/library/cpp/yt/logging/tagged_payload.h new file mode 100644 index 00000000000..da46f30f42a --- /dev/null +++ b/library/cpp/yt/logging/tagged_payload.h @@ -0,0 +1,201 @@ +#pragma once + +#include "public.h" + +#include <library/cpp/yt/string/string_builder.h> + +#include <library/cpp/yt/memory/ref.h> + +#include <util/generic/strbuf.h> +#include <util/generic/size_literals.h> + +#include <util/system/types.h> + +#include <optional> +#include <string> + +namespace NYT::NLogging { + +//////////////////////////////////////////////////////////////////////////////// + +// Plain-text events carry their message together with structured key/value tags in a +// flat, length-prefixed payload, deferring tag rendering to the consumer (the logging +// thread). These helpers own the wire format and isolate it from callers. + +//! A per-thread chunk-cached string builder backing payload buffers. +/*! + * Generic: it knows nothing about the payload layout (see #TTaggedPayloadWriter). + */ +class TTaggedPayloadBuilder + : public TStringBuilderBase +{ +public: + TSharedRef Flush(); + + //! Appends a trivially-copyable value as raw bytes (the ui32 length prefix). + template <class T> + void AppendPod(const T& value); + + //! Overwrites a trivially-copyable value at #offset. + //! #offset + sizeof(value) must not exceed the current length. + template <class T> + void WritePodAt(size_t offset, const T& value); + + //! For testing only. + static void DisablePerThreadCache(); + +private: + TSharedMutableRef Buffer_; + + static constexpr size_t ChunkSize = 128_KB - 64; + + void DoReset() override; + void DoReserve(size_t newCapacity) override; +}; + +//////////////////////////////////////////////////////////////////////////////// + +//! A log message together with its tag key/value pairs, serialized into a flat, +//! opaque byte payload that #TLogEvent hands to the logging thread. +/*! + * Layout (all sizes are host-endian |ui32|; the transport is in-process): + * \code + * [message size][message bytes] + * [key size][key bytes][value size][value bytes] x N + * \endcode + * + * A "well-known" tag sets the high bit of its key-size field; the low 31 bits stay the + * key length and the key bytes are still written. Consumers may render such tags + * specially (see #GetWellKnownLoggingTag). + * + * Both the producer (#TTaggedPayloadWriter) and the consumer + * (#TTaggedPayloadReader) own this single definition of the layout. + */ + +//! The high bit of a tag's key-size field, marking a well-known tag. +constexpr ui32 WellKnownTagFlag = 1u << 31; + +//////////////////////////////////////////////////////////////////////////////// + +//! Producer side: serializes the message and its tags into a payload. +/*! + * Owns a per-thread chunk-cached buffer; both the message text (#BeginMessage) and + * tag values (#BeginTag) are appended through the returned #TStringBuilderBase, so a + * formatted value is built directly into the payload without an intermediate + * allocation/copy. The length-prefix framing lives entirely here -- the underlying + * builder is format-agnostic. + */ +class TTaggedPayloadWriter +{ +public: + //! Constructs an empty writer; the message is built incrementally through the + //! builder returned by #BeginMessage. + TTaggedPayloadWriter() = default; + + TTaggedPayloadWriter(const TTaggedPayloadWriter&) = delete; + TTaggedPayloadWriter& operator=(const TTaggedPayloadWriter&) = delete; + + //! Begins the message field and returns a builder for appending its text. + //! Must be called exactly once, first. + TStringBuilderBase* BeginMessage() &; + + //! Ends the message field, filling in its reserved length prefix. Must be + //! called exactly once, after the message text and before any tag/#Finish. + TTaggedPayloadWriter& EndMessage() &; + + //! Begins a tag: writes #key, then reserves the value's length prefix and returns + //! a builder for appending the value. Lets the value be formatted directly into the + //! payload buffer. Pair with #EndTag. Must follow #EndMessage. + TStringBuilderBase* BeginTag(TStringBuf key) &; + + //! Like #BeginTag, but marks the tag well-known (sets #WellKnownTagFlag). + TStringBuilderBase* BeginWellKnownTag(TStringBuf key) &; + + //! Ends the current tag, filling in the value's reserved length prefix. + TTaggedPayloadWriter& EndTag() &; + + //! Returns the serialized payload. Must follow #EndMessage. + TTaggedLogEventPayload Finish() &; + + //! For testing only. + static void DisablePerThreadCache(); + +private: + TTaggedPayloadBuilder Builder_; + bool MessageStarted_ = false; + bool MessageEnded_ = false; + bool InTag_ = false; + //! Offset of the length prefix currently being filled (message or tag value). + size_t PrefixOffset_ = 0; + + //! Shared implementation of #BeginTag and #BeginWellKnownTag. + TStringBuilderBase* DoBeginTag(TStringBuf key, bool wellKnown); + //! Reserves a length prefix at the current position, remembering its offset. + void ReserveLengthPrefix(); + //! Backpatches the reserved prefix with the length appended after it. + void BackpatchLengthPrefix(); +}; + +//////////////////////////////////////////////////////////////////////////////// + +//! Consumer side: parses a payload produced by #TTaggedPayloadWriter. +/*! + * A single-pass cursor; the returned views point into #payload, which must outlive + * the reader. + * + * Call order: #ReadMessage must be called exactly once, first; then #TryReadTag + * must be called repeatedly until it returns |std::nullopt|, yielding the tags in + * write order. + */ +class TTaggedPayloadReader +{ +public: + struct TTag + { + bool IsWellKnown = false; + TStringBuf Key; + TStringBuf Value; + }; + + explicit TTaggedPayloadReader(const TTaggedLogEventPayload& payload); + + //! Reads the message field. Must be called exactly once, before any #TryReadTag. + TStringBuf ReadMessage(); + + //! Reads the next tag; returns |std::nullopt| once the tags are exhausted. + //! Must follow #ReadMessage. + std::optional<TTag> TryReadTag(); + +private: + const char* Current_; + const char* const End_; + bool MessageRead_ = false; + + //! Reads a ui32 length word. + ui32 ReadLength(); + //! Reads #size bytes as a view. + TStringBuf ReadBytes(ui32 size); + //! Reads a length-prefixed string (a length word followed by its bytes). + TStringBuf ReadString(); +}; + +//////////////////////////////////////////////////////////////////////////////// + +//! Producer convenience: builds a payload carrying only #message and no tags. +TTaggedLogEventPayload MakeTaggedPayloadFromMessage(TStringBuf message); + +//! Consumer convenience: returns the message, disregarding any tags. The result +//! views into #payload, which must outlive it. +TStringBuf GetMessageFromTaggedPayload(const TTaggedLogEventPayload& payload); + +//! Consumer convenience: renders the payload as |Message (Key: Value, ...)|, or just +//! the message if it carries no tags. +std::string FormatTaggedPayload(const TTaggedLogEventPayload& payload); + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace NYT::NLogging + +#define TAGGED_PAYLOAD_INL_H_ +#include "tagged_payload-inl.h" +#undef TAGGED_PAYLOAD_INL_H_ diff --git a/library/cpp/yt/logging/unittests/helpers.cpp b/library/cpp/yt/logging/unittests/helpers.cpp new file mode 100644 index 00000000000..2a2b20120cc --- /dev/null +++ b/library/cpp/yt/logging/unittests/helpers.cpp @@ -0,0 +1,27 @@ +#include "helpers.h" + +namespace NYT::NLogging { + +//////////////////////////////////////////////////////////////////////////////// + +void WriteMessage(TTaggedPayloadWriter* writer, TStringBuf message) +{ + writer->BeginMessage()->AppendString(message); + writer->EndMessage(); +} + +void WriteTag(TTaggedPayloadWriter* writer, TStringBuf key, TStringBuf value) +{ + writer->BeginTag(key)->AppendString(value); + writer->EndTag(); +} + +void WriteWellKnownTag(TTaggedPayloadWriter* writer, TStringBuf key, TStringBuf value) +{ + writer->BeginWellKnownTag(key)->AppendString(value); + writer->EndTag(); +} + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/unittests/helpers.h b/library/cpp/yt/logging/unittests/helpers.h new file mode 100644 index 00000000000..6785a65f99b --- /dev/null +++ b/library/cpp/yt/logging/unittests/helpers.h @@ -0,0 +1,22 @@ +#pragma once + +#include <library/cpp/yt/logging/tagged_payload.h> + +#include <util/generic/strbuf.h> + +namespace NYT::NLogging { + +//////////////////////////////////////////////////////////////////////////////// + +//! Writes the message (equivalent to BeginMessage, an append, and EndMessage). +void WriteMessage(TTaggedPayloadWriter* writer, TStringBuf message); + +//! Writes a tag with a ready string value (equivalent to BeginTag, an append, and EndTag). +void WriteTag(TTaggedPayloadWriter* writer, TStringBuf key, TStringBuf value); + +//! Writes a well-known tag with a ready string value (see BeginWellKnownTag). +void WriteWellKnownTag(TTaggedPayloadWriter* writer, TStringBuf key, TStringBuf value); + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/unittests/logger_ut.cpp b/library/cpp/yt/logging/unittests/logger_ut.cpp index 410a56fc309..db176ca5394 100644 --- a/library/cpp/yt/logging/unittests/logger_ut.cpp +++ b/library/cpp/yt/logging/unittests/logger_ut.cpp @@ -1,15 +1,117 @@ #include <library/cpp/testing/gtest/gtest.h> #include <library/cpp/yt/logging/logger.h> +#include <library/cpp/yt/logging/tagged_payload.h> +#include <library/cpp/yt/logging/structured_payload.h> #include <library/cpp/yt/error/error.h> +#include <library/cpp/yt/yson_string/string.h> + +#include <atomic> +#include <string> +#include <utility> +#include <vector> + namespace NYT::NLogging { namespace { +using namespace NDetail; + +//////////////////////////////////////////////////////////////////////////////// + +//! A log manager that captures enqueued events for inspection in tests. +class TMockLogManager + : public ILogManager +{ +public: + explicit TMockLogManager(ELogLevel minLevel = ELogLevel::Minimum) + { + Category_.MinPlainTextLevel.store(minLevel); + } + + void RegisterStaticAnchor(TLoggingAnchor* anchor, ::TSourceLocation /*sourceLocation*/, TStringBuf /*message*/) override + { + anchor->Registered.store(true); + } + + void UpdateAnchor(TLoggingAnchor* anchor) override + { + anchor->CurrentVersion.store(ActualVersion_.load()); + } + + void Enqueue(TLogEvent&& event) override + { + Events_.push_back(std::move(event)); + } + + const TLoggingCategory* GetCategory(TStringBuf /*categoryName*/) override + { + return &Category_; + } + + void UpdateCategory(TLoggingCategory* category) override + { + category->CurrentVersion.store(ActualVersion_.load()); + } + + bool GetAbortOnAlert() const override + { + return false; + } + + const std::vector<TLogEvent>& GetEvents() const + { + return Events_; + } + +private: + std::vector<TLogEvent> Events_; + std::atomic<int> ActualVersion_ = 1; + TLoggingCategory Category_ = { + .Name = "Test", + .MinPlainTextLevel = ELogLevel::Minimum, + .CurrentVersion = 0, + .ActualVersion = &ActualVersion_, + }; +}; + +struct TDecodedEvent +{ + std::string Message; + std::vector<std::pair<std::string, std::string>> Tags; +}; + +TDecodedEvent DecodeEvent(const TLogEvent& event) +{ + TTaggedPayloadReader reader(std::get<TTaggedLogEventPayload>(event.Payload)); + TDecodedEvent result; + result.Message = reader.ReadMessage(); + while (auto tag = reader.TryReadTag()) { + result.Tags.emplace_back(tag->Key, tag->Value); + } + return result; +} + +TDecodedEvent DecodeSingleEvent(const TMockLogManager& manager) +{ + EXPECT_EQ(manager.GetEvents().size(), 1u); + return DecodeEvent(manager.GetEvents()[0]); +} + +NYson::TYsonString MakeMapFragment(TStringBuf yson) +{ + return NYson::TYsonString(yson, NYson::EYsonType::MapFragment); +} + +TStringBuf GetStructuredYson(const TLogEvent& event) +{ + return GetYsonFromStructuredPayload(std::get<TStructuredLogEventPayload>(event.Payload)).AsStringBuf(); +} + //////////////////////////////////////////////////////////////////////////////// -TEST(TLogger, NullByDefault) +TEST(TLoggerTest, NullByDefault) { { TLogger logger; @@ -23,7 +125,7 @@ TEST(TLogger, NullByDefault) } } -TEST(TLogger, CopyOfNullLogger) +TEST(TLoggerTest, CopyOfNullLogger) { TLogger nullLogger{/*logManager*/ nullptr, "Category"}; ASSERT_FALSE(nullLogger); @@ -34,7 +136,7 @@ TEST(TLogger, CopyOfNullLogger) EXPECT_FALSE(logger.IsLevelEnabled(ELogLevel::Fatal)); } -TEST(TLogger, LogAlertAndThrowMessage) +TEST(TLoggerTest, LogAlertAndThrowMessage) { try { TLogger Logger; @@ -52,5 +154,228 @@ TEST(TLogger, LogAlertAndThrowMessage) //////////////////////////////////////////////////////////////////////////////// +TEST(TTaggedApiTest, MessageOnly) +{ + TMockLogManager manager; + TLogger Logger(&manager, "Test"); + YT_TLOG_INFO("Message"); + + auto decoded = DecodeSingleEvent(manager); + EXPECT_EQ(decoded.Message, "Message"); + EXPECT_TRUE(decoded.Tags.empty()); +} + +TEST(TTaggedApiTest, Tags) +{ + TMockLogManager manager; + TLogger Logger(&manager, "Test"); + YT_TLOG_INFO("Message") + .With("Arg1", 123) + .With("Arg2", "test"); + + auto decoded = DecodeSingleEvent(manager); + EXPECT_EQ(decoded.Message, "Message"); + ASSERT_EQ(decoded.Tags.size(), 2u); + EXPECT_EQ(decoded.Tags[0], std::pair(std::string("Arg1"), std::string("123"))); + EXPECT_EQ(decoded.Tags[1], std::pair(std::string("Arg2"), std::string("test"))); +} + +TEST(TTaggedApiTest, CustomSpec) +{ + TMockLogManager manager; + TLogger Logger(&manager, "Test"); + YT_TLOG_INFO("Message") + .With("Arg1", 256, "%x"); + + auto decoded = DecodeSingleEvent(manager); + ASSERT_EQ(decoded.Tags.size(), 1u); + EXPECT_EQ(decoded.Tags[0], std::pair(std::string("Arg1"), std::string("100"))); +} + +TEST(TTaggedApiTest, LoggerTagFoldedIntoMessage) +{ + TMockLogManager manager; + auto Logger = TLogger(&manager, "Test") + .WithTag("LoggingTag: %v", 555); + YT_TLOG_INFO("Message") + .With("Arg1", 123); + + auto decoded = DecodeSingleEvent(manager); + EXPECT_EQ(decoded.Message, "Message (LoggingTag: 555)"); + ASSERT_EQ(decoded.Tags.size(), 1u); + EXPECT_EQ(decoded.Tags[0], std::pair(std::string("Arg1"), std::string("123"))); +} + +TEST(TTaggedApiTest, DisabledDoesNotEvaluateTags) +{ + TMockLogManager manager(/*minLevel*/ ELogLevel::Warning); + TLogger Logger(&manager, "Test"); + + int evaluated = 0; + auto evaluate = [&] { + ++evaluated; + return 123; + }; + YT_TLOG_INFO("Message") + .With("Arg1", evaluate()); + + EXPECT_EQ(evaluated, 0); + EXPECT_TRUE(manager.GetEvents().empty()); +} + +TEST(TTaggedApiTest, WellKnownErrorTag) +{ + TMockLogManager manager; + TLogger Logger(&manager, "Test"); + auto error = TError("boom"); + YT_TLOG_INFO("Message") + .With("Tag", 1) + .With(error); + + ASSERT_EQ(manager.GetEvents().size(), 1u); + TTaggedPayloadReader reader(std::get<TTaggedLogEventPayload>(manager.GetEvents()[0].Payload)); + EXPECT_EQ(reader.ReadMessage(), "Message"); + + auto regular = reader.TryReadTag(); + ASSERT_TRUE(regular); + EXPECT_EQ(regular->Key, "Tag"); + EXPECT_EQ(regular->Value, "1"); + EXPECT_FALSE(regular->IsWellKnown); + + // |.With(error)| attaches the error under the well-known "Error" key (resolved via + // GetWellKnownLoggingTag), with the formatted error as the value. + auto errorTag = reader.TryReadTag(); + ASSERT_TRUE(errorTag); + EXPECT_EQ(errorTag->Key, "Error"); + EXPECT_TRUE(errorTag->IsWellKnown); + EXPECT_NE(errorTag->Value.find("boom"), TStringBuf::npos); + + EXPECT_FALSE(reader.TryReadTag()); +} + +// The single-pass formatter assumes well-known tags come last, so the fluent API must +// forbid a keyed tag after a well-known one (e.g. |.With(error).With("Key", 1)|) at +// compile time. +template <class TGuard> +concept CAllowsKeyedTagAfterWellKnown = requires (TGuard guard, TError error) { + guard.With(error).With("Key", 1); +}; + +// A further well-known tag after a well-known one stays allowed. +template <class TGuard> +concept CAllowsWellKnownTagAfterWellKnown = requires (TGuard guard, TError error) { + guard.With(error).With(error); +}; + +static_assert(!CAllowsKeyedTagAfterWellKnown<TTaggedLoggingGuard>); +static_assert(CAllowsWellKnownTagAfterWellKnown<TTaggedLoggingGuard>); + +TEST(TTaggedApiTest, AlertAndThrow) +{ + TMockLogManager manager; + TLogger Logger(&manager, "Test"); + + try { + YT_TLOG_ALERT_AND_THROW("Alert message") + .With("Arg1", 1) + .With("Arg2", 2); + EXPECT_TRUE(false); + } catch (const TErrorException& ex) { + const auto& error = ex.Error(); + EXPECT_EQ(error.GetCode(), NYT::EErrorCode::Fatal); + EXPECT_EQ(error.GetMessage(), "Malformed request or incorrect state detected"); + EXPECT_EQ(error.Attributes().Get<std::string>("message"), "Alert message"); + } + + // The alert is also logged, carrying the structured tags. + auto decoded = DecodeSingleEvent(manager); + EXPECT_EQ(decoded.Message, "Alert message"); + ASSERT_EQ(decoded.Tags.size(), 2u); + EXPECT_EQ(decoded.Tags[0], std::pair(std::string("Arg1"), std::string("1"))); + EXPECT_EQ(decoded.Tags[1], std::pair(std::string("Arg2"), std::string("2"))); +} + +TEST(TTaggedApiTest, AlertAndThrowDisabledStillThrows) +{ + TMockLogManager manager(/*minLevel*/ ELogLevel::Fatal); + TLogger Logger(&manager, "Test"); + + // The level is disabled, so nothing is logged, but the exception (with its message) + // is still raised. + EXPECT_THROW( + YT_TLOG_ALERT_AND_THROW("Alert message") + .With("Arg1", 1), + TErrorException); + EXPECT_TRUE(manager.GetEvents().empty()); +} + +TEST(TTaggedApiDeathTest, Fatal) +{ + EXPECT_DEATH({ + TMockLogManager manager; + TLogger Logger(&manager, "Test"); + YT_TLOG_FATAL("Fatal message") + .With("Arg1", 1); + }, "Fatal message \\(Arg1: 1\\)"); +} + +//////////////////////////////////////////////////////////////////////////////// + +TEST(TStructuredApiTest, StructuredEvent) +{ + TMockLogManager manager; + TLogger Logger(&manager, "Test"); + + LogStructuredEvent(Logger, MakeMapFragment("\"key\"=\"value\""), ELogLevel::Info); + + ASSERT_EQ(manager.GetEvents().size(), 1u); + const auto& event = manager.GetEvents()[0]; + EXPECT_TRUE(std::holds_alternative<TStructuredLogEventPayload>(event.Payload)); + EXPECT_EQ(event.Family, ELogFamily::Structured); + EXPECT_EQ(event.Level, ELogLevel::Info); + // The payload is the raw YSON map fragment. + EXPECT_EQ(GetStructuredYson(event), "\"key\"=\"value\""); +} + +TEST(TStructuredApiTest, PreservesLevel) +{ + TMockLogManager manager; + TLogger Logger(&manager, "Test"); + + LogStructuredEvent(Logger, MakeMapFragment("\"a\"=1;\"b\"=2"), ELogLevel::Warning); + + ASSERT_EQ(manager.GetEvents().size(), 1u); + EXPECT_EQ(manager.GetEvents()[0].Level, ELogLevel::Warning); + EXPECT_EQ(GetStructuredYson(manager.GetEvents()[0]), "\"a\"=1;\"b\"=2"); +} + +TEST(TStructuredApiTest, EmptyFragment) +{ + TMockLogManager manager; + TLogger Logger(&manager, "Test"); + + LogStructuredEvent(Logger, MakeMapFragment(""), ELogLevel::Info); + + ASSERT_EQ(manager.GetEvents().size(), 1u); + EXPECT_EQ(GetStructuredYson(manager.GetEvents()[0]), ""); +} + +TEST(TStructuredApiTest, MultipleEvents) +{ + TMockLogManager manager; + TLogger Logger(&manager, "Test"); + + LogStructuredEvent(Logger, MakeMapFragment("\"i\"=0"), ELogLevel::Debug); + LogStructuredEvent(Logger, MakeMapFragment("\"i\"=1"), ELogLevel::Info); + + ASSERT_EQ(manager.GetEvents().size(), 2u); + EXPECT_EQ(manager.GetEvents()[0].Level, ELogLevel::Debug); + EXPECT_EQ(GetStructuredYson(manager.GetEvents()[0]), "\"i\"=0"); + EXPECT_EQ(manager.GetEvents()[1].Level, ELogLevel::Info); + EXPECT_EQ(GetStructuredYson(manager.GetEvents()[1]), "\"i\"=1"); +} + +//////////////////////////////////////////////////////////////////////////////// + } // namespace } // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/unittests/structured_payload_ut.cpp b/library/cpp/yt/logging/unittests/structured_payload_ut.cpp new file mode 100644 index 00000000000..f15970dcb23 --- /dev/null +++ b/library/cpp/yt/logging/unittests/structured_payload_ut.cpp @@ -0,0 +1,36 @@ +#include <library/cpp/testing/gtest/gtest.h> + +#include <library/cpp/yt/logging/structured_payload.h> + +#include <library/cpp/yt/yson_string/string.h> + +namespace NYT::NLogging { +namespace { + +using namespace NYson; + +//////////////////////////////////////////////////////////////////////////////// + +TYsonString MakeMapFragment(TStringBuf yson) +{ + return TYsonString(yson, EYsonType::MapFragment); +} + +TEST(TStructuredPayloadTest, RoundTrip) +{ + auto payload = MakeStructuredPayloadFromYson(MakeMapFragment("\"key\"=\"value\"")); + auto view = GetYsonFromStructuredPayload(payload); + EXPECT_EQ(view.GetType(), EYsonType::MapFragment); + EXPECT_EQ(view.AsStringBuf(), "\"key\"=\"value\""); +} + +TEST(TStructuredPayloadTest, EmptyFragment) +{ + auto payload = MakeStructuredPayloadFromYson(MakeMapFragment("")); + EXPECT_EQ(GetYsonFromStructuredPayload(payload).AsStringBuf(), ""); +} + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace +} // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/unittests/tagged_payload_ut.cpp b/library/cpp/yt/logging/unittests/tagged_payload_ut.cpp new file mode 100644 index 00000000000..57d9ac168f4 --- /dev/null +++ b/library/cpp/yt/logging/unittests/tagged_payload_ut.cpp @@ -0,0 +1,146 @@ +#include "helpers.h" + +#include <library/cpp/testing/gtest/gtest.h> + +#include <library/cpp/yt/logging/tagged_payload.h> + +#include <string> +#include <vector> + +namespace NYT::NLogging { +namespace { + +using namespace NDetail; + +//////////////////////////////////////////////////////////////////////////////// + +struct TDecodedPayload +{ + std::string Message; + std::vector<std::pair<std::string, std::string>> Tags; +}; + +TTaggedLogEventPayload Encode(TStringBuf message, const std::vector<std::pair<TStringBuf, TStringBuf>>& tags = {}) +{ + TTaggedPayloadWriter writer; + WriteMessage(&writer, message); + for (auto [key, value] : tags) { + WriteTag(&writer, key, value); + } + return writer.Finish(); +} + +TDecodedPayload Decode(const TTaggedLogEventPayload& payload) +{ + TTaggedPayloadReader reader(payload); + TDecodedPayload result; + result.Message = reader.ReadMessage(); + while (auto tag = reader.TryReadTag()) { + result.Tags.emplace_back(tag->Key, tag->Value); + } + return result; +} + +TEST(TTaggedPayloadTest, MessageOnly) +{ + auto decoded = Decode(Encode("Hello")); + EXPECT_EQ(decoded.Message, "Hello"); + EXPECT_TRUE(decoded.Tags.empty()); +} + +TEST(TTaggedPayloadTest, EmptyMessage) +{ + auto decoded = Decode(Encode("")); + EXPECT_EQ(decoded.Message, ""); + EXPECT_TRUE(decoded.Tags.empty()); +} + +TEST(TTaggedPayloadTest, OneTag) +{ + auto decoded = Decode(Encode("Message", {{"Key", "Value"}})); + EXPECT_EQ(decoded.Message, "Message"); + ASSERT_EQ(decoded.Tags.size(), 1u); + EXPECT_EQ(decoded.Tags[0].first, "Key"); + EXPECT_EQ(decoded.Tags[0].second, "Value"); +} + +TEST(TTaggedPayloadTest, ManyTags) +{ + auto decoded = Decode(Encode("Message", {{"Arg1", "123"}, {"Arg2", "test"}, {"Arg3", ""}})); + EXPECT_EQ(decoded.Message, "Message"); + ASSERT_EQ(decoded.Tags.size(), 3u); + EXPECT_EQ(decoded.Tags[0], std::pair(std::string("Arg1"), std::string("123"))); + EXPECT_EQ(decoded.Tags[1], std::pair(std::string("Arg2"), std::string("test"))); + EXPECT_EQ(decoded.Tags[2], std::pair(std::string("Arg3"), std::string(""))); +} + +TEST(TTaggedPayloadTest, BinarySafeValues) +{ + // Keys/values may carry arbitrary bytes, including embedded NULs and delimiters. + std::string message("a\0b ()", 6); + std::string key("k\0:", 3); + std::string value("v\0, ", 4); + + auto decoded = Decode(Encode(message, {{key, value}})); + EXPECT_EQ(decoded.Message, message); + ASSERT_EQ(decoded.Tags.size(), 1u); + EXPECT_EQ(decoded.Tags[0].first, key); + EXPECT_EQ(decoded.Tags[0].second, value); +} + +TEST(TTaggedPayloadTest, ReaderViewsPointIntoPayload) +{ + auto payload = Encode("Message", {{"Key", "Value"}}); + + auto pointsInto = [&] (TStringBuf view) { + return view.data() >= payload.Underlying().Begin() && view.data() + view.size() <= payload.Underlying().End(); + }; + + TTaggedPayloadReader reader(payload); + EXPECT_TRUE(pointsInto(reader.ReadMessage())); + auto tag = reader.TryReadTag(); + ASSERT_TRUE(tag.has_value()); + EXPECT_TRUE(pointsInto(tag->Key)); + EXPECT_TRUE(pointsInto(tag->Value)); +} + +TEST(TTaggedPayloadTest, WellKnownTag) +{ + TTaggedPayloadWriter writer; + WriteMessage(&writer, "Message"); + WriteTag(&writer, "Key", "Value"); + WriteWellKnownTag(&writer, "Error", "boom"); + auto payload = writer.Finish(); + + TTaggedPayloadReader reader(payload); + EXPECT_EQ(reader.ReadMessage(), "Message"); + + auto regular = reader.TryReadTag(); + ASSERT_TRUE(regular); + EXPECT_EQ(regular->Key, "Key"); + EXPECT_EQ(regular->Value, "Value"); + EXPECT_FALSE(regular->IsWellKnown); + + auto wellKnown = reader.TryReadTag(); + ASSERT_TRUE(wellKnown); + EXPECT_EQ(wellKnown->Key, "Error"); + EXPECT_EQ(wellKnown->Value, "boom"); + EXPECT_TRUE(wellKnown->IsWellKnown); + + EXPECT_FALSE(reader.TryReadTag()); +} + +TEST(TTaggedPayloadTest, FormatWellKnownTagTrailing) +{ + TTaggedPayloadWriter writer; + WriteMessage(&writer, "Message"); + WriteTag(&writer, "Key", "Value"); + WriteWellKnownTag(&writer, "Error", "boom"); + // Regular tags stay inline; the well-known tag is appended after the |(...)| group. + EXPECT_EQ(FormatTaggedPayload(writer.Finish()), "Message (Key: Value)\nboom"); +} + +//////////////////////////////////////////////////////////////////////////////// + +} // namespace +} // namespace NYT::NLogging diff --git a/library/cpp/yt/logging/unittests/ya.make b/library/cpp/yt/logging/unittests/ya.make index 01946699bb2..cc068fa24c6 100644 --- a/library/cpp/yt/logging/unittests/ya.make +++ b/library/cpp/yt/logging/unittests/ya.make @@ -3,7 +3,10 @@ GTEST(unittester-library-logging) INCLUDE(${ARCADIA_ROOT}/library/cpp/yt/ya_cpp.make.inc) SRCS( + helpers.cpp logger_ut.cpp + tagged_payload_ut.cpp + structured_payload_ut.cpp static_analysis_ut.cpp ) diff --git a/library/cpp/yt/logging/ya.make b/library/cpp/yt/logging/ya.make index b9cf5c6e715..d839a6f07b7 100644 --- a/library/cpp/yt/logging/ya.make +++ b/library/cpp/yt/logging/ya.make @@ -4,6 +4,8 @@ INCLUDE(${ARCADIA_ROOT}/library/cpp/yt/ya_cpp.make.inc) SRCS( logger.cpp + tagged_payload.cpp + structured_payload.cpp ) PEERDIR( |