Skip to content

Commit 0559917

Browse files
committed
fix(plugin): dispatch on one thread, keep the real failure
Two findings from a fresh review pass. The failure exit fired the end hook inside its except block, so an exception out of the hook left that block before the handler's own failure was re-raised. The caller saw the plugin's exception and the real failure survived only as __context__. The end-hook dispatch does raise: it re-raises the control exceptions it holds through the fan-out. Instrumentation does not decide what an execution failed with, so the hook's exception is now contained and logged there and the original is re-raised unchanged. execute_plugins also had a sync parameter no caller ever passed. Its asynchronous branch submitted the hook to a per-invocation thread pool, which skipped the end-hook fan-out rule and swallowed a control exception in a Future nobody reads -- a way to opt out of the invariants this PR establishes, on a path with no production caller. The parameter and the pool are removed: hooks are dispatched on the calling thread, which is what lets a plugin set thread-affine state the SDK's own logging reads, and the gate that used to test the pool now tests the factory list. The pool created no thread either way, because ThreadPoolExecutor spawns lazily on first submit.
1 parent 2e84c0d commit 0559917

2 files changed

Lines changed: 122 additions & 61 deletions

File tree

packages/aws-durable-execution-sdk-python/src/aws_durable_execution_sdk_python/plugin.py

Lines changed: 43 additions & 39 deletions
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,6 @@
66
import functools
77
import logging
88
from collections.abc import Iterator, Mapping, Sequence
9-
from concurrent.futures import ThreadPoolExecutor
109
from dataclasses import dataclass, field
1110
from enum import Enum
1211
from typing import Any, Callable, MutableMapping, Protocol, cast
@@ -603,7 +602,6 @@ def __init__(self, plugins: list[DurableInstrumentationPluginFactory] | None):
603602
# Every later hook is dispatched to this list, so a plugin that never
604603
# received its start hook never receives its end hook.
605604
self._started: list[DurableInstrumentationPlugin] = []
606-
self._executor: ThreadPoolExecutor | None = None
607605
self._invocation_status: InvocationStartInfo | None = None
608606
self._operations_provider: Callable[[], Mapping[str, Operation]] | None = None
609607
self._run_entered = False
@@ -625,25 +623,14 @@ class exists to prevent; failing loudly here keeps the bug from
625623
)
626624
raise RuntimeError(msg)
627625
self._run_entered = True
628-
if self._plugin_factories:
629-
self._executor = ThreadPoolExecutor(
630-
max_workers=1,
631-
thread_name_prefix="plugin-executor",
632-
)
633626
try:
634627
yield
635628
finally:
636629
self._invocation_status = None
637630
self._operations_provider = None
638-
# Shut down the thread pool, waiting for pending tasks to complete.
639-
# The pool belongs to this invocation, so this drains only this
640-
# invocation's queued dispatches and cannot cut short a concurrent
641-
# invocation's.
642-
if self._executor:
643-
self._executor.shutdown(wait=True)
644-
# Drop this invocation's plugin instances. After the pool has
645-
# drained, so no queued dispatch still holds one: nothing outlives
646-
# the invocation.
631+
# Drop this invocation's plugin instances: nothing outlives the
632+
# invocation. Every dispatch is synchronous, so there is no queued
633+
# work still holding one.
647634
self._plugins = []
648635
self._started = []
649636

@@ -739,7 +726,7 @@ def _dispatch_plugin(plugin: DurableInstrumentationPlugin, info) -> None:
739726
if control is not None:
740727
raise control from None
741728

