Skip to content

Conversation

MadLittleMods
Copy link
Contributor

@MadLittleMods MadLittleMods commented Sep 18, 2025

Fix run_as_background_process not be awaited properly causing LoggingContext problems

Basically, searching for any instance of run_as_background_process(...) and making sure we wrap the deferred in make_deferred_yieldable(...) if we try to await the result to make it follow the Synapse logcontext rules.

Part of #18905

Dev notes

The problem code was introduced in #17326

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)

Reproduction:
```
SYNAPSE_TEST_LOG_LEVEL=INFO poetry run trial tests.rest.client.test_delayed_events.DelayedEventsTestCase.test_cancel_delayed_state_event
```

Check `_trial_temp/test.log` (notice the `sentinel` log context)

```
2025-09-18 10:58:23-0500 [-] synapse.handlers.delayed_events - 339 - INFO - POST-11 - asdf cancelling delayed event before _initialized_from_db syd_OlmchCwyUqznIXhlTDXQ
...
2025-09-18 10:58:23-0500 [-] synapse.handlers.delayed_events - 124 - INFO - _schedule_db_events-0 - asdf done _initialized_from_db
2025-09-18 10:58:23-0500 [-] synapse.handlers.delayed_events - 344 - INFO - sentinel - asdf cancelling delayed event after _initialized_from_db syd_OlmchCwyUqznIXhlTDXQ
```
(requester.user.to_string(), requester.device_id),
)
await self._initialized_from_db
await make_deferred_yieldable(self._initialized_from_db)
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As described in the docstring for why we need to do this:

Because the returned Deferred does not follow the synapse logcontext rules, awaiting
the result of this function will result in the log context being cleared (bad). In
order to properly await the result of this function and maintain the current log
context, use `make_deferred_yieldable`.

(docstring updated in #18900)

If you're wondering what the problem looks like in practice, see 1668023

@MadLittleMods MadLittleMods marked this pull request as ready for review September 19, 2025 00:42
@MadLittleMods MadLittleMods requested a review from a team as a code owner September 19, 2025 00:42
@MadLittleMods MadLittleMods merged commit 8d5d87f into develop Sep 22, 2025
44 checks passed
@MadLittleMods MadLittleMods deleted the madlittlemods/delayed-events-run-as-background-process-sentinel-context branch September 22, 2025 16:02
@MadLittleMods
Copy link
Contributor Author

Thanks for the review @reivilibre 🦊

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants