Fix run_as_background_process messing with the caller logging context

[MadLittleMods]

Fix run_as_background_process messing with the caller logging context

Spawning from #18870

Testing strategy

There seems to be some test pollution with logging context as running all tests.util.test_logcontext.LoggingContextTestCase tests will only result in one of these failing. But if you run them individually, they both fail (without a fix):

1. SYNAPSE_TEST_LOG_LEVEL=INFO poetry run trial tests.util.test_logcontext.LoggingContextTestCase.test_run_as_background_process
2. SYNAPSE_TEST_LOG_LEVEL=INFO poetry run trial tests.util.test_logcontext.LoggingContextTestCase.test_run_as_background_process_make_deferred_yieldable

Todo

• Come up with a fix
• Add tests

Dev notes

Synapse log context docs: docs/log_contexts.md

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]

No fix has been added yet. Only tests to reproduce the problem so far

[MadLittleMods]

To sanity check myself, would you also expect these tests to pass in an ideal world?

We currently fallback to the sentinel context at the end within the main block.

[MadLittleMods]

cc @erikjohnston

[erikjohnston]

I'd expect the logcontexts to be messed up by await bg_process_d.

run_as_background_process takes an awaitable that follows the logcontext rules and makes it so that you can safely not await on them. This means that the returned deferred doesn't actually follow the logcontext rules itself, and so if you then want to await on the deferred again you must use make_deferred_awaitable (or similar) to make it follow the rules again

[MadLittleMods]

Ahh, totally makes sense why it's broken in this test case! I jumped the gun on thinking I reproduced the problem here.

In terms of where this PR is spawning from with the problems in #18870; from a pairing session with @erikjohnston, the main thing I was banging my head against was that I removed PreserveLoggingContext at the following spot in order to maintain the main logging context further into Synapse starting up and running. But this also meant leaking the main logging context into the Twisted reactor event loop and apply to the next task which appeared like the desired result because the next task was start but also meant it got messed up later down the line.

synapse/synapse/app/_base.py

Lines 196 to 204 in 4b43e6f

	with PreserveLoggingContext():
	if daemonize:
	assert pid_file is not None
	if print_pidfile:
	print(pid_file)
	daemonize_process(pid_file, logger)
	run()

While I haven't explored this thread to its' end, I think this is the key insight into why I was chasing ghosts.

See #18870 (comment) for the other discussion around this.

Thank you @erikjohnston for hopping on a call 🙇