Skip to content

Commit 998cea5

Browse files
Alex Wangwangyb-A
authored andcommitted
test(otel): pin cross-thread and nested re-entry behaviour
The cross-thread test shut the worker pool down before asserting, which destroyed the very thread whose contamination matters. Keep the worker alive and probe it, so the limitation is asserted instead of hidden: the foreign token is dropped rather than reset, the re-entering thread unwinds cleanly, and the worker that suspended keeps the abandoned span current. Add a nested re-entry test for both plugins. An outer child context and an inner one both suspend, then both are replayed. Ending the inner operation restores the scope captured for the abandoned outer span, not the resumed one, because re-entry releases scopes in replay order rather than in reverse attach order. Deterministic CONTEXT span ids make the two indistinguishable downstream, so parenting and log correlation are unaffected, but the current span object is never exported. Both assertions flip once the SDK reports a user function that does not complete, which is the only way to unwind these scopes in order.
1 parent ecdf6ed commit 998cea5

2 files changed

Lines changed: 197 additions & 26 deletions

File tree

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

Lines changed: 96 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -595,13 +595,15 @@ def _step_end_info(
595595
)
596596

597597

598-
def _context_start_info(operation_id: str) -> UserFunctionStartInfo:
598+
def _context_start_info(
599+
operation_id: str, parent_id: str | None = None
600+
) -> UserFunctionStartInfo:
599601
return UserFunctionStartInfo(
600602
operation_id=operation_id,
601603
operation_type=OperationType.CONTEXT,
602604
sub_type=OperationSubType.RUN_IN_CHILD_CONTEXT,
603605
name=operation_id,
604-
parent_id=None,
606+
parent_id=parent_id,
605607
start_time=START_TIME,
606608
is_replayed=False,
607609
status=OperationStatus.STARTED,
@@ -610,13 +612,15 @@ def _context_start_info(operation_id: str) -> UserFunctionStartInfo:
610612
)
611613

612614

