Skip to content

Commit c79cfda

Browse files
author
Alex Wang
committed
fix(otel): address review on context scopes
Three review findings, all real: Same-invocation re-entry. The epoch check only caught a previous invocation's leftovers, but the same operation key can be entered twice inside one invocation: a suspended operation is re-entered when its branch is resubmitted, and its first scope is still attached because the suspending path has no end hook. The second enter stacked on the first and the end hook popped one, leaving a stale layer per re-entry. enter_scope now unwinds an existing (owner, key) even when the epoch matches. Extracted context values. Basing every scope on the current context dropped baggage and other non-span values supplied by the context extractor, because the worker running user code starts with an empty context. The outermost scope on a thread is now layered onto the extracted context; nested scopes keep using the current one, which already carries it transitively. Ambient span vs durable span. In GLOBAL mode the ADOT Lambda span stays current on the handler thread, so get_current_span_context returned it instead of the Invocation span, contradicting what the previous commit documented. The current span is now trusted only while this plugin holds a scope on this thread; otherwise the registry answers. The earlier test missed this by using an explicit provider with no ambient span. Adds the tests each finding asked for: same-key re-entry at the helper level and through the plugin hooks on a worker thread, baggage surviving into user code and into a nested scope, and a GLOBAL-mode ambient Lambda span not displacing the Invocation span in log records.
1 parent 6b72aa7 commit c79cfda

5 files changed

Lines changed: 246 additions & 29 deletions

File tree

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

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -95,6 +95,7 @@ def enter_scope(owner: Any, key: str, context: Context, epoch: int = 0) -> None:
9595

9696
owner_id = id(owner)
9797
_discard_stale(owner_id, epoch)
98+
_discard_reentered(owner_id, key)
9899
try:
99100
token = otel_context.attach(context)
100101
except Exception: # noqa: BLE001
@@ -145,6 +146,32 @@ def depth(owner: Any | None = None) -> int:
145146
return sum(1 for entry in _state.entries if entry.owner_id == owner_id)
146147

147148

149+
def _discard_reentered(owner_id: int, key: str) -> None:
150+
"""Unwind a scope this owner already holds under ``key`` on this thread.
151+
152+
The epoch check only catches a *previous invocation's* leftovers. The same
153+
operation key can also be entered twice inside one invocation: a suspended
154+
operation is re-entered when its branch is resubmitted, and its first scope
155+
is still attached because the suspending path had no end hook to pop it.
156+
Without this, the second enter would stack on the first and the eventual end
157+
hook -- which pops one scope -- would leave the original attached, one stale
158+
layer per re-entry.
159+
"""
160+
index = next(
161+
(
162+
position
163+
for position, entry in enumerate(_state.entries)
164+
if entry.owner_id == owner_id and entry.key == key
165+
),
166+
None,
167+
)
168+
if index is None:
169+
return
170+
for entry in reversed(_state.entries[index:]):
171+
_detach(entry)
172+
del _state.entries[index:]
173+
174+
148175
def _discard_stale(owner_id: int, epoch: int) -> None:
149176
"""Unwind this owner's scopes left over from a previous epoch."""
150177
index = next(

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

Lines changed: 37 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -183,11 +183,40 @@ def _scope_key(cls, info: UserFunctionStartInfo | UserFunctionEndInfo) -> str:
183183
return cls._attempt_key(info)
184184
return info.operation_id
185185

186+
def _scope_base_context(self) -> Context:
187+
"""Return the context a new operation scope should be layered onto.
188+
189+
For the outermost durable scope on a thread, the extracted upstream
190+
context is the base: user code runs on a worker whose context starts
191+
empty, so anything the context extractor supplied -- a remote parent,
192+
baggage -- would be dropped by using the current context there, and
193+
downstream propagation inside steps would lose it.
194+
195+
For a nested scope the current context already carries that extracted
196+
context transitively, via the enclosing scope, so it is used as the base
197+
to preserve whatever ran in between (ambient spans, baggage added by user
198+
code).
199+
"""
200+
if context_scope.depth(self) > 0:
201+
return otel_context.get_current()
202+
return self._extracted_context or otel_context.get_current()
203+
186204
def get_current_span_context(self) -> SpanContext | None:
187-
"""Return the active span context for log correlation (see log_filter)."""
188-
span_context = trace.get_current_span().get_span_context()
189-
if span_context and span_context.is_valid:
190-
return span_context
205+
"""Return the active span context for log correlation (see log_filter).
206+
207+
The current span is used only while this plugin holds an operation scope
208+
on this thread -- inside a step or child context, where the current span
209+
is the one this plugin attached. Otherwise the registry is used, so a
210+
record emitted between operations, or on the handler thread, correlates to
211+
the durable Invocation span rather than to whatever else happens to be
212+
current. That distinction matters in GLOBAL (ADOT) mode: the ambient
213+
Lambda span is current on the handler thread and would otherwise be
214+
reported in place of the durable span.
215+
"""
216+
if context_scope.depth(self) > 0:
217+
span_context = trace.get_current_span().get_span_context()
218+
if span_context and span_context.is_valid:
219+
return span_context
191220
for candidate in (self._invocation_span, self._workflow_span):
192221
if candidate is not None:
193222
ctx = candidate.get_span_context()
@@ -483,14 +512,13 @@ def on_user_function_start(self, info: UserFunctionStartInfo) -> None:
483512
start_time=info.start_time,
484513
)
485514
# 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.
515+
# user function become children of this span. The span's own parent was
516+
# chosen explicitly in _start_span; this only sets what is ambient while
517+
# the user function runs.
490518
context_scope.enter_scope(
491519
self,
492520
self._scope_key(info),
493-
trace.set_span_in_context(span, otel_context.get_current()),
521+
trace.set_span_in_context(span, self._scope_base_context()),
494522
epoch=self._epoch,
495523
)
496524

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

