From 275c4aa4aa977dd283fa1e6f79d3bb9ea5798689 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 09:40:35 -0500 Subject: [PATCH 01/15] WIP: Explain how Deferred callbacks interact with logcontexts Spawning from https://github.com/matrix-org/synapse/pull/12588#discussion_r865843321 --- docs/log_contexts.md | 64 +++++++++++++++++++++++++++++++- tests/util/test_logcontext.py | 69 ++++++++++++++++++++++++++++++++++- 2 files changed, 129 insertions(+), 4 deletions(-) diff --git a/docs/log_contexts.md b/docs/log_contexts.md index 4e0c0e64f79..b2e08f9a35b 100644 --- a/docs/log_contexts.md +++ b/docs/log_contexts.md @@ -143,8 +143,7 @@ cares about. The following sections describe pitfalls and helpful patterns when implementing these rules. -Always await your awaitables ----------------------------- +## Always await your awaitables Whenever you get an awaitable back from a function, you should `await` on it as soon as possible. Do not pass go; do not do any logging; do not @@ -203,6 +202,67 @@ async def sleep(seconds): return await context.make_deferred_yieldable(get_sleep_deferred(seconds)) ``` +## Deferred callbacks + +When a deferred callback is called, it will use the current context. + +The first issue is that the current context could finish before the callback is +finishes. In the following example, the callback is called with the "foo" context and +runs until the `await` where we yield control back to the reactor, setting the sentinel +logcontext TODO + +```python +async def competing_callback(): + with LoggingContext("competing"): + await clock.sleep(0) + +with LoggingContext("foo"): + d = defer.Deferred() + d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) + # Call the callback with the "foo" context. + d.callback(None) +``` + +The callback can resume a coroutine, which will restore its +own logging context, then run: + + - until it blocks, setting the sentinel context + - or until it terminates, setting the context it was started with + +```python +async def some_function(): + with LoggingContext("competing"): + await clock.sleep(0) + +d = defer.Deferred() + +d.addCallback(lambda: defer.ensureDeferred(some_function())) + +# +d.callback(result) +``` + +Similarly, calling the errback may do the same thing. + +```python +d = defer.Deferred() + +d.addErrback(some_other_function) + +d.errback(failure) +``` + +Cancellation is the same as directly calling the errback with a `twisted.internet.defer.CancelledError`: + +```python +d = defer.Deferred() + +d.cancel() +``` + + + + ## Fire-and-forget Sometimes you want to fire off a chain of execution, but not wait for diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index af36e685d7c..64505d801bc 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -19,6 +19,7 @@ # # +import logging from typing import Callable, Generator, cast import twisted.python.failure @@ -32,25 +33,89 @@ make_deferred_yieldable, nested_logging_context, run_in_background, + _Sentinel, ) from synapse.types import ISynapseReactor from synapse.util import Clock from .. import unittest +logger = logging.getLogger(__name__) + reactor = cast(ISynapseReactor, _reactor) class LoggingContextTestCase(unittest.TestCase): def _check_test_key(self, value: str) -> None: context = current_context() - assert isinstance(context, LoggingContext) - self.assertEqual(context.name, value) + assert isinstance(context, LoggingContext) or isinstance(context, _Sentinel), ( + f"Expected LoggingContext({value}) but saw {context}" + ) + self.assertEqual( + str(context), value, f"Expected LoggingContext({value}) but saw {context}" + ) def test_with_context(self) -> None: with LoggingContext("test"): self._check_test_key("test") + async def test_deferred_asdf(self) -> None: + clock = Clock(reactor) + + # Sanity check that we start in the sentinel context + self._check_test_key("sentinel") + + async def competing_callback(): + with LoggingContext("competing"): + await clock.sleep(0) + + with LoggingContext("foo"): + d = defer.Deferred() + d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) + # Call the callback with the "foo" context. + d.callback(None) + + async def test_deferred(self) -> None: + clock = Clock(reactor) + + # 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 + logger.info("competing_callback1") + # The deferred callback should have the same logcontext as the caller + self._check_test_key("one") + + logger.info("competing_callback2") + with LoggingContext("competing"): + await clock.sleep(0) + self._check_test_key("competing") + + self._check_test_key("one") + logger.info("competing_callback3") + callback_finished = True + + with LoggingContext("one"): + d = defer.Deferred() + d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) + self._check_test_key("one") + d.callback(None) + self._check_test_key("one") + await clock.sleep(0) + self._check_test_key("one") + 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_sleep(self) -> None: clock = Clock(reactor) From 9069fd170ecec8bb830f6e12c7521e3fd6faefb2 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 14:32:56 -0500 Subject: [PATCH 02/15] Iterate on docs --- docs/log_contexts.md | 99 +++++++++++++++++++++++++---------- tests/util/test_logcontext.py | 10 +++- 2 files changed, 79 insertions(+), 30 deletions(-) diff --git a/docs/log_contexts.md b/docs/log_contexts.md index b2e08f9a35b..66e67ca6a51 100644 --- a/docs/log_contexts.md +++ b/docs/log_contexts.md @@ -204,59 +204,100 @@ async def sleep(seconds): ## Deferred callbacks -When a deferred callback is called, it will use the current context. +When a deferred callback is called, it will use the current logcontext. -The first issue is that the current context could finish before the callback is -finishes. In the following example, the callback is called with the "foo" context and -runs until the `await` where we yield control back to the reactor, setting the sentinel -logcontext TODO +The deferred callback chain can resume a coroutine, which if following our logcontext +rules, will restore its own logcontext, then run: + + - until it yields control back to the reactor, setting the sentinel logcontext + - or until it finishes, restoring the logcontext it was started with (calling context) + +The first issue is that the current logcontext could finish before the callback +finishes. In the following example, the deferred callback is called with the "main" +logcontext and runs until we yield control back to the reactor in the `await` inside +`clock.sleep(0)`. Since `clock.sleep(0)` follows our logcontext rules, it sets the +logcontext to the sentinel before yielding control back to the reactor. Our `main` +function continues and the `with LoggingContext("main")` block exits, finishing the +"main" logcontext yielding control back to the reactor again. Finally, later on when +`clock.sleep(0)` completes, our `with LoggingContext("competing")` block exits, and +restores the previous "main" logcontext which has already finished, resulting in +`WARNING: Re-starting finished log context main` and leaking the `main` logcontext into +the reactor which will then erronously get associated with the next thing the reactor +does. + +The second issue is TODO ```python async def competing_callback(): + # Since this is run with the "main" logcontext, when the "competing" + # logcontext exits, it will restore the previous "main" logcontext which has + # already finished and results in "WARNING: Re-starting finished log context main" with LoggingContext("competing"): await clock.sleep(0) -with LoggingContext("foo"): - d = defer.Deferred() - d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) - # Call the callback with the "foo" context. - d.callback(None) -``` +def main(): + with LoggingContext("main"): + d = defer.Deferred() + d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) + # Call the callback within the "main" logcontext. + d.callback(None) + # Bad: This will be logged against sentinel logcontext + logger.debug("ugh") -The callback can resume a coroutine, which will restore its -own logging context, then run: +main() +``` - - until it blocks, setting the sentinel context - - or until it terminates, setting the context it was started with +We could of course fix this by following the general rule of "always await your +awaitables": ```python -async def some_function(): - with LoggingContext("competing"): - await clock.sleep(0) +async def main(): + with LoggingContext("main"): + d = defer.Deferred() + d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) + d.callback(None) + # Wait for `d` to finish before continuing so the "main" logcontext is + # still active. This works because `d` already follows our logcontext + # rules. If not, we would also have to use `make_deferred_yieldable(d)`. + await d + # Good: This will be logged against the "main" logcontext + logger.debug("phew") +``` + +We could also fix this by surrounding the call to `d.callback` with a +`PreserveLoggingContext`, which will reset the logcontext to the sentinel before calling +the callback, and restore the "foo" logcontext afterwards before continuing the `main` +function: -d = defer.Deferred() - -d.addCallback(lambda: defer.ensureDeferred(some_function())) - -# -d.callback(result) +```python +async def main(): + with LoggingContext("main"): + d = defer.Deferred() + d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) + d.callback(None) + with PreserveLoggingContext(): + d.callback(None) + # Good: This will be logged against the "main" logcontext + logger.debug("phew") ``` -Similarly, calling the errback may do the same thing. +### Deferred errbacks and cancellations + +The same care should be taken when calling errbacks on deferreds. An errback and +callback act the same in this regard (see section above). ```python d = defer.Deferred() - d.addErrback(some_other_function) - d.errback(failure) ``` -Cancellation is the same as directly calling the errback with a `twisted.internet.defer.CancelledError`: +Additionally, cancellation is the same as directly calling the errback with a +`twisted.internet.defer.CancelledError`: ```python d = defer.Deferred() - +d.addErrback(some_other_function) d.cancel() ``` diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index 64505d801bc..b73e3a9ed77 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -66,6 +66,9 @@ async def test_deferred_asdf(self) -> None: self._check_test_key("sentinel") async def competing_callback(): + # Since this is run with the "foo" logcontext, when the "competing" + # logcontext exits, it will restore the previous "foo" logcontext which has + # already finished and results in "WARNING: Re-starting finished log context foo" with LoggingContext("competing"): await clock.sleep(0) @@ -73,7 +76,12 @@ async def competing_callback(): d = defer.Deferred() d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) # Call the callback with the "foo" context. - d.callback(None) + # d.callback(None) + with PreserveLoggingContext(): + d.callback(None) + + # This will be logged against sentinel logcontext + logger.debug("ugh") async def test_deferred(self) -> None: clock = Clock(reactor) From 9ea87da317bb3978f98b82859b597fe85238feee Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 15:15:38 -0500 Subject: [PATCH 03/15] Structure docs --- docs/log_contexts.md | 69 +++++++++++++++++++++++++++-------- tests/util/test_logcontext.py | 27 +++++++++++++- 2 files changed, 80 insertions(+), 16 deletions(-) diff --git a/docs/log_contexts.md b/docs/log_contexts.md index 66e67ca6a51..a55e75d4b9a 100644 --- a/docs/log_contexts.md +++ b/docs/log_contexts.md @@ -212,26 +212,31 @@ rules, will restore its own logcontext, then run: - until it yields control back to the reactor, setting the sentinel logcontext - or until it finishes, restoring the logcontext it was started with (calling context) -The first issue is that the current logcontext could finish before the callback -finishes. In the following example, the deferred callback is called with the "main" -logcontext and runs until we yield control back to the reactor in the `await` inside -`clock.sleep(0)`. Since `clock.sleep(0)` follows our logcontext rules, it sets the -logcontext to the sentinel before yielding control back to the reactor. Our `main` -function continues and the `with LoggingContext("main")` block exits, finishing the -"main" logcontext yielding control back to the reactor again. Finally, later on when -`clock.sleep(0)` completes, our `with LoggingContext("competing")` block exits, and -restores the previous "main" logcontext which has already finished, resulting in -`WARNING: Re-starting finished log context main` and leaking the `main` logcontext into -the reactor which will then erronously get associated with the next thing the reactor -does. - -The second issue is TODO +The first issue is that the callback may have reset the logcontext to the sentinel +before returning. This means our calling function will continue with the sentinel +logcontext instead of the logcontext it was started with (bad). + +The second issue is that the current logcontext that called the deferred callback could +finish before the callback finishes (bad). + +In the following example, the deferred callback is called with the "main" logcontext and +runs until we yield control back to the reactor in the `await` inside `clock.sleep(0)`. +Since `clock.sleep(0)` follows our logcontext rules, it sets the logcontext to the +sentinel before yielding control back to the reactor. Our `main` function continues with +the sentinel logcontext (first bad thing) instead of the "main" logcontext. Then the +`with LoggingContext("main")` block exits, finishing the "main" logcontext and yielding +control back to the reactor again. Finally, later on when `clock.sleep(0)` completes, +our `with LoggingContext("competing")` block exits, and restores the previous "main" +logcontext which has already finished, resulting in `WARNING: Re-starting finished log +context main` and leaking the `main` logcontext into the reactor which will then +erronously be associated with the next task the reactor picks up. ```python async def competing_callback(): # Since this is run with the "main" logcontext, when the "competing" # logcontext exits, it will restore the previous "main" logcontext which has # already finished and results in "WARNING: Re-starting finished log context main" + # and leaking the `main` logcontext into the reactor. with LoggingContext("competing"): await clock.sleep(0) @@ -267,7 +272,9 @@ async def main(): We could also fix this by surrounding the call to `d.callback` with a `PreserveLoggingContext`, which will reset the logcontext to the sentinel before calling the callback, and restore the "foo" logcontext afterwards before continuing the `main` -function: +function. This solves the problem because when the "competing" logcontext exits, it will +restore the sentinel logcontext which is not finished, so there is no warning and no +leakage into the reactor. ```python async def main(): @@ -281,6 +288,38 @@ async def main(): logger.debug("phew") ``` +Another way to extend the lifetime of the "main" logcontext is to avoid calling the +context manager lifetime methods of `LoggingContext` (`__enter__`/`__exit__`). We can +still set the current logcontext by using `PreserveLoggingContext` and passing in the +"main" logcontext. + + +```python +async def main(): + main_context = LoggingContext("main") + with PreserveLoggingContext(main_context): + d = defer.Deferred() + d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) + d.callback(None) + # TODO: Still bad: This will be logged against sentinel logcontext + # Good: This will be logged against the "main" logcontext + logger.debug("phew") + +... + +# Wherever possible, it's best to finish the logcontext by exiting at some point. This +# allows us to catch bugs if we later try to erroneously restart a finished logcontext. +# +# Since the "main" logcontext stores the `LoggingContext.previous_context` when it is +# created, we can wrap this call in `PreserveLoggingContext()` to restore the correct +# previous logcontext. Our goal is to have the calling context remain unchanged after +# finishing the "main" logcontext. +with PreserveLoggingContext(): + # Finish the "main" logcontext + with main_context: + pass +``` + ### Deferred errbacks and cancellations The same care should be taken when calling errbacks on deferreds. An errback and diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index b73e3a9ed77..ac227238b9b 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -19,6 +19,7 @@ # # + import logging from typing import Callable, Generator, cast @@ -59,7 +60,7 @@ def test_with_context(self) -> None: with LoggingContext("test"): self._check_test_key("test") - async def test_deferred_asdf(self) -> None: + async def test_deferred_asdf1(self) -> None: clock = Clock(reactor) # Sanity check that we start in the sentinel context @@ -83,6 +84,30 @@ async def competing_callback(): # This will be logged against sentinel logcontext logger.debug("ugh") + async def test_deferred_asdf2(self) -> None: + clock = Clock(reactor) + + # Sanity check that we start in the sentinel context + self._check_test_key("sentinel") + + async def competing_callback(): + # Since this is run with the "foo" logcontext, when the "competing" + # logcontext exits, it will restore the previous "foo" logcontext which has + # already finished and results in "WARNING: Re-starting finished log context foo" + with LoggingContext("competing"): + await clock.sleep(0) + + with PreserveLoggingContext(LoggingContext("foo")): + d = defer.Deferred() + d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) + # Call the callback with the "foo" context. + d.callback(None) + # with PreserveLoggingContext(): + # d.callback(None) + + # This will be logged against sentinel logcontext + logger.debug("ugh") + async def test_deferred(self) -> None: clock = Clock(reactor) From 8b50ed3821450da674a62abe236c54150ce2db40 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 16:34:37 -0500 Subject: [PATCH 04/15] Solve the deferred callback in current context problem --- docs/log_contexts.md | 29 +++++++++++++++++++++-------- tests/util/test_logcontext.py | 7 ++++++- 2 files changed, 27 insertions(+), 9 deletions(-) diff --git a/docs/log_contexts.md b/docs/log_contexts.md index a55e75d4b9a..b4a913e0a2f 100644 --- a/docs/log_contexts.md +++ b/docs/log_contexts.md @@ -273,8 +273,8 @@ We could also fix this by surrounding the call to `d.callback` with a `PreserveLoggingContext`, which will reset the logcontext to the sentinel before calling the callback, and restore the "foo" logcontext afterwards before continuing the `main` function. This solves the problem because when the "competing" logcontext exits, it will -restore the sentinel logcontext which is not finished, so there is no warning and no -leakage into the reactor. +restore the sentinel logcontext which is never finished by its nature, so there is no +warning and no leakage into the reactor. ```python async def main(): @@ -283,15 +283,25 @@ async def main(): d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) d.callback(None) with PreserveLoggingContext(): + # Call the callback with the sentinel logcontext. d.callback(None) # Good: This will be logged against the "main" logcontext logger.debug("phew") ``` -Another way to extend the lifetime of the "main" logcontext is to avoid calling the -context manager lifetime methods of `LoggingContext` (`__enter__`/`__exit__`). We can -still set the current logcontext by using `PreserveLoggingContext` and passing in the -"main" logcontext. +But let's say you *do* want to run the deferred callback in the current context without +running into issues: + +We can solve the first issue by using `run_in_background(...)` to run the callback 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. + +To solve the second problem, we can extend the lifetime of the "main" 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 "main" logcontext. ```python @@ -300,8 +310,11 @@ async def main(): with PreserveLoggingContext(main_context): d = defer.Deferred() d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) - d.callback(None) - # TODO: Still bad: This will be logged against sentinel logcontext + # The whole lambda will be run in the "main" logcontext. But we're using + # a trick to return the deferred `d` 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 "main" logcontext into the reactor. + run_in_background(lambda: (d.callback(None), d)[1]) # Good: This will be logged against the "main" logcontext logger.debug("phew") diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index ac227238b9b..52f090d3754 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -91,6 +91,7 @@ async def test_deferred_asdf2(self) -> None: self._check_test_key("sentinel") async def competing_callback(): + logger.info("competing_callback1") # Since this is run with the "foo" logcontext, when the "competing" # logcontext exits, it will restore the previous "foo" logcontext which has # already finished and results in "WARNING: Re-starting finished log context foo" @@ -101,9 +102,13 @@ async def competing_callback(): d = defer.Deferred() d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) # Call the callback with the "foo" context. - d.callback(None) + # d.callback(None) # with PreserveLoggingContext(): # d.callback(None) + # run_in_background(d.callback, None) + # run_in_background(lambda: d.callback(None)) + run_in_background(lambda: (d.callback(None), d)[1]) + # run_in_background(lambda: defer.ensureDeferred(competing_callback())) # This will be logged against sentinel logcontext logger.debug("ugh") From d39cc96681ef9268a6e85023703a7fc4afbd6248 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 16:37:34 -0500 Subject: [PATCH 05/15] Clarify "exit" --- docs/log_contexts.md | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/docs/log_contexts.md b/docs/log_contexts.md index b4a913e0a2f..9ef6f9df054 100644 --- a/docs/log_contexts.md +++ b/docs/log_contexts.md @@ -320,8 +320,9 @@ async def main(): ... -# Wherever possible, it's best to finish the logcontext by exiting at some point. This -# allows us to catch bugs if we later try to erroneously restart a finished logcontext. +# Wherever possible, it's best to finish the logcontext by calling `__exit__` at some +# point. This allows us to catch bugs if we later try to erroneously restart a finished +# logcontext. # # Since the "main" logcontext stores the `LoggingContext.previous_context` when it is # created, we can wrap this call in `PreserveLoggingContext()` to restore the correct From 271fe4ee171a291876c543c13fb5a07760750806 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 16:47:13 -0500 Subject: [PATCH 06/15] Clarify why we have an empty `pass` block in the context manager --- docs/log_contexts.md | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/docs/log_contexts.md b/docs/log_contexts.md index 9ef6f9df054..800cae94948 100644 --- a/docs/log_contexts.md +++ b/docs/log_contexts.md @@ -331,6 +331,11 @@ async def main(): with PreserveLoggingContext(): # Finish the "main" logcontext with main_context: + # Empty block - We're just trying to call `__exit__` on the "main" context + # manager to finish it. We can't call `__exit__` directly as the code expects us + # to `__enter__` before calling `__exit__` to `start`/`stop` things + # appropriately. And in any case, it's probably best not to call the internal + # methods directly. pass ``` From 56c723f597915c9cb076db57f49df06b46d9ff64 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 16:49:47 -0500 Subject: [PATCH 07/15] Add changelog --- changelog.d/18914.doc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/18914.doc diff --git a/changelog.d/18914.doc b/changelog.d/18914.doc new file mode 100644 index 00000000000..9d4f03ade7f --- /dev/null +++ b/changelog.d/18914.doc @@ -0,0 +1 @@ +Explain how Deferred callbacks interact with logcontexts. From bd0516b71fefeec48ab4c92d4dce9eced118b31e Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 17:48:31 -0500 Subject: [PATCH 08/15] Add tests --- docs/log_contexts.md | 7 +- tests/util/test_logcontext.py | 218 ++++++++++++++++++++++++---------- 2 files changed, 160 insertions(+), 65 deletions(-) diff --git a/docs/log_contexts.md b/docs/log_contexts.md index 800cae94948..15d3c3bc7cf 100644 --- a/docs/log_contexts.md +++ b/docs/log_contexts.md @@ -271,7 +271,7 @@ async def main(): We could also fix this by surrounding the call to `d.callback` with a `PreserveLoggingContext`, which will reset the logcontext to the sentinel before calling -the callback, and restore the "foo" logcontext afterwards before continuing the `main` +the callback, and restore the "main" logcontext afterwards before continuing the `main` function. This solves the problem because when the "competing" logcontext exits, it will restore the sentinel logcontext which is never finished by its nature, so there is no warning and no leakage into the reactor. @@ -289,8 +289,8 @@ async def main(): logger.debug("phew") ``` -But let's say you *do* want to run the deferred callback in the current context without -running into issues: +But let's say you *do* want to run (fire-and-forget) the deferred callback in the +current context without running into issues: We can solve the first issue by using `run_in_background(...)` to run the callback in the current logcontext and it handles the magic behind the scenes of a) restoring the @@ -339,6 +339,7 @@ with PreserveLoggingContext(): pass ``` + ### Deferred errbacks and cancellations The same care should be taken when calling errbacks on deferreds. An errback and diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index 52f090d3754..c829e459eac 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -60,60 +60,87 @@ def test_with_context(self) -> None: with LoggingContext("test"): self._check_test_key("test") - async def test_deferred_asdf1(self) -> None: + async def test_sleep(self) -> None: clock = Clock(reactor) - # Sanity check that we start in the sentinel context - self._check_test_key("sentinel") - - async def competing_callback(): - # Since this is run with the "foo" logcontext, when the "competing" - # logcontext exits, it will restore the previous "foo" logcontext which has - # already finished and results in "WARNING: Re-starting finished log context foo" + async def competing_callback() -> None: with LoggingContext("competing"): await clock.sleep(0) + self._check_test_key("competing") - with LoggingContext("foo"): - d = defer.Deferred() - d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) - # Call the callback with the "foo" context. - # d.callback(None) - with PreserveLoggingContext(): - d.callback(None) + reactor.callLater(0, lambda: defer.ensureDeferred(competing_callback())) + + with LoggingContext("one"): + await clock.sleep(0) + self._check_test_key("one") - # This will be logged against sentinel logcontext - logger.debug("ugh") + async def test_deferred_callback_await_in_current_logcontext(self) -> None: + """ + Test that calling the deferred callback in the current logcontext ("foo") and + waiting for it to finish in a logcontext blocks works as expected. - async def test_deferred_asdf2(self) -> None: + Works because "always await your awaitables". + + 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. + """ clock = Clock(reactor) # Sanity check that we start in the sentinel context self._check_test_key("sentinel") - async def competing_callback(): - logger.info("competing_callback1") - # Since this is run with the "foo" logcontext, when the "competing" - # logcontext exits, it will restore the previous "foo" logcontext which has - # already finished and results in "WARNING: Re-starting finished log context foo" - with LoggingContext("competing"): - await clock.sleep(0) + callback_finished = False - with PreserveLoggingContext(LoggingContext("foo")): + 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("competing"): + 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 + + with LoggingContext("foo"): d = defer.Deferred() d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) - # Call the callback with the "foo" context. - # d.callback(None) - # with PreserveLoggingContext(): - # d.callback(None) - # run_in_background(d.callback, None) - # run_in_background(lambda: d.callback(None)) - run_in_background(lambda: (d.callback(None), d)[1]) - # run_in_background(lambda: defer.ensureDeferred(competing_callback())) + self._check_test_key("foo") + d.callback(None) + # The fix for the naive case is here (i.e. things don't work correctly if we + # don't await here). + # + # Wait for `d` to finish before continuing so the "main" logcontext is + # still active. This works because `d` already follows our logcontext + # rules. If not, we would also have to use `make_deferred_yieldable(d)`. + await d + self._check_test_key("foo") - # This will be logged against sentinel logcontext - logger.debug("ugh") + await clock.sleep(0) - async def test_deferred(self) -> None: + 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_deferred_callback_preserve_logging_context(self) -> None: + """ + Test that calling the deferred callback inside `PreserveLoggingContext()` works + as expected. + + 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. + """ clock = Clock(reactor) # Sanity check that we start in the sentinel context @@ -123,28 +150,38 @@ async def test_deferred(self) -> None: async def competing_callback() -> None: nonlocal callback_finished - logger.info("competing_callback1") - # The deferred callback should have the same logcontext as the caller - self._check_test_key("one") + try: + # The deferred callback should have the same logcontext as the caller + self._check_test_key("sentinel") - logger.info("competing_callback2") - with LoggingContext("competing"): - await clock.sleep(0) - self._check_test_key("competing") + with LoggingContext("competing"): + await clock.sleep(0) + self._check_test_key("competing") - self._check_test_key("one") - logger.info("competing_callback3") - callback_finished = True + self._check_test_key("sentinel") + 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 - with LoggingContext("one"): + with LoggingContext("foo"): d = defer.Deferred() d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) - self._check_test_key("one") - d.callback(None) - self._check_test_key("one") - await clock.sleep(0) - self._check_test_key("one") - await clock.sleep(0) + self._check_test_key("foo") + # The fix for the naive case is here (i.e. things don't work correctly if we + # don't `PreserveLoggingContext()` here). + # + # `PreserveLoggingContext` will reset the logcontext to the sentinel before + # calling the callback, and restore the "foo" logcontext afterwards before + # continuing the foo block. This solves the problem because when the + # "competing" logcontext exits, it will restore the sentinel logcontext + # which is never finished by its nature, so there is no warning and no + # leakage into the reactor. + with PreserveLoggingContext(): + d.callback(None) + self._check_test_key("foo") + + await clock.sleep(0) self.assertTrue( callback_finished, @@ -154,19 +191,76 @@ async def competing_callback() -> None: # Back to the sentinel context self._check_test_key("sentinel") - async def test_sleep(self) -> None: + async def test_deferred_callback_fire_and_forget_with_current_context(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. + """ clock = Clock(reactor) + # Sanity check that we start in the sentinel context + self._check_test_key("sentinel") + + callback_finished = False + async def competing_callback() -> None: - with LoggingContext("competing"): - await clock.sleep(0) - self._check_test_key("competing") + nonlocal callback_finished + try: + # The deferred callback should have the same logcontext as the caller + self._check_test_key("foo") + + with LoggingContext("competing"): + 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 + + # 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("foo")): + d = defer.Deferred() + d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) + 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. + run_in_background(lambda: (d.callback(None), d)[1]) + self._check_test_key("foo") - reactor.callLater(0, lambda: defer.ensureDeferred(competing_callback())) + await clock.sleep(0) - with LoggingContext("one"): - await clock.sleep(0) - self._check_test_key("one") + 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") def _test_run_in_background(self, function: Callable[[], object]) -> defer.Deferred: sentinel_context = current_context() From 98952e15493294f623c97d0f6ac517b22adbbd85 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 18:02:35 -0500 Subject: [PATCH 09/15] Fix lints --- tests/util/test_logcontext.py | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index c829e459eac..e16d33fb11c 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -30,11 +30,11 @@ SENTINEL_CONTEXT, LoggingContext, PreserveLoggingContext, + _Sentinel, current_context, make_deferred_yieldable, nested_logging_context, run_in_background, - _Sentinel, ) from synapse.types import ISynapseReactor from synapse.util import Clock @@ -109,7 +109,7 @@ async def competing_callback() -> None: callback_finished = True with LoggingContext("foo"): - d = defer.Deferred() + d: defer.Deferred[None] = defer.Deferred() d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) self._check_test_key("foo") d.callback(None) @@ -165,7 +165,7 @@ async def competing_callback() -> None: callback_finished = True with LoggingContext("foo"): - d = defer.Deferred() + d: defer.Deferred[None] = defer.Deferred() d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) self._check_test_key("foo") # The fix for the naive case is here (i.e. things don't work correctly if we @@ -232,7 +232,7 @@ async def competing_callback() -> None: # And we can still set the current logcontext by using `PreserveLoggingContext` # and passing in the "foo" logcontext. with PreserveLoggingContext(LoggingContext("foo")): - d = defer.Deferred() + d: defer.Deferred[None] = defer.Deferred() d.addCallback(lambda _: defer.ensureDeferred(competing_callback())) self._check_test_key("foo") # Other part of fix for the naive case is here (i.e. things don't work @@ -249,7 +249,14 @@ async def competing_callback() -> None: # 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. - run_in_background(lambda: (d.callback(None), d)[1]) + # + # 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.callback(None), d)[1]) # type: ignore[call-overload, func-returns-value] self._check_test_key("foo") await clock.sleep(0) From ec113e091c0cba0c99e0e60015d3678e6d4d2ff4 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 18:12:12 -0500 Subject: [PATCH 10/15] Add `@logcontext_clean` --- tests/util/test_logcontext.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index e16d33fb11c..438b079e1a2 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -38,6 +38,7 @@ ) from synapse.types import ISynapseReactor from synapse.util import Clock +from tests.unittest import logcontext_clean from .. import unittest @@ -74,6 +75,7 @@ async def competing_callback() -> None: await clock.sleep(0) self._check_test_key("one") + @logcontext_clean async def test_deferred_callback_await_in_current_logcontext(self) -> None: """ Test that calling the deferred callback in the current logcontext ("foo") and @@ -132,6 +134,7 @@ async def competing_callback() -> None: # Back to the sentinel context self._check_test_key("sentinel") + @logcontext_clean async def test_deferred_callback_preserve_logging_context(self) -> None: """ Test that calling the deferred callback inside `PreserveLoggingContext()` works @@ -191,6 +194,7 @@ 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(self) -> None: """ Test that it's possible to call the deferred callback with the current context From d30d92a0c736bf3432eee8a0872076a312ca5668 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 18:12:25 -0500 Subject: [PATCH 11/15] Describe what context explicitly --- tests/util/test_logcontext.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index 438b079e1a2..66eecab67a2 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -137,8 +137,8 @@ async def competing_callback() -> None: @logcontext_clean async def test_deferred_callback_preserve_logging_context(self) -> None: """ - Test that calling the deferred callback inside `PreserveLoggingContext()` works - as expected. + Test that calling the deferred callback inside `PreserveLoggingContext()` (in + the sentinel context) works as expected. 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 From c21697c19408690526e4f9e3f91ae16fa2f92eb8 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 20:17:28 -0500 Subject: [PATCH 12/15] Fix lints --- tests/util/test_logcontext.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index 66eecab67a2..5b45828e058 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -38,6 +38,7 @@ ) from synapse.types import ISynapseReactor from synapse.util import Clock + from tests.unittest import logcontext_clean from .. import unittest From 7fd588d7a94b6ac5541d1af11c8ca757e9a44404 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Fri, 12 Sep 2025 20:17:53 -0500 Subject: [PATCH 13/15] Add note about other deferreds that you may have stored --- docs/log_contexts.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/docs/log_contexts.md b/docs/log_contexts.md index 15d3c3bc7cf..103da15d9f9 100644 --- a/docs/log_contexts.md +++ b/docs/log_contexts.md @@ -339,6 +339,9 @@ with PreserveLoggingContext(): pass ``` +The same thing applies if you have some deferreds stored somewhere which you want to +callback in the current logcontext. + ### Deferred errbacks and cancellations From 74f4140f8e2bd60595dff79fe969180a961c5f81 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Sat, 13 Sep 2025 11:18:02 -0500 Subject: [PATCH 14/15] Better flow --- docs/log_contexts.md | 35 ++++++++++++++++++----------------- 1 file changed, 18 insertions(+), 17 deletions(-) diff --git a/docs/log_contexts.md b/docs/log_contexts.md index 103da15d9f9..bbe9e86827b 100644 --- a/docs/log_contexts.md +++ b/docs/log_contexts.md @@ -204,20 +204,21 @@ async def sleep(seconds): ## Deferred callbacks -When a deferred callback is called, it will use the current logcontext. - -The deferred callback chain can resume a coroutine, which if following our logcontext -rules, will restore its own logcontext, then run: +When a deferred callback is called, it inherits the current logcontext. The deferred +callback chain can resume a coroutine, which if following our logcontext rules, will +restore its own logcontext, then run: - until it yields control back to the reactor, setting the sentinel logcontext - or until it finishes, restoring the logcontext it was started with (calling context) -The first issue is that the callback may have reset the logcontext to the sentinel -before returning. This means our calling function will continue with the sentinel -logcontext instead of the logcontext it was started with (bad). +This behavior creates two specific issues: + +**Issue 1:** The first issue is that the callback may have reset the logcontext to the +sentinel before returning. This means our calling function will continue with the +sentinel logcontext instead of the logcontext it was started with (bad). -The second issue is that the current logcontext that called the deferred callback could -finish before the callback finishes (bad). +**Issue 2:** The second issue is that the current logcontext that called the deferred +callback could finish before the callback finishes (bad). In the following example, the deferred callback is called with the "main" logcontext and runs until we yield control back to the reactor in the `await` inside `clock.sleep(0)`. @@ -252,8 +253,8 @@ def main(): main() ``` -We could of course fix this by following the general rule of "always await your -awaitables": +**Solution 1:** We could of course fix this by following the general rule of "always +await your awaitables": ```python async def main(): @@ -269,7 +270,7 @@ async def main(): logger.debug("phew") ``` -We could also fix this by surrounding the call to `d.callback` with a +**Solution 2:** We could also fix this by surrounding the call to `d.callback` with a `PreserveLoggingContext`, which will reset the logcontext to the sentinel before calling the callback, and restore the "main" logcontext afterwards before continuing the `main` function. This solves the problem because when the "competing" logcontext exits, it will @@ -289,8 +290,8 @@ async def main(): logger.debug("phew") ``` -But let's say you *do* want to run (fire-and-forget) the deferred callback in the -current context without running into issues: +**Solution 3:** But let's say you *do* want to run (fire-and-forget) the deferred +callback in the current context without running into issues: We can solve the first issue by using `run_in_background(...)` to run the callback in the current logcontext and it handles the magic behind the scenes of a) restoring the @@ -298,9 +299,9 @@ calling logcontext before returning to the caller and b) resetting the logcontex sentinel after the deferred completes and we yield control back to the reactor to avoid leaking the logcontext into the reactor. -To solve the second problem, we can extend the lifetime of the "main" logcontext is to -avoid calling the context manager lifetime methods of `LoggingContext` -(`__enter__`/`__exit__`). And we can still set the current logcontext by using +To solve the second issue, we can extend the lifetime of the "main" logcontext by +avoiding the `LoggingContext`'s context manager lifetime methods +(`__enter__`/`__exit__`). We can still set "main" as the current logcontext by using `PreserveLoggingContext` and passing in the "main" logcontext. From 48aeb269fd721321a48961b8d83029b5a4608299 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 22 Sep 2025 14:55:52 -0500 Subject: [PATCH 15/15] Remove stray newline --- tests/util/test_logcontext.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index 49b36fec614..0efb958f675 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -19,7 +19,6 @@ # # - import logging from typing import Callable, Generator, cast