613-
def _context_end_info(operation_id: str) -> UserFunctionEndInfo:
615+
def _context_end_info(
616+
operation_id: str, parent_id: str | None = None
617+
) -> UserFunctionEndInfo:
614618
return UserFunctionEndInfo(
615619
operation_id=operation_id,
616620
operation_type=OperationType.CONTEXT,
617621
sub_type=OperationSubType.RUN_IN_CHILD_CONTEXT,
618622
name=operation_id,
619-
parent_id=None,
623+
parent_id=parent_id,
620624
start_time=START_TIME,
621625
is_replayed=False,
622626
status=OperationStatus.STARTED,
@@ -860,31 +864,108 @@ def test_reentered_step_attempt_releases_the_previous_scope():
860864
assert plugin._context_tokens == {}
861865

862866

863-
def test_reentry_replaces_a_scope_attached_on_another_thread():
864-
"""Verify a foreign token is replaced without a cross-thread reset.
867+
def test_reentry_on_another_thread_leaves_the_originating_worker_dirty():
868+
"""Pin what re-entry can and cannot clean up across threads.
865869
866870
A resumed branch can land on a different pool thread than the one that
867-
suspended. The foreign token cannot be reset here, so it is dropped and the
868-
new scope still unwinds cleanly on this thread.
871+
suspended. Re-entry drops the foreign token instead of resetting it, because
872+
a context token can only be reset on its own thread, and it unwinds cleanly
873+
on the thread that re-entered. The worker that suspended keeps the abandoned
874+
span current: releasing it needs a hook invoked on that thread when the user
875+
function fails to complete, which the SDK does not provide. The worker is
876+
kept alive here so this limitation is asserted rather than hidden by pool
877+
shutdown; the assertion flips once such a hook exists.
869878
"""
870879
plugin, _ = _create_plugin()
871880
plugin.on_invocation_start(_invocation_start_info())
872881
before_context = otel_context.get_current()
873882
span_key = "step-1:attempt:1"
874883

875-
with ThreadPoolExecutor(max_workers=1) as executor:
876-
executor.submit(
884+
with ThreadPoolExecutor(max_workers=1) as worker:
885+
# The suspending run happens on the worker and never reports an end.
886+
worker.submit(
877887
plugin.on_user_function_start, _step_start_info("step-1")
878888
).result()
879-
foreign_thread_ident, _foreign_token = plugin._context_tokens[span_key]
880-
assert foreign_thread_ident != threading.get_ident()
889+
abandoned_span = plugin._get_span(span_key)
890+
assert abandoned_span is not None
891+
foreign_thread_ident, _foreign_token = plugin._context_tokens[span_key]
892+
assert foreign_thread_ident != threading.get_ident()
893+
894+
# The timed resume lands on this thread instead.
895+
plugin.on_user_function_start(_step_start_info("step-1"))
896+
assert plugin._context_tokens[span_key][0] == threading.get_ident()
897+
plugin.on_user_function_end(_step_end_info("step-1"))
898+
899+
# This thread unwound to where it started.
900+
assert otel_context.get_current() == before_context
901+
902+
# The originating worker is still carrying the abandoned span.
903+
worker_span_id = worker.submit(
904+
lambda: trace.get_current_span().get_span_context().span_id
905+
).result()
906+
assert worker_span_id == abandoned_span.get_span_context().span_id
881907

882-
plugin.on_user_function_start(_step_start_info("step-1"))
883-
assert plugin._context_tokens[span_key][0] == threading.get_ident()
908+
plugin.on_invocation_end(_invocation_end_info())
884909

885-
plugin.on_user_function_end(_step_end_info("step-1"))
886910

911+
def test_nested_reentry_restores_the_abandoned_outer_scope():
912+
"""Pin nested re-entry: correct ids, but the abandoned outer span object.
913+
914+
When an outer child context and an inner one both suspend, re-entry releases
915+
each scope in the order the operations are replayed, which is not the reverse
916+
of the order they were attached. Ending the inner operation therefore
917+
restores the scope captured for the abandoned outer span rather than the
918+
resumed one. Deterministic CONTEXT span ids make the two indistinguishable
919+
downstream -- same trace id and span id, so parenting and log correlation are
920+
unaffected -- but the current span object is one that is never exported, so
921+
anything an instrumentation library records on it is lost. Reverse-order
922+
unwinding needs the SDK to report the suspension; this test documents the
923+
current behaviour and flips when that lands.
924+
"""
925+
plugin, _ = _create_plugin()
926+
plugin.on_invocation_start(_invocation_start_info())
927+
before_context = otel_context.get_current()
928+
929+
# Both contexts suspend, so neither reports an end.
930+
plugin.on_user_function_start(_context_start_info("ctx-outer"))
931+
abandoned_outer = plugin._get_span("ctx-outer")
932+
plugin.on_user_function_start(
933+
_context_start_info("ctx-inner", parent_id="ctx-outer")
934+
)
935+
assert abandoned_outer is not None
936+
937+
# The timed in-process resume replays both contexts, outer first.
938+
plugin.on_user_function_start(_context_start_info("ctx-outer"))
939+
resumed_outer = plugin._get_span("ctx-outer")
940+
plugin.on_user_function_start(
941+
_context_start_info("ctx-inner", parent_id="ctx-outer")
942+
)
943+
resumed_inner = plugin._get_span("ctx-inner")
944+
assert resumed_outer is not None
945+
assert resumed_inner is not None
946+
assert resumed_outer is not abandoned_outer
947+
948+
# Resumed inner code runs under the resumed inner span.
949+
assert trace.get_current_span() is resumed_inner
950+
951+
plugin.on_user_function_end(_context_end_info("ctx-inner", parent_id="ctx-outer"))
952+
953+
# The restored scope carries the abandoned outer span, whose ids match the
954+
# resumed one because CONTEXT span ids are derived from the operation id.
955+
assert trace.get_current_span() is abandoned_outer
956+
assert (
957+
abandoned_outer.get_span_context().span_id
958+
== resumed_outer.get_span_context().span_id
959+
)
960+
assert (
961+
abandoned_outer.get_span_context().trace_id
962+
== resumed_outer.get_span_context().trace_id
963+
)
964+
965+
# Leaving the outer context still unwinds to where the invocation started.
966+
plugin.on_user_function_end(_context_end_info("ctx-outer"))
887967
assert otel_context.get_current() == before_context
888968
assert set(plugin._context_tokens) == {"__invocation_context__"}
889969

890970
plugin.on_invocation_end(_invocation_end_info())
971+
assert plugin._context_tokens == {}

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

Lines changed: 101 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -1382,31 +1382,121 @@ def test_reentered_step_attempt_releases_the_previous_scope():
13821382
plugin.on_invocation_end(_invocation_end_info())
13831383

13841384

1385-
def test_reentry_replaces_a_scope_attached_on_another_thread():
1386-
"""Verify a foreign token is replaced without a cross-thread reset.
1385+
def test_reentry_on_another_thread_leaves_the_originating_worker_dirty():
1386+
"""Pin what re-entry can and cannot clean up across threads.
13871387
13881388
A resumed branch can land on a different pool thread than the one that
1389-
suspended. The foreign token cannot be reset here, so it is dropped and the
1390-
new scope still unwinds cleanly on this thread.
1389+
suspended. Re-entry drops the foreign token instead of resetting it, because
1390+
a context token can only be reset on its own thread, and it unwinds cleanly
1391+
on the thread that re-entered. The worker that suspended keeps the abandoned
1392+
span current: releasing it needs a hook invoked on that thread when the user
1393+
function fails to complete, which the SDK does not provide. The worker is
1394+
kept alive here so this limitation is asserted rather than hidden by pool
1395+
shutdown; the assertion flips once such a hook exists.
13911396
"""
13921397
plugin, _ = _create_plugin()
13931398
plugin.on_invocation_start(_invocation_start_info())
13941399
before_context = otel_context.get_current()
13951400
operation_id = "step-1"
13961401
span_key = "step-1:attempt:1"
13971402

1398-
with ThreadPoolExecutor(max_workers=1) as executor:
1399-
executor.submit(
1403+
with ThreadPoolExecutor(max_workers=1) as worker:
1404+
# The suspending run happens on the worker and never reports an end.
1405+
worker.submit(
14001406
plugin.on_user_function_start, _user_function_start_info(operation_id)
14011407
).result()
1402-
foreign_thread_ident, _foreign_token = plugin._context_tokens[span_key]
1403-
assert foreign_thread_ident != threading.get_ident()
1408+
abandoned_span = plugin._get_span(span_key)
1409+
assert abandoned_span is not None
1410+
foreign_thread_ident, _foreign_token = plugin._context_tokens[span_key]
1411+
assert foreign_thread_ident != threading.get_ident()
14041412

1405-
plugin.on_user_function_start(_user_function_start_info(operation_id))
1406-
assert plugin._context_tokens[span_key][0] == threading.get_ident()
1413+
# The timed resume lands on this thread instead.
1414+
plugin.on_user_function_start(_user_function_start_info(operation_id))
1415+
assert plugin._context_tokens[span_key][0] == threading.get_ident()
1416+
plugin.on_user_function_end(_user_function_end_info(operation_id))
1417+
1418+
# This thread unwound to where it started.
1419+
assert otel_context.get_current() == before_context
1420+
1421+
# The originating worker is still carrying the abandoned span.
1422+
worker_span_id = worker.submit(
1423+
lambda: trace.get_current_span().get_span_context().span_id
1424+
).result()
1425+
assert worker_span_id == abandoned_span.get_span_context().span_id
1426+
1427+
plugin.on_invocation_end(_invocation_end_info())
14071428

1408-
plugin.on_user_function_end(_user_function_end_info(operation_id))
14091429

1430+
def test_nested_reentry_restores_the_abandoned_outer_scope():
1431+
"""Pin nested re-entry: correct ids, but the abandoned outer span object.
1432+
1433+
When an outer child context and an inner one both suspend, re-entry releases
1434+
each scope in the order the operations are replayed, which is not the reverse
1435+
of the order they were attached. Ending the inner operation therefore
1436+
restores the scope captured for the abandoned outer span rather than the
1437+
resumed one. Deterministic CONTEXT span ids make the two indistinguishable
1438+
downstream -- same trace id and span id, so parenting and log correlation are
1439+
unaffected -- but the current span object is one that is never exported, so
1440+
anything an instrumentation library records on it is lost. Reverse-order
1441+
unwinding needs the SDK to report the suspension; this test documents the
1442+
current behaviour and flips when that lands.
1443+
"""
1444+
plugin, _ = _create_plugin()
1445+
plugin.on_invocation_start(_invocation_start_info())
1446+
before_context = otel_context.get_current()
1447+
1448+
# Both contexts suspend, so neither reports an end.
1449+
plugin.on_user_function_start(
1450+
_user_function_start_info("ctx-outer", operation_type=OperationType.CONTEXT)
1451+
)
1452+
abandoned_outer = plugin._get_span("ctx-outer")
1453+
plugin.on_user_function_start(
1454+
_user_function_start_info(
1455+
"ctx-inner", parent_id="ctx-outer", operation_type=OperationType.CONTEXT
1456+
)
1457+
)
1458+
assert abandoned_outer is not None
1459+
1460+
# The timed in-process resume replays both contexts, outer first.
1461+
plugin.on_user_function_start(
1462+
_user_function_start_info("ctx-outer", operation_type=OperationType.CONTEXT)
1463+
)
1464+
resumed_outer = plugin._get_span("ctx-outer")
1465+
plugin.on_user_function_start(
1466+
_user_function_start_info(
1467+
"ctx-inner", parent_id="ctx-outer", operation_type=OperationType.CONTEXT
1468+
)
1469+
)
1470+
resumed_inner = plugin._get_span("ctx-inner")
1471+
assert resumed_outer is not None
1472+
assert resumed_inner is not None
1473+
assert resumed_outer is not abandoned_outer
1474+
1475+
# Resumed inner code runs under the resumed inner span.
1476+
assert trace.get_current_span() is resumed_inner
1477+
1478+
plugin.on_user_function_end(
1479+
_user_function_end_info(
1480+
"ctx-inner", parent_id="ctx-outer", operation_type=OperationType.CONTEXT
1481+
)
1482+
)
1483+
1484+
# The restored scope carries the abandoned outer span, whose ids match the
1485+
# resumed one because CONTEXT span ids are derived from the operation id.
1486+
assert trace.get_current_span() is abandoned_outer
1487+
assert (
1488+
abandoned_outer.get_span_context().span_id
1489+
== resumed_outer.get_span_context().span_id
1490+
)
1491+
assert (
1492+
abandoned_outer.get_span_context().trace_id
1493+
== resumed_outer.get_span_context().trace_id
1494+
)
1495+
1496+
# Leaving the outer context still unwinds to where the invocation started.
1497+
plugin.on_user_function_end(
1498+
_user_function_end_info("ctx-outer", operation_type=OperationType.CONTEXT)
1499+
)
14101500
assert otel_context.get_current() == before_context
14111501
assert plugin._context_tokens == {}
14121502

0 commit comments

Comments
 (0)