Lines changed: 38 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -211,28 +211,48 @@ def _scope_key(cls, info: UserFunctionStartInfo | UserFunctionEndInfo) -> str:
211211
return cls._attempt_span_key(info)
212212
return info.operation_id
213213

214+
def _scope_base_context(self) -> Context:
215+
"""Return the context a new operation scope should be layered onto.
216+
217+
For the outermost durable scope on a thread, the extracted upstream
218+
context is the base: user code runs on a worker whose context starts
219+
empty, so anything the context extractor supplied -- a remote parent,
220+
baggage -- would be dropped by using the current context there, and
221+
downstream propagation inside steps would lose it.
222+
223+
For a nested scope the current context already carries that extracted
224+
context transitively, via the enclosing scope, so it is used as the base
225+
to preserve whatever ran in between (ambient spans, baggage added by user
226+
code).
227+
"""
228+
if context_scope.depth(self) > 0:
229+
return context.get_current()
230+
return self._extracted_context or context.get_current()
231+
214232
def get_current_span_context(self) -> SpanContext | None:
215233
"""Return the span context to use for log correlation.
216234
217235
Resolution order:
218-
1. The span attached to the OTel thread-local context. Inside a step
219-
this is the active attempt span, and inside a child context this is
220-
the active context span (attached in on_user_function_start). After a
221-
nested operation ends, its scope is detached and the enclosing child
222-
context span -- still attached -- becomes current again.
223-
2. The invocation span from the plugin registry. This is the path used
224-
for top-level handler code: the invocation span is never attached to
225-
any thread's context, so the registry is the only way to resolve it.
226-
It also covers code that runs between top-level operations, where
227-
detaching the operation scope leaves the thread's ambient context
228-
current.
236+
1. The span attached to the OTel thread-local context, but only while this
237+
plugin holds an operation scope on this thread. Inside a step that is
238+
the active attempt span, and inside a child context the active context
239+
span. After a nested operation ends, its scope is detached and the
240+
enclosing child context span -- still attached -- becomes current
241+
again.
242+
2. The invocation span from the plugin registry. This covers top-level
243+
handler code (the invocation span is never attached to any thread's
244+
context) and code between top-level operations. Gating step 1 on an
245+
owned scope matters in GLOBAL (ADOT) mode: the ambient Lambda span is
246+
current on the handler thread and would otherwise be reported in place
247+
of the durable span.
229248
230249
Returns:
231250
A valid SpanContext, or None if no span is active.
232251
"""
233-
span_context = trace.get_current_span().get_span_context()
234-
if span_context and span_context.is_valid:
235-
return span_context
252+
if context_scope.depth(self) > 0:
253+
span_context = trace.get_current_span().get_span_context()
254+
if span_context and span_context.is_valid:
255+
return span_context
236256