742-
def execute_plugins(self, info, sync):
729+
def execute_plugins(self, info):
743730
"""Dispatch one hook to this invocation's plugins.
744731
745732
A plugin receives a hook only once it has received the invocation-start
@@ -770,20 +757,25 @@ def execute_plugins(self, info, sync):
770757
``BaseException`` rather than naming the three again. Naming them would
771758
miss a :class:`BaseExceptionGroup` carrying one, which is what
772759
:func:`_contain_plugin_failure` hands back.
760+
761+
Every hook is dispatched on the calling thread. That is what lets a
762+
plugin set a ``ThreadLocal`` or an MDC key the SDK's own logging then
763+
reads, and it is what makes the pairing and re-raise rules above
764+
enforceable: a hook dispatched to a pool would land in a
765+
:class:`~concurrent.futures.Future` nobody reads, so a control exception
766+
raised there would be swallowed and the end-hook fan-out could not hold
767+
it. An earlier ``sync`` parameter offered the pool path; no caller ever
768+
passed it, and it is removed rather than left as a way to opt out of
769+
those rules.
773770
"""
774-
if not self._executor:
771+
if not self._plugin_factories:
775772
return
776773
starting = isinstance(info, InvocationStartInfo)
777774
ending = isinstance(info, InvocationEndInfo)
778775
deferred_control: BaseException | None = None
779776
for plugin in self._plugins if starting else self._started:
780777
if starting:
781778
self._started.append(plugin)
782-
if not sync:
783-
# this is called asynchronously, so plugins cannot manipulate thread local objects
784-
self._executor.submit(self._dispatch_plugin, plugin, info)
785-
continue
786-
# this is called synchronously, so plugins will be able to manipulate thread local objects
787779
if not ending:
788780
self._dispatch_plugin(plugin, info)
789781
continue
@@ -870,7 +862,7 @@ def on_invocation_start(
870862
# Build this invocation's plugin instances from the very info their first
871863
# hook receives, and before that hook is dispatched.
872864
self._create_plugins(self._invocation_status)
873-
self.execute_plugins(self._invocation_status, sync=True)
865+
self.execute_plugins(self._invocation_status)
874866

875867
def _snapshot_execution_input(self, execution_input: Any) -> Any:
876868
"""Deep-copy the execution input so the plugin view is isolated.
@@ -918,7 +910,7 @@ def on_invocation_end(
918910
operations=self._snapshot_operation_infos(self._operations_provider),
919911
)
920912
)
921-
self.execute_plugins(invocation_end_info, sync=True)
913+
self.execute_plugins(invocation_end_info)
922914

923915
def on_user_function_start(
924916
self,
@@ -939,7 +931,7 @@ def on_user_function_start(
939931
is_replay_children=is_replay_children,
940932
attempt=attempt,
941933
)
942-
self.execute_plugins(start_info, sync=True)
934+
self.execute_plugins(start_info)
943935
return start_info
944936

945937
def on_user_function_end(
@@ -952,7 +944,6 @@ def on_user_function_end(
952944
"""Execute plugins when a user function returns, fails, or is incomplete."""
953945
self.execute_plugins(
954946
UserFunctionEndInfo.from_start_info(start_info, error, outcome=outcome),
955-
sync=True,
956947
)
957948

958949
def on_operation_action(
@@ -982,7 +973,6 @@ def on_operation_action(
982973
is_replayed=previous_operation is not None,
983974
status=OperationStatus.STARTED,
984975
),
985-
sync=True,
986976
)
987977

988978
def on_operation_replay(self, operation: Operation) -> None:
@@ -1000,7 +990,7 @@ def on_operation_replay(self, operation: Operation) -> None:
1000990
is_replayed=True,
1001991
status=operation.status,
1002992
)
1003-
self.execute_plugins(start_info, sync=True)
993+
self.execute_plugins(start_info)
1004994

1005995
def on_child_context_end(
1006996
self,
@@ -1025,7 +1015,6 @@ def on_child_context_end(
10251015
error=error,
10261016
is_replayed=is_replayed,
10271017
),
1028-
sync=True,
10291018
)
10301019

10311020
def on_operation_update(
@@ -1075,7 +1064,6 @@ def on_operation_update(
10751064
),
10761065
is_replayed=False,
10771066
),
1078-
sync=True,
10791067
)
10801068

10811069
if (
@@ -1103,7 +1091,6 @@ def on_operation_update(
11031091
},
11041092
operations=_to_operation_info_map(operations),
11051093
),
1106-
sync=True,
11071094
)
11081095

11091096
@staticmethod
@@ -1204,13 +1191,30 @@ def wrapper(event: Any, context: LambdaContext):
12041191
# they also fire the hook. The hook is what a plugin needs
12051192
# to flush, and a process being torn down is when flushing
12061193
# matters; the cost is the same bounded work any
1207-
# invocation end does. The exception itself is re-raised
1208-
# unchanged, so what the caller sees is untouched.
1209-
plugin_executor.on_invocation_end(
1210-
output=DurableExecutionInvocationOutput.create_retry(
1211-
ErrorObject.from_exception(e)
1212-
),
1213-
)
1194+
# invocation end does.
1195+
#
1196+
# The handler's exception is what the caller sees,
1197+
# whatever the hook does. The end-hook dispatch can raise
1198+
# -- it re-raises the control exceptions it holds through
1199+
# the fan-out -- and letting that replace the handler's
1200+
# failure would report an instrumentation problem as the
1201+
# execution's outcome and leave the real failure reachable
1202+
# only as __context__. Instrumentation does not decide
1203+
# what an execution failed with, so the hook's exception
1204+
# is contained here and the original is re-raised
1205+
# unchanged.
1206+
try:
1207+
plugin_executor.on_invocation_end(
1208+
output=DurableExecutionInvocationOutput.create_retry(
1209+
ErrorObject.from_exception(e)
1210+
),
1211+
)
1212+
except BaseException: # noqa: BLE001 - the handler's failure wins
1213+
logger.exception(
1214+
"Plugin invocation-end hook failed while the "
1215+
"invocation was already failing; the original "
1216+
"failure is raised"
1217+
)
12141218
raise
12151219
plugin_executor.on_invocation_end(output=completed)
12161220
return output

packages/aws-durable-execution-sdk-python/tests/plugin_test.py

Lines changed: 79 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33
import datetime
44
import logging
55
import pickle
6+
import threading
67
import unittest
78
from collections.abc import Iterator
89
from copy import deepcopy
@@ -705,6 +706,38 @@ def test_a_factory_raising_a_group_without_a_control_exception_is_contained(self
705706
self.assertIn("boom", "\n".join(logs.output))
706707
self.assertEqual(surviving.calls, ["invocation_start:req-1"])
707708

709+
def test_a_failing_end_hook_does_not_replace_the_handlers_failure(self):
710+
"""Instrumentation does not decide what an execution failed with.
711+
712+
The end-hook dispatch can raise: it re-raises the control exceptions it
713+
holds through the fan-out. On the failure exit that raise used to leave
714+
the ``except`` block before the handler's own exception was re-raised, so
715+
the caller saw the plugin's exception and the real failure survived only
716+
as ``__context__``.
717+
"""
718+
plugin = _ControlOnEndPlugin()
719+
host = PluginHost(plugins=[plugin_factory(plugin)])
720+
721+
@host.handle_durable_output
722+
def handler(event, context, plugin_executor):
723+
plugin_executor.on_invocation_start(
724+
execution_arn="arn:exec",
725+
lambda_context=LAMBDA_CTX,
726+
execution_start_time=START_TS,
727+
is_first_invocation=True,
728+
)
729+
raise ValueError("the real failure")
730+
731+
with self.assertLogs(
732+
"aws_durable_execution_sdk_python.plugin", level=logging.ERROR
733+
):
734+
with self.assertRaises(ValueError) as raised:
735+
handler({}, LAMBDA_CTX)
736+
737+
self.assertEqual(str(raised.exception), "the real failure")
738+
# The hook still ran, and still saw the failing outcome.
739+
self.assertEqual(plugin.end_statuses, [InvocationStatus.RETRY])
740+
708741
def test_an_end_hook_that_stops_the_thread_still_finishes_the_dispatch(self):
709742
"""Every started plugin receives the end hook, then the thread stops.
710743
@@ -1136,26 +1169,50 @@ def test_a_hook_raising_cancellation_is_contained(self):
11361169
"aws_durable_execution_sdk_python.plugin", level=logging.ERROR
11371170
) as logs:
11381171
with _invocation(executor, tracking):
1139-
executor.execute_plugins(OPERATION_START_INFO, sync=True)
1172+
executor.execute_plugins(OPERATION_START_INFO)
11401173

