Skip to content

Commit ceb4551

Browse files
author
Alex Wang
committed
fix(otel): balance context attach and detach across plugin lifecycles
Both OTel plugins called opentelemetry.context.attach() without keeping the returned token, and "restored" the enclosing span by attaching another context rather than detaching. Each operation therefore pushed two context layers and popped none, leaving an ended span current after its scope had finished. The worst consequence was cross-execution trace pollution. The invocation-start attach ran on the Lambda handler thread, which is reused across warm invocations, so the next execution's context extractor and ambient-parent lookup adopted the previous execution's ended Workflow span -- merging two unrelated executions into a single trace. Changes: - Add context_scope, a thread-confined LIFO stack of attach tokens. Detaches unwind downwards so the underlying ContextVar is always reset in order: unlike Java's Scope.close(), ContextVar.reset() writes back its captured value unconditionally and would otherwise revive a stale context. The stack is module level so the two plugins, which ship as separate entry points and can be enabled together, still unwind in true LIFO order. An epoch check discards scopes a suspended operation left behind, since the SDK re-raises SuspendExecution without calling on_user_function_end. - Pair every user-function attach with a detach on the same thread, replacing the re-attach that previously stood in for restoring the enclosing context. - Unwind any remaining scopes at invocation end. - Drop the invocation-start attach entirely. User code runs on a separate worker and ThreadPoolExecutor does not copy contextvars, so that attach never reached the code it was meant to parent; it only leaked. The Workflow and Invocation spans are used as explicit parents instead, matching the Java plugins, which never make either span current. Tests no longer reset the OTel context to isolate themselves; an autouse fixture asserts instead that every test leaves the context exactly as it found it. Adds coverage for nested contexts, sequential steps, failures, suspension, worker-thread hooks, both plugins on one thread, and warm invocation reuse keeping two executions in separate traces. Ambient spans emitted outside any operation are no longer parented to the Invocation span; the README documents this, and log correlation is unchanged because the logging filter resolves through the plugin's span registry.
1 parent 122979a commit ceb4551

10 files changed

Lines changed: 942 additions & 84 deletions

File tree

packages/aws-durable-execution-sdk-python-otel/README.md

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -235,6 +235,23 @@ context onto every emitted log record using these attributes:
235235
These attributes are only set when a valid span context is active, so any log
236236
formatter or schema must treat the fields as optional.
237237

238+
### Active Span Scope
239+
240+
The plugin makes a span current only while your step or child-context function
241+
runs, and detaches it when that function returns. Two consequences are worth
242+
knowing:
243+
244+
- Auto-instrumented calls (botocore, urllib3, and similar) made **inside** a step
245+
or child context become children of that operation's span.
246+
- Auto-instrumented calls made **outside** any operation -- for example directly
247+
in the handler between two steps -- are not parented to the durable spans. In
248+
an ADOT deployment they attach to the ambient Lambda invocation span instead.
249+
Put such work in a step if you need it inside the durable trace.
250+
251+
Log correlation is unaffected either way: the logging filter resolves the trace
252+
context from the plugin's own span registry, so records emitted between
253+
operations still carry the invocation's `traceId` and `spanId`.
254+
238255
## Verification
239256

