Skip to content

Commit 7bf83c4

Browse files
author
Alex Wang
committed
fix(otel): balance otel context attach and detach
- Track every context.attach() token in the plugin and release it at the matching lifecycle end: user-function scopes in on_user_function_end, the invocation scope during invocation cleanup - Replace the re-attach of the enclosing span in on_user_function_end with a detach, so nested operations manage a balanced scope instead of stacking a new one - Release scopes still open at invocation end (a suspended user function or an aborted invocation) so nothing survives into a warm invocation - Skip tokens recorded on another thread, which OpenTelemetry cannot reset - Replace the autouse OTel context reset in the plugin tests with an assertion that each test leaves the context as it found it, and cover nested child contexts, sequential steps, failures, suspension, and warm invocation reuse Resolves #643
1 parent 20e1f84 commit 7bf83c4

6 files changed

Lines changed: 610 additions & 75 deletions

File tree

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

Lines changed: 71 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,11 @@
1717
- context is attached inside the synchronous ``on_user_function_*`` hooks and
1818
log correlation is handled by :mod:`log_filter`), the hook wiring mirrors the
1919
existing :class:`~aws_durable_execution_sdk_python_otel.invocation_plugin.InvocationOtelPlugin`.
20+
21+
Every context the plugin attaches is tracked by its token and detached at the
22+
matching lifecycle end: a user-function scope is released in
23+
``on_user_function_end`` and the invocation scope in ``on_invocation_end``, so
24+
the plugin never leaves an ended or suspended span current.
2025
"""
2126

2227
from __future__ import annotations
@@ -75,6 +80,9 @@
7580
# Registry key for the invocation span (operations use their operation_id).
7681
_INVOCATION_KEY = "__invocation__"
7782

83+
# Token key for the invocation-level context scope attached at invocation start.
84+
_INVOCATION_CONTEXT_KEY = "__invocation_context__"
85+
7886

7987
def _to_otel_timestamp(dt: datetime.datetime | None) -> int | None:
8088
"""Convert a datetime to an OTel timestamp (ns since epoch), or None."""
@@ -114,6 +122,11 @@ def __init__(self, config: OtelPluginConfig | None = None) -> None:
114122
self._workflow_span: Span | None = None
115123
self._invocation_span: Span | None = None
116124
self._operation_spans: dict[str, Span] = {}
125+
# Tokens returned by context.attach(), keyed by the span registry key,
126+
# paired with the thread that attached them. Every attach the plugin
127+
# owns is released through _detach_context so the plugin never leaves a
128+
# scope on the context stack.
129+
self._context_tokens: dict[str, tuple[int, object]] = {}
117130
self._lock = threading.RLock()
118131
self._tracing_enabled = False
119132

@@ -157,6 +170,46 @@ def _pop_span(self, key: str) -> Span | None:
157170
def _attempt_key(info: UserFunctionStartInfo | UserFunctionEndInfo) -> str:
158171
return f"{info.operation_id}:attempt:{info.attempt or 1}"
159172

173+
# ------------------------------------------------------------------
174+
# Context scope helpers
175+
# ------------------------------------------------------------------
176+
def _attach_context(self, key: str, new_context: Context) -> None:
177+
"""Attach a context and remember its token under ``key``."""
178+
with self._lock:
179+
self._context_tokens[key] = (
180+
threading.get_ident(),
181+
otel_context.attach(new_context),
182+
)
183+
184+
def _detach_context(self, key: str) -> None:
185+
"""Detach the context attached under ``key``, restoring its predecessor.
186+
187+
A context token can only be reset on the thread that created it, so a
188+
token recorded on another thread is dropped instead of detached (OTel
189+
logs an error for a cross-thread reset). In practice the pairs always
190+
line up: invocation hooks run on the Lambda handler thread and
191+
user-function hooks run on the thread executing user code.
192+
"""
193+
with self._lock:
194+
entry = self._context_tokens.pop(key, None)
195+
if entry is None:
196+
return
197+
thread_ident, token = entry
198+
if thread_ident == threading.get_ident():
199+
otel_context.detach(token) # type: ignore[arg-type]
200+
201+
def _detach_remaining_contexts(self) -> None:
202+
"""Release scopes still open, newest first, so nothing outlives the plugin.
203+
204+
Reached when a lifecycle end hook never fires -- for example a user
205+
function that suspends, or a warm invocation that starts before the
206+
previous one was cleaned up.
207+
"""
208+
with self._lock:
209+
keys = list(reversed(self._context_tokens))
210+
for key in keys:
211+
self._detach_context(key)
212+
160213
def get_current_span_context(self) -> SpanContext | None:
161214
"""Return the active span context for log correlation (see log_filter)."""
162215
span_context = trace.get_current_span().get_span_context()
@@ -225,10 +278,13 @@ def on_invocation_start(self, info: InvocationStartInfo) -> None:
225278
self._start_invocation_span(info)
226279

227280
# Make the Workflow span the active span so auto-instrumented spans
228-
# created during the invocation become its children.
281+
# created during the invocation become its children. The token is
282+
# released in _reset_state at invocation end, restoring the context that
283+
# was active before the invocation started.
229284
if self._workflow_span is not None:
230-
otel_context.attach(
231-
trace.set_span_in_context(self._workflow_span, self._extracted_context)
285+
self._attach_context(
286+
_INVOCATION_CONTEXT_KEY,
287+
trace.set_span_in_context(self._workflow_span, self._extracted_context),
232288
)
233289

234290
def _start_workflow_span(self, info: InvocationStartInfo) -> None:
@@ -324,6 +380,7 @@ def on_invocation_end(self, info: InvocationEndInfo) -> None:
324380
logger.exception("force_flush failed at invocation end")
325381

326382
def _reset_state(self) -> None:
383+
self._detach_remaining_contexts()
327384
self._execution_arn = ""
328385
self._execution_trace_id = None
329386
self._extracted_context = None
@@ -439,25 +496,29 @@ def on_user_function_start(self, info: UserFunctionStartInfo) -> None:
439496
info.parent_id
440497
)
441498
name = f"{info.name or info.operation_id} attempt {info.attempt or 1}"
499+
key = self._attempt_key(info)
442500
span = self._start_span(
443501
operation_id=info.operation_id,
444502
name=name,
445503
info=info,
446504
parent=parent,
447505
start_time=info.start_time,
448-
span_key=self._attempt_key(info),
506+
span_key=key,
449507
deterministic=False,
450508
)
451509
else: # CONTEXT
452510
parent = self._resolve_parent(info.parent_id)
511+
key = info.operation_id
453512
span = self._start_span(
454513
operation_id=info.operation_id,
455514
name=info.name or info.operation_id,
456515
info=info,
457516
parent=parent,
458517
start_time=info.start_time,
459518
)
460-
otel_context.attach(trace.set_span_in_context(span, self._extracted_context))
519+
self._attach_context(
520+
key, trace.set_span_in_context(span, self._extracted_context)
521+
)
461522

462523
def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
463524
logger.debug("Durable user function ended: %s", info)
@@ -500,16 +561,11 @@ def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
500561
if popped is not None:
501562
popped.end(end_time=_to_otel_timestamp(end_time))
502563

503-
# Restore the enclosing span as active (parent op, else invocation/workflow).
504-
enclosing = (
505-
self._get_span(info.parent_id)
506-
or self._invocation_span
507-
or self._workflow_span
508-
)
509-
if enclosing is not None:
510-
otel_context.attach(
511-
trace.set_span_in_context(enclosing, self._extracted_context)
512-
)
564+
# Restore the enclosing context by releasing the scope this user
565+
# function attached, so the parent operation (or, at the top level, the
566+
# context that was active before the operation) becomes current again
567+
# without stacking another scope.
568+
self._detach_context(key)
513569

514570
# ------------------------------------------------------------------
515571
# Attributes

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

Lines changed: 62 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -123,6 +123,11 @@ def __init__(self, config: OtelPluginConfig | None = None) -> None:
123123
self._workflow_span: Span | None = None
124124
# Maps operation ID (None for root) to the active span.
125125
self._operation_spans: dict[str | None, Span] = {}
126+
# Tokens returned by context.attach(), keyed by the span registry key,
127+
# paired with the thread that attached them. Every attach the plugin
128+
# owns is released through _detach_context so the plugin never leaves a
129+
# scope on the context stack.
130+
self._context_tokens: dict[str, tuple[int, object]] = {}
126131
self._operation_spans_lock = threading.RLock()
127132
self._tracing_enabled = False
128133

@@ -167,19 +172,62 @@ def _attempt_span_key(info: UserFunctionStartInfo | UserFunctionEndInfo) -> str:
167172
"""Return the registry key for a STEP attempt span."""
168173
return f"{info.operation_id}:attempt:{info.attempt or 1}"
169174

175+
# ------------------------------------------------------------------
176+
# Context scope helpers
177+
# ------------------------------------------------------------------
178+
def _attach_context(self, key: str, new_context: Context) -> None:
179+
"""Attach a context and remember its token under ``key``."""
180+
with self._operation_spans_lock:
181+
self._context_tokens[key] = (
182+
threading.get_ident(),
183+
context.attach(new_context),
184+
)
185+
186+
def _detach_context(self, key: str) -> None:
187+
"""Detach the context attached under ``key``, restoring its predecessor.
188+
189+
A context token can only be reset on the thread that created it, so a
190+
token recorded on another thread is dropped instead of detached (OTel
191+
logs an error for a cross-thread reset). In practice the pairs always
192+
line up: user-function hooks run on the thread executing user code, and
193+
both the start and end hook for one attempt run on that same thread.
194+
"""
195+
with self._operation_spans_lock:
196+
entry = self._context_tokens.pop(key, None)
197+
if entry is None:
198+
return
199+
thread_ident, token = entry
200+
if thread_ident == threading.get_ident():
201+
context.detach(token) # type: ignore[arg-type]
202+
203+
def _detach_remaining_contexts(self) -> None:
204+
"""Release scopes still open, newest first, so nothing outlives the plugin.
205+
206+
Reached when a lifecycle end hook never fires -- for example a user
207+
function that suspends, or a warm invocation that starts before the
208+
previous one was cleaned up.
209+
"""
210+
with self._operation_spans_lock:
211+
keys = list(reversed(self._context_tokens))
212+
for key in keys:
213+
self._detach_context(key)
214+
170215
def get_current_span_context(self) -> SpanContext | None:
171216
"""Return the span context to use for log correlation.
172217
173218
Resolution order:
174219
1. The span attached to the OTel thread-local context. Inside a step
175220
this is the active attempt span, and inside a child context this is
176221
the active context span (attached in
177-
on_user_function_start), and between operations it is the enclosing
178-
operation span (restored in on_user_function_end).
222+
on_user_function_start), and between the steps of a child context it
223+
is the enclosing context span, restored when on_user_function_end
224+
detaches the inner scope.
179225
2. The invocation span from the plugin registry. This is the path used
180226
for top-level handler code: the invocation span is never attached to
181227
the worker thread's context, so the registry is the only way to
182-
resolve it.
228+
resolve it. It also covers code between top-level operations, where
229+
detaching the operation scope restores a context with no durable
230+
span.
183231
184232
Returns:
185233
A valid SpanContext, or None if no span is active.
@@ -445,6 +493,7 @@ def on_invocation_end(self, info: InvocationEndInfo) -> None:
445493

