Introduce `Clock.call_when_running(...)` to include logcontext by default by MadLittleMods · Pull Request #18944 · element-hq/synapse

MadLittleMods · 2025-09-19T20:07:54Z

This PR can be reviewed commit-by-commit.

Introduce Clock.call_when_running(...) to wrap startup code in a logcontext, ensuring we can identify which server generated the logs.

Background:

synapse/docs/log_contexts.md

Lines 71 to 81 in 9cc4001

    
           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).

Also adds a lint to prefer Clock.call_when_running(...) over reactor.callWhenRunning(...)

Part of #18905

Dev notes

Originally, we covered Synapse startup by manually adding a logcontext, see #18870

Adding logcontext to looping_call and call_later in #18907

Mypy lint pattern came from #18828

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 · 2025-09-19T20:15:58Z

@@ -0,0 +1 @@
+Introduce `Clock.call_when_running(...)` to wrap startup code in a logcontext, ensuring we can identify which server generated the logs.


This PR can be reviewed commit-by-commit. There are lots of changes because I split out JSON and Clock utilities to avoid circular imports.

MadLittleMods · 2025-09-19T20:17:34Z

        return None


+def check_call_when_running(ctx: MethodSigContext) -> CallableType:


This lint pattern is coming from #18828 where we're also going to lint call_later and looping_call in the future.

MadLittleMods · 2025-09-19T20:18:51Z