240257
After deploying your function with the plugin configured:
Lines changed: 179 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,179 @@
1+
"""Balanced ``opentelemetry.context`` attach/detach bookkeeping for the plugins.
2+
3+
The OpenTelemetry Context specification requires every ``context.attach()`` to
4+
have a corresponding ``context.detach(token)``. Detaching is only possible with
5+
the token that ``attach`` returned, so the token has to survive from the hook
6+
that attached to the hook that pops it -- the plugin hooks are separate calls,
7+
so the idiomatic ``with tracer.start_as_current_span(...)`` form is unavailable.
8+
9+
Two properties of the runtime shape the design:
10+
11+
* **Tokens are thread-confined.** The plugin hooks run on several threads: the
12+
invocation hooks on the Lambda handler thread, the user-function hooks on the
13+
``dex-handler`` worker that runs user code, and on a branch worker for each
14+
``map``/``parallel`` branch. ``ContextVar.reset()`` only accepts a token
15+
created in the same ``contextvars.Context``, so each thread keeps its own
16+
stack and only ever detaches its own tokens.
17+
* **Detach order matters.** Unlike OpenTelemetry Java's ``Scope.close()`` --
18+
which ignores a close that does not represent the current context --
19+
``ContextVar.reset()`` unconditionally writes back the token's captured value.
20+
Detaching out of order therefore *revives* a stale context instead of failing
21+
safe. The stack is module level rather than per plugin instance so that two
22+
plugins attaching on the same thread (both ship as separate entry points and
23+
can be enabled together) still unwind in true LIFO order.
24+
25+
Scopes are keyed by ``(owner, key)`` so a plugin instance can pop the exact
26+
scope it pushed, while :func:`exit_scope` still unwinds anything stacked above
27+
it. Nothing here raises: a plugin must never break an execution over
28+
observability bookkeeping.
29+
"""
30+
31+
from __future__ import annotations
32+
33+
import logging
34+
import threading
35+
from dataclasses import dataclass
36+
from typing import TYPE_CHECKING, Any
37+
38+
39+
if TYPE_CHECKING:
40+
from contextvars import Token
41+
42+
from opentelemetry.context import Context
43+
44+
45+
logger = logging.getLogger(__name__)
46+
47+
48+
@dataclass(slots=True)
49+
class _Entry:
50+
"""One attached scope: who pushed it, under what key, and its token."""
51+
52+
owner_id: int
53+
key: str
54+
epoch: int
55+
token: Token[Context]
56+
57+
58+
class _ThreadState(threading.local):
59+
"""Per-thread LIFO stack of attached scopes."""
60+
61+
def __init__(self) -> None:
62+
self.entries: list[_Entry] = []
63+
64+
65+
_state = _ThreadState()
66+
67+
68+
def _detach(entry: _Entry) -> None:
69+
"""Detach one entry, swallowing any failure."""
70+
from opentelemetry import context as otel_context
71+
72+
try:
73+
otel_context.detach(entry.token)
74+
except Exception: # noqa: BLE001 - observability must not break execution
75+
logger.debug("Failed to detach OTel context scope %s", entry.key, exc_info=True)
76+
77+
78+
def enter_scope(owner: Any, key: str, context: Context, epoch: int = 0) -> None:
79+
"""Attach ``context`` on this thread and remember how to restore it.
80+
81+
Any scope still on this thread's stack from an earlier ``epoch`` is unwound
82+
first. That covers the paths where a paired pop never runs: the SDK re-raises
83+
``SuspendExecution`` without calling ``on_user_function_end``, so a suspended
84+
operation leaves its scope attached, and a reused thread would otherwise
85+
inherit it.
86+
87+
Args:
88+
owner: The plugin instance pushing the scope.
89+
key: Registry key for the scope, unique per owner (operation or attempt).
90+
context: The context to attach.
91+
epoch: The owner's invocation counter; scopes from older epochs are
92+
discarded before the new scope is pushed.
93+
"""
94+
from opentelemetry import context as otel_context
95+
96+
owner_id = id(owner)
97+
_discard_stale(owner_id, epoch)
98+
try:
99+
token = otel_context.attach(context)
100+
except Exception: # noqa: BLE001
101+
logger.debug("Failed to attach OTel context scope %s", key, exc_info=True)
102+
return
103+
_state.entries.append(_Entry(owner_id=owner_id, key=key, epoch=epoch, token=token))
104+
105+
106+
def exit_scope(owner: Any, key: str) -> None:
107+
"""Detach the scope ``owner`` pushed under ``key``, restoring what preceded it.
108+
109+
Scopes stacked above the target are detached first so the underlying
110+
``ContextVar`` is always reset in LIFO order. A key this thread never pushed
111+
is a no-op -- the scope belongs to another thread (or was already unwound),
112+
and detaching someone else's token would corrupt the context.
113+
"""
114+
owner_id = id(owner)
115+
index = _find_last(owner_id, key)
116+
if index is None:
117+
return
118+
for entry in reversed(_state.entries[index:]):
119+
_detach(entry)
120+
del _state.entries[index:]
121+
122+
123+
def unwind(owner: Any) -> None:
124+
"""Detach every scope ``owner`` still holds on this thread, newest first.
125+
126+
Called at invocation end so the handler thread is left exactly as the plugin
127+
found it. Scopes this owner pushed on *other* threads cannot be detached from
128+
here; those threads are created per invocation and their context dies with
129+
them.
130+
"""
131+
owner_id = id(owner)
132+
index = _find_first(owner_id)
133+
if index is None:
134+
return
135+
for entry in reversed(_state.entries[index:]):
136+
_detach(entry)
137+
del _state.entries[index:]
138+
139+
140+
def depth(owner: Any | None = None) -> int:
141+
"""Return the number of scopes attached on this thread (for tests)."""
142+
if owner is None:
143+
return len(_state.entries)
144+
owner_id = id(owner)
145+
return sum(1 for entry in _state.entries if entry.owner_id == owner_id)
146+
147+
148+
def _discard_stale(owner_id: int, epoch: int) -> None:
149+
"""Unwind this owner's scopes left over from a previous epoch."""
150+
index = next(
151+
(
152+
position
153+
for position, entry in enumerate(_state.entries)
154+
if entry.owner_id == owner_id and entry.epoch != epoch
155+
),
156+
None,
157+
)
158+
if index is None:
159+
return
160+
for entry in reversed(_state.entries[index:]):
161+
_detach(entry)
162+
del _state.entries[index:]
163+
164+
165+
def _find_last(owner_id: int, key: str) -> int | None:
166+
"""Index of this owner's most recent scope for ``key``, if any."""
167+
for position in range(len(_state.entries) - 1, -1, -1):
168+
entry = _state.entries[position]
169+
if entry.owner_id == owner_id and entry.key == key:
170+
return position
171+
return None
172+
173+
174+
def _find_first(owner_id: int) -> int | None:
175+
"""Index of this owner's oldest scope, if any."""
176+
for position, entry in enumerate(_state.entries):
177+
if entry.owner_id == owner_id:
178+
return position
179+
return None

