Fix lost logcontext when using timeout_deferred(...)

[MadLittleMods]

Fix lost logcontext when using timeout_deferred(...) and things actually timeout.

Fix #19087 (our HTTP client times out requests using timeout_deferred(...)
Fix #19066 (/sync uses notifier.wait_for_events() which uses timeout_deferred(...) under the hood)

When/why did these lost logcontext warnings start happening?

synapse.logging.context - 107 - WARNING - sentinel - Expected logging context call_later but found POST-2453

synapse.logging.context - 107 - WARNING - sentinel - Expected logging context call_later was lost

In #18828, we switched timeout_deferred(...) from using reactor.callLater(...) to clock.call_later(...) under the hood. This meant it started dealing with logcontexts but our time_it_out() callback didn't follow our Synapse logcontext rules.

Dev notes

SYNAPSE_TEST_LOG_LEVEL=DEBUG poetry run trial tests.util.test_async_helpers.TimeoutDeferredTest.test_logcontext_is_not_lost_when_awaiting_on_timeout_cancellation

SYNAPSE_TEST_LOG_LEVEL=INFO poetry run trial tests.rest.client.sliding_sync.test_sliding_sync.SlidingSyncTestCase_new.test_wait_for_new_data_timeout

Pull Request Checklist

• Pull request is based on the develop branch
• Pull request includes a changelog file. The entry should:
  • Be a short description of your change which makes sense to users. "Fixed a bug that prevented receiving messages from other servers." instead of "Moved X method from EventStore to EventWorkerStore.".
  • Use markdown where necessary, mostly for code blocks.
  • End with either a period (.) or an exclamation mark (!).
  • Start with a capital letter.
  • Feel free to credit yourself, by adding a sentence "Contributed by @github_username." or "Contributed by [Your Name]." to the end of the entry.
• Code style is correct (run the linters)

[MadLittleMods]

Extra protection when our assumption is wrong.

This did happen for the case we're fixing.

[MadLittleMods]

This is the main fix!

See the Deferred callbacks section of our logcontext docs for more info (specifically using solution 2).

Heads-up, I wrote the docs too so it's my assumptions/understanding all the way down. Apply your own scrutiny.

[MadLittleMods]

Copy/paste typo

[MadLittleMods]

Quality of life so these the logcontext errors appear in the logs (_trial_temp/test.log) just like if we never used @logcontext_clean to patch it.

logger.warning(...) is the same as what we're doing in the actual thing:

synapse/synapse/logging/context.py

Lines 105 to 107 in 3b59ac3

	# a hook which can be set during testing to assert that we aren't abusing logcontexts.
	def logcontext_error(msg: str) -> None:
	logger.warning(msg)

---

Perhaps it would be even better if we just called the original implementation alongside raising the AssertionError but the implementation is simple enough for now so just going to duplicate.

[MadLittleMods]

This test reproduces the Expected logging context call_later was lost problem with timeout_deferred(...)

And now passes with the fix introduced in this PR.

[MadLittleMods]

In an ideal world, I think it should be possible to call the deferred callback/errbacks/cancel with some logcontext. I spent too much time trying to figure out the intricacies here and trying to use solution 3 from the Deferred callbacks docs but wasn't successful.

It makes me question if what I wrote there is correct in the first place 🤔

---

The problem is that calling deferred.cancel() can change the logcontext but it's also complete at that point. Because the deferred is already complete, run_in_background(lambda: (deferred.cancel(), deferred)[1]) assumes that the logcontext was unchanged and returns it as-is which leaves the logcontext is messed up for the caller.

I can't tell if the problem is a) our function just isn't following logcontext rules (and how to resolve that well) or b) we should set_current_context(calling_context) regardless of whether the deferred is already complete.

Instead of banging my head against this more, I've opted to go for the simple route with PreserveLoggingContext():. Which also matches what we do elsewhere in the codebase. Something to improve in the future ⏩