+            if not ignore_errs:
+                raise
+
+    def call_when_running(


The new function is here Clock.call_when_running

We're wrapping reactor.callWhenRunning so there is always a logcontext active and therefore know which server generated the logs

MadLittleMods · 2025-09-19T20:19:14Z

+        d.addErrback(log_failure, "Looping call died", consumeErrors=False)
+        return call
+
+    def call_later(


The other functions like looping_call and call_later are getting their own logcontext wrappers in #18944

MadLittleMods · 2025-09-22T15:28:14Z

Thanks for the review @reivilibre 🐩

…ooping_call_now`, `call_later`) (#18907) Part of #18905 Lints for ensuring we use `Clock.call_later` instead of `reactor.callLater`, etc are coming in #18944 ### Testing strategy 1. Configure Synapse to log at the `DEBUG` level 1. Start Synapse: `poetry run synapse_homeserver --config-path homeserver.yaml` 1. Wait 10 seconds for the [database profiling loop](https://github.com/element-hq/synapse/blob/9cc400177822805e2a08d4d934daad6f3bc2a4df/synapse/storage/database.py#L711) to execute 1. Notice the logcontext being used for the `Total database time` log line Before (`sentinel`): ``` 2025-09-10 16:36:58,651 - synapse.storage.TIME - 707 - DEBUG - sentinel - Total database time: 0.646% {room_forgetter_stream_pos(2): 0.131%, reap_monthly_active_users(1): 0.083%, get_device_change_last_converted_pos(1): 0.078%} ``` After (`looping_call`): ``` 2025-09-10 16:36:58,651 - synapse.storage.TIME - 707 - DEBUG - looping_call - Total database time: 0.646% {room_forgetter_stream_pos(2): 0.131%, reap_monthly_active_users(1): 0.083%, get_device_change_last_converted_pos(1): 0.078%} ```

…ooping_call_now`, `call_later`) (#18907) Part of element-hq/synapse#18905 Lints for ensuring we use `Clock.call_later` instead of `reactor.callLater`, etc are coming in element-hq/synapse#18944 ### Testing strategy 1. Configure Synapse to log at the `DEBUG` level 1. Start Synapse: `poetry run synapse_homeserver --config-path homeserver.yaml` 1. Wait 10 seconds for the [database profiling loop](https://github.com/element-hq/synapse/blob/9cc400177822805e2a08d4d934daad6f3bc2a4df/synapse/storage/database.py#L711) to execute 1. Notice the logcontext being used for the `Total database time` log line Before (`sentinel`): ``` 2025-09-10 16:36:58,651 - synapse.storage.TIME - 707 - DEBUG - sentinel - Total database time: 0.646% {room_forgetter_stream_pos(2): 0.131%, reap_monthly_active_users(1): 0.083%, get_device_change_last_converted_pos(1): 0.078%} ``` After (`looping_call`): ``` 2025-09-10 16:36:58,651 - synapse.storage.TIME - 707 - DEBUG - looping_call - Total database time: 0.646% {room_forgetter_stream_pos(2): 0.131%, reap_monthly_active_users(1): 0.083%, get_device_change_last_converted_pos(1): 0.078%} ```

MadLittleMods added 8 commits September 18, 2025 21:18

Split out JSON and Clock utilities to avoid circular imports

e45dd4f

Fix imports

bccd224

Add Clock.call_when_running(...)

2d1331f

Add lint to prefer Clock.call_when_running

f1e6887

Fix reactor.callWhenRunning lints

12e7cf4

Remove manual LoggingContext

731f36e

Fix copy-paste typos

0f8076a

We can't assume sentinel context when callback is called

6938134

MadLittleMods added the A-Logging label Sep 19, 2025

MadLittleMods mentioned this pull request Sep 19, 2025

Remove sentinel logcontext where we log in Synapse #18905

Closed

MadLittleMods added 2 commits September 19, 2025 15:11

Add changelog

7b83c9f

Better changelog

62f93de

MadLittleMods commented Sep 19, 2025

View reviewed changes

Fix lints

19a4f8c

MadLittleMods mentioned this pull request Sep 19, 2025

Remove sentinel logcontext in Clock utilities (looping_call, looping_call_now, call_later) #18907

Merged

3 tasks

Fix wrong config typo

4a9730e

MadLittleMods marked this pull request as ready for review September 19, 2025 21:06

MadLittleMods requested a review from a team as a code owner September 19, 2025 21:06

MadLittleMods mentioned this pull request Sep 19, 2025

Introduce Clock.add_system_event_trigger(...) to include logcontext by default #18945

Merged

4 tasks

reivilibre approved these changes Sep 22, 2025

View reviewed changes

MadLittleMods merged commit 5a9ca1e into develop Sep 22, 2025
44 checks passed

MadLittleMods deleted the madlittlemods/hs-clock-utils-logcontext branch September 22, 2025 15:28

itsoyou mentioned this pull request Oct 9, 2025

chore: fix clock util import path famedly/synapse-invite-checker#103

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Introduce `Clock.call_when_running(...)` to include logcontext by default#18944

Introduce `Clock.call_when_running(...)` to include logcontext by default#18944
MadLittleMods merged 12 commits intodevelopfrom
madlittlemods/hs-clock-utils-logcontext

MadLittleMods commented Sep 19, 2025 •

edited

Loading

Uh oh!

MadLittleMods Sep 19, 2025

Uh oh!

MadLittleMods Sep 19, 2025

Uh oh!

MadLittleMods Sep 19, 2025

Uh oh!

MadLittleMods Sep 19, 2025

Uh oh!

Uh oh!

MadLittleMods commented Sep 22, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

	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).

		@@ -0,0 +1 @@
		Introduce `Clock.call_when_running(...)` to wrap startup code in a logcontext, ensuring we can identify which server generated the logs.

		return None


		def check_call_when_running(ctx: MethodSigContext) -> CallableType:

Conversation

MadLittleMods commented Sep 19, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Dev notes

Pull Request Checklist

Uh oh!

MadLittleMods Sep 19, 2025

Choose a reason for hiding this comment

Uh oh!

MadLittleMods Sep 19, 2025

Choose a reason for hiding this comment

Uh oh!

MadLittleMods Sep 19, 2025

Choose a reason for hiding this comment

Uh oh!

MadLittleMods Sep 19, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!

MadLittleMods commented Sep 22, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

MadLittleMods commented Sep 19, 2025 •

edited

Loading