Skip to content

fix(otel): correct operation spans across replay #591

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
zhongkechen wants to merge 5 commits into
base: main
Choose a base branch
from
Open

fix(otel): correct operation spans across replay #591

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
f5a025e
fix(otel): avoid duplicate spans for terminal replays
zhongkechen Jul 27, 2026
591d328
Merge branch 'main' into codex/fix-otel-terminal-replay-spans
zhongkechen Jul 27, 2026
d038e49
fix(otel): start operation spans at current time
zhongkechen Jul 27, 2026
dba1fb4
fix(otel): normalize continuation span timestamps
zhongkechen Jul 28, 2026
9835af3
fix(otel): use current operation end times
zhongkechen Jul 28, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 15 additions & 0 deletions ...e-execution-sdk-python-otel/src/aws_durable_execution_sdk_python_otel/execution_plugin.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@

from aws_durable_execution_sdk_python.lambda_service import (
InvocationStatus,
OperationStatus,
OperationType,
)
from aws_durable_execution_sdk_python.plugin import (
Expand Down Expand Up @@ -76,6 +77,16 @@
{InvocationStatus.SUCCEEDED, InvocationStatus.FAILED}
)

_TERMINAL_OPERATION_STATUSES = frozenset(
{
OperationStatus.SUCCEEDED,
OperationStatus.FAILED,
OperationStatus.TIMED_OUT,
OperationStatus.CANCELLED,
OperationStatus.STOPPED,
}
)

# Registry key for the invocation span (operations use their operation_id).
_INVOCATION_KEY = "__invocation__"

Expand Down Expand Up @@ -346,6 +357,8 @@ def _reset_state(self) -> None:
# ------------------------------------------------------------------
def on_operation_start(self, info: OperationStartInfo) -> None:
logger.debug("Durable operation started: %s", info)
if info.is_replayed and info.status in _TERMINAL_OPERATION_STATUSES:
return
if info.operation_type is OperationType.CONTEXT:
return # tracked via on_user_function_start
parent = self._resolve_parent(info.parent_id)
Expand All @@ -359,6 +372,8 @@ def on_operation_start(self, info: OperationStartInfo) -> None:

def on_operation_end(self, info: OperationEndInfo) -> None:
logger.debug("Durable operation ended: %s", info)
if info.is_replayed:
return
if info.operation_type is OperationType.CONTEXT:
return
span = self._get_span(info.operation_id)
Expand Down
35 changes: 26 additions & 9 deletions ...-execution-sdk-python-otel/src/aws_durable_execution_sdk_python_otel/invocation_plugin.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@