packages/aws-durable-execution-sdk-python-otel/src/aws_durable_execution_sdk_python_otel/execution_plugin.py

Lines changed: 50 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -51,6 +51,7 @@
5151
Tracer,
5252
)
5353

54+
from aws_durable_execution_sdk_python_otel import context_scope
5455
from aws_durable_execution_sdk_python_otel.context_extractors import (
5556
ContextExtractor,
5657
xray_context_extractor,
@@ -143,6 +144,9 @@ def __init__(self, config: OtelPluginConfig | None = None) -> None:
143144
self._invocation_span: Span | None = None
144145
self._operation_spans: dict[str, Span] = {}
145146
self._lock = threading.RLock()
147+
# Bumped every invocation. context_scope uses it to discard scopes a
148+
# previous invocation left attached on a reused thread.
149+
self._epoch = 0
146150

147151
if self._config.enrich_logger:
148152
install_log_filter(self)
@@ -168,6 +172,17 @@ def _pop_span(self, key: str) -> Span | None:
168172
def _attempt_key(info: UserFunctionStartInfo | UserFunctionEndInfo) -> str:
169173
return f"{info.operation_id}:attempt:{info.attempt or 1}"
170174

175+
@classmethod
176+
def _scope_key(cls, info: UserFunctionStartInfo | UserFunctionEndInfo) -> str:
177+
"""Return the context-scope key for a user-function hook pair.
178+
179+
Mirrors the span registry key so the scope pushed by
180+
``on_user_function_start`` is the one ``on_user_function_end`` pops.
181+
"""
182+
if info.operation_type is OperationType.STEP:
183+
return cls._attempt_key(info)
184+
return info.operation_id
185+
171186
def get_current_span_context(self) -> SpanContext | None:
172187
"""Return the active span context for log correlation (see log_filter)."""
173188
span_context = trace.get_current_span().get_span_context()
@@ -204,6 +219,7 @@ def _resolve_parent(self, parent_id: str | None) -> Span | None:
204219
# ------------------------------------------------------------------
205220
def on_invocation_start(self, info: InvocationStartInfo) -> None:
206221
logger.debug("Durable invocation started: %s", info)
222+
self._epoch += 1
207223
self._execution_arn = info.execution_arn or ""
208224
self._extracted_context = self._context_extractor(info)
209225
self._id_generator.set_trace_id(self._execution_arn, info.execution_start_time)
@@ -213,12 +229,16 @@ def on_invocation_start(self, info: InvocationStartInfo) -> None:
213229
# is parented to the ambient Lambda invocation span.
214230
self._start_invocation_span(info)
215231

216-
# Make the Workflow span the active span so auto-instrumented spans
217-
# created during the invocation become its children.
218-
if self._workflow_span is not None:
219-
otel_context.attach(
220-
trace.set_span_in_context(self._workflow_span, self._extracted_context)
221-
)
232+
# No context is attached here. Nothing on this thread needs it: user code
233+
# runs on a separate worker (ThreadPoolExecutor does not copy
234+
# contextvars), so an attach here would never reach it, while the Lambda
235+
# handler thread is reused across warm invocations -- an unpaired attach
236+
# would leak an ended span into the next execution, whose context
237+
# extractor and ambient-parent lookup would then adopt it and merge two
238+
# executions into one trace. The Workflow and Invocation spans are used
239+
# as explicit parents instead (see _resolve_parent), matching the Java
240+
# plugins, which never make either span current. Log correlation for this
241+
# thread resolves through get_current_span_context().
222242

223243
def _start_workflow_span(self, info: InvocationStartInfo) -> None:
224244
if not self._execution_arn:
@@ -329,6 +349,13 @@ def on_invocation_end(self, info: InvocationEndInfo) -> None:
329349
logger.exception("force_flush failed at invocation end")
330350

331351
def _reset_state(self) -> None:
352+
# Detach anything this plugin still holds on this thread so the handler
353+
# thread is left exactly as it was found. Scopes attached on the
354+
# per-invocation worker threads cannot be detached from here (a token is
355+
# only resettable in the context that created it); those threads are
356+
# destroyed with the invocation, and any scope a suspended operation left
357+
# behind is discarded by the epoch check on the next enter_scope.
358+
context_scope.unwind(self)
332359
self._execution_arn = ""
333360
self._extracted_context = None
334361
self._workflow_span = None
@@ -455,14 +482,30 @@ def on_user_function_start(self, info: UserFunctionStartInfo) -> None:
455482
parent=parent,
456483
start_time=info.start_time,
457484
)
458-
otel_context.attach(trace.set_span_in_context(span, self._extracted_context))
485+
# Attach on this worker thread so auto-instrumented calls made by the
486+
# user function become children of this span. The scope is pushed onto
487+
# whatever is already current (rather than replacing it with
488+
# _extracted_context) so an ambient context on this thread survives; the
489+
# span's own parent was chosen explicitly in _start_span.
490+
context_scope.enter_scope(
491+
self,
492+
self._scope_key(info),
493+
trace.set_span_in_context(span, otel_context.get_current()),
494+
epoch=self._epoch,
495+
)
459496

