Remove sentinel logcontext where we log in Synapse
Since I plan to tackle this in a piece-meal fashion, this issue serves as a central place to link back to and organize the work.
Why
|
Ideally, nothing from the Synapse homeserver would be logged against the `sentinel` |
|
logcontext as we want to know which server the logs came from. In practice, this is not |
|
always the case yet especially outside of request handling. |
|
|
|
Global things outside of Synapse (e.g. Twisted reactor code) should run in the |
|
`sentinel` logcontext. It's only when it calls into application code that a logcontext |
|
gets activated. This means the reactor should be started in the `sentinel` logcontext, |
|
and any time an awaitable yields control back to the reactor, it should reset the |
|
logcontext to be the `sentinel` logcontext. This is important to avoid leaking the |
|
current logcontext to the reactor (which would then get picked up and associated with |
|
the next thing the reactor does). |
(docs updated in #18900)
Why are we doing this now?
This is spawning from #18868
As part of Element's plan to support a light form of vhosting (virtual host) (multiple instances of Synapse in the same Python process), we're currently diving into the details and implications of running multiple instances of Synapse in the same Python process.
Removing our sentinel logcontext usage is a prerequisite for #18868. Logging with the sentinel logcontext means we won't know which server the log came from.
"Per-tenant logging" tracked internally by https://github.com/element-hq/synapse-small-hosts/issues/48
Dev notes
Places to look out for
- Wherever we have a callback from the reactor, replace with
Clock utility that manages the logcontext (and add lints)
callLater/call_later -> #18907
task.LoopingCall/looping_call -> #18907
callWhenRunning -> #18944
addSystemEventTrigger -> #18945
with PreserveLoggingContext(): which the default here is using the sentinel logcontext
- Ensure usages of
run_as_background_process use make_deferred_yieldable if they wait on the result -> #18938
- Ensure usages of
run_in_background use make_deferred_yieldable if they wait on the result -> #18937
PR list
Historical related PR's before this issue:
Remove
sentinellogcontext where we log in SynapseSince I plan to tackle this in a piece-meal fashion, this issue serves as a central place to link back to and organize the work.
Why
synapse/docs/log_contexts.md
Lines 71 to 81 in 9cc4001
(docs updated in #18900)
Why are we doing this now?
This is spawning from #18868
Removing our
sentinellogcontext usage is a prerequisite for #18868. Logging with thesentinellogcontext means we won't know which server the log came from."Per-tenant logging" tracked internally by https://github.com/element-hq/synapse-small-hosts/issues/48
Dev notes
Places to look out for
Clockutility that manages the logcontext (and add lints)callLater/call_later-> #18907task.LoopingCall/looping_call-> #18907callWhenRunning-> #18944addSystemEventTrigger-> #18945with PreserveLoggingContext():which the default here is using thesentinellogcontextrun_as_background_processusemake_deferred_yieldableif they wait on the result -> #18938run_in_backgroundusemake_deferred_yieldableif they wait on the result -> #18937PR list
sentinellogcontext where we log insetup,startand exit #18870make_deferred_yieldable#18903sentinellogcontext inClockutilities (looping_call,looping_call_now,call_later) #18907run_in_backgroundnot be awaited properly causingLoggingContextproblems #18937run_as_background_processnot be awaited properly causingLoggingContextproblems #18938Clock.call_when_running(...)to include logcontext by default #18944Clock.add_system_event_trigger(...)to include logcontext by default #18945run_coroutine_in_background(...)incorrectly handling logcontext #18964timeout_deferredtests #18974Historical related PR's before this issue:
awaittosleepcalls #18763