237257
invocation_span = self._get_span(None)
238258
if invocation_span:
@@ -588,14 +608,13 @@ def on_user_function_start(self, info: UserFunctionStartInfo) -> None:
588608
deterministic_span_id=info.operation_type is not OperationType.STEP,
589609
)
590610
# Attach on this worker thread so auto-instrumented calls made by the
591-
# user function become children of this span. The scope is pushed onto
592-
# whatever is already current (rather than replacing it with
593-
# _extracted_context) so an ambient context on this thread survives; the
594-
# span's own parent was chosen explicitly in _start_span.
611+
# user function become children of this span. The span's own parent was
612+
# chosen explicitly in _start_span; this only sets what is ambient while
613+
# the user function runs.
595614
context_scope.enter_scope(
596615
self,
597616
self._scope_key(info),
598-
trace.set_span_in_context(span, context.get_current()),
617+
trace.set_span_in_context(span, self._scope_base_context()),
599618
epoch=self._epoch,
600619
)
601620

packages/aws-durable-execution-sdk-python-otel/tests/test_context_scope.py

Lines changed: 103 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,7 @@
2525
UserFunctionOutcome,
2626
UserFunctionStartInfo,
2727
)
28-
from opentelemetry import trace
28+
from opentelemetry import baggage, trace
2929
from opentelemetry.context import Context
3030
from opentelemetry.sdk.trace import TracerProvider
3131
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
@@ -133,6 +133,42 @@ def test_exit_with_unknown_key_is_a_noop():
133133
assert context_scope.depth(owner) == 0
134134

135135

136+
def test_reentering_the_same_key_replaces_the_previous_scope():
137+
"""Re-entering a key inside one invocation must not stack a second scope.
138+
139+
A suspended operation is re-entered when its branch is resubmitted, and its
140+
first scope is still attached because the suspending path had no end hook to
141+
pop it. The epoch is unchanged, so only the same-key guard catches this.
142+
"""
143+
owner = _Owner()
144+
before = otel_context.get_current()
145+
146+
context_scope.enter_scope(owner, "wfc-1", _span_context("poll-1"), epoch=1)
147+
context_scope.enter_scope(owner, "wfc-1", _span_context("poll-2"), epoch=1)
148+
149+
assert context_scope.depth(owner) == 1
150+
151+
context_scope.exit_scope(owner, "wfc-1")
152+
assert otel_context.get_current() is before
153+
assert context_scope.depth(owner) == 0
154+
155+
156+
def test_reentry_guard_keeps_enclosing_scopes():
157+
"""Re-entering a nested key must not disturb the scope it is nested in."""
158+
owner = _Owner()
159+
context_scope.enter_scope(owner, "ctx", _span_context("ctx"), epoch=1)
160+
enclosing = otel_context.get_current()
161+
162+
context_scope.enter_scope(owner, "inner", _span_context("inner-1"), epoch=1)
163+
context_scope.enter_scope(owner, "inner", _span_context("inner-2"), epoch=1)
164+
165+
assert context_scope.depth(owner) == 2
166+
context_scope.exit_scope(owner, "inner")
167+
assert otel_context.get_current() is enclosing
168+
169+
context_scope.exit_scope(owner, "ctx")
170+
171+
136172
def test_enter_discards_scopes_from_a_previous_epoch():
137173
"""A scope a suspended operation left behind must not outlive its invocation.
138174
@@ -347,6 +383,72 @@ def run_step() -> None:
347383
plugin.on_invocation_end(_invocation_end())
348384

349385

386+
@pytest.mark.parametrize("factory", [_execution_plugin, _invocation_plugin])
387+
def test_extracted_context_values_reach_user_code_on_a_worker_thread(factory):
388+
"""Values from the context extractor must be current inside user code.
389+
390+
The worker running user code starts with an empty context, so the outermost
391+
durable scope has to be layered onto the extracted context -- otherwise
392+
baggage and any other non-span values the extractor supplied are dropped and
393+
downstream instrumentation inside the step cannot propagate them.
394+
"""
395+
plugin, _ = factory()
396+
# An extractor that supplies baggage, as a propagator-based one would.
397+
plugin._context_extractor = lambda _info: baggage.set_baggage(
398+
"tenant", "acme", context=Context()
399+
)
400+
plugin.on_invocation_start(_invocation_start())
401+
observed: dict[str, object] = {}
402+
403+
def run_step() -> None:
404+
plugin.on_user_function_start(_step_start("step-1"))
405+
observed["inside"] = baggage.get_baggage("tenant")
406+
# A nested scope keeps it too, since it layers onto the current context.
407+
plugin.on_user_function_start(_step_start("step-2"))
408+
observed["nested"] = baggage.get_baggage("tenant")
409+
plugin.on_user_function_end(_step_end("step-2"))
410+
plugin.on_user_function_end(_step_end("step-1"))
411+
412+
with ThreadPoolExecutor(max_workers=1) as executor:
413+
executor.submit(run_step).result()
414+
415+
assert observed["inside"] == "acme"
416+
assert observed["nested"] == "acme"
417+
418+
plugin.on_invocation_end(_invocation_end())
419+
420+
421+
@pytest.mark.parametrize("factory", [_execution_plugin, _invocation_plugin])
422+
def test_suspend_then_reenter_then_end_leaves_no_residue(factory):
423+
"""A suspended operation re-entered in the same invocation stays balanced.
424+
425+
The first start has no matching end (the SDK re-raises SuspendExecution), so
426+
the re-entry must replace that scope rather than stack on it.
427+
"""
428+
plugin, _ = factory()
429+
before = otel_context.get_current()
430+
plugin.on_invocation_start(_invocation_start())
431+
observed: dict[str, object] = {}
432+
433+
def run_polls() -> None:
434+
# Poll 1 suspends: start fires, end never does.
435+
plugin.on_user_function_start(_step_start("wfc-1"))
436+
# Poll 2 re-enters the same operation and completes.
437+
plugin.on_user_function_start(_step_start("wfc-1"))
438+
observed["depth_after_reentry"] = context_scope.depth(plugin)
439+
plugin.on_user_function_end(_step_end("wfc-1"))
440+
observed["depth_after_end"] = context_scope.depth(plugin)
441+
442+
with ThreadPoolExecutor(max_workers=1) as executor:
443+
executor.submit(run_polls).result()
444+
445+
assert observed["depth_after_reentry"] == 1
446+
assert observed["depth_after_end"] == 0
447+
assert otel_context.get_current() is before
448+
449+
plugin.on_invocation_end(_invocation_end())
450+
451+
350452
def test_two_plugins_on_one_thread_unwind_in_lifo_order():
351453
"""Both plugins ship as entry points and can be enabled together.
352454

