fix(otel): correct operation spans across replay

[zhongkechen]

Summary

• skip OTel operation spans for terminal operations observed only through replay history
• start invocation-view operation spans at the current time so they remain within their invocation parent
• preserve spans for retries and backend completions reported in the current invocation
• cover terminal replay and operation timestamp behavior with regression tests

Root cause

on_operation_replay emits start and end callbacks for terminal checkpointed operations with is_replayed=True. The OTel plugins treated those callbacks as new continuations, so an already-successful submitter was emitted again during replay.

Invocation-view operation spans also reused the durable operation timestamp from OperationStartInfo. During continuation invocations, that timestamp predates the new invocation and causes operation spans to overlap.

Conformance failures:

• https://github.com/aws/aws-durable-execution-conformance-tests/actions/runs/30304154081/job/90104146029
• https://github.com/aws/aws-durable-execution-conformance-tests/actions/runs/30310125440/job/90123537458

Testing

• hatch run dev-otel:test (102 passed)
• hatch run types:check
• hatch fmt --check
• hatch run test:all (3051 passed, 2 skipped)

[SilanHe]

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]

Yeah, that is the behavior without this fix

[SilanHe]

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]

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]

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]

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	✅

[github-actions]

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.

[github-actions]

Low severity — mixed clock sources can yield a negative-duration span. For an operation that both started and ended in the current invocation (is_continuation is False), the span's start was changed to datetime.datetime.now(UTC) in on_operation_start, but here the end still uses info.end_time, which is the backend-assigned durable timestamp. These come from two different clocks. When the backend's end_time precedes the local now() recorded at start (clock skew for a very short operation), the span ends before it starts.

The pre-existing guard on the next line only bumps by 1µs when end_timestamp == info.start_time, i.e. it compares against the durable start, which is no longer the span's actual start time — so it neither catches the inversion nor serves its original zero-duration purpose for this path.

Consider guarding against inversion directly (e.g. record the now() start used at span creation and clamp end_timestamp to be >= start, or fall back to None so OTel stamps the current time) instead of the == info.start_time check.

[github-actions]

Codex AI review

No actionable findings.

Residual risk: regression tests call plugin hooks directly rather than exercising replay/update sequencing end to end. Tests were not run per review constraints.

Reviewed commit 9835af36d66571473ef359071082844681e121ec. Workflow run

[github-actions]

Claude AI review

I reviewed the four changed files against the callback contract in plugin.py, the replay/update dispatch gate in context.py:556-562, and the state dedup in state.py. No actionable findings.

Assessment (confirmed correct)

Suppression logic — on_operation_start skips only terminal replayed callbacks (is_replayed and status in _TERMINAL_OPERATION_STATUSES) while on_operation_end skips all replayed callbacks. This asymmetry is sound: on_operation_replay (plugin.py:409) emits an end callback only for terminal statuses, and for a terminal op it also emits a terminal-status start — so both halves are suppressed as a pair. Non-terminal replayed starts (STARTED retries at plugin.py:403, still-PENDING continuations) still create their linked continuation span, and their completion arrives via on_operation_update with is_replayed=False, which is not suppressed. _TERMINAL_OPERATION_STATUSES (execution_plugin.py:80, invocation_plugin.py:53) matches _is_terminal_status (plugin.py:532-539) exactly.

Timestamp change — Starting invocation-view operation spans at datetime.now() (invocation_plugin.py:400, 434) instead of the durable start is correct: those spans are parented to the per-invocation span, and a continuation invocation's durable start predates it. execution_plugin correctly keeps durable timestamps since its operation spans hang off the execution-long Workflow span (no overlap possible). Span timestamps are observability-only and don't affect replay determinism. Removing the obsolete end_time == start_time microsecond bump is safe — _end_span(operation_id) with no timestamp lets OTel stamp the end via time_ns(), always ≥ start.

Tests — New parametrized tests cover all five terminal statuses in both plugins plus invocation-parent time-ordering. The is_replayed flip in test_cross_invocation_operation_end_uses_deterministic_span_id and the if not span→if span is None tightening are consistent with the new semantics.

Residual test risk (non-blocking)

• Correctness of "backend completions while suspended arrive with is_replayed=False" rests on UpdatedOperationIds completeness (context.py:556, state.py:498). If a terminal op ever reached a later invocation as replay without a prior live emission, its span would now be silently dropped. I could not construct a reachable violation, and it matches the documented contract — but no regression test asserts this impossibility.
• test_continuation_span_uses_current_start_and_end_times and test_operation_callbacks_... assert on time.time_ns()/wall-clock ordering; they use <= so they tolerate clock coarseness but are timing-dependent by nature.

Reviewed commit 9835af36d66571473ef359071082844681e121ec. Workflow run