From 16680237d20196a91f9482a46de6990b7cb6478c Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 18 Sep 2025 10:58:58 -0500 Subject: [PATCH 1/4] Reproduce `sentinel` context Reproduction: ``` SYNAPSE_TEST_LOG_LEVEL=INFO poetry run trial tests.rest.client.test_delayed_events.DelayedEventsTestCase.test_cancel_delayed_state_event ``` Check `_trial_temp/test.log` (notice the `sentinel` log context) ``` 2025-09-18 10:58:23-0500 [-] synapse.handlers.delayed_events - 339 - INFO - POST-11 - asdf cancelling delayed event before _initialized_from_db syd_OlmchCwyUqznIXhlTDXQ ... 2025-09-18 10:58:23-0500 [-] synapse.handlers.delayed_events - 124 - INFO - _schedule_db_events-0 - asdf done _initialized_from_db 2025-09-18 10:58:23-0500 [-] synapse.handlers.delayed_events - 344 - INFO - sentinel - asdf cancelling delayed event after _initialized_from_db syd_OlmchCwyUqznIXhlTDXQ ``` --- synapse/handlers/delayed_events.py | 17 ++++++++++++++++- 1 file changed, 16 insertions(+), 1 deletion(-) diff --git a/synapse/handlers/delayed_events.py b/synapse/handlers/delayed_events.py index a6749801a50..9f739603ea7 100644 --- a/synapse/handlers/delayed_events.py +++ b/synapse/handlers/delayed_events.py @@ -23,7 +23,10 @@ from synapse.config.workers import MAIN_PROCESS_INSTANCE_NAME from synapse.logging.opentracing import set_tag from synapse.metrics import SERVER_NAME_LABEL, event_processing_positions -from synapse.metrics.background_process_metrics import run_as_background_process +from synapse.metrics.background_process_metrics import ( + run_as_background_process, +) +from synapse.logging.context import make_deferred_yieldable from synapse.replication.http.delayed_events import ( ReplicationAddedDelayedEventRestServlet, ) @@ -115,6 +118,11 @@ async def _schedule_db_events() -> None: events, ) + await self._clock.sleep(1) + await self._clock.sleep(0.3) + # await self._clock.sleep(0.1) + logger.info("asdf done _initialized_from_db") + self._initialized_from_db = run_as_background_process( "_schedule_db_events", self.server_name, _schedule_db_events ) @@ -328,7 +336,14 @@ async def cancel(self, requester: Requester, delay_id: str) -> None: requester, (requester.user.to_string(), requester.device_id), ) + logger.info( + "asdf cancelling delayed event before _initialized_from_db %s", delay_id + ) await self._initialized_from_db + # await make_deferred_yieldable(self._initialized_from_db) + logger.info( + "asdf cancelling delayed event after _initialized_from_db %s", delay_id + ) next_send_ts = await self._store.cancel_delayed_event( delay_id=delay_id, From 1b931b195fed5002a33e1d49239980ad9ac83ff3 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 18 Sep 2025 11:01:37 -0500 Subject: [PATCH 2/4] Cleanup --- synapse/handlers/delayed_events.py | 18 +++--------------- 1 file changed, 3 insertions(+), 15 deletions(-) diff --git a/synapse/handlers/delayed_events.py b/synapse/handlers/delayed_events.py index 9f739603ea7..f7346cc848a 100644 --- a/synapse/handlers/delayed_events.py +++ b/synapse/handlers/delayed_events.py @@ -118,11 +118,6 @@ async def _schedule_db_events() -> None: events, ) - await self._clock.sleep(1) - await self._clock.sleep(0.3) - # await self._clock.sleep(0.1) - logger.info("asdf done _initialized_from_db") - self._initialized_from_db = run_as_background_process( "_schedule_db_events", self.server_name, _schedule_db_events ) @@ -336,14 +331,7 @@ async def cancel(self, requester: Requester, delay_id: str) -> None: requester, (requester.user.to_string(), requester.device_id), ) - logger.info( - "asdf cancelling delayed event before _initialized_from_db %s", delay_id - ) - await self._initialized_from_db - # await make_deferred_yieldable(self._initialized_from_db) - logger.info( - "asdf cancelling delayed event after _initialized_from_db %s", delay_id - ) + await make_deferred_yieldable(self._initialized_from_db) next_send_ts = await self._store.cancel_delayed_event( delay_id=delay_id, @@ -369,7 +357,7 @@ async def restart(self, requester: Requester, delay_id: str) -> None: requester, (requester.user.to_string(), requester.device_id), ) - await self._initialized_from_db + await make_deferred_yieldable(self._initialized_from_db) next_send_ts = await self._store.restart_delayed_event( delay_id=delay_id, @@ -395,7 +383,7 @@ async def send(self, requester: Requester, delay_id: str) -> None: # Use standard request limiter for sending delayed events on-demand, # as an on-demand send is similar to sending a regular event. await self._request_ratelimiter.ratelimit(requester) - await self._initialized_from_db + await make_deferred_yieldable(self._initialized_from_db) event, next_send_ts = await self._store.process_target_delayed_event( delay_id=delay_id, From cfb3ee517a4ca4dcb56be0b417ab1084d4d25af5 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 18 Sep 2025 11:20:17 -0500 Subject: [PATCH 3/4] Fix lints --- synapse/handlers/delayed_events.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/handlers/delayed_events.py b/synapse/handlers/delayed_events.py index f7346cc848a..fa24014438a 100644 --- a/synapse/handlers/delayed_events.py +++ b/synapse/handlers/delayed_events.py @@ -21,12 +21,12 @@ from synapse.api.errors import ShadowBanError from synapse.api.ratelimiting import Ratelimiter from synapse.config.workers import MAIN_PROCESS_INSTANCE_NAME +from synapse.logging.context import make_deferred_yieldable from synapse.logging.opentracing import set_tag from synapse.metrics import SERVER_NAME_LABEL, event_processing_positions from synapse.metrics.background_process_metrics import ( run_as_background_process, ) -from synapse.logging.context import make_deferred_yieldable from synapse.replication.http.delayed_events import ( ReplicationAddedDelayedEventRestServlet, ) From 140093571f0f5d2859edf448598bce8f3c9c33f0 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 18 Sep 2025 17:33:07 -0500 Subject: [PATCH 4/4] Add changelog --- changelog.d/18938.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/18938.misc diff --git a/changelog.d/18938.misc b/changelog.d/18938.misc new file mode 100644 index 00000000000..ab31cb72996 --- /dev/null +++ b/changelog.d/18938.misc @@ -0,0 +1 @@ +Fix `run_as_background_process` not be awaited properly causing `LoggingContext` problems in experimental [MSC4140](https://github.com/matrix-org/matrix-spec-proposals/pull/4140): Delayed events implementation.