11411174
self.assertIn("hook cancelled", "\n".join(logs.output))
11421175
self.assertIn("operation_start:op-2", tracking.calls)
11431176

11441177

11451178
class TestPluginExecutor(unittest.TestCase):
1146-
def test_no_thread_pool_when_plugins_is_none(self):
1147-
"""Tests that PluginExecutor does not create a thread pool when plugins is empty."""
1148-
executor = PluginExecutor(plugins=None)
1149-
self.assertIsNone(executor._executor)
1150-
1151-
def test_no_thread_pool_when_plugins_is_empty_list(self):
1152-
executor = PluginExecutor(plugins=[])
1153-
self.assertIsNone(executor._executor)
1179+
def test_dispatch_is_a_no_op_when_no_factory_is_registered(self):
1180+
"""An executor with no factories dispatches nothing and needs no thread.
1181+
1182+
Hooks are dispatched on the calling thread, which is what lets a plugin
1183+
set thread-affine state the SDK's own logging then reads, and what makes
1184+
the end-hook pairing and re-raise rules enforceable. There is therefore no
1185+
pool to create, and an executor with nothing registered returns before it
1186+
touches anything.
1187+
"""
1188+
for plugins in (None, []):
1189+
with self.subTest(plugins=plugins):
1190+
executor = PluginExecutor(plugins=plugins)
1191+
self.assertEqual(executor._plugin_factories, [])
1192+
with executor.run():
1193+
# Nothing registered, so no hook reaches a plugin and no
1194+
# dispatch raises on the way through.
1195+
executor.execute_plugins(INVOCATION_START_INFO)
1196+
executor.execute_plugins(OPERATION_START_INFO)
1197+
1198+
def test_hooks_are_dispatched_on_the_calling_thread(self):
1199+
"""Thread affinity is the contract, so it is asserted rather than assumed."""
1200+
seen: list[str] = []
1201+
1202+
class _ThreadRecordingPlugin(DurableInstrumentationPlugin):
1203+
def on_invocation_start(self, info: InvocationStartInfo) -> None:
1204+
seen.append(threading.current_thread().name)
11541205

