Skip to content

Commit 4e59e90

Browse files
author
Alex Wang
committed
fix(otel): balance context attach and detach
Both plugins called opentelemetry.context.attach() without keeping the returned token, and "restored" the enclosing span by attaching another context rather than detaching. Every operation pushed two context layers and popped none, leaving an ended span current after its scope had finished. The worst consequence: the invocation-start attach runs on the Lambda handler thread, which is reused across warm invocations, so the next execution's context extractor and GLOBAL-mode ambient-parent lookup adopted the previous execution's ended Workflow span. A valid parent overrides the deterministic ID generator's trace ID, so two unrelated durable executions merged into a single trace. Each attach now keeps its token, keyed the same way as the span registry, and the hook that pairs with it pops the scope: - on_invocation_start attaches; on_invocation_end detaches. - on_user_function_start attaches; on_user_function_end detaches, replacing the re-attach that stood in for restoring the enclosing context. - Anything still held when the invocation ends is swept, since the SDK re-raises SuspendExecution without calling on_user_function_end. A scope is only detached while it is still the current one. That mirrors OpenTelemetry Java's ScopeImpl.close(), which ignores a close that does not represent the current context, and it matters more in Python: ContextVar.reset writes back its captured value unconditionally, so an out-of-order or wrong-thread detach would revive a stale context instead of failing safe. A skipped detach keeps its entry so the owning thread can still undo it. 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, and the tests that drove hooks without completing the lifecycle now complete it. Adds coverage for warm invocation reuse keeping two executions in separate traces, a suspended operation's scope being swept, sequential steps not accumulating layers, exact restore on success and failure, nested child contexts, worker-thread confinement, and the identity guard skipping both out-of-order and cross-thread detaches.
1 parent c7b494e commit 4e59e90

8 files changed

Lines changed: 536 additions & 80 deletions

File tree

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

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -235,6 +235,12 @@ 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+
Between two operations the plugin holds no span current: the scope a step or child
239+
context attached is detached when that function returns. Log correlation is
240+
unaffected -- the filter resolves the trace context from the plugin's own span
241+
registry, so records emitted between operations still carry the invocation's
242+
`traceId` and `spanId`.
243+
238244
## Verification
239245

240246
After deploying your function with the plugin configured:

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

Lines changed: 92 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@
2323
import datetime
2424
import logging
2525
import threading
26+
from contextvars import Token
2627
from typing import Any
2728

