Skip to content

Commit af13837

Browse files
author
Ayushi Ahjolia
committed
fix(otel): stop reusing operation span IDs on resume
The execution plugin now ends operation spans left open at invocation end, so an operation that suspends and resumes across invocations would export its deterministic operation span ID more than once, corrupting the trace. Mirror the invocation plugin: a replayed or cross-invocation operation span uses a fresh span ID and links back to the deterministic operation context, so each per-invocation segment correlates without sharing a span ID. Also resolve the Workflow placeholder and operation link trace state from the sampling result (falling back to the ancestor state) in both plugins, so a same-trace ambient tracestate is preserved on non-terminal invocations instead of being dropped to the empty ancestor state. sim: #642
1 parent 610690e commit af13837

4 files changed

Lines changed: 293 additions & 12 deletions

File tree

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

Lines changed: 56 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,7 @@
5656
SpanKind,
5757
StatusCode,
5858
Tracer,
59+
TraceState,
5960
)
6061

6162
from aws_durable_execution_sdk_python_otel.context_extractors import (
@@ -293,6 +294,41 @@ def _resolve_parent(self, parent_id: str | None) -> Span | None:
293294
return existing
294295
return self._workflow_span
295296

297+
def _resolved_trace_state(self) -> TraceState:
298+
"""Return the trace state shared by every durable span this invocation.
299+
300+
The sampling result carries the ``tracestate`` resolved for the
301+
execution: when the invocation runs under a same-trace ambient span the
302+
result preserves that vendor state, whereas the execution ancestor's
303+
state is empty. Prefer the resolved state so placeholders match the
304+
recording spans; fall back to the ancestor state when no intent exists.
305+
"""
306+
intent = self._sampling_intent
307+
if intent is not None and intent.result.trace_state is not None:
308+
return intent.result.trace_state
309+
if self._execution_trace_context is not None:
310+
return self._execution_trace_context.execution_ancestor.trace_state
311+
return TraceState()
312+
313+
def _operation_link_context(self, operation_id: str) -> SpanContext | None:
314+
"""Return the deterministic logical operation context for links.
315+
316+
A continuation span (a replayed operation, or one stitched across
317+
invocations) uses a fresh span ID and links back to this deterministic
318+
context so every per-invocation segment of one logical operation
319+
correlates without sharing a span ID.
320+
"""
321+
execution_trace_context = self._execution_trace_context
322+
if execution_trace_context is None:
323+
return None
324+
return SpanContext(
325+
trace_id=execution_trace_context.trace_id,
326+
span_id=operation_id_to_span_id(self._execution_arn, operation_id),
327+
is_remote=False,
328+
trace_flags=execution_trace_context.trace_flags,
329+
trace_state=self._resolved_trace_state(),
330+
)
331+
296332
def _invocation_parent_context(self) -> Context:
297333
"""Return same-trace ambient context, else execution ancestor context."""
298334
execution_trace_context = self._execution_trace_context
@@ -415,7 +451,7 @@ def _start_workflow_span(self, info: InvocationStartInfo) -> None:
415451
span_id=derive_workflow_span_id(self._execution_arn),
416452
is_remote=False,
417453
trace_flags=self._execution_trace_context.trace_flags,
418-
trace_state=self._execution_trace_context.execution_ancestor.trace_state,
454+
trace_state=self._resolved_trace_state(),
419455
)
420456
self._workflow_span = NonRecordingSpan(workflow_span_context)
421457

@@ -568,6 +604,7 @@ def on_operation_start(self, info: OperationStartInfo) -> None:
568604
info=info,
569605
parent=parent,
570606
start_time=info.start_time,
607+
existed=info.is_replayed,
571608
)
572609

