[LOGS] Pass resolved context to LogRecordProcessor::OnEmit unconditionally - #4421
Open
om7057 wants to merge 9 commits into
Open
[LOGS] Pass resolved context to LogRecordProcessor::OnEmit unconditionally#4421om7057 wants to merge 9 commits into
om7057 wants to merge 9 commits into
Conversation
…nally Split out of open-telemetry#4309 per review from dbarker and ThomsonTan: the EventToSpanEventBridgeProcessor added there needs the resolved trace Context at OnEmit time to reach the live Span it bridges an event onto. Getting that right turned out to be public API surface for both logs::Logger and sdk::logs::LogRecordProcessor, so it gets its own PR with its own analysis before the bridge processor depends on it. The bug: Logger::EmitLogRecord(record) re-derived the resolved context from RuntimeContext::GetCurrent() (ambient) instead of reusing whatever context had already been resolved for this record, so an explicitly supplied context could be silently dropped in favor of whatever span happened to be ambient at emit time. Design, evaluated against the 7 use cases below: resolve context once and always pass it to OnEmit, no per-processor opt-in. * api/include/opentelemetry/logs/logger.h (ABI v2): added EmitLogRecordWithContext(record, resolved_context), a new virtual with a default that forwards to EmitLogRecord(record) so existing Logger implementations keep compiling unchanged. Distinct name (not an EmitLogRecord() overload) so a derived class overriding only the record-only overload can't hide it. EmitLogRecord(args...) now calls it with the context_or_span it already resolved for the Enabled() filter chain, instead of discarding that resolution. Extracted the per-argument stamping loop (previously duplicated) into a shared StampLogRecordFields() helper. * sdk/include/opentelemetry/sdk/logs/processor.h: added OnEmitWithContext(record, context), unconditional (no opt-in flag), default forwards to OnEmit() so unrelated processors are unaffected. * sdk/src/logs/logger.cc: EmitToProcessor() always calls OnEmitWithContext(). When no context was ever supplied to this specific call (the plain EmitLogRecord(record) path), it resolves ambient fresh as a best-effort fallback. * sdk/{include,src}/logs/multi_log_record_processor.{h,cc}: fans OnEmitWithContext() out to every child processor. The 7 use cases (matrix from review), and how each resolves: Context context = trace::SetSpan(original_context, my_span); 1. EmitLogRecord("msg", context) -- explicit Context. 2. EmitLogRecord("msg") -- implicit ambient. 3. CreateLogRecord(); EmitLogRecord(r) -- no context anywhere. 4. CreateLogRecord(context); EmitLogRecord(r) -- explicit to Create only. 5. EmitLogRecord("msg", span_context) -- bare SpanContext. 6. EmitLogRecord("msg", trace_id, span_id, flags) 7. CreateLogRecord(span_context); EmitLogRecord(r) Cases 1/2/5/6 already resolve context inside EmitLogRecord(args...) regardless of any processor -- passing it through costs nothing new. Cases 3/4/7 use the two-step create-then-emit pattern, which the Logger has no way to carry an explicit context across: the resolved Context (and any live Span it owns) is not retained anywhere between the two calls. Storing it on the Recordable to bridge that gap was considered and rejected -- BatchLogRecordProcessor buffers a Recordable for up to scheduled_delay_millis (default 5000ms) before export, so a Context stashed there would keep its Span alive for that whole window, an unrelated subsystem silently extending a span's lifetime. Reconstructing a SpanContext from the record's own stamped fields was also considered and rejected -- the base Recordable interface is write-only (no GetTraceId/GetSpanId), so recovering it generically would need either an unsafe downcast or expanding that interface for every processor's own Recordable implementation. So case 3 (no explicit context ever given) resolves ambient fresh at emit time -- spec-correct, since ambient-at-emit-time is the right answer when nothing explicit was supplied. Cases 4 and 7 (explicit context/span_context given to Create only) are a documented, tested limitation: the plain EmitLogRecord(record) call sees ambient, not the original context. Callers who need the processor to see the same context they gave CreateLogRecord must call EmitLogRecordWithContext(record, context) instead, re-passing the context they already have in hand. Case 7 is not actually a regression versus case 5/6: a bare SpanContext never carried a live Span to begin with, so the ids delivered via EmitLogRecordWithContext are full compliance for that case. Verified etw::Logger (exporters/etw/include/opentelemetry/exporters/etw/etw_logger.h), the one real production logs::Logger subclass besides the SDK's own: it only overrides the record-only EmitLogRecord(), not EmitLogRecordWithContext, so it is unaffected and keeps its existing ambient-fallback behavior. No production LogRecordProcessor subclass exists outside sdk/src/logs/ (checked exporters/otlp, elasticsearch, ostream, opentracing-shim). Tests: sdk/test/logs/logger_sdk_test.cc adds ContextCapturingProcessor and one test per case above, including the two documented-limitation tests for cases 4/7 and their EmitLogRecordWithContext-fixed counterparts, plus three tests pinning the exact GetCurrent() call count for cases 1/2/3 (0, 1, and 2 respectively) to make the cost claim in this description verifiable rather than asserted. Verified in a from-scratch ABI v2 build (WITH_ABI_VERSION_1=OFF WITH_ABI_VERSION_2=ON) as well as the existing ABI v1 build: full ctest suites green in both (904/904 and 1367/1367), clang-format applied, doxygen and misspell clean.
…solved-context # Conflicts: # CHANGELOG.md
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #4421 +/- ##
==========================================
- Coverage 83.22% 83.21% -0.01%
==========================================
Files 521 521
Lines 20404 20443 +39
==========================================
+ Hits 16980 17010 +30
- Misses 3424 3433 +9
🚀 New features to boost your workflow:
|
…solved-context # Conflicts: # CHANGELOG.md
- sdk/test/logs/logger_sdk_test.cc: mark nostd/unique_ptr.h as IWYU pragma: keep, since it's only referenced from ABI v2 gated code, same pattern as the other ABI-gated includes in this file. - Add tests for lines codecov flagged as uncovered in the diff: the disabled-logger path through EmitLogRecordWithContext, the null log_record guard in EmitLogRecord(args...) after CreateLogRecord(context_or_span) returns null, and MultiLogRecordProcessor::OnEmitWithContext's fan-out and null-record guard.
The new MultiLogRecordProcessor::OnEmitWithContext tests construct a SpanContext directly, which needs trace/span_id.h, trace/trace_flags.h, and trace/trace_id.h -- flagged identically across all three iwyu configs (abiv1, abiv1-preview, abiv2-preview).
…solved-context # Conflicts: # CHANGELOG.md
Contributor
Author
|
@dbarker small reminder on this one! |
Contributor
Author
…solved-context # Conflicts: # CHANGELOG.md # sdk/test/logs/simple_log_record_processor_test.cc
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Split out of #4309 per review:
EventToSpanEventBridgeProcessorneeds the resolved traceContextatOnEmittime to reach the liveSpanit bridges an event onto. That turned out to be a public API surface for bothlogs::Loggerandsdk::logs::LogRecordProcessor, so it gets its own PR with its own analysis before the bridge processor depends on it. #4309 will be rebased on top of this once it merges, and cut down to just the bridge processor + declarative config.The bug:
Logger::EmitLogRecord(record)re-derived the resolved context fromRuntimeContext::GetCurrent()(ambient) instead of reusing whatever context had already been resolved for this record, so an explicitly supplied context could be silently dropped in favor of whatever span happened to be ambient at emit time.Design: resolve context once and always pass it to
OnEmit, no per-processor opt-in flag (an earlier draft of this had one; removed per @dbarker's review that it's unnecessary API surface once the cost of passing it through is understood -- see below).The 7 use cases
EmitLogRecord("msg", context)-- explicitContext.EmitLogRecord("msg")-- implicit ambient.CreateLogRecord(); EmitLogRecord(r)-- no context anywhere.CreateLogRecord(context); EmitLogRecord(r)-- explicit to Create only.EmitLogRecord("msg", span_context)-- bareSpanContext.EmitLogRecord("msg", trace_id, span_id, flags)CreateLogRecord(span_context); EmitLogRecord(r)Cases 1/2/5/6 already resolve context inside
EmitLogRecord(args...)regardless of any processor (needed for theEnabled()filter chain) -- passing it through to processors costs nothing new.Cases 3/4/7 use the two-step create-then-emit pattern, which the
Loggerhas no way to carry an explicit context across: the resolvedContext(and any liveSpanit owns) isn't retained anywhere between the two calls.Two mechanisms for closing that gap were considered and rejected:
Contexton theRecordablebetween the two calls.BatchLogRecordProcessorbuffers aRecordablefor up toscheduled_delay_millis(default 5000ms) before export, so aContextstashed there would keep itsSpanalive for that whole window -- an unrelated subsystem silently extending a span's lifetime.SpanContextfrom the record's own stamped fields. The baseRecordableinterface is write-only (noGetTraceId/GetSpanId), so recovering it generically would need either an unsafe downcast or expanding that interface for every processor's ownRecordableimplementation.So: case 3 (no explicit context ever given) resolves ambient fresh at emit time -- spec-correct, since ambient-at-emit-time is the right answer when nothing explicit was supplied. Cases 4 and 7 (explicit context/span_context given to
Createonly) are a documented, tested limitation: the plainEmitLogRecord(record)call sees ambient, not the original context. Callers who need the processor to see the same context they gaveCreateLogRecordmust callEmitLogRecordWithContext(record, context)instead, re-passing the context they already have in hand. Case 7 isn't actually a regression versus case 5/6: a bareSpanContextnever carried a liveSpanto begin with, so the ids delivered viaEmitLogRecordWithContextare fully compliant for that case.Changes
api/include/opentelemetry/logs/logger.h(ABI v2): addedEmitLogRecordWithContext(record, resolved_context), a new virtual with a default that forwards toEmitLogRecord(record)so existingLoggerimplementations keep compiling unchanged. Distinct name (not anEmitLogRecord()overload) so a derived class overriding only the record-only overload can't hide it -- same reasoning as theLogRecordProcessorside below.EmitLogRecord(args...)now calls it with thecontext_or_spanit already resolved, instead of discarding that resolution. Extracted the per-argument stamping loop (previously duplicated) into a sharedStampLogRecordFields()helper.sdk/include/opentelemetry/sdk/logs/processor.h: addedOnEmitWithContext(record, context), unconditional (no opt-in flag), default forwards toOnEmit().sdk/src/logs/logger.cc:EmitToProcessor()always callsOnEmitWithContext(). When no context was ever supplied to this specific call (the plainEmitLogRecord(record)path), it resolves ambient fresh as a best-effort fallback.sdk/{include,src}/logs/multi_log_record_processor.{h,cc}: fansOnEmitWithContext()out to every child processor.Verified unaffected:
exporters/etw/include/opentelemetry/exporters/etw/etw_logger.h, the one real productionlogs::Loggersubclass besides the SDK's own -- it only overrides the record-onlyEmitLogRecord(), notEmitLogRecordWithContext, so it keeps its existing ambient-fallback behavior unchanged. No productionLogRecordProcessorsubclass exists outsidesdk/src/logs/(checkedexporters/otlp,elasticsearch,ostream,opentracing-shim).Test plan
sdk/test/logs/logger_sdk_test.cc:ContextCapturingProcessor+ one test per case above, including the two documented-limitation tests for cases 4/7 and theirEmitLogRecordWithContext-fixed counterparts.RuntimeContext::GetCurrent()call count for cases 1/2/3 (0, 1, and 2 respectively), so the cost claim above is verifiable rather than asserted.ctestgreen in a from-scratch ABI v2 build (-DWITH_ABI_VERSION_1=OFF -DWITH_ABI_VERSION_2=ON) -- 904/904.ctestgreen in the existing ABI v1 build -- 1367/1367.clang-format,doxygen docs/public/Doxyfile.lint,misspellall clean.