from aws_durable_execution_sdk_python.lambda_service import (
InvocationStatus,
OperationStatus,
OperationType,
)
from aws_durable_execution_sdk_python.plugin import (
Expand Down Expand Up @@ -49,6 +50,16 @@

_SpanAttributes = dict[str, str | bool | int]

_TERMINAL_OPERATION_STATUSES = frozenset(
{
OperationStatus.SUCCEEDED,
OperationStatus.FAILED,
OperationStatus.TIMED_OUT,
OperationStatus.CANCELLED,
OperationStatus.STOPPED,
}
)


def _to_otel_timestamp(dt: datetime.datetime | None) -> int | None:
"""Convert a datetime to OTel timestamp (nanoseconds since epoch), or None."""
Expand All @@ -68,8 +79,9 @@ class InvocationOtelPlugin(DurableInstrumentationPlugin):
Operation IDs are converted into deterministic span IDs. The first observed
span for an operation uses that deterministic ID; later continuation spans
use newly generated span IDs and link back to the deterministic span ID so
trace viewers can relate retries and replay-created terminal spans to the
original logical operation.
trace viewers can relate retries and cross-invocation completions to the
original logical operation. Terminal operations encountered only as replay
history do not emit another span.

Args:
trace_provider: OpenTelemetry tracer provider used to create spans.
Expand Down Expand Up @@ -373,6 +385,8 @@ def on_invocation_end(self, info: InvocationEndInfo) -> None:
def on_operation_start(self, info: OperationStartInfo) -> None:

@SilanHe SilanHe Jul 27, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

more meta comment about the plugin interface in Python: does this mean that given an operation that completes with a terminal status in the first invocation, and there are 5 invocations in total. Will the on_operation_start be triggered with OperationStartInfo 5 times for that operation?

@zhongkechen zhongkechen Jul 27, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, that is the behavior without this fix

@SilanHe SilanHe Jul 27, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

hmm in TS, the plugin interface onOperationStart behaves in the following manner:

  1. SDK calls onOperationStart with isFirst=true when the operation has started for the first time.
  2. SDK calls onOperationStart is called with isFirst=false for subsequent times the operation is processed but whose status is not terminal.
  3. SDK does NOT call onOperationStart when the operation status is terminal

@SilanHe SilanHe Jul 27, 2026 •
edited
Loading

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As a result, the Otel Plugin doesn't need this "fix" at all. Is there no way to close this gap within the SDK's plugin interface?

@zhongkechen zhongkechen Jul 27, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Python plugin interface behaves the same except no 3:

SDK does NOT call onOperationStart when the operation status is terminal

onOperationStart is still called when its context is replayed

@SilanHe SilanHe Jul 28, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

hmm this is different in Java as well but rather 2.

SDK calls onOperationStart is called with isFirst=false for subsequent times the operation is processed but whose status is not terminal.

Rule TS Java Match
1. First → isReplay=false all types all types ✅
2. Non-terminal replay → isReplay=true all types STEP/CONTEXT only ⚠️ partial
— WAIT / INVOKE / CALLBACK (rule 2) fires does not fire ❌
3. Terminal → no call no call no call ✅

"""Called when an operation begins. Creates a span for the operation."""
logger.debug("Durable operation started: %s", info)
if info.is_replayed and info.status in _TERMINAL_OPERATION_STATUSES:
return
if info.operation_type is OperationType.CONTEXT:
# Context operations are tracked using on_user_function_start.
return
Expand All @@ -383,7 +397,7 @@ def on_operation_start(self, info: OperationStartInfo) -> None:
operation_id=info.operation_id,
name=info.name or info.operation_id,
attributes=attributes,
start_time=info.start_time,
start_time=datetime.datetime.now(datetime.UTC),

@github-actions github-actions Bot Jul 28, 2026

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Operation span now mixes two clocks for start vs. end, allowing negative durations.

This changes the span start to the local Lambda wall clock (datetime.now(UTC)), but on_operation_end still ends the span at the backend-recorded info.end_time (self._end_span(info.operation_id, end_timestamp)). The two timestamps come from different clocks, so whenever info.end_time precedes the current invocation's local time the finished span has end_time < start_time — a negative duration. This is reachable under clock skew between the durable backend and the Lambda runtime for any operation that both starts and completes within this invocation (e.g. a WAIT/STEP whose backend end_timestamp lands slightly before local now()).

The pre-existing zero-duration guard no longer protects the span either: it bumps end_timestamp only when info.end_time == info.start_time, but the span's actual start is now now(), not info.start_time, so the comparison guards against a value unrelated to the real start.

Note the new assertion in test_operation_callbacks_emit_child_span_with_deterministic_span_id (invocation_span.start_time <= active_wait_span.start_time) checks only ordering vs. the invocation span; it never asserts wait_span.end_time >= wait_span.start_time, so with the test's START_TIME/END_TIME (2024) and a later now(), the wait span already has a negative duration that the suite silently accepts.

Fix: derive both endpoints from the same clock. Either keep start_time=info.start_time (and, if the goal is to avoid a child span preceding the invocation span, clamp start to max(info.start_time, invocation_span_start)), or clamp the end passed to _end_span to be >= the span's start. The ExecutionOtelPlugin.on_operation_start was intentionally left on info.start_time, so this also diverges the two plugins.

parent_span=parent_span,
existed=info.is_replayed,
)
Expand All @@ -396,13 +410,19 @@ def on_operation_end(self, info: OperationEndInfo) -> None:
invocation is completing an operation that began earlier, so a short
continuation span is created and linked to the deterministic logical
operation span before being ended.

