-
Notifications
You must be signed in to change notification settings - Fork 385
Remove sentinel
logcontext where we log in setup
, start
and exit
#18870
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Remove sentinel
logcontext where we log in setup
, start
and exit
#18870
Conversation
Relevant comment introductions: - matrix-org/synapse#5609 - 067b00d
``` 2025-08-26 18:40:27,996 - my.synapse.linux.server - synapse.app.homeserver - 187 - WARNING - main - Starting daemon. 2025-08-26 18:40:27,996 - my.synapse.linux.server - synapse.app.homeserver - 181 - WARNING - atexit - Stopping daemon. ```
Running a normal server (`daemonize: false`): ``` poetry run synapse_homeserver --config-path homeserver.yaml ``` Bad logs being seen: ``` PreserveLoggingContext: Expected logging context sentinel but found main ``` ``` LoggingContext: Expected logging context main was lost ```
This reverts commit fce59b2.
Resulting in bad logs being seen: ``` PreserveLoggingContext: Expected logging context sentinel but found main ``` ``` LoggingContext: Expected logging context main was lost ```
# make sure that we run the reactor with the sentinel log context, | ||
# otherwise other PreserveLoggingContext instances will get confused | ||
# and complain when they see the logcontext arbitrarily swapping | ||
# between the sentinel and `run` logcontexts. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This comment was added in 067b00d#diff-6e21d6a61b2f6b6f2d4ce961991ba7f27e83605f927eaa4b19d2c46a975a96c1R460-R463 (matrix-org/synapse#2027)
I can't tell exactly what's it's referring to but the one spot I was seeing Expected logging context sentinel but found main
around run_as_background_process(...)
usage has been fixed (#18870 (comment)).
Reproduction:
poetry run synapse_homeserver --config-path homeserver.yaml
- Ctrl + C to stop the server
- Notice
LoggingContext: Expected logging context main was lost
in the logs
# We also need to drop the logcontext before forking if we're daemonizing, | ||
# otherwise the cputime metrics get confused about the per-thread resource usage | ||
# appearing to go backwards. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This comment was added in matrix-org/synapse#5609 and is accurately describing a real problem.
But we can be way more precise about what do to here. We only need to stop
the current log context right before forking the process and start
it again right after. This can be accomplished with the PreserveLoggingContext
being moved strictly around the os.fork()
call (search for os.fork()
below).
Previously, this caused the sentinel
context to be used for a whole bunch of logs (basically anything outside of a request). We now get the main
context used 💪
Reproduction instructions: 1. `poetry run synapse_homeserver --config-path homeserver.yaml` 1. `curl http://localhost:8008/_matrix/client/versions` 1. Stop Synapse (`Ctrl + c`) Notice the bad log: ``` synapse.logging.context - WARNING - sentinel - LoggingContext: Expected logging context main was lost ```
…text rules" This reverts commit 675d94a. Things get stuck with this, see #18870 (comment)
Reproduction: 1. `poetry run synapse_homeserver --config-path homeserver.yaml` 1. Ctrl + C to stop the server 1. Notice `LoggingContext: Expected logging context main was lost` in the logs
…ement-hq/synapse into madlittlemods/remove-sentinel-context
So downstream usage doesn't need to use `PreserveLoggingContext()` or `make_deferred_yieldable` Spawning from #18870 and #18357 (comment)
So downstream usage doesn't need to use `PreserveLoggingContext()` or `make_deferred_yieldable` Spawning from #18870 and #18357 (comment)
…kground_process(...)` (#18900) Also adds a section in the docs explaining the `sentinel` logcontext. Spawning from #18870 ### Testing strategy 1. Run Synapse normally and with `daemonize: true`: `poetry run synapse_homeserver --config-path homeserver.yaml` 1. Execute some requests 1. Shutdown the server 1. Look for any bad log entries in your homeserver logs: - `Expected logging context sentinel but found main` - `Expected logging context main was lost` - `Expected previous context` - `utime went backwards!`/`stime went backwards!` - `Called stop on logcontext POST-0 without recording a start rusage` - `Background process re-entered without a proc` Twisted trial tests: 1. Run full Twisted trial test suite. 1. Check the logs for `Test starting with non-sentinel logging context ...`
setup
, start
and exit
setup
, start
and exitsentinel
logcontext where we log in setup
, start
and exit
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Looks like it does the right things, and I learned more about logcontexts in the process!
Nice to see errors actually disappear after these changes.
Thanks for the review @anoadragon453 🐄 |
Remove
sentinel
logcontext where we log insetup
,start
, and exit.Instead of having one giant PR that removes all places we use
sentinel
logcontext, I've decided to tackle this more piece-meal. This PR covers the parts if you just startup Synapse and exit it with no requests or activity going on in between.Part of #18905 (Remove
sentinel
logcontext where we log in Synapse)Prerequisite for #18868. Logging with the
sentinel
logcontext means we won't know which server the log came from.Why
synapse/docs/log_contexts.md
Lines 71 to 81 in 9cc4001
(docs updated in #18900)
Testing strategy
daemonize: true
:poetry run synapse_homeserver --config-path homeserver.yaml
Expected logging context sentinel but found main
Expected logging context main was lost
Expected previous context
utime went backwards!
/stime went backwards!
Called stop on logcontext POST-0 without recording a start rusage
sentinel
contextWith these changes, you should only see the following logs (not from Synapse) using the
sentinel
context if you start up Synapse and exit:homeserver.log
Dev notes
Logcontexts
Whenever we yield to the Twisted reactor (event loop), we need to set the
sentinel
log context so log contexts don't leak and apply to the next task.Synapse log context docs:
docs/log_contexts.md
This is part of tracing though:
sentinel
spotsTodo
Previous todo list
I've since decided to tackle this piece-meal and added these notes to #18905
run_as_background_process
usemake_deferred_yieldable
if they wait on the resultrun_in_background
usemake_deferred_yieldable
if they wait on the resultPull Request Checklist
EventStore
toEventWorkerStore
.".code blocks
.