1155-
def test_thread_pool_created_when_plugins_provided(self):
1156-
executor = PluginExecutor(plugins=[plugin_factory(_NoOpPlugin())])
1206+
executor = PluginExecutor(plugins=[plugin_factory(_ThreadRecordingPlugin())])
11571207
with executor.run():
1158-
self.assertIsNotNone(executor._executor)
1208+
executor.on_invocation_start(
1209+
execution_arn="arn:exec",
1210+
lambda_context=LAMBDA_CTX,
1211+
execution_start_time=START_TS,
1212+
is_first_invocation=True,
1213+
)
1214+
1215+
self.assertEqual(seen, [threading.current_thread().name])
11591216

11601217
def test_start_is_noop_when_empty(self):
11611218
executor = PluginExecutor(plugins=[])
@@ -1234,37 +1291,37 @@ def setUp(self):
12341291

12351292
def test_dispatch_invocation_start_info(self):
12361293
with _invocation(self.executor, self.plugin):
1237-
self.executor.execute_plugins(INVOCATION_START_INFO, sync=True)
1294+
self.executor.execute_plugins(INVOCATION_START_INFO)
12381295
self.assertIn("invocation_start:req-1", self.plugin.calls)
12391296

12401297
def test_dispatch_invocation_end_info(self):
12411298
with _invocation(self.executor, self.plugin):
1242-
self.executor.execute_plugins(INVOCATION_END_INFO, sync=True)
1299+
self.executor.execute_plugins(INVOCATION_END_INFO)
12431300
self.assertIn("invocation_end:req-1", self.plugin.calls)
12441301