460497
def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
461498
logger.debug("Durable user function ended: %s", info)
462499
if info.operation_type not in (OperationType.CONTEXT, OperationType.STEP):
463500
raise RuntimeError(
464501
"on_user_function_end only supports CONTEXT and STEP operations"
465502
)
503+
# Detach first, on the same thread that attached, so the context this
504+
# operation was entered from is restored exactly. Detaching (rather than
505+
# attaching the enclosing span again) is what keeps the scopes balanced:
506+
# a nested operation lands back on its parent's still-attached scope, and
507+
# a top-level one lands back on the thread's ambient context.
508+
context_scope.exit_scope(self, self._scope_key(info))
466509
key = (
467510
self._attempt_key(info)
468511
if info.operation_type is OperationType.STEP
@@ -496,17 +539,6 @@ def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
496539
if popped is not None:
497540
popped.end(end_time=_to_otel_timestamp(end_time))
498541

499-
# Restore the enclosing span as active (parent op, else invocation/workflow).
500-
enclosing = (
501-
self._get_span(info.parent_id)
502-
or self._invocation_span
503-
or self._workflow_span
504-
)
505-
if enclosing is not None:
506-
otel_context.attach(
507-
trace.set_span_in_context(enclosing, self._extracted_context)
508-
)
509-
510542
# ------------------------------------------------------------------
511543
# Attributes
512544
# ------------------------------------------------------------------

0 commit comments

Comments
 (0)