Scrub spans and logs lazily in the exporter thread - #2187
Conversation
Scrubbing ran in `MainSpanProcessorWrapper.on_end` and `MainLogProcessorWrapper.on_emit`, i.e. in whichever thread ended the span or emitted the log - often an application's event loop. Spans and log records are now wrapped in `LazilyScrubbedReadableSpan` / `LazilyScrubbedLogRecord`, which scrub on first read of their contents. That read happens inside `SpanExporter.export()`, which for the Logfire exporter runs on the batch processor's background thread. The result is cached under a lock, so it's computed once no matter how many exporters read the span.
|
Warning Review limit reached
Next review available in: 27 seconds Enable usage-based reviews in Billing to review now. Otherwise, wait until the next included review is available. How can I continue?After more reviews become available, a review can be triggered using the To avoid repeated limits, reduce automatic review volume by pausing incremental auto-reviews earlier, using label-based review opt-in, excluding WIP or generated PR titles, or requesting reviews manually when the PR is ready. If your team needs uninterrupted high-volume reviews, an organization admin can enable usage-based reviews. How do review limits work?CodeRabbit enforces per-developer PR review limits for each organization. Most developers receive the normal plan review availability. For paid Pro and Pro+ PR reviews, CodeRabbit uses adaptive limits for sustained high-volume activity. When a developer's recent PR review activity reaches the 95th percentile or higher among CodeRabbit users, additional reviews become available more gradually as earlier reviews age out of the rolling window. Please refer docs for additional details. Review details⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Pro Plus Run ID: 📒 Files selected for processing (6)
Comment |
![macroscopeapp[bot]](https://avatars.githubusercontent.com/in/900172?s=60&v=4){kind=small}
| self._scrubbed = self._scrubber.scrub_log(self._unscrubbed) | ||
| return self._scrubbed | ||
|
|
||
| @property |
There was a problem hiding this comment.
🟠 High _internal/scrubbing.py:420
LazilyScrubbedLogRecord exposes attributes and body as read-only @property getters, so any downstream LogRecord processor that assigns to log_record.attributes = ... or log_record.body = ... now raises AttributeError instead of updating the record. This breaks processors configured via advanced.log_record_processors that enrich or transform logs, preventing the log from being emitted. The proxy delegates other attributes through __getattr__, but @property setters are not defined, so mutation of these fields is impossible. Consider making these fields settable (e.g. adding property setters that forward to the underlying record), or caching the scrubbed result in the original LogRecord instead of wrapping it in a read-only proxy.
🚀 Reply "fix it for me" or copy this AI Prompt for your agent:
In file @logfire/_internal/scrubbing.py around line 420:
`LazilyScrubbedLogRecord` exposes `attributes` and `body` as read-only `@property` getters, so any downstream `LogRecord` processor that assigns to `log_record.attributes = ...` or `log_record.body = ...` now raises `AttributeError` instead of updating the record. This breaks processors configured via `advanced.log_record_processors` that enrich or transform logs, preventing the log from being emitted. The proxy delegates other attributes through `__getattr__`, but `@property` setters are not defined, so mutation of these fields is impossible. Consider making these fields settable (e.g. adding property setters that forward to the underlying record), or caching the scrubbed result in the original `LogRecord` instead of wrapping it in a read-only proxy.
![veria-ai[bot]](https://avatars.githubusercontent.com/in/1723776?s=60&v=4){kind=small}
| if self._scrub_done: | ||
| return | ||
| self._scrub_done = True | ||
| with handle_internal_errors: |
There was a problem hiding this comment.
Medium: Scrubbing failures export the original span
handle_internal_errors suppresses exceptions from the scrubbing callback, after _scrub_done has already been set. The code then copies the original attributes, events, and links into the span, so an attacker can cause sensitive telemetry to be exported unredacted by producing a scrub match when a callback raises—for example, because a context variable available on the request thread is absent on the exporter thread. Fail closed by dropping the span or replacing its sensitive fields with empty/redacted values when scrubbing does not complete.
PR overviewThis pull request moves span and log scrubbing to occur lazily in the exporter thread. It updates the scrubbing flow for telemetry attributes, events, and links. One security issue remains open: if a scrubbing callback raises in the exporter thread, the original telemetry can still be exported instead of being redacted or dropped. An attacker able to trigger this failure could cause sensitive span data to reach the telemetry backend unredacted, so the scrubbing path currently fails open. Open issues (1)
Fixed/addressed: 0 · PR risk: 7/10 |
![cubic-dev-ai[bot]](https://avatars.githubusercontent.com/in/1082092?s=60&v=4){kind=small}
There was a problem hiding this comment.
3 issues found across 6 files
Confidence score: 2/5
- In
logfire/_internal/scrubbing.py, error handling around span scrubbing can leave the “scrubbed” flag set after a callback failure, then copy unsanitized originals back into_attributes/_events, which risks leaking data that should be redacted — make the flag/update sequence atomic or reset state on exception. - In
logfire/_internal/scrubbing.py, lazy log scrubbing callsscrub_log()without the internal error guard, so callback exceptions can escape the export path and fail log export entirely — wrap the lazyscrub_log()call inhandle_internal_errors(or equivalent) to contain failures. - In
logfire/_internal/scrubbing.py,LazilyScrubbedLogRecordexposes read-onlyattributes/body, so downstream processors that mutate log records may raise at runtime and break processing chains — add compatible setters or a mutable adapter to preserve processor interoperability.
Prompt for AI agents (unresolved issues)
Check if these issues are valid — if so, understand the root cause of each and fix them. If appropriate, use sub-agents to investigate and fix each issue separately.
<file name="logfire/_internal/scrubbing.py">
<violation number="1" location="logfire/_internal/scrubbing.py:370">
P1: If the scrubbing callback or `scrub_span()` raises, `handle_internal_errors` suppresses the exception, but this flag has already been set and the code then copies the original values back into `_attributes`, `_events`, and `_links`. Subsequent exporter reads skip scrubbing and receive the unsanitized span, which can leak exactly the sensitive data this wrapper is intended to protect. The completion flag should only be committed after a successful scrub, and the failure path should not expose the original span contents.</violation>
<violation number="2" location="logfire/_internal/scrubbing.py:417">
P1: A scrubbing callback exception can now bubble out of log export and fail the export path, because lazy log scrubbing calls `scrub_log()` without the internal error guard. Wrapping this call with `handle_internal_errors` and falling back to the original record would keep exporter-thread failures from breaking log delivery.</violation>
<violation number="3" location="logfire/_internal/scrubbing.py:421">
P2: LazilyScrubbedLogRecord defines `attributes` and `body` as read-only properties with no setters. Any downstream log record processor (e.g. one configured via advanced.log_record_processors) that tries to assign `log_record.attributes = ...` or `log_record.body = ...` to enrich/transform a log will now raise AttributeError instead of updating the record, unlike the previous plain LogRecord which allowed mutation. Consider adding setters that forward to the underlying record, or caching the scrubbed result on the original LogRecord instead of wrapping it in a read-only proxy.</violation>
</file>
Reply with feedback, questions, or to request a fix.
Re-trigger cubic
| def _scrub(self) -> LogRecord: | ||
| with self._scrub_lock: | ||
| if self._scrubbed is None: | ||
| self._scrubbed = self._scrubber.scrub_log(self._unscrubbed) |
There was a problem hiding this comment.
P1: A scrubbing callback exception can now bubble out of log export and fail the export path, because lazy log scrubbing calls scrub_log() without the internal error guard. Wrapping this call with handle_internal_errors and falling back to the original record would keep exporter-thread failures from breaking log delivery.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At logfire/_internal/scrubbing.py, line 417:
<comment>A scrubbing callback exception can now bubble out of log export and fail the export path, because lazy log scrubbing calls `scrub_log()` without the internal error guard. Wrapping this call with `handle_internal_errors` and falling back to the original record would keep exporter-thread failures from breaking log delivery.</comment>
<file context>
@@ -347,6 +349,83 @@ def _redact(self, match: ScrubMatch) -> Any:
+ def _scrub(self) -> LogRecord:
+ with self._scrub_lock:
+ if self._scrubbed is None:
+ self._scrubbed = self._scrubber.scrub_log(self._unscrubbed)
+ return self._scrubbed
+
</file context>
| self._scrubbed = self._scrubber.scrub_log(self._unscrubbed) | |
| with handle_internal_errors: | |
| self._scrubbed = self._scrubber.scrub_log(self._unscrubbed) | |
| self._scrubbed = self._scrubbed or self._unscrubbed |
| with self._scrub_lock: | ||
| if self._scrub_done: | ||
| return | ||
| self._scrub_done = True |
There was a problem hiding this comment.
P1: If the scrubbing callback or scrub_span() raises, handle_internal_errors suppresses the exception, but this flag has already been set and the code then copies the original values back into _attributes, _events, and _links. Subsequent exporter reads skip scrubbing and receive the unsanitized span, which can leak exactly the sensitive data this wrapper is intended to protect. The completion flag should only be committed after a successful scrub, and the failure path should not expose the original span contents.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At logfire/_internal/scrubbing.py, line 370:
<comment>If the scrubbing callback or `scrub_span()` raises, `handle_internal_errors` suppresses the exception, but this flag has already been set and the code then copies the original values back into `_attributes`, `_events`, and `_links`. Subsequent exporter reads skip scrubbing and receive the unsanitized span, which can leak exactly the sensitive data this wrapper is intended to protect. The completion flag should only be committed after a successful scrub, and the failure path should not expose the original span contents.</comment>
<file context>
@@ -347,6 +349,83 @@ def _redact(self, match: ScrubMatch) -> Any:
+ with self._scrub_lock:
+ if self._scrub_done:
+ return
+ self._scrub_done = True
+ with handle_internal_errors:
+ self._scrubber.scrub_span(self._span_dict)
</file context>
| return self._scrubbed | ||
|
|
||
| @property | ||
| def attributes(self) -> otel_types._ExtendedAttributes | None: # pyright: ignore[reportPrivateUsage] |
There was a problem hiding this comment.
P2: LazilyScrubbedLogRecord defines attributes and body as read-only properties with no setters. Any downstream log record processor (e.g. one configured via advanced.log_record_processors) that tries to assign log_record.attributes = ... or log_record.body = ... to enrich/transform a log will now raise AttributeError instead of updating the record, unlike the previous plain LogRecord which allowed mutation. Consider adding setters that forward to the underlying record, or caching the scrubbed result on the original LogRecord instead of wrapping it in a read-only proxy.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At logfire/_internal/scrubbing.py, line 421:
<comment>LazilyScrubbedLogRecord defines `attributes` and `body` as read-only properties with no setters. Any downstream log record processor (e.g. one configured via advanced.log_record_processors) that tries to assign `log_record.attributes = ...` or `log_record.body = ...` to enrich/transform a log will now raise AttributeError instead of updating the record, unlike the previous plain LogRecord which allowed mutation. Consider adding setters that forward to the underlying record, or caching the scrubbed result on the original LogRecord instead of wrapping it in a read-only proxy.</comment>
<file context>
@@ -347,6 +349,83 @@ def _redact(self, match: ScrubMatch) -> Any:
+ return self._scrubbed
+
+ @property
+ def attributes(self) -> otel_types._ExtendedAttributes | None: # pyright: ignore[reportPrivateUsage]
+ return self._scrub().attributes
+
</file context>
|
It doesn't seem this solves the problem I was trying to solve. |
1 participant
Scrubbing ran in
MainSpanProcessorWrapper.on_endandMainLogProcessorWrapper.on_emit, i.e. in whichever thread ended the span or emitted the log - often an application's event loop.Spans and log records are now wrapped in
LazilyScrubbedReadableSpan/LazilyScrubbedLogRecord, which scrub on first read of their contents. That read happens insideSpanExporter.export(), which for the Logfire exporter runs on the batch processor's background thread. The result is cached under a lock, so it's computed once no matter how many exporters read the span. Every exporter still receives scrubbed data, including user-providedadditional_span_processors- only the timing moved.Measurements
Time spent inside
logfire.info()- the part that runs on the event loop - with a 200-item nested payload, 50 calls:Tagging each scrubbing callback invocation with
threading.current_thread().nameconfirms it moved fromMainThreadtoOtelBatchSpanRecordProcessor.Caveat: measuring event-loop heartbeat lag instead gives 12.1ms after vs 12.9ms before - essentially unchanged. Scrubbing is pure Python, so on the worker thread it still holds the GIL. What changed is that the work is now preemptible at
sys.getswitchinterval()granularity instead of one monolithic block, and it's off the critical path of the coroutine that logged. For an app genuinely CPU-bound on scrubbing this redistributes the cost rather than eliminating it.Notes
SimpleSpanProcessor(the console exporter,TestExporter) the read still happens in the calling thread - unavoidable, since those export synchronously.sampling=SamplingOptions(tail=...),TailSamplingProcessorreadsspan.attributesto get the level, which triggers the scrub inline again. Not addressed here.span.attributesnow skips scrubbing entirely. The real OTLP path serializes every attribute, so it's unaffected.force_flush()scrubs on whatever thread calls it, since the pending batch is drained there.docs/how-to-guides/scrubbing.md.test_otel_logs.pycompared the log record by identity; it now compares body and attributes.AI Disclaimer
This PR was developed with the assistance of either Claude or Codex. I've reviewed and verified the changes.