573610
def on_operation_end(self, info: OperationEndInfo) -> None:
@@ -577,14 +614,16 @@ def on_operation_end(self, info: OperationEndInfo) -> None:
577614
span = self._get_span(info.operation_id)
578615
if span is None:
579616
# Cross-invocation stitching: operation started in a prior
580-
# invocation. Create + immediately end a linked span.
617+
# invocation. Create + immediately end a continuation span with a
618+
# fresh ID that links back to the deterministic operation context.
581619
parent = self._resolve_parent(info.parent_id)
582620
span = self._start_span(
583621
operation_id=info.operation_id,
584622
name=info.name or info.operation_id,
585623
info=info,
586624
parent=parent,
587625
start_time=info.start_time,
626+
existed=True,
588627
)
589628
else:
590629
span.set_attributes(self._operation_attributes(info))
@@ -614,16 +653,29 @@ def _start_span(
614653
start_time: datetime.datetime | None,
615654
span_key: str | None = None,
616655
deterministic: bool = True,
656+
existed: bool = False,
617657
) -> Span:
618-
"""Start a span for an operation/attempt and register it."""
658+
"""Start a span for an operation/attempt and register it.
659+
660+
The first span observed for a logical operation uses the deterministic
661+
operation span ID. A continuation -- a replayed operation, or one
662+
stitched across invocations in ``on_operation_end`` -- instead uses a
663+
fresh span ID and links back to the deterministic operation context, so
664+
the segments correlate without two exported spans sharing one ID.
665+
"""
619666
key = span_key if span_key is not None else operation_id
620667
with self._lock:
621668
links = self._build_invocation_links()
669+
use_deterministic_id = deterministic and not existed
622670
span_id = (
623671
operation_id_to_span_id(self._execution_arn, operation_id)
624-
if deterministic
672+
if use_deterministic_id
625673
else None
626674
)
675+
if deterministic and existed:
676+
operation_context = self._operation_link_context(operation_id)
677+
if operation_context is not None and operation_context.is_valid:
678+
links = [*links, Link(context=operation_context)]
627679

628680
if parent is None:
629681
parent_ctx = self._with_sampling(Context())

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

Lines changed: 20 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@
3131
SpanKind,
3232
StatusCode,
3333
Tracer,
34+
TraceState,
3435
)
3536

3637
from aws_durable_execution_sdk_python_otel.context_extractors import (
@@ -359,6 +360,23 @@ def _next_ordered_timestamp(
359360
self._span_time_floor_ns = candidate
360361
return candidate
361362

363+
def _resolved_trace_state(self) -> TraceState:
364+
"""Return the trace state shared by every durable span this invocation.
365+
366+
The sampling result carries the ``tracestate`` resolved for the
367+
execution: when the invocation runs under a same-trace ambient span the
368+
result preserves that vendor state, whereas the execution ancestor's
369+
state is empty. Prefer the resolved state so placeholders and links
370+
match the recording spans; fall back to the ancestor state when no
371+
intent exists.
372+
"""
373+
intent = self._sampling_intent
374+
if intent is not None and intent.result.trace_state is not None:
375+
return intent.result.trace_state
376+
if self._execution_trace_context is not None:
377+
return self._execution_trace_context.execution_ancestor.trace_state
378+
return TraceState()
379+
362380
def _operation_link_context(self, operation_id: str) -> SpanContext | None:
363381
"""Return the deterministic logical operation context for links."""
364382
execution_trace_context = self._execution_trace_context
@@ -369,7 +387,7 @@ def _operation_link_context(self, operation_id: str) -> SpanContext | None:
369387
span_id=operation_id_to_span_id(self._execution_arn, operation_id),
370388
is_remote=False,
371389
trace_flags=execution_trace_context.trace_flags,
372-
trace_state=execution_trace_context.execution_ancestor.trace_state,
390+
trace_state=self._resolved_trace_state(),
373391
)
374392

375393
def _start_span(
@@ -573,7 +591,7 @@ def _start_workflow_span(self, info: InvocationStartInfo) -> None:
573591
span_id=derive_workflow_span_id(self._execution_arn),
574592
is_remote=False,
575593
trace_flags=self._execution_trace_context.trace_flags,
576-
trace_state=self._execution_trace_context.execution_ancestor.trace_state,
594+
trace_state=self._resolved_trace_state(),
577595
)
578596
self._workflow_span = NonRecordingSpan(workflow_span_context)
579597

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

Lines changed: 162 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -26,11 +26,19 @@
2626
UserFunctionStartInfo,
2727
)
2828
from opentelemetry import baggage, trace
29+
from opentelemetry.context import Context
2930
from opentelemetry.sdk.trace import TracerProvider
3031
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
3132
from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter
33+
from opentelemetry.trace import (
34+
NonRecordingSpan,
35+
SpanContext,
36+
TraceFlags,
37+
TraceState,
38+
)
3239