Terminal replay callbacks describe history that completed before this
invocation and do not produce another span. Operations completed by the
backend while suspended are delivered with ``is_replayed=False``.
"""
logger.debug("Durable operation ended: %s", info)
if info.is_replayed:
return
if info.operation_type is OperationType.CONTEXT:
# Context operations are tracked using on_user_function_end.
return
span = self._get_span(info.operation_id)
if not span:
if span is None:
# the span was not started in the current invocation, so we need to
# create a new one that links to the previous one
parent_span = self._resolve_parent_span(info.parent_id)
Expand All @@ -411,7 +431,7 @@ def on_operation_end(self, info: OperationEndInfo) -> None:
operation_id=info.operation_id,
name=info.name or info.operation_id,
attributes=attributes,
start_time=info.start_time,
start_time=datetime.datetime.now(datetime.UTC),
parent_span=parent_span,
existed=True,
)
Expand All @@ -426,10 +446,7 @@ def on_operation_end(self, info: OperationEndInfo) -> None:
else:
span.set_status(StatusCode.OK)

end_timestamp = info.end_time
if end_timestamp is not None and end_timestamp == info.start_time:
end_timestamp += datetime.timedelta(microseconds=1)
self._end_span(info.operation_id, end_timestamp)
self._end_span(info.operation_id)

def on_user_function_start(self, info: UserFunctionStartInfo) -> None:
"""Called when a context or step operation starts user code.
Expand Down
51 changes: 49 additions & 2 deletions packages/aws-durable-execution-sdk-python-otel/tests/test_execution_plugin.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -209,7 +209,7 @@ def test_cross_invocation_operation_end_uses_deterministic_span_id():
plugin, exporter = _create_plugin()
plugin.on_invocation_start(_invocation_start_info())

# Operation end with no matching start (started in a prior invocation).
# Backend-updated completion for an operation started in a prior invocation.
plugin.on_operation_end(
OperationEndInfo(
operation_id="step-earlier",
Expand All @@ -218,7 +218,7 @@ def test_cross_invocation_operation_end_uses_deterministic_span_id():
name="earlier-step",
parent_id=None,
start_time=START_TIME,
is_replayed=True,
is_replayed=False,
status=OperationStatus.SUCCEEDED,
end_time=END_TIME,
error=None,
Expand All @@ -235,6 +235,53 @@ def test_cross_invocation_operation_end_uses_deterministic_span_id():
)


@pytest.mark.parametrize(
"operation_status",
[
OperationStatus.SUCCEEDED,
OperationStatus.FAILED,
OperationStatus.TIMED_OUT,
OperationStatus.CANCELLED,
OperationStatus.STOPPED,
],
)
def test_terminal_replayed_operation_does_not_emit_duplicate_span(
operation_status: OperationStatus,
):
plugin, exporter = _create_plugin()
plugin.on_invocation_start(_invocation_start_info())

plugin.on_operation_start(
OperationStartInfo(
operation_id="step-earlier",
operation_type=OperationType.STEP,
sub_type=OperationSubType.STEP,
name="earlier-step",
parent_id=None,
start_time=START_TIME,
is_replayed=True,
status=operation_status,
)
)
plugin.on_operation_end(
OperationEndInfo(
operation_id="step-earlier",
operation_type=OperationType.STEP,
sub_type=OperationSubType.STEP,
name="earlier-step",
parent_id=None,
start_time=START_TIME,
is_replayed=True,
status=operation_status,
end_time=END_TIME,
error=None,
)
)
plugin.on_invocation_end(_invocation_end_info())

assert "earlier-step" not in {span.name for span in exporter.get_finished_spans()}


# ---------------------------------------------------------------------------
# Default-provider mode: invocation span
# ---------------------------------------------------------------------------
Expand Down
58 changes: 36 additions & 22 deletions packages/aws-durable-execution-sdk-python-otel/tests/test_invocation_plugin.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@

from __future__ import annotations

import time
from concurrent.futures import ThreadPoolExecutor
from datetime import UTC, datetime

Expand Down Expand Up @@ -218,6 +219,9 @@ def test_operation_callbacks_emit_child_span_with_deterministic_span_id():
)
active_wait_span = plugin._get_span(operation_id)
assert active_wait_span is not None
invocation_span = plugin._get_span(None)
assert invocation_span is not None
assert invocation_span.start_time <= active_wait_span.start_time
assert (
active_wait_span.attributes["durable.operation.status"]
== OperationStatus.STARTED.value
Expand Down Expand Up @@ -250,6 +254,12 @@ def test_operation_callbacks_emit_child_span_with_deterministic_span_id():
EXECUTION_ARN, operation_id
)
assert wait_span.parent.span_id == invocation_span.context.span_id
assert (
invocation_span.start_time
<= wait_span.start_time
<= wait_span.end_time
<= invocation_span.end_time
)
assert wait_span.attributes["durable.operation.id"] == operation_id
assert wait_span.attributes["durable.operation.type"] == OperationType.WAIT.value
assert (
Expand Down Expand Up @@ -297,10 +307,13 @@ def test_operation_end_without_start_emits_continuation_span_with_link():
)


