From 5eea20ad0130fefe88c4c2ab236090c1edbf7500 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 21 Oct 2025 15:54:58 -0500 Subject: [PATCH 01/17] Add reproduction test for scenario 1 (not fire-and-forget) --- synapse/logging/context.py | 22 ++++++++--- tests/unittest.py | 3 ++ tests/util/test_async_helpers.py | 64 +++++++++++++++++++++++++++++++- 3 files changed, 82 insertions(+), 7 deletions(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 1b9c7703119..70f42853bc6 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -898,7 +898,7 @@ def run_in_background( # If the function messes with logcontexts, we can assume it follows the Synapse # logcontext rules (Rules for functions returning awaitables: "If the awaitable # is already complete, the function returns with the same logcontext it started - # with."). If it function doesn't touch logcontexts at all, we can also assume + # with."). If the function doesn't touch logcontexts at all, we can also assume # the logcontext is unchanged. # # Either way, the function should have maintained the calling logcontext, so we @@ -907,11 +907,21 @@ def run_in_background( # to reset the logcontext to the sentinel logcontext as that would run # immediately (remember our goal is to maintain the calling logcontext when we # return). - logcontext_debug_logger.debug( - "run_in_background(%s): deferred already completed and the function should have maintained the logcontext %s", - instance_id, - calling_context, - ) + if current_context() != calling_context: + logcontext_error( + "run_in_background(%s): deferred already completed but the function did not maintain the calling logcontext %s (found %s)" + % ( + instance_id, + calling_context, + current_context(), + ) + ) + else: + logcontext_debug_logger.debug( + "run_in_background(%s): deferred already completed and the function should have maintained the calling logcontext %s", + instance_id, + calling_context, + ) return d # Since the function we called may follow the Synapse logcontext rules (Rules for diff --git a/tests/unittest.py b/tests/unittest.py index 9ab052e7c0c..1970fbc0bc2 100644 --- a/tests/unittest.py +++ b/tests/unittest.py @@ -345,6 +345,9 @@ def logcontext_clean(target: TV) -> TV: """ def logcontext_error(msg: str) -> NoReturn: + # Log so we can still see it in the logs like normal + logger.warning(msg) + # But also fail the test raise AssertionError("logcontext error: %s" % (msg)) patcher = patch("synapse.logging.context.logcontext_error", new=logcontext_error) diff --git a/tests/util/test_async_helpers.py b/tests/util/test_async_helpers.py index fd8d576aea8..4bc4c4aef51 100644 --- a/tests/util/test_async_helpers.py +++ b/tests/util/test_async_helpers.py @@ -26,6 +26,7 @@ from twisted.internet import defer from twisted.internet.defer import CancelledError, Deferred, ensureDeferred from twisted.python.failure import Failure +from tests.unittest import logcontext_clean from synapse.logging.context import ( SENTINEL_CONTEXT, @@ -198,7 +199,12 @@ def canceller(_d: Deferred) -> None: self.failureResultOf(timing_out_d, defer.TimeoutError) - async def test_logcontext_is_preserved_on_cancellation(self) -> None: + @logcontext_clean + async def test_logcontext_is_preserved_on_timeout_cancellation(self) -> None: + """ + Test that the logcontext is preserved when we timeout and the deferred is + cancelled. + """ # Sanity check that we start in the sentinel context self.assertEqual(current_context(), SENTINEL_CONTEXT) @@ -270,6 +276,62 @@ def mark_was_cancelled(res: Failure) -> None: # Back to the sentinel context self.assertEqual(current_context(), SENTINEL_CONTEXT) + @logcontext_clean + async def test_logcontext_is_not_lost_when_awaiting_on_timeout_cancellation( + self, + ) -> None: + """ + Test that the logcontext isn't lost when we `await` the deferred to + complete/timeout and it times out. + """ + + # Sanity check that we start in the sentinel context + self.assertEqual(current_context(), SENTINEL_CONTEXT) + + # Create a deferred which we will never complete + incomplete_d: Deferred = Deferred() + + async def competing_task() -> None: + with LoggingContext(name="one", server_name="test_server") as context_one: + timing_out_d = timeout_deferred( + deferred=incomplete_d, + timeout=1.0, + clock=self.clock, + ) + self.assertNoResult(timing_out_d) + # We should still be in the logcontext we started in + self.assertIs(current_context(), context_one) + + # Mimic the normal use case to wait for the work to complete or timeout. + # + # We expect the deferred to timeout and raise an exception at this + # point. + await make_deferred_yieldable(timing_out_d) + + # We're still in the same logcontext + self.assertIs(current_context(), context_one) + + d = defer.ensureDeferred(competing_task()) + + # Still in the sentinel context + self.assertEqual(current_context(), SENTINEL_CONTEXT) + + # Pump until we trigger the timeout + self.reactor.pump( + # We only need to pump `1.0` (seconds) as we set + # `timeout_deferred(timeout=1.0)` above + (1.0,) + ) + + # Still in the sentinel context + self.assertEqual(current_context(), SENTINEL_CONTEXT) + + # We expect a failure due to the timeout + self.failureResultOf(d, defer.TimeoutError) + + # Back to the sentinel context at the end of the day + self.assertEqual(current_context(), SENTINEL_CONTEXT) + class _TestException(Exception): # pass From 6be53d8528521d61813d33a942da8a9afb57371c Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 21 Oct 2025 15:55:54 -0500 Subject: [PATCH 02/17] Messing around in situ --- synapse/http/client.py | 4 ++-- synapse/rest/client/versions.py | 28 ++++++++++++++++++++++++++++ tests/test_utils/logging_setup.py | 3 +++ 3 files changed, 33 insertions(+), 2 deletions(-) diff --git a/synapse/http/client.py b/synapse/http/client.py index 370cdc3568b..12a55fcf32c 100644 --- a/synapse/http/client.py +++ b/synapse/http/client.py @@ -412,7 +412,7 @@ async def request( if data is not None: body_producer = QuieterFileBodyProducer( BytesIO(data), - cooperator=self._cooperator, + # cooperator=self._cooperator, ) # Always make sure we add a user agent to the request @@ -438,7 +438,7 @@ async def request( # for https://twistedmatrix.com/trac/ticket/9534. request_deferred = timeout_deferred( deferred=request_deferred, - timeout=60, + timeout=2, clock=self.hs.get_clock(), ) diff --git a/synapse/rest/client/versions.py b/synapse/rest/client/versions.py index 20395430d70..7383aa0dc5c 100644 --- a/synapse/rest/client/versions.py +++ b/synapse/rest/client/versions.py @@ -47,6 +47,7 @@ def __init__(self, hs: "HomeServer"): self.config = hs.config self.auth = hs.get_auth() self.store = hs.get_datastores().main + self.http_client = hs.get_proxied_blocklisted_http_client() # Calculate these once since they shouldn't change after start-up. self.e2ee_forced_public = ( @@ -63,6 +64,33 @@ def __init__(self, hs: "HomeServer"): ) async def on_GET(self, request: SynapseRequest) -> Tuple[int, JsonDict]: + logger.info("asdf before test") + try: + from twisted.internet import defer + + async def _catch_errors(task: defer.Deferred, url: str): + try: + await task + except Exception: + logger.exception("Error in async callback (POST %s)", url) + + stub_url = "http://localhost:3000/post" + await self.http_client.post_json_get_json( + uri=stub_url, post_json="{}", headers=None + ) + # task = self.http_client.post_json_get_json( + # uri=stub_url, post_json="{}", headers=None + # ) + # await task + # if False: + # defer.ensureDeferred(_catch_errors(task, stub_url)) + # else: + # await task + except Exception as exc: + logger.exception("asdf exception during test: %s", exc) + finally: + logger.info("asdf after test") + msc3881_enabled = self.config.experimental.msc3881_enabled msc3575_enabled = self.config.experimental.msc3575_enabled diff --git a/tests/test_utils/logging_setup.py b/tests/test_utils/logging_setup.py index d58222a9f6b..7d4650dbfe5 100644 --- a/tests/test_utils/logging_setup.py +++ b/tests/test_utils/logging_setup.py @@ -59,6 +59,9 @@ def setup_logging() -> None: log_level = os.environ.get("SYNAPSE_TEST_LOG_LEVEL", "ERROR") root_logger.setLevel(log_level) + # TODO: Remove + logging.getLogger("synapse.logging.context.debug").setLevel(logging.DEBUG) + # In order to not add noise by default (since we only log ERROR messages for trial # tests as configured above), we only enable this for developers for looking for # more INFO or DEBUG. From 947819432efda16914357a22f419792c40e53f2f Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 21 Oct 2025 16:50:28 -0500 Subject: [PATCH 03/17] Better logcontext names in tests --- tests/util/test_async_helpers.py | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/tests/util/test_async_helpers.py b/tests/util/test_async_helpers.py index 4bc4c4aef51..575ba9d06b9 100644 --- a/tests/util/test_async_helpers.py +++ b/tests/util/test_async_helpers.py @@ -292,7 +292,9 @@ async def test_logcontext_is_not_lost_when_awaiting_on_timeout_cancellation( incomplete_d: Deferred = Deferred() async def competing_task() -> None: - with LoggingContext(name="one", server_name="test_server") as context_one: + with LoggingContext( + name="competing", server_name="test_server" + ) as context_competing: timing_out_d = timeout_deferred( deferred=incomplete_d, timeout=1.0, @@ -300,16 +302,16 @@ async def competing_task() -> None: ) self.assertNoResult(timing_out_d) # We should still be in the logcontext we started in - self.assertIs(current_context(), context_one) + self.assertIs(current_context(), context_competing) # Mimic the normal use case to wait for the work to complete or timeout. # - # We expect the deferred to timeout and raise an exception at this - # point. + # In this specific test, we expect the deferred to timeout and raise an + # exception at this point. await make_deferred_yieldable(timing_out_d) # We're still in the same logcontext - self.assertIs(current_context(), context_one) + self.assertIs(current_context(), context_competing) d = defer.ensureDeferred(competing_task()) From 33776c0685202cb9f0d6f0b3a9be6144fe3df9c2 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 21 Oct 2025 22:11:43 -0500 Subject: [PATCH 04/17] WIP: tests --- synapse/util/async_helpers.py | 10 +- tests/util/test_async_helpers.py | 1 + tests/util/test_logcontext.py | 171 +++++++++++++++++++++++++++++++ 3 files changed, 181 insertions(+), 1 deletion(-) diff --git a/synapse/util/async_helpers.py b/synapse/util/async_helpers.py index 2a167f209cb..cb6593c8a08 100644 --- a/synapse/util/async_helpers.py +++ b/synapse/util/async_helpers.py @@ -812,7 +812,15 @@ def time_it_out() -> None: timed_out[0] = True try: - deferred.cancel() + logger.info("asdf timeout_deferred cancel") + # with PreserveLoggingContext(): + # deferred.cancel() + # The whole lambda will be run in the current logcontext. But we're using a + # trick to return the deferred itself so that `run_in_background` will wait + # on that to complete and reset the logcontext back to the calling + # logcontext when it does to avoid leaking the current logcontext into the + # reactor. + run_in_background(lambda: (deferred.cancel(), deferred)[1]) except Exception: # if we throw any exception it'll break time outs logger.exception("Canceller failed during timeout") diff --git a/tests/util/test_async_helpers.py b/tests/util/test_async_helpers.py index 575ba9d06b9..b4206d10599 100644 --- a/tests/util/test_async_helpers.py +++ b/tests/util/test_async_helpers.py @@ -308,6 +308,7 @@ async def competing_task() -> None: # # In this specific test, we expect the deferred to timeout and raise an # exception at this point. + logger.info("asdf awaiting make_deferred_yieldable") await make_deferred_yieldable(timing_out_d) # We're still in the same logcontext diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index ca805bb20a0..234664a6e89 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -23,6 +23,7 @@ from typing import Callable, Generator, cast from twisted.internet import defer, reactor as _reactor +from twisted.internet.defer import CancelledError, Deferred from synapse.logging.context import ( SENTINEL_CONTEXT, @@ -456,6 +457,105 @@ async def competing_callback() -> None: # Back to the sentinel context self._check_test_key("sentinel") + @logcontext_clean + async def test_deferred_callback_fire_and_forget_with_current_context_asdf( + self, + ) -> None: + """ + Test that it's possible to call the deferred callback with the current context + while fire-and-forgetting the callback (no adverse effects like leaking the + logcontext into the reactor or restarting an already finished logcontext). + + Demonstrates one pattern that we can use fix the naive case where we just call + `d.callback(None)` without anything else. See the *Deferred callbacks* section + of docs/log_contexts.md for more details. + """ + # Ignore linter error since we are creating a `Clock` for testing purposes. + clock = Clock(reactor, server_name="test_server") # type: ignore[multiple-internal-clocks] + + # Sanity check that we start in the sentinel context + self._check_test_key("sentinel") + + callback_finished = False + + async def competing_callback() -> None: + nonlocal callback_finished + try: + # The deferred callback should have the same logcontext as the caller + self._check_test_key("foo") + + with LoggingContext(name="competing", server_name="test_server"): + await clock.sleep(0) + self._check_test_key("competing") + + self._check_test_key("foo") + finally: + # When exceptions happen, we still want to mark the callback as finished + # so that the test can complete and we see the underlying error. + callback_finished = True + + def competing_callback2() -> None: + nonlocal callback_finished + try: + with LoggingContext(name="competing2", server_name="test_server"): + # clock.call_later( + # 0, lambda: defer.ensureDeferred(competing_callback()) + # ) + pass + finally: + # When exceptions happen, we still want to mark the callback as finished + # so that the test can complete and we see the underlying error. + callback_finished = True + + # Part of fix for the naive case is here (i.e. things don't work correctly if we + # don't `PreserveLoggingContext(...)` here). + # + # We can extend the lifetime of the "foo" logcontext is to avoid calling the + # context manager lifetime methods of `LoggingContext` (`__enter__`/`__exit__`). + # And we can still set the current logcontext by using `PreserveLoggingContext` + # and passing in the "foo" logcontext. + with PreserveLoggingContext( + LoggingContext(name="foo", server_name="test_server") + ): + d: defer.Deferred[None] = defer.Deferred() + # d.addErrback(lambda _: defer.ensureDeferred(competing_callback())) + d.addErrback(lambda _: competing_callback2()) + # make_deferred_yieldable(d) + self._check_test_key("foo") + # Other part of fix for the naive case is here (i.e. things don't work + # correctly if we don't `run_in_background(...)` here). + # + # `run_in_background(...)` will run the whole lambda in the current + # logcontext and it handles the magic behind the scenes of a) restoring the + # calling logcontext before returning to the caller and b) resetting the + # logcontext to the sentinel after the deferred completes and we yield + # control back to the reactor to avoid leaking the logcontext into the + # reactor. + # + # We're using a lambda here as a little trick so we can still get everything + # to run in the "foo" logcontext, but return the deferred `d` itself so that + # `run_in_background` will wait on that to complete before resetting the + # logcontext to the sentinel. + # + # type-ignore[call-overload]: This appears like a mypy type inference bug. A + # function that returns a deferred is exactly what `run_in_background` + # expects. + # + # type-ignore[func-returns-value]: This appears like a mypy type inference + # bug. We're always returning the deferred `d`. + run_in_background(lambda: (d.cancel(), d)[1]) # type: ignore[call-overload, func-returns-value] + self._check_test_key("foo") + + await clock.sleep(0) + + self.assertTrue( + callback_finished, + "Callback never finished which means the test probably didn't wait long enough", + ) + + # Back to the sentinel context + self._check_test_key("sentinel") + async def _test_run_in_background(self, function: Callable[[], object]) -> None: # Ignore linter error since we are creating a `Clock` for testing purposes. clock = Clock(reactor, server_name="test_server") # type: ignore[multiple-internal-clocks] @@ -688,6 +788,77 @@ def test_make_deferred_yieldable_with_chained_deferreds( # now it should be restored self._check_test_key("foo") + # @logcontext_clean + async def test_make_deferred_yieldable_asdf(self) -> None: + # Ignore linter error since we are creating a `Clock` for testing purposes. + clock = Clock(reactor, server_name="test_server") # type: ignore[multiple-internal-clocks] + + # Sanity check that we start in the sentinel context + self.assertEqual(current_context(), SENTINEL_CONTEXT) + + # Create a deferred which we will never complete + incomplete_d: Deferred = Deferred() + + async def competing_task() -> None: + with LoggingContext( + name="competing", server_name="test_server" + ) as context_competing: + self.assertNoResult(incomplete_d) + # We should still be in the logcontext we started in + self.assertIs(current_context(), context_competing) + + # Mimic the normal use case to wait for the work to complete or timeout. + # + # In this specific test, we expect the deferred to timeout and raise an + # exception at this point. + logger.info("asdf awaiting make_deferred_yieldable") + await make_deferred_yieldable(incomplete_d) + + # We're still in the same logcontext + self.assertIs(current_context(), context_competing) + + # with LoggingContext(name="foo", server_name="test_server"): + with PreserveLoggingContext( + LoggingContext(name="foo", server_name="test_server") + ): + # d = defer.ensureDeferred(competing_task()) + d = run_in_background(competing_task) + # reactor.callLater(0, lambda: defer.ensureDeferred(competing_task())) + await clock.sleep(0) + + logger.info("asdf 1") + + self._check_test_key("foo") + + # Pump the competing task a bit + # await clock.sleep(0) + + # Cancel the deferred + logger.info("asdf going to cancel incomplete_d") + # incomplete_d.cancel() + # with PreserveLoggingContext(): + # incomplete_d.cancel() + # await run_in_background(lambda: (incomplete_d.cancel(), incomplete_d)[1]) + + def _cancel_d() -> None: + logger.info("asdf before cancel") + incomplete_d.cancel() + logger.info("asdf after cancel") + + await run_in_background(lambda: (_cancel_d(), incomplete_d)[1]) + + logger.info("asdf 2") + + self._check_test_key("foo") + + # We expect a failure due to the timeout + self.failureResultOf(d, defer.CancelledError) + + self._check_test_key("foo") + + # Back to the sentinel context at the end of the day + self.assertEqual(current_context(), SENTINEL_CONTEXT) + @logcontext_clean def test_nested_logging_context(self) -> None: with LoggingContext(name="foo", server_name="test_server"): From 4b9441e9988c9ceca1e688704e359bd38bebf772 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 21 Oct 2025 23:21:40 -0500 Subject: [PATCH 05/17] Transparent deferred callback/errback when we `_set_context_cb` --- synapse/logging/context.py | 24 +++++++++++++++++++++++- 1 file changed, 23 insertions(+), 1 deletion(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 70f42853bc6..8cbc8280be7 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -52,6 +52,7 @@ from typing_extensions import ParamSpec from twisted.internet import defer, threads +from twisted.python.failure import Failure from twisted.python.threadpool import ThreadPool from synapse.logging.loggers import ExplicitlyConfiguredLogger @@ -963,6 +964,12 @@ def _log_set_context_cb( context, ) set_current_context(context) + + # Re-raise the exception so that any further errbacks can do their thing as + # normal + if isinstance(result, Failure): + result.raiseException() + # Otherwise, pass the result through return result d.addBoth(_log_set_context_cb, SENTINEL_CONTEXT) @@ -1069,6 +1076,12 @@ def _log_set_context_cb( context, ) set_current_context(context) + + # Re-raise the exception so that any further errbacks can do their thing as + # normal + if isinstance(result, Failure): + result.raiseException() + # Otherwise, pass the result through return result deferred.addBoth(_log_set_context_cb, calling_context) @@ -1082,8 +1095,17 @@ def _log_set_context_cb( def _set_context_cb(result: ResultT, context: LoggingContextOrSentinel) -> ResultT: - """A callback function which just sets the logging context""" + """ + A transparent passthrough deferred callback/errback which sets the logging context + """ set_current_context(context) + + # Re-raise the exception so that any further errbacks can do their thing as + # normal + if isinstance(result, Failure): + result.raiseException() + + # Otherwise, pass the result through return result From 630792c282a9fd232b987df94fbc18fe3d321d6c Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 21 Oct 2025 23:22:11 -0500 Subject: [PATCH 06/17] Revert "Transparent deferred callback/errback when we `_set_context_cb`" This reverts commit 4b9441e9988c9ceca1e688704e359bd38bebf772. --- synapse/logging/context.py | 24 +----------------------- 1 file changed, 1 insertion(+), 23 deletions(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 8cbc8280be7..70f42853bc6 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -52,7 +52,6 @@ from typing_extensions import ParamSpec from twisted.internet import defer, threads -from twisted.python.failure import Failure from twisted.python.threadpool import ThreadPool from synapse.logging.loggers import ExplicitlyConfiguredLogger @@ -964,12 +963,6 @@ def _log_set_context_cb( context, ) set_current_context(context) - - # Re-raise the exception so that any further errbacks can do their thing as - # normal - if isinstance(result, Failure): - result.raiseException() - # Otherwise, pass the result through return result d.addBoth(_log_set_context_cb, SENTINEL_CONTEXT) @@ -1076,12 +1069,6 @@ def _log_set_context_cb( context, ) set_current_context(context) - - # Re-raise the exception so that any further errbacks can do their thing as - # normal - if isinstance(result, Failure): - result.raiseException() - # Otherwise, pass the result through return result deferred.addBoth(_log_set_context_cb, calling_context) @@ -1095,17 +1082,8 @@ def _log_set_context_cb( def _set_context_cb(result: ResultT, context: LoggingContextOrSentinel) -> ResultT: - """ - A transparent passthrough deferred callback/errback which sets the logging context - """ + """A callback function which just sets the logging context""" set_current_context(context) - - # Re-raise the exception so that any further errbacks can do their thing as - # normal - if isinstance(result, Failure): - result.raiseException() - - # Otherwise, pass the result through return result From 73080af49422ab888d2c7b13e4f1c7da0f97502b Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Tue, 21 Oct 2025 23:22:23 -0500 Subject: [PATCH 07/17] More test twiddling --- tests/util/test_async_helpers.py | 3 +- tests/util/test_logcontext.py | 111 +++++++++++++++++++++++++++---- 2 files changed, 98 insertions(+), 16 deletions(-) diff --git a/tests/util/test_async_helpers.py b/tests/util/test_async_helpers.py index b4206d10599..257a62a2b22 100644 --- a/tests/util/test_async_helpers.py +++ b/tests/util/test_async_helpers.py @@ -26,7 +26,6 @@ from twisted.internet import defer from twisted.internet.defer import CancelledError, Deferred, ensureDeferred from twisted.python.failure import Failure -from tests.unittest import logcontext_clean from synapse.logging.context import ( SENTINEL_CONTEXT, @@ -46,7 +45,7 @@ ) from tests.server import get_clock -from tests.unittest import TestCase +from tests.unittest import TestCase, logcontext_clean logger = logging.getLogger(__name__) diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index 234664a6e89..0a68eec7aed 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -23,11 +23,13 @@ from typing import Callable, Generator, cast from twisted.internet import defer, reactor as _reactor -from twisted.internet.defer import CancelledError, Deferred +from twisted.internet.defer import Deferred +from twisted.python.failure import Failure from synapse.logging.context import ( SENTINEL_CONTEXT, LoggingContext, + LoggingContextOrSentinel, PreserveLoggingContext, _Sentinel, current_context, @@ -457,7 +459,7 @@ async def competing_callback() -> None: # Back to the sentinel context self._check_test_key("sentinel") - @logcontext_clean + # @logcontext_clean async def test_deferred_callback_fire_and_forget_with_current_context_asdf( self, ) -> None: @@ -519,7 +521,8 @@ def competing_callback2() -> None: ): d: defer.Deferred[None] = defer.Deferred() # d.addErrback(lambda _: defer.ensureDeferred(competing_callback())) - d.addErrback(lambda _: competing_callback2()) + # d.addErrback(lambda _: competing_callback2()) + d.addErrback(lambda _: make_deferred_yieldable(d)) # make_deferred_yieldable(d) self._check_test_key("foo") # Other part of fix for the naive case is here (i.e. things don't work @@ -789,7 +792,7 @@ def test_make_deferred_yieldable_with_chained_deferreds( self._check_test_key("foo") # @logcontext_clean - async def test_make_deferred_yieldable_asdf(self) -> None: + async def test_make_deferred_yieldable_asdf1(self) -> None: # Ignore linter error since we are creating a `Clock` for testing purposes. clock = Clock(reactor, server_name="test_server") # type: ignore[multiple-internal-clocks] @@ -799,6 +802,18 @@ async def test_make_deferred_yieldable_asdf(self) -> None: # Create a deferred which we will never complete incomplete_d: Deferred = Deferred() + errback_logcontext: LoggingContextOrSentinel = None + + def check_errback_logcontext(res: Failure) -> None: + nonlocal errback_logcontext + errback_logcontext = current_context() + + # Re-raise the exception so that any further errbacks can do their thing as + # normal + res.raiseException() + + incomplete_d.addErrback(check_errback_logcontext) + async def competing_task() -> None: with LoggingContext( name="competing", server_name="test_server" @@ -811,11 +826,15 @@ async def competing_task() -> None: # # In this specific test, we expect the deferred to timeout and raise an # exception at this point. - logger.info("asdf awaiting make_deferred_yieldable") + logger.info( + "asdf before awaiting make_deferred_yieldable incomplete_d=%s", + incomplete_d, + ) await make_deferred_yieldable(incomplete_d) - # We're still in the same logcontext - self.assertIs(current_context(), context_competing) + self.fail( + "Did not expect to make it past this point as the `incomplete_d` should have been cancelled" + ) # with LoggingContext(name="foo", server_name="test_server"): with PreserveLoggingContext( @@ -838,21 +857,85 @@ async def competing_task() -> None: # incomplete_d.cancel() # with PreserveLoggingContext(): # incomplete_d.cancel() - # await run_in_background(lambda: (incomplete_d.cancel(), incomplete_d)[1]) + await run_in_background(lambda: (incomplete_d.cancel(), incomplete_d)[1]) + # await run_in_background( + # lambda: (incomplete_d.callback(None), incomplete_d)[1] + # ) - def _cancel_d() -> None: - logger.info("asdf before cancel") - incomplete_d.cancel() - logger.info("asdf after cancel") + # def _cancel_d() -> None: + # logger.info("asdf before cancel") + # incomplete_d.cancel() + # logger.info("asdf after cancel") - await run_in_background(lambda: (_cancel_d(), incomplete_d)[1]) + # await run_in_background(lambda: (_cancel_d(), incomplete_d)[1]) logger.info("asdf 2") self._check_test_key("foo") + # Pump the competing task a bit + # await clock.sleep(0) + # await clock.sleep(0) + + # We expect a failure due to the timeout + # self.failureResultOf(d, defer.CancelledError) + self.successResultOf(d) + + self._check_test_key("foo") + + self.assertEqual(str(errback_logcontext), "foo") + + # Back to the sentinel context at the end of the day + self.assertEqual(current_context(), SENTINEL_CONTEXT) + + # @logcontext_clean + async def test_make_deferred_yieldable_asdf2(self) -> None: + # Ignore linter error since we are creating a `Clock` for testing purposes. + clock = Clock(reactor, server_name="test_server") # type: ignore[multiple-internal-clocks] + + # Sanity check that we start in the sentinel context + self.assertEqual(current_context(), SENTINEL_CONTEXT) + + # Create a deferred which we will never complete + incomplete_d: Deferred = Deferred() + + async def bbb() -> None: + logger.info("asdf before cancel") + # incomplete_d.cancel() + with PreserveLoggingContext(): + incomplete_d.cancel() + logger.info("asdf after cancel") + + async def competing_task() -> None: + with LoggingContext( + name="competing", server_name="test_server" + ) as context_competing: + self.assertNoResult(incomplete_d) + # We should still be in the logcontext we started in + self.assertIs(current_context(), context_competing) + + # Mimic the normal use case to wait for the work to complete or timeout. + # + # In this specific test, we expect the deferred to timeout and raise an + # exception at this point. + logger.info("asdf awaiting make_deferred_yieldable") + await make_deferred_yieldable(incomplete_d) + + # We're still in the same logcontext + self.assertIs(current_context(), context_competing) + + # with LoggingContext(name="foo", server_name="test_server"): + with PreserveLoggingContext( + LoggingContext(name="foo", server_name="test_server") + ): + # d = defer.ensureDeferred(competing_task()) + d1 = run_in_background(competing_task) + _d2 = run_in_background(bbb) + # reactor.callLater(0, lambda: defer.ensureDeferred(competing_task())) + await clock.sleep(0) + # We expect a failure due to the timeout - self.failureResultOf(d, defer.CancelledError) + self.failureResultOf(d1, defer.CancelledError) self._check_test_key("foo") From 5179ea34902746ccd9a970221653f529a41a7091 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 22 Oct 2025 00:13:51 -0500 Subject: [PATCH 08/17] Fix typo --- synapse/util/clock.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/util/clock.py b/synapse/util/clock.py index 5e65cf32a4b..737465f7f4d 100644 --- a/synapse/util/clock.py +++ b/synapse/util/clock.py @@ -268,7 +268,7 @@ def wrapped_callback(*args: Any, **kwargs: Any) -> None: # We use `PreserveLoggingContext` to prevent our new `call_later` # logcontext from finishing as soon as we exit this function, in case `f` # returns an awaitable/deferred which would continue running and may try to - # restore the `loop_call` context when it's done (because it's trying to + # restore the `call_later` context when it's done (because it's trying to # adhere to the Synapse logcontext rules.) # # This also ensures that we return to the `sentinel` context when we exit From 202906e4d8d852ddd74f69a4dc5f37565e5ff7be Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 22 Oct 2025 00:14:23 -0500 Subject: [PATCH 09/17] Further clean up test --- tests/util/test_async_helpers.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/tests/util/test_async_helpers.py b/tests/util/test_async_helpers.py index 257a62a2b22..9b20025cd0b 100644 --- a/tests/util/test_async_helpers.py +++ b/tests/util/test_async_helpers.py @@ -310,8 +310,9 @@ async def competing_task() -> None: logger.info("asdf awaiting make_deferred_yieldable") await make_deferred_yieldable(timing_out_d) - # We're still in the same logcontext - self.assertIs(current_context(), context_competing) + self.fail( + "We should not make it to this point as the `timing_out_d` should have been cancelled" + ) d = defer.ensureDeferred(competing_task()) From 0325f979a1a3298f2723831fb92848c8e0a0e7b4 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 22 Oct 2025 00:28:16 -0500 Subject: [PATCH 10/17] Fix comment --- synapse/util/async_helpers.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/synapse/util/async_helpers.py b/synapse/util/async_helpers.py index cb6593c8a08..91364b67b66 100644 --- a/synapse/util/async_helpers.py +++ b/synapse/util/async_helpers.py @@ -817,9 +817,8 @@ def time_it_out() -> None: # deferred.cancel() # The whole lambda will be run in the current logcontext. But we're using a # trick to return the deferred itself so that `run_in_background` will wait - # on that to complete and reset the logcontext back to the calling - # logcontext when it does to avoid leaking the current logcontext into the - # reactor. + # on that to complete and reset the logcontext to the sentinel when it does + # to avoid leaking the current logcontext into the reactor. run_in_background(lambda: (deferred.cancel(), deferred)[1]) except Exception: # if we throw any exception it'll break time outs logger.exception("Canceller failed during timeout") From 18ae299abef6c9706fb8f0d57067568dbe307003 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 22 Oct 2025 00:30:16 -0500 Subject: [PATCH 11/17] Just settle for good enough and works --- synapse/util/async_helpers.py | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-) diff --git a/synapse/util/async_helpers.py b/synapse/util/async_helpers.py index 91364b67b66..eaf8c28d25f 100644 --- a/synapse/util/async_helpers.py +++ b/synapse/util/async_helpers.py @@ -813,13 +813,8 @@ def time_it_out() -> None: try: logger.info("asdf timeout_deferred cancel") - # with PreserveLoggingContext(): - # deferred.cancel() - # The whole lambda will be run in the current logcontext. But we're using a - # trick to return the deferred itself so that `run_in_background` will wait - # on that to complete and reset the logcontext to the sentinel when it does - # to avoid leaking the current logcontext into the reactor. - run_in_background(lambda: (deferred.cancel(), deferred)[1]) + with PreserveLoggingContext(): + deferred.cancel() except Exception: # if we throw any exception it'll break time outs logger.exception("Canceller failed during timeout") From a31eadd2b59ff9c074a3f0c9762d98aa25be362d Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 22 Oct 2025 00:41:15 -0500 Subject: [PATCH 12/17] Remove cruft --- synapse/http/client.py | 4 +- synapse/rest/client/versions.py | 28 ---- tests/test_utils/logging_setup.py | 3 - tests/util/test_logcontext.py | 254 ------------------------------ 4 files changed, 2 insertions(+), 287 deletions(-) diff --git a/synapse/http/client.py b/synapse/http/client.py index 12a55fcf32c..370cdc3568b 100644 --- a/synapse/http/client.py +++ b/synapse/http/client.py @@ -412,7 +412,7 @@ async def request( if data is not None: body_producer = QuieterFileBodyProducer( BytesIO(data), - # cooperator=self._cooperator, + cooperator=self._cooperator, ) # Always make sure we add a user agent to the request @@ -438,7 +438,7 @@ async def request( # for https://twistedmatrix.com/trac/ticket/9534. request_deferred = timeout_deferred( deferred=request_deferred, - timeout=2, + timeout=60, clock=self.hs.get_clock(), ) diff --git a/synapse/rest/client/versions.py b/synapse/rest/client/versions.py index 7383aa0dc5c..20395430d70 100644 --- a/synapse/rest/client/versions.py +++ b/synapse/rest/client/versions.py @@ -47,7 +47,6 @@ def __init__(self, hs: "HomeServer"): self.config = hs.config self.auth = hs.get_auth() self.store = hs.get_datastores().main - self.http_client = hs.get_proxied_blocklisted_http_client() # Calculate these once since they shouldn't change after start-up. self.e2ee_forced_public = ( @@ -64,33 +63,6 @@ def __init__(self, hs: "HomeServer"): ) async def on_GET(self, request: SynapseRequest) -> Tuple[int, JsonDict]: - logger.info("asdf before test") - try: - from twisted.internet import defer - - async def _catch_errors(task: defer.Deferred, url: str): - try: - await task - except Exception: - logger.exception("Error in async callback (POST %s)", url) - - stub_url = "http://localhost:3000/post" - await self.http_client.post_json_get_json( - uri=stub_url, post_json="{}", headers=None - ) - # task = self.http_client.post_json_get_json( - # uri=stub_url, post_json="{}", headers=None - # ) - # await task - # if False: - # defer.ensureDeferred(_catch_errors(task, stub_url)) - # else: - # await task - except Exception as exc: - logger.exception("asdf exception during test: %s", exc) - finally: - logger.info("asdf after test") - msc3881_enabled = self.config.experimental.msc3881_enabled msc3575_enabled = self.config.experimental.msc3575_enabled diff --git a/tests/test_utils/logging_setup.py b/tests/test_utils/logging_setup.py index 7d4650dbfe5..d58222a9f6b 100644 --- a/tests/test_utils/logging_setup.py +++ b/tests/test_utils/logging_setup.py @@ -59,9 +59,6 @@ def setup_logging() -> None: log_level = os.environ.get("SYNAPSE_TEST_LOG_LEVEL", "ERROR") root_logger.setLevel(log_level) - # TODO: Remove - logging.getLogger("synapse.logging.context.debug").setLevel(logging.DEBUG) - # In order to not add noise by default (since we only log ERROR messages for trial # tests as configured above), we only enable this for developers for looking for # more INFO or DEBUG. diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index 0a68eec7aed..ca805bb20a0 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -23,13 +23,10 @@ from typing import Callable, Generator, cast from twisted.internet import defer, reactor as _reactor -from twisted.internet.defer import Deferred -from twisted.python.failure import Failure from synapse.logging.context import ( SENTINEL_CONTEXT, LoggingContext, - LoggingContextOrSentinel, PreserveLoggingContext, _Sentinel, current_context, @@ -459,106 +456,6 @@ async def competing_callback() -> None: # Back to the sentinel context self._check_test_key("sentinel") - # @logcontext_clean - async def test_deferred_callback_fire_and_forget_with_current_context_asdf( - self, - ) -> None: - """ - Test that it's possible to call the deferred callback with the current context - while fire-and-forgetting the callback (no adverse effects like leaking the - logcontext into the reactor or restarting an already finished logcontext). - - Demonstrates one pattern that we can use fix the naive case where we just call - `d.callback(None)` without anything else. See the *Deferred callbacks* section - of docs/log_contexts.md for more details. - """ - # Ignore linter error since we are creating a `Clock` for testing purposes. - clock = Clock(reactor, server_name="test_server") # type: ignore[multiple-internal-clocks] - - # Sanity check that we start in the sentinel context - self._check_test_key("sentinel") - - callback_finished = False - - async def competing_callback() -> None: - nonlocal callback_finished - try: - # The deferred callback should have the same logcontext as the caller - self._check_test_key("foo") - - with LoggingContext(name="competing", server_name="test_server"): - await clock.sleep(0) - self._check_test_key("competing") - - self._check_test_key("foo") - finally: - # When exceptions happen, we still want to mark the callback as finished - # so that the test can complete and we see the underlying error. - callback_finished = True - - def competing_callback2() -> None: - nonlocal callback_finished - try: - with LoggingContext(name="competing2", server_name="test_server"): - # clock.call_later( - # 0, lambda: defer.ensureDeferred(competing_callback()) - # ) - pass - finally: - # When exceptions happen, we still want to mark the callback as finished - # so that the test can complete and we see the underlying error. - callback_finished = True - - # Part of fix for the naive case is here (i.e. things don't work correctly if we - # don't `PreserveLoggingContext(...)` here). - # - # We can extend the lifetime of the "foo" logcontext is to avoid calling the - # context manager lifetime methods of `LoggingContext` (`__enter__`/`__exit__`). - # And we can still set the current logcontext by using `PreserveLoggingContext` - # and passing in the "foo" logcontext. - with PreserveLoggingContext( - LoggingContext(name="foo", server_name="test_server") - ): - d: defer.Deferred[None] = defer.Deferred() - # d.addErrback(lambda _: defer.ensureDeferred(competing_callback())) - # d.addErrback(lambda _: competing_callback2()) - d.addErrback(lambda _: make_deferred_yieldable(d)) - # make_deferred_yieldable(d) - self._check_test_key("foo") - # Other part of fix for the naive case is here (i.e. things don't work - # correctly if we don't `run_in_background(...)` here). - # - # `run_in_background(...)` will run the whole lambda in the current - # logcontext and it handles the magic behind the scenes of a) restoring the - # calling logcontext before returning to the caller and b) resetting the - # logcontext to the sentinel after the deferred completes and we yield - # control back to the reactor to avoid leaking the logcontext into the - # reactor. - # - # We're using a lambda here as a little trick so we can still get everything - # to run in the "foo" logcontext, but return the deferred `d` itself so that - # `run_in_background` will wait on that to complete before resetting the - # logcontext to the sentinel. - # - # type-ignore[call-overload]: This appears like a mypy type inference bug. A - # function that returns a deferred is exactly what `run_in_background` - # expects. - # - # type-ignore[func-returns-value]: This appears like a mypy type inference - # bug. We're always returning the deferred `d`. - run_in_background(lambda: (d.cancel(), d)[1]) # type: ignore[call-overload, func-returns-value] - self._check_test_key("foo") - - await clock.sleep(0) - - self.assertTrue( - callback_finished, - "Callback never finished which means the test probably didn't wait long enough", - ) - - # Back to the sentinel context - self._check_test_key("sentinel") - async def _test_run_in_background(self, function: Callable[[], object]) -> None: # Ignore linter error since we are creating a `Clock` for testing purposes. clock = Clock(reactor, server_name="test_server") # type: ignore[multiple-internal-clocks] @@ -791,157 +688,6 @@ def test_make_deferred_yieldable_with_chained_deferreds( # now it should be restored self._check_test_key("foo") - # @logcontext_clean - async def test_make_deferred_yieldable_asdf1(self) -> None: - # Ignore linter error since we are creating a `Clock` for testing purposes. - clock = Clock(reactor, server_name="test_server") # type: ignore[multiple-internal-clocks] - - # Sanity check that we start in the sentinel context - self.assertEqual(current_context(), SENTINEL_CONTEXT) - - # Create a deferred which we will never complete - incomplete_d: Deferred = Deferred() - - errback_logcontext: LoggingContextOrSentinel = None - - def check_errback_logcontext(res: Failure) -> None: - nonlocal errback_logcontext - errback_logcontext = current_context() - - # Re-raise the exception so that any further errbacks can do their thing as - # normal - res.raiseException() - - incomplete_d.addErrback(check_errback_logcontext) - - async def competing_task() -> None: - with LoggingContext( - name="competing", server_name="test_server" - ) as context_competing: - self.assertNoResult(incomplete_d) - # We should still be in the logcontext we started in - self.assertIs(current_context(), context_competing) - - # Mimic the normal use case to wait for the work to complete or timeout. - # - # In this specific test, we expect the deferred to timeout and raise an - # exception at this point. - logger.info( - "asdf before awaiting make_deferred_yieldable incomplete_d=%s", - incomplete_d, - ) - await make_deferred_yieldable(incomplete_d) - - self.fail( - "Did not expect to make it past this point as the `incomplete_d` should have been cancelled" - ) - - # with LoggingContext(name="foo", server_name="test_server"): - with PreserveLoggingContext( - LoggingContext(name="foo", server_name="test_server") - ): - # d = defer.ensureDeferred(competing_task()) - d = run_in_background(competing_task) - # reactor.callLater(0, lambda: defer.ensureDeferred(competing_task())) - await clock.sleep(0) - - logger.info("asdf 1") - - self._check_test_key("foo") - - # Pump the competing task a bit - # await clock.sleep(0) - - # Cancel the deferred - logger.info("asdf going to cancel incomplete_d") - # incomplete_d.cancel() - # with PreserveLoggingContext(): - # incomplete_d.cancel() - await run_in_background(lambda: (incomplete_d.cancel(), incomplete_d)[1]) - # await run_in_background( - # lambda: (incomplete_d.callback(None), incomplete_d)[1] - # ) - - # def _cancel_d() -> None: - # logger.info("asdf before cancel") - # incomplete_d.cancel() - # logger.info("asdf after cancel") - - # await run_in_background(lambda: (_cancel_d(), incomplete_d)[1]) - - logger.info("asdf 2") - - self._check_test_key("foo") - - # Pump the competing task a bit - # await clock.sleep(0) - # await clock.sleep(0) - - # We expect a failure due to the timeout - # self.failureResultOf(d, defer.CancelledError) - self.successResultOf(d) - - self._check_test_key("foo") - - self.assertEqual(str(errback_logcontext), "foo") - - # Back to the sentinel context at the end of the day - self.assertEqual(current_context(), SENTINEL_CONTEXT) - - # @logcontext_clean - async def test_make_deferred_yieldable_asdf2(self) -> None: - # Ignore linter error since we are creating a `Clock` for testing purposes. - clock = Clock(reactor, server_name="test_server") # type: ignore[multiple-internal-clocks] - - # Sanity check that we start in the sentinel context - self.assertEqual(current_context(), SENTINEL_CONTEXT) - - # Create a deferred which we will never complete - incomplete_d: Deferred = Deferred() - - async def bbb() -> None: - logger.info("asdf before cancel") - # incomplete_d.cancel() - with PreserveLoggingContext(): - incomplete_d.cancel() - logger.info("asdf after cancel") - - async def competing_task() -> None: - with LoggingContext( - name="competing", server_name="test_server" - ) as context_competing: - self.assertNoResult(incomplete_d) - # We should still be in the logcontext we started in - self.assertIs(current_context(), context_competing) - - # Mimic the normal use case to wait for the work to complete or timeout. - # - # In this specific test, we expect the deferred to timeout and raise an - # exception at this point. - logger.info("asdf awaiting make_deferred_yieldable") - await make_deferred_yieldable(incomplete_d) - - # We're still in the same logcontext - self.assertIs(current_context(), context_competing) - - # with LoggingContext(name="foo", server_name="test_server"): - with PreserveLoggingContext( - LoggingContext(name="foo", server_name="test_server") - ): - # d = defer.ensureDeferred(competing_task()) - d1 = run_in_background(competing_task) - _d2 = run_in_background(bbb) - # reactor.callLater(0, lambda: defer.ensureDeferred(competing_task())) - await clock.sleep(0) - - # We expect a failure due to the timeout - self.failureResultOf(d1, defer.CancelledError) - - self._check_test_key("foo") - - # Back to the sentinel context at the end of the day - self.assertEqual(current_context(), SENTINEL_CONTEXT) - @logcontext_clean def test_nested_logging_context(self) -> None: with LoggingContext(name="foo", server_name="test_server"): From 71d490c96d05043b5835cc452f3dcc826a1fed25 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 22 Oct 2025 00:43:34 -0500 Subject: [PATCH 13/17] Add changelog --- changelog.d/19090.bugfix | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/19090.bugfix diff --git a/changelog.d/19090.bugfix b/changelog.d/19090.bugfix new file mode 100644 index 00000000000..077dafcbf89 --- /dev/null +++ b/changelog.d/19090.bugfix @@ -0,0 +1 @@ +Fix lost logcontext warnings from timeouts in sync and requests made by Synapse itself. From 140bb59638dc077651d1ed49b9349c57fd2635bf Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 22 Oct 2025 00:45:45 -0500 Subject: [PATCH 14/17] Remove debug logs --- synapse/util/async_helpers.py | 1 - tests/util/test_async_helpers.py | 1 - 2 files changed, 2 deletions(-) diff --git a/synapse/util/async_helpers.py b/synapse/util/async_helpers.py index eaf8c28d25f..b47504aa422 100644 --- a/synapse/util/async_helpers.py +++ b/synapse/util/async_helpers.py @@ -812,7 +812,6 @@ def time_it_out() -> None: timed_out[0] = True try: - logger.info("asdf timeout_deferred cancel") with PreserveLoggingContext(): deferred.cancel() except Exception: # if we throw any exception it'll break time outs diff --git a/tests/util/test_async_helpers.py b/tests/util/test_async_helpers.py index 9b20025cd0b..b550f03cec5 100644 --- a/tests/util/test_async_helpers.py +++ b/tests/util/test_async_helpers.py @@ -307,7 +307,6 @@ async def competing_task() -> None: # # In this specific test, we expect the deferred to timeout and raise an # exception at this point. - logger.info("asdf awaiting make_deferred_yieldable") await make_deferred_yieldable(timing_out_d) self.fail( From 9aa49198dede737db4e1bc47d4dc7910a23d226d Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 22 Oct 2025 01:07:37 -0500 Subject: [PATCH 15/17] Fix unrelated lints from `develop` --- scripts-dev/release.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/scripts-dev/release.py b/scripts-dev/release.py index fafa55c770a..c5c72156ccd 100755 --- a/scripts-dev/release.py +++ b/scripts-dev/release.py @@ -821,7 +821,9 @@ def get_repo_and_check_clean_checkout( f"{path} is not a git repository (expecting a {name} repository)." ) while repo.is_dirty(): - if not click.confirm(f"Uncommitted changes exist in {path}. Commit or stash them. Ready to continue?"): + if not click.confirm( + f"Uncommitted changes exist in {path}. Commit or stash them. Ready to continue?" + ): raise click.ClickException("Aborted.") return repo From 7bb2ffc0e9251ff1a4d2f52a78982cb07c58f28e Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Wed, 22 Oct 2025 01:17:23 -0500 Subject: [PATCH 16/17] Make it more clear what's being tested --- tests/util/test_async_helpers.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/util/test_async_helpers.py b/tests/util/test_async_helpers.py index b550f03cec5..b417a7ca584 100644 --- a/tests/util/test_async_helpers.py +++ b/tests/util/test_async_helpers.py @@ -280,8 +280,8 @@ async def test_logcontext_is_not_lost_when_awaiting_on_timeout_cancellation( self, ) -> None: """ - Test that the logcontext isn't lost when we `await` the deferred to - complete/timeout and it times out. + Test that the logcontext isn't lost when we `await make_deferred_yieldable(...)` + the deferred to complete/timeout and it times out. """ # Sanity check that we start in the sentinel context From 3100b6379aedbf131fb26fc47d270f0cc2c417bc Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Thu, 30 Oct 2025 11:10:24 -0500 Subject: [PATCH 17/17] Make it more clear when nothing is wrong See https://github.com/element-hq/synapse/pull/19090#discussion_r2478523241 --- synapse/logging/context.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 45c83f0d61d..963bcb56761 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -916,7 +916,7 @@ def run_in_background( ) else: logcontext_debug_logger.debug( - "run_in_background(%s): deferred already completed and the function should have maintained the calling logcontext %s", + "run_in_background(%s): deferred already completed (maintained the calling logcontext %s)", instance_id, calling_context, )