3340
from aws_durable_execution_sdk_python_otel.deterministic_id_generator import (
41+
_to_otel_trace_id,
3442
derive_execution_root_span_id,
3543
derive_workflow_span_id,
3644
operation_id_to_span_id,
@@ -343,14 +351,20 @@ def test_operation_parented_under_workflow_and_linked_to_invocation():
343351
assert invocation.context.span_id in linked_span_ids
344352

345353

346-
def test_cross_invocation_operation_end_uses_deterministic_span_id():
354+
def test_cross_invocation_operation_end_links_previous_logical_operation():
355+
"""A continuation uses a fresh ID and links the deterministic operation."""
347356
plugin, exporter = _create_plugin()
348357
plugin.on_invocation_start(_invocation_start_info())
358+
operation_id = "step-earlier"
359+
random_span_id = int("1234567890abcdef", 16)
360+
plugin._id_generator._fallback_id_generator.generate_span_id = lambda: (
361+
random_span_id
362+
)
349363

350364
# Backend-updated completion for an operation started in a prior invocation.
351365
plugin.on_operation_end(
352366
OperationEndInfo(
353-
operation_id="step-earlier",
367+
operation_id=operation_id,
354368
operation_type=OperationType.STEP,
355369
sub_type=None,
356370
name="earlier-step",
@@ -365,12 +379,16 @@ def test_cross_invocation_operation_end_uses_deterministic_span_id():
365379
plugin.on_invocation_end(_invocation_end_info())
366380

367381
matching = [s for s in exporter.get_finished_spans() if s.name == "earlier-step"]
368-
# Exported exactly once, using the deterministic logical-operation span ID
369-
# (no separate continuation span).
382+
# Exported exactly once, with a fresh span ID (not the deterministic one) so
383+
# a later terminal completion cannot collide with this segment.
370384
assert len(matching) == 1
371-
assert matching[0].context.span_id == operation_id_to_span_id(
372-
EXECUTION_ARN, "step-earlier"
385+
assert matching[0].context.span_id == random_span_id
386+
assert matching[0].context.span_id != operation_id_to_span_id(
387+
EXECUTION_ARN, operation_id
373388
)
389+
# Links back to the deterministic logical operation context for correlation.
390+
linked_span_ids = {link.context.span_id for link in matching[0].links}
391+
assert operation_id_to_span_id(EXECUTION_ARN, operation_id) in linked_span_ids
374392

375393

376394
@pytest.mark.parametrize(
@@ -621,6 +639,144 @@ def test_open_operation_span_ended_at_invocation_end():
621639
assert "wait-for-signal" in exported
622640

623641

642+
def test_suspend_then_resume_operation_exports_unique_span_ids():
643+
"""An operation that suspends then resumes never reuses a span ID.
644+
645+
Invocation N starts the operation and suspends: its deterministic-ID span
646+
is ended at invocation end. Invocation N+1 replays the still-open operation
647+
(on_operation_replay -> on_operation_start with is_replayed=True) and then
648+
completes it. Each exported segment must carry a distinct span ID so no two
649+
exported spans collide on one span_id/trace_id.
650+
"""
651+
plugin, exporter = _create_plugin()
652+
operation_id = "wait-across-invocations"
653+
replay_span_id = int("1111111111111111", 16)
654+
resume_span_id = int("2222222222222222", 16)
655+
656+
# Invocation N: operation starts and suspends (non-terminal invocation end).
657+
plugin.on_invocation_start(_invocation_start_info())
658+
plugin.on_operation_start(
659+
OperationStartInfo(
660+
operation_id=operation_id,
661+
operation_type=OperationType.WAIT,
662+
sub_type=OperationSubType.WAIT,
663+
name="long-wait",
664+
parent_id=None,
665+
start_time=START_TIME,
666+
is_replayed=False,
667+
status=OperationStatus.STARTED,
668+
)
669+
)
670+
plugin.on_invocation_end(_invocation_end_info(status=InvocationStatus.PENDING))
671+
672+
# Invocation N+1: the still-open operation is replayed, then completes.
673+
plugin.on_invocation_start(_invocation_start_info())
674+
plugin._id_generator._fallback_id_generator.generate_span_id = lambda: (
675+
replay_span_id
676+
)
677+
plugin.on_operation_start(
678+
OperationStartInfo(
679+
operation_id=operation_id,
680+
operation_type=OperationType.WAIT,
681+
sub_type=OperationSubType.WAIT,
682+
name="long-wait",
683+
parent_id=None,
684+
start_time=START_TIME,
685+
is_replayed=True,
686+
status=OperationStatus.STARTED,
687+
)
688+
)
689+
plugin._id_generator._fallback_id_generator.generate_span_id = lambda: (
690+
resume_span_id
691+
)
692+
plugin.on_operation_end(
693+
OperationEndInfo(
694+
operation_id=operation_id,
695+
operation_type=OperationType.WAIT,
696+
sub_type=OperationSubType.WAIT,
697+
name="long-wait",
698+
parent_id=None,
699+
start_time=START_TIME,
700+
is_replayed=False,
701+
status=OperationStatus.SUCCEEDED,
702+
end_time=END_TIME,
703+
error=None,
704+
)
705+
)
706+
plugin.on_invocation_end(_invocation_end_info(status=InvocationStatus.SUCCEEDED))
707+
708+
operation_spans = [
709+
s for s in exporter.get_finished_spans() if s.name == "long-wait"
710+
]
711+
span_ids = [s.context.span_id for s in operation_spans]
712+
# Every exported segment has a unique span ID (no reuse across invocations).
713+
assert len(span_ids) == len(set(span_ids))
714+
# The first segment used the deterministic ID; every continuation used a
715+
# fresh ID and links back to the deterministic logical operation context.
716+
deterministic_id = operation_id_to_span_id(EXECUTION_ARN, operation_id)
717+
assert deterministic_id in span_ids
718+
for span in operation_spans:
719+
if span.context.span_id != deterministic_id:
720+
linked = {link.context.span_id for link in span.links}
721+
assert deterministic_id in linked
722+
723+
724+
def test_pre_terminal_placeholder_preserves_same_trace_tracestate():
725+
"""The Workflow placeholder and operation links carry ambient tracestate.
726+
727+
A same-trace ambient span carries vendor ``tracestate``. On a non-terminal
728+
invocation the recording Workflow span is never exported, so the placeholder
729+
is the only Workflow context that parents operation spans; it (and the
730+
deterministic operation link a continuation emits) must carry that resolved
731+
tracestate rather than the empty ancestor state.
732+
"""
733+
plugin, exporter = _create_plugin()
734+
canonical = _to_otel_trace_id(EXECUTION_ARN, START_TIME)
735+
trace_state = TraceState([("vendor", "opaque")])
736+
ambient_context = SpanContext(
737+
trace_id=canonical,
738+
span_id=int("1234567890abcdef", 16),
739+
is_remote=False,
740+
trace_flags=TraceFlags(TraceFlags.SAMPLED),
741+
trace_state=trace_state,
742+
)
743+
ambient = NonRecordingSpan(ambient_context)
744+
token = otel_context.attach(trace.set_span_in_context(ambient, Context()))
745+
try:
746+
plugin.on_invocation_start(_invocation_start_info())
747+
# Placeholder Workflow span carries the resolved tracestate.
748+
assert plugin._workflow_span is not None
749+
assert plugin._workflow_span.get_span_context().trace_state == trace_state
750+
# A cross-invocation completion links the deterministic operation
751+
# context, which must also carry the resolved tracestate.
752+
plugin.on_operation_end(
753+
OperationEndInfo(
754+
operation_id="wait-existing",
755+
operation_type=OperationType.WAIT,
756+
sub_type=OperationSubType.WAIT,
757+
name="existing-wait",
758+
parent_id=None,
759+
start_time=START_TIME,
760+
is_replayed=False,
761+
status=OperationStatus.SUCCEEDED,
762+
end_time=END_TIME,
763+
error=None,
764+
)
765+
)
766+
plugin.on_invocation_end(_invocation_end_info(status=InvocationStatus.PENDING))
767+
finally:
768+
otel_context.detach(token)
769+
770+
span = next(s for s in exporter.get_finished_spans() if s.name == "existing-wait")
771+
operation_link = next(
772+
link
773+
for link in span.links
774+
if link.context.span_id
775+
== operation_id_to_span_id(EXECUTION_ARN, "wait-existing")
776+
)
777+
assert operation_link.context.trace_state == trace_state
778+
779+
624780
@pytest.mark.parametrize(
625781
("status", "expected_code"),
626782
[

0 commit comments

Comments
 (0)