[CONFIGURATION] Implement EventToSpanEventBridge log record processor - #4309
[CONFIGURATION] Implement EventToSpanEventBridge log record processor#4309om7057 wants to merge 31 commits into
Conversation
Adds the ExperimentalEventToSpanEventBridgeLogRecordProcessor type from the declarative configuration spec. When a log record carries an event name and matches the trace and span id of the currently active span, this processor copies it over as a span event, mirroring the existing implementation in the Java SDK. Fixes open-telemetry#4155
Codecov Report❌ Patch coverage is Additional details and impacted files@@ Coverage Diff @@
## main #4309 +/- ##
==========================================
- Coverage 82.35% 82.23% -0.12%
==========================================
Files 502 506 +4
Lines 19877 20044 +167
==========================================
+ Hits 16368 16481 +113
- Misses 3509 3563 +54
🚀 New features to boost your workflow:
|
The new yaml_logs_test.cc test case used dynamic_cast, but one CI config builds with -fno-rtti; switched to reinterpret_cast to match the rest of the file. Also reverted an unrelated indentation change in sdk_builder.cc that a local clang-format 14 run introduced on lines I didn't touch; CI runs clang-format 18, which formats these continuation lines differently.
clang-tidy flagged three things that pushed the abiv2-preview preset over its warning budget: the attributes_ member stored a reference instead of a pointer, OnEmit released the incoming unique_ptr without an explicit std::move, and ForEachKeyValue could let an allocation failure escape a noexcept override. Switched the member to a pointer, added std::move, and wrapped the iteration in a try/catch guarded by OPENTELEMETRY_HAVE_EXCEPTIONS, matching the pattern already used in periodic_exporting_metric_reader.cc. iwyu wanted <utility> in both files for std::move, plus a few trace headers directly included in the test file rather than pulled in transitively.
…ectly configuration_parser.cc used EventToSpanEventBridgeLogRecordProcessorConfiguration via a transitive include only, which iwyu flagged in both abiv1-preview and abiv2-preview jobs.
lalitb
left a comment
There was a problem hiding this comment.
As mentioned here - . This violates the Logs SDK specification for explicitly supplied contexts and can silently drop valid events. The current C++ LogRecordProcessor::OnEmit() API does not expose that context, so the API gap
needs to be addressed before this bridge can be implemented correctly.
@lalitb Thank you for pointing this out. The current implementation doesn't handle explicitly supplied contexts properly; it will silently drop events from logs that were emitted with a different span context than what's currently active. Would it be acceptable to: Add a method to the Recordable interface to store/retrieve the resolved context |
Add OnEmitWithContext() method to LogRecordProcessor interface to pass the resolved context (explicit if provided, else ambient) to processors that need it. The context is valid only for the duration of the call and must not be retained. Updates: - LogRecordProcessor: new OnEmitWithContext() virtual method (default forwards to OnEmit) - Logger: call OnEmitWithContext with resolved context - MultiLogRecordProcessor: implement OnEmitWithContext to forward to child processors This enables processors like EventToSpanEventBridge to access the log's resolved context for proper span matching, addressing spec compliance for explicit contexts.
…pport Update EventToSpanEventBridgeProcessor to override OnEmitWithContext and use the log's resolved context (explicit if provided, else ambient) for proper span matching. Changes: - Override OnEmitWithContext to receive the resolved context from the logger - Extract span context from the variant (SpanContext or Context) - Compare resolved span context to log's trace/span IDs - Verify current active span matches resolved context before adding event - Update processor docstring to clarify context usage This ensures spec compliance for explicitly-supplied log contexts where the log and ambient span might differ.
4e0808a to
ec30ecb
Compare
|
@lalitb Thank you for the guidance. I've implemented the solution exactly as you suggested:
The context is passed by reference and never retained. All changes are pushed and ready for review. |
…nt-bridge-config # Conflicts: # CHANGELOG.md
…n, harden tests Bridge onto the span from the resolved context (ThomsonTan review): OnEmitWithContext() looked up the live span from the resolved Context and then discarded it in favour of the ambient span, so an event whose ids referred to an explicitly supplied span was dropped whenever a different span was ambient. The span from the resolved Context is now the span the event is added to. A bare SpanContext carries no live Span, so that alternative is handled separately and still resolves through the ambient span, with the id check rejecting a mismatch. Remove the duplicated emit pipeline: OnEmit() and OnEmitWithContext() had drifted apart. Both now share BridgeRecordToSpan(), which holds all preconditions and the emission in one place. Keep the emit hot path free of context resolution: LogRecordProcessor gains ConsumesResolvedContext() (default false), MultiLogRecordProcessor reports true when any child does, and LoggerContext caches the answer the same way it already caches RecordableEnforcesLogRecordLimits(). Logger only resolves the ambient context and dispatches through OnEmitWithContext() when some processor will actually read it, so simple/batch pipelines keep dispatching through OnEmit() with no extra RuntimeContext::GetCurrent() call. Document compatibility: OnEmitWithContext() and ConsumesResolvedContext() are source compatible via default implementations but change the LogRecordProcessor vtable, so subclasses must be recompiled. Noted in the header and in the CHANGELOG breaking-changes section. VisitEventToSpanEventBridge() was pure virtual, which broke existing visitors, and now defaults to a no-op. Make the YAML assertion type-aware: the reinterpret_cast only repeated the preceding non-null check and passed for a misspelled key that fell through to the extension configuration. The test now dispatches through Accept() with a recording visitor, and a companion test pins the misspelled-key fallback. Tests: explicit span_a with ambient span_b asserting only span_a receives the event (fails against the previous code), explicit-context mismatch, bare SpanContext, and Logger-level tests that a context-ignoring processor dispatches through OnEmit() and adds no GetCurrent() call, using a counting RuntimeContextStorage.
The base declaration left the second parameter unnamed while the comment documented @PARAM context, so Doxygen warned that the documented argument was not in the argument list -- once for LogRecordProcessor and again for the EventToSpanEventBridgeProcessor override that inherits the comment. Name the parameter and mark it OPENTELEMETRY_MAYBE_UNUSED, since the default implementation forwards to OnEmit() without reading it. Keeps the parameter documented rather than dropping the @PARAM line. Verified with doxygen against docs/public/Doxyfile.lint: no warnings remain for any file this PR touches. The warnings still reported for api logs logger.h, noop.h and sdk resource.h are pre-existing on main, are not emitted by the Doxygen version CI uses, and are untouched here.
|
Thanks for the thorough review @ThomsonTan. Fully addressed: the compatibility documentation and the visitor source break, the type-aware YAML assertion (plus a misspelled-key guard), and the duplicated emit pipeline. Partially addressed, with one honest caveat: the discarded-span bug is fixed in the processor and covered by a regression test that fails against the old code, and ordinary dispatch is back on OnEmit() with no added GetCurrent() for context-ignoring pipelines. But the explicit context still never reaches the processor end-to-end, because Logger::EmitLogRecord() doesn't receive it, so in practice the bridge is still handed the ambient context. I've left details and a question on the relevant threads. Still open: the eager child recordable. I couldn't find a fix that actually avoids the copy and would like your steer before touching MultiRecordable; details on that thread. Verified locally; please check once more that the changes have been made. |
- event_to_span_event_bridge_processor.cc: drop <memory>, no longer needed
directly now that the shared BridgeRecordToSpan() helper pulls unique_ptr
transitively through recordable.h.
- event_to_span_event_bridge_processor_test.cc: swap trace/context.h for
nostd/string_view.h + trace/span_metadata.h; the new regression tests use
trace_api::kSpanKey directly and never call GetSpan()/SetSpan().
- logger_sdk_test.cc: add stddef.h (size_t) and nostd/unique_ptr.h
(CountingRuntimeContextStorage::Attach's return type), both used directly
by the new dispatch tests.
- yaml_logs_test.cc: swap the two concrete
{event_to_span_event_bridge,extension}_log_record_processor_configuration.h
includes for the base log_record_processor_configuration.h; the parsed
processor pointer is typed as the base class and only Accept() is called on
it, the concrete types are only named as visitor-callback parameters, which
the visitor header already forward-declares.
Verified with 'iwyu' locally is not available in this environment, so
confirmed by inspection against the CI diagnostics and by rebuilding: full
build is clean and ctest is 931/931 passing. doxygen docs/public/Doxyfile.lint
still reports zero warnings for any file this PR touches.
clang-tidy (both abiv1-preview and abiv2-preview pushed the warning count over the job's threshold by 2): - event_to_span_event_bridge_processor.cc:237 bugprone-exception-escape: OnEmitWithContext() is noexcept but used holds_alternative<Context>() + get<Context>(context), and nostd::get() throws bad_variant_access on a mismatched alternative. Even though the holds_alternative check made that path unreachable, clang-tidy can't prove it statically. Switched to nostd::get_if<Context>(&context), which returns nullptr instead of throwing -- the same pattern Logger::ExtractSpanContext already uses for this exact variant in logger.cc. - logger_sdk_test.cc:1014 cppcoreguidelines-rvalue-reference-param-not-moved: DispatchRecordingProcessor::OnEmit() took its unique_ptr<Recordable>&& by dropping it unnamed. Named the parameter and moved it into a static_cast<void>(...), mirroring the sibling OnEmitWithContext() override a few lines below that already does this. iwyu (abiv2-preview only; abiv1/abiv1-preview already required these directly and passed): - logger_sdk_test.cc: marked the <stddef.h> and opentelemetry/context/
…nt-bridge-config # Conflicts: # CHANGELOG.md
|
@lalitb, can you confirm if all the changes requested are addressed in the later commits, and if so could you please approve the PR? |
…nt-bridge-config # Conflicts: # CHANGELOG.md
CI / CMake gcc 14 (maintainer mode, sync) failed with a glibc heap-corruption abort (double free or corruption (fasttop)) inside the functional/otlp mTLS integration test binary during the mtls-ok test case. Both full ctest runs in that job completed 100% passing (1332/1332) beforehand; the crash is in a separate OTLP gRPC exporter mTLS test harness untouched by this PR's diff. Not a Required check. Retriggering to see if it clears as a transient flake.
Two unrelated flakes seen across recent runs: - CI / CMake gcc 14 (maintainer mode, sync): glibc heap-corruption abort in the functional/otlp mTLS integration test (mtls-ok case), after both ctest suites in that job passed 100%. Not touched by this PR's diff. - CI / CMake FetchContent usage with opentelemetry-cpp: BasicCurlHttpTests. ElegantQuitQuick failed a hardcoded 20ms shutdown-latency assertion (actual 247ms) in ext/test/http/curl_http_test.cc, whose own comment already documents this margin as CI-host-load-sensitive. Not touched by this PR's diff. Retriggering to see if both clear as transient CI-host flakes.
CI / CMake gcc 14 (maintainer mode, async) failed after both ctest suites passed 100% (1334/1334). The failure is in functional/otlp/run_test.sh's docker build step, timing out while pulling otel/opentelemetry-collector:0.123.0 from Docker Hub: dial tcp 54.164.79.128:443: i/o timeout Network/registry timeout on the runner, unrelated to this PR's diff (no functional/otlp or Dockerfile changes here). Retriggering.
…nt-bridge-config # Conflicts: # CHANGELOG.md # sdk/test/logs/logger_sdk_test.cc
|
@lalitb, just a small reminder: the merge conflicts have been resolved after addressing the request changes please have a look at them. |
…nt-bridge-config # Conflicts: # CHANGELOG.md
… stuck/cancelled)
…nt-bridge-config # Conflicts: # CHANGELOG.md
…nt-bridge-config # Conflicts: # CHANGELOG.md
|
@ThomsonTan @lalitb Everything else from the review is addressed. One thing is still open: this question on whether to add the ABI-v2-guarded Would like to know what can be preferred! |
|
@lalitb small ping on this |
| // the common pipelines (simple/batch) that ignore the context entirely. | ||
| if (context_->ConsumesResolvedContext()) | ||
| { | ||
| const nostd::variant<trace_api::SpanContext, context::Context> resolved_context{ |
There was a problem hiding this comment.
@om7057 - The explicit context is still lost here. If the log uses span_a while span_b is ambient, this passes span_b to the processor and the event is silently dropped.
Please carry the already resolved context through the logger emit path and add an end-to-end test with explicit span_a and ambient span_b.
There was a problem hiding this comment.
Thanks for catching; the resolved context was getting lost. EmitLogRecord(args...) computed context_or_span but then called the record-only overload, which re-derived it from RuntimeContext::GetCurrent() instead of using the one already resolved. Exactly the span_a/span_b case you described.
Fixed in 7696c6b: added Logger::EmitLogRecordWithContext() (distinctly named, default forwards to EmitLogRecord() so existing implementations are unaffected) and threaded the resolved context through to it. Added ContextAwareProcessorReceivesExplicitContextNotAmbientSpan, which reproduces your scenario and fails against the old code. Verified in a fresh ABI v2 build (my local builds were all ABI v1) plus the full ABI v1 suite
…nt-bridge-config # Conflicts: # CHANGELOG.md # sdk/src/configuration/sdk_builder.cc
Fixes the gap lalitb flagged: EmitLogRecord() was re-deriving the resolved context from RuntimeContext::GetCurrent() (ambient) instead of using the one EmitLogRecord(args...) had already resolved (explicit if supplied). If a log used an explicit context for span_a while span_b was ambient, the processor was handed span_b's context and the event bridge silently dropped it. api/include/opentelemetry/logs/logger.h (ABI v2): - Added Logger::EmitLogRecordWithContext(record, resolved_context), a new virtual (distinct name, not an EmitLogRecord() overload, so it can't be hidden by a derived class that only overrides the existing overloads -- same reasoning already applied to LogRecordProcessor::OnEmitWithContext). Default implementation forwards to EmitLogRecord(record), so existing Logger implementations keep compiling and behaving as before. - Extracted the per-argument LogRecordSetterTrait loop, previously inlined in EmitLogRecord(record, args...), into a private StampLogRecordFields() helper shared by both call sites. - EmitLogRecord(args...)'s ABI v2 branch now stamps the record via that helper and calls EmitLogRecordWithContext(record, context_or_span) with the context_or_span it just resolved, instead of forwarding to EmitLogRecord(record, args...) and losing context_or_span at the end of the function. sdk/include+src/logs/logger.h/.cc: - Logger overrides EmitLogRecordWithContext() (ABI v2) and passes the supplied resolved_context straight to the processor, no RuntimeContext lookup involved. - EmitLogRecord(record) (the ABI-version-agnostic override, used when no context was ever resolved) keeps the existing ambient-context fallback. - Both now share EmitToProcessor(recordable, resolved_context), which keeps the existing gate on LoggerContext::ConsumesResolvedContext(): a processor that ignores context still costs nothing on the emit path. sdk/test/logs/logger_sdk_test.cc: added ContextCapturingProcessor and LoggerEmitWithExplicitTraceTest.ContextAwareProcessorReceivesExplicitContextNotAmbientSpan, reproducing lalitb's exact scenario (explicit span_a, ambient span_b) and asserting the processor receives span_a's context. Confirmed this fails against the pre-fix code (received span_b instead). Verified in a from-scratch ABI v2 build (this repo's only local build directories were ABI v1, which compiles out everything gated behind OPENTELEMETRY_ABI_VERSION_NO >= 2 and would have silently skipped this code and the new test): logger_sdk_test, event_to_span_event_bridge_processor_test, and sdk_builder_test all pass. Also verified the existing ABI v1 build (build_qualify) still builds clean and passes its full 1353-test ctest suite. doxygen docs/public/Doxyfile.lint reports no new warnings.
|
@lalitb I've addressed the comment, please check once again! |
dbarker
left a comment
There was a problem hiding this comment.
Thanks for digging into this! The bridge processor is a nice driver to get these interfaces aligned with the spec.
Since this is a major API driving change for both the logger API and the logs SDK. I think it is worth breaking those changes out to a new PR with more analysis and design documentation accounting for currently supported otel-cpp use cases and spec requirements. It is possible that some of the ABIv2 logger interfaces should change to address passing context explicitly through to the processors.
Once those interfaces are settled and merged the bridge processor can use them.
Please see feedback below with some of the use cases that we need to support or explicitly break. Sharing links to the relevant specs:
https://opentelemetry.io/docs/specs/otel/logs/api/#emit-a-logrecord
https://opentelemetry.io/docs/specs/otel/logs/sdk/#onemit
https://opentelemetry.io/docs/specs/otel/context/
| * Only processors that override OnEmitWithContext() should return true. Composite processors | ||
| * return true if any child does. | ||
| */ | ||
| virtual bool ConsumesResolvedContext() const noexcept { return false; } |
There was a problem hiding this comment.
Once the context is passed through EmitLogRecord to processor OnEmit, it should be done so unconditionally. This extra virtual method here is not necessary and should be removed.
There was a problem hiding this comment.
Understood on removing the gate for spec compliance, want to flag a conflict before I do since it affects the design of the follow up PR.
ThomsonTan's earlier review on this same code asked for the opposite: resolving the context costs a RuntimeContext::GetCurrent() call, and that shouldn't happen on the hot path for pipelines (simple/batch) that never read it, hence the ConsumesResolvedContext() gate.
If the spec requires the resolved context to always reach OnEmit(), the cost has to be paid unconditionally, which reopens that concern. A couple of options for the new PR to consider:
- Pay the cost always, as you're describing. Spec says so, this is likely correct.
- Or resolve lazily: pass something like a thunk or callable that resolves RuntimeContext::GetCurrent() only if a processor actually invokes it, so processors that ignore the parameter never pay for the lookup.
Which direction should the new design PR pursue?
| { | ||
| const nostd::variant<trace_api::SpanContext, context::Context> resolved_context{ | ||
| context::RuntimeContext::GetCurrent()}; | ||
| processor.OnEmitWithContext(std::move(recordable), resolved_context); |
There was a problem hiding this comment.
Calling emit with the resolved context is a spec requirement and should occur unconditionally. ConsumesResolvedContext should be removed as an unnecessary API expansion of the processor interface.
As @lalitb points out the Context must be resolved during the API EmitLogRecord calls (it is either explicitly passed in by the user or the current context is implicitly used).
We need to account for all supported logger API use cases and document what the expected behavior will be with the new bridge processor for each.
Here are the uses cases that need to be supported from the API.
Context original_context;
Context context = trace::SetSpan(original_context, my_span);
// Cases 1-4 conform to the spec since a full Context is resolved and
// a span ptr can be accessed from the processor.
// Case 1: call emit with context resolved to explicit context
logger->EmitLogRecord("with explicit context", context);
// Case 2: call emit with context resolved to current context
logger->EmitLogRecord("with implicit current context");
// Case 3: call create then emit with ABIv1. Context is resolved to current context OR to
auto record_abiv1 = logger->CreateLogRecord();
logger->EmitLogRecord(std::move(record_abiv1);
// Case 4: call create then emit with ABIv2. Context is resolved to the explicit context
auto record_abiv2 = logger->CreateLogRecord(context);
logger->EmitLogRecord(std::move(record_abiv2);
// Cases 5-7 are supported by the otel-cpp API but don't comply with the spec since a full context cannot be effectively resolved in a way that would make the underlying span ptr accessible.
SpanContext span_context; // a user-managed SpanContext (ids + flags only, no live Span)
TraceId trace_id;
SpanId span_id;
TraceFlags flags;
// Case 5: explicit SpanContext
logger->EmitLogRecord("with span context", span_context);
// Case 6: explicit TraceId + SpanId (+ optional TraceFlags)
logger->EmitLogRecord("with trace/span id parts", trace_id, span_id, flags);
// Case 7: ABI v2 create-then-emit with explicit SpanContext
auto record_w_span_context= logger->CreateLogRecord(span_context);
logger->EmitLogRecord(std::move(record_w_span_context));
There was a problem hiding this comment.
Thank you for these cases, this is exactly the kind of matrix that was missing. Replied on the other thread about the ConsumesResolvedContext tension with ThomsonTan's feedback, so I will not repeat that here.
On cases 1 to 4, agreed those are the clean spec compliant ones and should just work once the context passing is unconditional.
On cases 5 to 7, I think the honest answer is that a bare SpanContext or TraceId plus SpanId cannot resolve to a live Span, so no processor can get a Span pointer out of them no matter how we wire things. My current bridge implementation falls back to comparing against the ambient span's ids in that case, meaning the event only gets added if the ambient span happens to be the one the ids refer to. That is a real, documented limitation rather than a bug, since the API genuinely gives us nothing to look up a Span by id.
Case 7 looks like it has a second version of the same bug though. CreateLogRecord(span_context) stamps the record's trace and span ids, but nothing carries span_context forward to the later EmitLogRecord(record) call, so that call falls back to resolving the ambient context again, same as case 3. If that is correct then case 7 needs the same fix as the case this PR started from, just for the create then emit pattern instead of the single call pattern.
Also want to flag that case 3's comment cuts off after "Context is resolved to current context OR to", might be missing the rest of that sentence.
I will pull all of this into the new PR's design doc once we're aligned on the ConsumesResolvedContext direction, want to avoid designing it piecemeal across comments here.
dbarker
left a comment
There was a problem hiding this comment.
Per comments above I'm requesting that this PR be broken up into:
- A PR with Logger API and SDK changes and tests for spec compliant context passing through emit to the processors. More design and analysis is needed.
- A PR (this existing one is fine) with only the bridge processor and declarative config support
|
Thanks @dbarker, that makes sense. I'll split it: bridge processor and declarative config stay here, and I'll open a new PR for the Logger API and SDK context passing work with the use case matrix you laid out documented against the spec. Before I start on that PR, I'd like to get alignment on one open tension (left a comment on the ConsumesResolvedContext() thread). ThomsonTan's earlier feedback on this same PR was that resolving context should be opt-in (only when a processor needs it) to avoid a RuntimeContext::GetCurrent() call on every log for pipelines that don't care. Your comment says the opposite: it should be unconditional per spec, and ConsumesResolvedContext() should go away. I want to design the new PR around whichever of these is actually correct rather than build it twice. |
Fixes #4155
Implements ExperimentalEventToSpanEventBridgeLogRecordProcessor from the declarative configuration spec. Mirrors the EventToSpanEventBridge processor already in the Java SDK: if a log record has an event name and its trace/span id match the currently active span, it gets copied over as a span event on that span. Doesn't export anything itself and doesn't stop the record from continuing through the rest of the pipeline.
YAML key is event_to_span_event_bridge/development, matching the schema in open-telemetry/opentelemetry-configuration (checked opentelemetry_configuration.json and meta_schema_language_cpp.yaml, which list this type as not_implemented with no extra properties).
New processor class under sdk/include/opentelemetry/sdk/logs/event_to_span_event_bridge_processor.h + .cc, wired into the config parser, the visitor, and SdkBuilder the same way simple/batch already are.
Tests: sdk/test/logs/event_to_span_event_bridge_processor_test.cc covers bridging onto the current matching span, ignoring records with no event name, and ignoring events from a different span. sdk/test/configuration/yaml_logs_test.cc covers the YAML parsing side.
Ran the full local test suite (915 tests) before pushing, all green. CHANGELOG updated.