12451302
def test_dispatch_operation_end_info(self):
12461303
with _invocation(self.executor, self.plugin):
1247-
self.executor.execute_plugins(OPERATION_END_INFO, sync=False)
1304+
self.executor.execute_plugins(OPERATION_END_INFO)
12481305
self.assertIn("operation_end:op-1", self.plugin.calls)
12491306

12501307
def test_dispatch_operation_start_info(self):
12511308
with _invocation(self.executor, self.plugin):
1252-
self.executor.execute_plugins(OPERATION_START_INFO, sync=False)
1309+
self.executor.execute_plugins(OPERATION_START_INFO)
12531310
self.assertIn("operation_start:op-2", self.plugin.calls)
12541311

12551312
def test_dispatch_operation_change_info(self):
12561313
with _invocation(self.executor, self.plugin):
1257-
self.executor.execute_plugins(OPERATION_CHANGE_INFO, sync=False)
1314+
self.executor.execute_plugins(OPERATION_CHANGE_INFO)
12581315
self.assertIn("operation_change:op-1", self.plugin.calls)
12591316

12601317
def test_dispatch_user_function_start_info(self):
12611318
with _invocation(self.executor, self.plugin):
1262-
self.executor.execute_plugins(USER_FUNCTION_START_INFO, sync=True)
1319+
self.executor.execute_plugins(USER_FUNCTION_START_INFO)
12631320
self.assertIn("user_function_start:op-1", self.plugin.calls)
12641321

12651322
def test_dispatch_user_function_end_info(self):
12661323
with _invocation(self.executor, self.plugin):
1267-
self.executor.execute_plugins(USER_FUNCTION_END_INFO, sync=True)
1324+
self.executor.execute_plugins(USER_FUNCTION_END_INFO)
12681325
self.assertIn("user_function_end:op-1", self.plugin.calls)
12691326

12701327
def test_dispatch_unknown_type_logs_exception(self):
@@ -1273,7 +1330,7 @@ def test_dispatch_unknown_type_logs_exception(self):
12731330
"aws_durable_execution_sdk_python.plugin", level=logging.ERROR
12741331
):
12751332
with _invocation(self.executor, self.plugin):
1276-
self.executor.execute_plugins("not a valid info type", sync=True)
1333+
self.executor.execute_plugins("not a valid info type")
12771334

12781335
def test_plugin_exception_is_swallowed(self):
12791336
"""If a plugin raises, the exception is logged and execution continues."""
@@ -1287,7 +1344,7 @@ def test_plugin_exception_is_swallowed(self):
12871344
"aws_durable_execution_sdk_python.plugin", level=logging.ERROR
12881345
):
12891346
with _invocation(executor, tracking_plugin):
1290-
executor.execute_plugins(OPERATION_START_INFO, sync=True)
1347+
executor.execute_plugins(OPERATION_START_INFO)
12911348

12921349
# The second plugin should still have been called
12931350
self.assertIn("operation_start:op-2", tracking_plugin.calls)
@@ -1298,7 +1355,7 @@ def test_multiple_plugins_all_called(self):
12981355
executor = PluginExecutor(plugins=[plugin_factory(p1), plugin_factory(p2)])
12991356

13001357
with _invocation(executor, p1, p2):
1301-
executor.execute_plugins(OPERATION_START_INFO, sync=True)
1358+
executor.execute_plugins(OPERATION_START_INFO)
13021359

13031360
self.assertIn("operation_start:op-2", p1.calls)
13041361
self.assertIn("operation_start:op-2", p2.calls)

0 commit comments

Comments
 (0)