packages/aws-durable-execution-sdk-python-otel/tests/test_log_filter.py

Lines changed: 41 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818
UserFunctionStartInfo,
1919
)
2020
import opentelemetry.context as otel_context
21+
from opentelemetry import trace
2122
import pytest
2223
from opentelemetry.context import Context
2324
from opentelemetry.sdk.trace import TracerProvider
@@ -239,6 +240,46 @@ def test_execution_plugin_handler_thread_uses_the_invocation_span():
239240
plugin.on_invocation_end(_invocation_end_info())
240241

241242

243+
def test_ambient_lambda_span_does_not_displace_the_invocation_span(monkeypatch):
244+
"""An ambient ADOT span must not be reported in place of the durable span.
245+
246+
In GLOBAL mode the Lambda invocation span from the ADOT layer stays current on
247+
the handler thread. Log records emitted there must still carry the durable
248+
Invocation span, so the filter only trusts the current span while the plugin
249+
holds an operation scope on that thread.
250+
"""
251+
exporter = InMemorySpanExporter()
252+
provider = TracerProvider()
253+
provider.add_span_processor(SimpleSpanProcessor(exporter))
254+
monkeypatch.setattr(trace, "get_tracer_provider", lambda: provider)
255+
plugin = ExecutionOtelPlugin(
256+
OtelPluginConfig(
257+
provider_source=ProviderSource.GLOBAL,
258+
context_extractor=lambda _: Context(),
259+
enrich_logger=False,
260+
)
261+
)
262+
263+
ambient = provider.get_tracer("ambient").start_span("lambda-invocation")
264+
token = otel_context.attach(trace.set_span_in_context(ambient))
265+
try:
266+
plugin.on_invocation_start(_invocation_start_info())
267+
record = _make_record()
268+
OtelContextLogFilter(plugin).filter(record)
269+
270+
ambient_span_id = format(ambient.get_span_context().span_id, "016x")
271+
invocation_span_id = format(
272+
plugin._invocation_span.get_span_context().span_id, "016x"
273+
)
274+
assert record.spanId == invocation_span_id
275+
assert record.spanId != ambient_span_id
276+
277+
plugin.on_invocation_end(_invocation_end_info())
278+
finally:
279+
otel_context.detach(token)
280+
ambient.end()
281+
282+
242283
def test_install_log_filter_attaches_to_handlers():
243284
"""install_log_filter adds the filter to each handler on the target logger."""
244285
plugin, _ = _create_plugin()

0 commit comments

Comments
 (0)