446494
def _reset_state(self) -> None:
447495
"""Clear per-invocation state for warm Lambda environment reuse."""
496+
self._detach_remaining_contexts()
448497
self._execution_arn = ""
449498
self._execution_trace_id = None
450499
self._extracted_context = None
@@ -557,7 +606,9 @@ def on_user_function_start(self, info: UserFunctionStartInfo) -> None:
557606
span_key=span_key,
558607
deterministic_span_id=info.operation_type is not OperationType.STEP,
559608
)
560-
context.attach(trace.set_span_in_context(span, self._extracted_context))
609+
self._attach_context(
610+
span_key, trace.set_span_in_context(span, self._extracted_context)
611+
)
561612

562613
def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
563614
"""Called when a context or step operation finishes user code.
@@ -607,16 +658,13 @@ def on_user_function_end(self, info: UserFunctionEndInfo) -> None:
607658
if end_timestamp is not None and end_timestamp == info.start_time:
608659
end_timestamp += datetime.timedelta(microseconds=1)
609660
self._end_span(span_key, end_timestamp)
610-
# Restore the enclosing operation span as current so code that runs
611-
# after this operation (e.g. between steps in a child context)
612-
# correlates to its enclosing operation, not the operation that just
613-
# ended. For a top-level operation (parent_id is None) this is the
614-
# invocation span; for a nested operation it is the parent context span.
615-
parent_span = self._get_span(info.parent_id) or self._get_span(None)
616-
if parent_span:
617-
context.attach(
618-
trace.set_span_in_context(parent_span, self._extracted_context)
619-
)
661+
# Restore the enclosing context by releasing the scope this user
662+
# function attached. Code that runs after this operation (e.g. between
663+
# steps in a child context) correlates to its enclosing operation
664+
# again -- the parent context span for a nested operation, and the
665+
# context active before the operation for a top-level one, where
666+
# get_current_span_context falls back to the invocation span.
667+
self._detach_context(span_key)
620668

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

0 commit comments

Comments
 (0)