def test_continuation_span_uses_recorded_start_and_end_times():
"""Continuation spans use the recorded operation start/end times."""
def test_continuation_span_uses_current_start_and_end_times():
"""Continuation spans use current times within the invocation."""
plugin, exporter = _create_plugin()
plugin.on_invocation_start(_invocation_start_info())
invocation_span = plugin._get_span(None)
assert invocation_span is not None
before_callback = time.time_ns()

plugin.on_operation_end(
OperationEndInfo(
Expand All @@ -316,25 +329,30 @@ def test_continuation_span_uses_recorded_start_and_end_times():
error=None,
)
)
after_callback = time.time_ns()

span = exporter.get_finished_spans()[0]
expected_start = int(START_TIME.timestamp() * 1_000_000_000)
expected_end = int(END_TIME.timestamp() * 1_000_000_000)
assert span.start_time == expected_start
assert span.end_time == expected_end
# Duration must be non-negative.
assert span.end_time >= span.start_time
assert invocation_span.start_time <= span.start_time
assert before_callback <= span.start_time <= span.end_time <= after_callback


def test_replayed_operation_start_emits_continuation_span_with_link():
"""Replayed operation spans should not reuse the original deterministic span ID."""
@pytest.mark.parametrize(
"operation_status",
[
OperationStatus.SUCCEEDED,
OperationStatus.FAILED,
OperationStatus.TIMED_OUT,
OperationStatus.CANCELLED,
OperationStatus.STOPPED,
],
)
def test_terminal_replayed_operation_does_not_emit_duplicate_span(
operation_status: OperationStatus,
):
"""Terminal operations completed before this invocation are not re-emitted."""
plugin, exporter = _create_plugin()
plugin.on_invocation_start(_invocation_start_info())
operation_id = "wait-replayed"
random_span_id = int("abcdef1234567890", 16)
plugin._id_generator._fallback_id_generator.generate_span_id = lambda: (
random_span_id
)

plugin.on_operation_start(
OperationStartInfo(
Expand All @@ -345,7 +363,7 @@ def test_replayed_operation_start_emits_continuation_span_with_link():
parent_id=None,
start_time=START_TIME,
is_replayed=True,
status=OperationStatus.SUCCEEDED,
status=operation_status,
)
)
plugin.on_operation_end(
Expand All @@ -357,18 +375,14 @@ def test_replayed_operation_start_emits_continuation_span_with_link():
parent_id=None,
start_time=START_TIME,
is_replayed=True,
status=OperationStatus.SUCCEEDED,
status=operation_status,
end_time=END_TIME,
error=None,
)
)
plugin.on_invocation_end(_invocation_end_info())

span = exporter.get_finished_spans()[0]
assert span.name == "replayed-wait"
assert span.context.span_id == random_span_id
assert span.links[0].context.span_id == operation_id_to_span_id(
EXECUTION_ARN, operation_id
)
assert [span.name for span in exporter.get_finished_spans()] == ["invocation"]


def test_retried_operation_start_emits_continuation_span_with_link():
Expand Down
Loading