fix: log and uncache OTel spans that end on another thread - #941
sangkyoonnam wants to merge 2 commits into
Conversation
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
CanReader
left a comment
There was a problem hiding this comment.
Nice fix. I ran the otel and tracking tests on the branch and they pass, and the new tests fail on main. I also tried it with a real app where every step starts a child span on a ThreadPoolExecutor worker: on main nothing gets logged for those spans and span_map keeps growing, on this branch everything is logged and span_map ends empty.
Some things for later, not blocking:
- The real cause looks like
post_run_stepdoingtracker_context.set(None)instead of resetting to the old value. If you run a sub application inside an action, the outer app loses its tracker for the rest of that action. Your fallback covers this now (I checked, outer spans get theirend_spanagain), but saving the token inpre_run_stepand callingtracker_context.reset(token)would fix it at the source. A test for this nested case would be nice too since it's fixed but not tested. _tracker_forstill prefers the context var overcached_span.tracker, so a span can still be logged to another app's tracker. Same as main so not a regression, just wondering if the owner tracker should win now that we store it.FullSpanContextnow keeps a reference to the tracker, so if an entry still leaks (for examplepre_start_spanraising inon_start) the tracker and its log file stay alive with it. Small thing, maybe a follow up.
|
Thanks for running it against a real app. Agreed that |
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
With
use_otel_tracing=True, a span opened inside an action on a worker thread that only attaches the OTel context is never logged to the Burr tracker, and its entry stays in the module-levelspan_mapfor the life of the process.BurrTrackingSpanProcessorlooks up the tracker through thetracker_contextContextVar.ThreadPoolExecutordoesn't copy context vars, so a worker that only attaches the OTel context sees no tracker.on_startstill caches the span, buton_endonly logs and uncaches it when a tracker is present. The same happens to a span that ends afterpost_run_step, which clears the context var.Repro: an action that runs one child span in a
ThreadPoolExecutorworker withcontext.attach(ctx), stepped 50 times with the local tracker. On main,len(span_map)is 50 and the log has 0begin_spanand 0attributerecords. Without the thread, or with this change, it's 0, 50 and 50. Plain synchronousMapStatesdoesn't reproduce this, since each sub-application sets the context var in its executor thread, but a worker inside a child action still does.Changes
FullSpanContextcarries the tracker that started the action span. Whentracker_contextis unset, a child span takes its parent's tracker. This covers the "track a map of span ID -> tracker" TODO for the unset case.tracker_contextwhen it's set, so tracker selection doesn't change there.on_endremoves the cache entry before calling the tracker, so a missing tracker or a failing tracker call can't leave it behind.How I tested this
TracerProvidercover a child span on a worker thread, a span that ends afterpost_run_step, a tracker whosepost_end_spanraises, and a span the outer action opens after a nested app step. The existing none-trackeron_endtest now also asserts the entry is removed. Those five cases fail on main and pass here; the same-thread variant of the first test passes on both as a control.pytest tests --ignore=tests/integrations/persisters --ignore=tests/integrations/test_bip0042_bedrock.py: 661 passed, 2 skipped.pre-commit runon both files passes.Notes
pre_start_spanraises inon_start, the entry still stays inspan_map, as on main, and it now also holds the tracker.Checklist