2829
from aws_durable_execution_sdk_python.lambda_service import (
@@ -142,11 +143,70 @@ def __init__(self, config: OtelPluginConfig | None = None) -> None:
142143
self._workflow_span: Span | None = None
143144
self._invocation_span: Span | None = None
144145
self._operation_spans: dict[str, Span] = {}
146+
# Contexts this plugin has attached, keyed the same way as the span
147+
# registry, so each attach can be undone by the hook that pairs with it.
148+
self._scopes: dict[str, tuple[Token[Context], Context]] = {}
145149
self._lock = threading.RLock()
146150

147151
if self._config.enrich_logger:
148152
install_log_filter(self)
149153

154+
# ------------------------------------------------------------------
155+
# Context scopes
156+
# ------------------------------------------------------------------
157+
def _enter_scope(self, key: str, context: Context) -> None:
158+
"""Attach ``context`` and remember what is needed to restore it.
159+
160+
``otel_context.attach`` returns a token that is the only way to undo it,
161+
and the hook that attaches is not the hook that pops, so the token has to
162+
be kept. The context is kept alongside it for the identity check in
163+
:meth:`_exit_scope`.
164+
"""
165+
with self._lock:
166+
self._scopes[key] = (otel_context.attach(context), context)
167+
168+
def _exit_scope(self, key: str) -> None:
169+
"""Restore the context that preceded the scope attached under ``key``.
170+
171+
Only detaches when the scope being popped is still the current one. This
172+
mirrors OpenTelemetry Java's ``ScopeImpl.close()``, which ignores a close
173+
that does not represent the current context, and it matters more here:
174+
``ContextVar.reset`` writes back its captured value unconditionally, so an
175+
out-of-order or wrong-thread detach would *revive* a stale context instead
176+
of failing safe. Skipping leaves the layer attached, which is inert.
177+
"""
178+
with self._lock:
179+
entry = self._scopes.get(key)
180+
if entry is None:
181+
return
182+
token, context = entry
183+
if otel_context.get_current() is not context:
184+
# Not ours to pop right now: another scope is stacked above it, or
185+
# this is not the thread that attached it. The entry is left in
186+
# place so it can still be undone later -- discarding the token
187+
# here would strand the context permanently.
188+
logger.debug("Skipping out-of-scope OTel context detach for %s", key)
189+
return
190+
del self._scopes[key]
191+
try:
192+
otel_context.detach(token)
193+
except Exception: # noqa: BLE001 - observability must not break execution
194+
logger.debug("Failed to detach OTel context for %s", key, exc_info=True)
195+
196+
def _exit_all_scopes(self) -> None:
197+
"""Pop every scope this plugin still holds, newest first.
198+
199+
Reached when a hook that would have popped a scope never ran: the SDK
200+
re-raises ``SuspendExecution`` without calling ``on_user_function_end``.
201+
Scopes attached on another thread fail the identity check and are dropped
202+
without detaching; those threads are per-invocation and their context dies
203+
with them.
204+
"""
205+
with self._lock:
206+
keys = list(reversed(self._scopes))
207+
for key in keys:
208+
self._exit_scope(key)
209+
150210
# ------------------------------------------------------------------
151211
# Span registry helpers
152212
# ------------------------------------------------------------------
@@ -168,6 +228,17 @@ def _pop_span(self, key: str) -> Span | None:
168228
def _attempt_key(info: UserFunctionStartInfo | UserFunctionEndInfo) -> str:
169229
return f"{info.operation_id}:attempt:{info.attempt or 1}"
170230

231+
@classmethod
232+
def _scope_key(cls, info: UserFunctionStartInfo | UserFunctionEndInfo) -> str:
233+
"""Return the context-scope key for a user-function hook pair.
234+
235+
Mirrors the span registry key so the scope attached by
236+
``on_user_function_start`` is the one ``on_user_function_end`` pops.
237+
"""
238+
if info.operation_type is OperationType.STEP:
239+
return cls._attempt_key(info)
240+
return info.operation_id
241+
171242
def get_current_span_context(self) -> SpanContext | None:
172243
"""Return the active span context for log correlation (see log_filter)."""
173244
span_context = trace.get_current_span().get_span_context()
@@ -214,10 +285,16 @@ def on_invocation_start(self, info: InvocationStartInfo) -> None:
214285
self._start_invocation_span(info)
215286

216287
# Make the Workflow span the active span so auto-instrumented spans
217-
# created during the invocation become its children.
288+
# created during the invocation become its children. Paired with the
289+
# _exit_scope in on_invocation_end: this thread is the Lambda handler
290+
# thread, which is reused across warm invocations, so leaving it attached
291+
# let the next execution's context extractor and ambient-parent lookup
292+
# adopt this execution's ended Workflow span -- merging two unrelated
293+
# executions into one trace.
218294
if self._workflow_span is not None:
219-
otel_context.attach(
220-
trace.set_span_in_context(self._workflow_span, self._extracted_context)
295+
self._enter_scope(
296+
_INVOCATION_KEY,
297+
trace.set_span_in_context(self._workflow_span, self._extracted_context),
221298
)
222299

223300
def _start_workflow_span(self, info: InvocationStartInfo) -> None:
@@ -329,6 +406,9 @@ def on_invocation_end(self, info: InvocationEndInfo) -> None:
329406
logger.exception("force_flush failed at invocation end")
330407

331408
def _reset_state(self) -> None:
409+
# Undo the invocation scope, and anything a suspended operation left
410+
# behind, so the handler thread is returned to the state it was found in.
411+
self._exit_all_scopes()
332412
self._execution_arn = ""
333413
self._extracted_context = None
334414
self._workflow_span = None
@@ -455,14 +535,22 @@ def on_user_function_start(self, info: UserFunctionStartInfo) -> None:
455535
parent=parent,
456536
start_time=info.start_time,
457537
)
458-
otel_context.attach(trace.set_span_in_context(span, self._extracted_context))
538+
self._enter_scope(
539+
self._scope_key(info),
540+
trace.set_span_in_context(span, self._extracted_context),
541+
)
459542

460543
def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
461544
logger.debug("Durable user function ended: %s", info)
462545
if info.operation_type not in (OperationType.CONTEXT, OperationType.STEP):
463546
raise RuntimeError(
464547
"on_user_function_end only supports CONTEXT and STEP operations"
465548
)
549+
# Pop the scope this operation attached, restoring exactly what preceded
550+
# it. Detaching rather than attaching the enclosing span again is what
551+
# keeps this balanced: the previous code pushed a second context here, so
552+
# every operation added a layer and removed none.
553+
self._exit_scope(self._scope_key(info))
466554
key = (
467555
self._attempt_key(info)
468556
if info.operation_type is OperationType.STEP
@@ -496,17 +584,6 @@ def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
496584
if popped is not None:
497585
popped.end(end_time=_to_otel_timestamp(end_time))
498586

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-
510587
# ------------------------------------------------------------------
511588
# Attributes
512589
# ------------------------------------------------------------------

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

Lines changed: 83 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55
import datetime
66
import logging
77
import threading
8+
from contextvars import Token
89
from typing import Any
910

1011
from aws_durable_execution_sdk_python.lambda_service import (
@@ -167,6 +168,9 @@ def __init__(self, config: OtelPluginConfig | None = None) -> None:
167168
self._workflow_span: Span | None = None
168169
# Maps operation ID (None for root) to the active span.
169170
self._operation_spans: dict[str | None, Span] = {}
171+
# Contexts this plugin has attached, keyed the same way as the span
172+
# registry, so each attach can be undone by the hook that pairs with it.
173+
self._scopes: dict[str, tuple[Token[Context], Context]] = {}
170174
self._operation_spans_lock = threading.RLock()
171175

172176
if self._enrich_logger:
@@ -176,6 +180,59 @@ def __init__(self, config: OtelPluginConfig | None = None) -> None:
176180
# plugin is constructed), so the handlers are available here.
177181
install_log_filter(self)
178182

183+
def _enter_scope(self, key: str, context_to_attach: Context) -> None:
184+
"""Attach a context and remember what is needed to restore it.
185+
186+
``context.attach`` returns a token that is the only way to undo it, and
187+
the hook that attaches is not the hook that pops, so the token has to be
188+
kept. The context is kept alongside it for the identity check in
189+
:meth:`_exit_scope`.
190+
"""
191+
with self._operation_spans_lock:
192+
self._scopes[key] = (context.attach(context_to_attach), context_to_attach)
193+
194+
def _exit_scope(self, key: str) -> None:
195+
"""Restore the context that preceded the scope attached under ``key``.
196+
197+
Only detaches when the scope being popped is still the current one. This
198+
mirrors OpenTelemetry Java's ``ScopeImpl.close()``, which ignores a close
199+
that does not represent the current context, and it matters more here:
200+
``ContextVar.reset`` writes back its captured value unconditionally, so an
201+
out-of-order or wrong-thread detach would *revive* a stale context instead
202+
of failing safe. Skipping leaves the layer attached, which is inert.
203+
"""
204+
with self._operation_spans_lock:
205+
entry = self._scopes.get(key)
206+
if entry is None:
207+
return
208+
token, attached = entry
209+
if context.get_current() is not attached:
210+
# Not ours to pop right now: another scope is stacked above it, or
211+
# this is not the thread that attached it. The entry is left in
212+
# place so it can still be undone later -- discarding the token
213+
# here would strand the context permanently.
214+
logger.debug("Skipping out-of-scope OTel context detach for %s", key)
215+
return
216+
del self._scopes[key]
217+
try:
218+
context.detach(token)
219+
except Exception: # noqa: BLE001 - observability must not break execution
220+
logger.debug("Failed to detach OTel context for %s", key, exc_info=True)
221+
222+
def _exit_all_scopes(self) -> None:
223+
"""Pop every scope this plugin still holds, newest first.
224+
225+
Reached when a hook that would have popped a scope never ran: the SDK
226+
re-raises ``SuspendExecution`` without calling ``on_user_function_end``.
227+
Scopes attached on another thread fail the identity check and are dropped
228+
without detaching; those threads are per-invocation and their context dies
229+
with them.
230+
"""
231+
with self._operation_spans_lock:
232+
keys = list(reversed(self._scopes))
233+
for key in keys:
234+
self._exit_scope(key)
235+
179236
def _set_span(self, operation_id: str | None, span: Span) -> None:
180237
"""Register the active span for an operation ID."""
181238
with self._operation_spans_lock:
@@ -196,6 +253,17 @@ def _attempt_span_key(info: UserFunctionStartInfo | UserFunctionEndInfo) -> str:
196253
"""Return the registry key for a STEP attempt span."""
197254
return f"{info.operation_id}:attempt:{info.attempt or 1}"
198255

256+
@classmethod
257+
def _scope_key(cls, info: UserFunctionStartInfo | UserFunctionEndInfo) -> str:
258+
"""Return the context-scope key for a user-function hook pair.
259+
260+
Mirrors the span registry key so the scope attached by
261+
``on_user_function_start`` is the one ``on_user_function_end`` pops.
262+
"""
263+
if info.operation_type is OperationType.STEP:
264+
return cls._attempt_span_key(info)
265+
return info.operation_id
266+
199267
def get_current_span_context(self) -> SpanContext | None:
200268
"""Return the span context to use for log correlation.
201269
@@ -453,6 +521,10 @@ def on_invocation_end(self, info: InvocationEndInfo) -> None:
453521
self._workflow_span.set_status(StatusCode.OK)
454522
self._workflow_span.end()
455523

524+
# Undo anything a suspended operation left attached, so no scope outlives
525+
# the invocation that created it.
526+
self._exit_all_scopes()
527+
456528
# Clear all per-invocation state to prevent leaks across warm Lambda reuses
457529
self._execution_arn = ""
458530
self._extracted_context = None
@@ -562,7 +634,10 @@ def on_user_function_start(self, info: UserFunctionStartInfo) -> None:
562634
span_key=span_key,
563635
deterministic_span_id=info.operation_type is not OperationType.STEP,
564636
)
565-
context.attach(trace.set_span_in_context(span, self._extracted_context))
637+
self._enter_scope(
638+
self._scope_key(info),
639+
trace.set_span_in_context(span, self._extracted_context),
640+
)
566641

567642
def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
568643
"""Called when a context or step operation finishes user code.
@@ -578,6 +653,13 @@ def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
578653
raise RuntimeError(
579654
"on_user_function_end should only be called for CONTEXT and STEP operations"
580655
)
656+
# Pop the scope this operation attached, restoring exactly what preceded
657+
# it. Detaching rather than attaching the enclosing span again is what
658+
# keeps this balanced: the previous code pushed a second context here, so
659+
# every operation added a layer and removed none. Between operations the
660+
# log filter resolves through the span registry (see
661+
# get_current_span_context), so correlation is unaffected.
662+
self._exit_scope(self._scope_key(info))
581663
# key = f"{info.operation_id}-{int(info.start_time.timestamp())}"
582664
span_key = (
583665
self._attempt_span_key(info)
@@ -610,16 +692,6 @@ def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
610692
if end_timestamp is not None and end_timestamp == info.start_time:
611693
end_timestamp += datetime.timedelta(microseconds=1)
612694
self._end_span(span_key, end_timestamp)
613-
# Restore the enclosing operation span as current so code that runs
614-
# after this operation (e.g. between steps in a child context)
615-
# correlates to its enclosing operation, not the operation that just
616-
# ended. For a top-level operation (parent_id is None) this is the
617-
# invocation span; for a nested operation it is the parent context span.
618-
parent_span = self._get_span(info.parent_id) or self._get_span(None)
619-
if parent_span:
620-
context.attach(
621-
trace.set_span_in_context(parent_span, self._extracted_context)
622-
)
623695

624696
def _extract_attributes(self, info: Any) -> _SpanAttributes:
625697
"""Extract durable execution fields as OpenTelemetry span attributes.

0 commit comments

Comments
 (0)