Port `LogContext` to Rust by erikjohnston · Pull Request #19979 · element-hq/synapse

erikjohnston · 2026-07-17T15:21:22Z

Ports the logcontext classes to Rust, and gives tokio tasks a captured logcontext so that work running in (or spawned from) Rust is attributed to the request that caused it.

Best reviewed commit by commit:

Add characterization tests for logcontext error messages and the filter — pins the exact logcontext_error message shapes, the abuse-detection code paths and LoggingContextFilter's observable behaviour, against the existing Python implementation (this commit is green on its own). These are the behavioural contract the port has to satisfy.
Port ContextResourceUsage to a Rust pyclass — self-contained: the new synapse_rust.logcontext module, the class, its stub and the re-export.
Move the logcontext storage and LoggingContext to Rust — the core change; the commit message carries detailed design notes. Highlights:
- The slot is typed Option<Py<LoggingContext>>, with None representing the sentinel. _Sentinel/SENTINEL_CONTEXT stay pure Python (unchanged); thin wrappers on current_context/set_current_context convert at the boundary, and pyo3's extraction enforces the type (TypeError otherwise).
- The accounting is native: one getrusage(RUSAGE_THREAD) read per switch via libc, inline stop/start bookkeeping for base LoggingContexts, Python dispatch only for subclasses (BackgroundProcessLoggingContext) so their overrides run. The thread id comes from PyThread_get_thread_ident (the exact threading.get_ident()
  value) without calling into Python.
- The hot paths avoid per-operation allocation: names are Py<PyString> (the per-log-record str(context)/server_name reads are INCREF-only), error branches materialise strings only when hit.
Attribute Rust-spawned work to the caller's logcontext — create_deferred captures the caller's context and scopes it onto the spawned task via a tokio task-local (LogContextHandle); current_context() gives the task-local read precedence, so LoggingContextFilter/pyo3-log resolve the right context on worker
threads with no per-record stamping. run_python_awaitable restores the captured context (via a with_logcontext helper, the Rust PreserveLoggingContext) around Python called back from Rust, so e.g. runInteraction from the Rust /versions handler accounts its DB usage against the right request. Integration tests exercise both guarantees through real production code paths.

Follow-up work on top of this (separate PR): porting BackgroundProcessLoggingContext natively and removing further Py<_> indirections. The fact that BackgroundProcessLoggingContext is a subclass is what forces some of the warts in this PR: e.g. having to use Py<LoggingContext> everywhere, etc.

We don't try (yet) to make this pure Rust, instead we see this as simply maintaining the Python logcontext machinery when crossing, rather than trying to make a Rust equivalent that can be used by pure Rust dependencies. We probably do want to do that in future, as well as wire up e.g. CPU recording on Rust side, but that is unnecessary for now.

Reviewable commit-by-commit.

Pin the Python-observable behaviour of the logcontext machinery ahead of porting it to Rust: - LogContextErrorMessageTestCase pins the exact logcontext_error message wording, argument order and the conditions that trigger each abuse warning. These are load-bearing: tests and downstream log scraping match on them. Messages interpolating a context via %r embed the object's repr (id/address), so expected strings are reconstructed from the same live objects rather than hard-coded. - LoggingContextFilterTestCase pins LoggingContextFilter — the entire observable surface for logging: record attributes are filled from a real logcontext, and (crucially for 3rd-party code) under the sentinel only absent attributes get defaults. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01JFbRtswu7rsHrttJFauUUb

The first slice of moving the logcontext machinery into the Rust extension: ContextResourceUsage becomes a native class in the new synapse.synapse_rust.logcontext module (rust/src/logging/context.rs), re-exported from synapse.logging.context so callers are unchanged. The public attribute surface, operators and repr are a compatibility contract with the Python callers (Measure, request/background-process metrics, the task scheduler, ...). Keeping the tracker native lets the upcoming switch machinery do its rusage accounting without allocating a Python object per operation. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01JFbRtswu7rsHrttJFauUUb

The "current logcontext" slot moves from a Python threading.local into the Rust extension, together with a native port of LoggingContext. A Python thread-local is invisible to Rust: each tokio worker thread would see its own slot, permanently at the sentinel, so logging emitted from Rust could not be attributed to the request that caused it. This lays the storage groundwork; a follow-up change gives tokio tasks a task-scoped capture (see the module-doc TODO). Design notes, for review: - The slot is typed: Option<Py<LoggingContext>>, with None representing the sentinel. The _Sentinel class and SENTINEL_CONTEXT singleton stay pure Python, unchanged; thin wrappers on current_context and set_current_context in synapse.logging.context convert between the singleton and None at the boundary, so no Rust code ever sees or produces the sentinel object. pyo3's extraction enforces the type: anything that is not a LoggingContext (or subclass) or None raises TypeError. - The accounting policy is native too: set_current_context reads the thread rusage once via libc (no per-switch struct_rusage allocation) and runs the stop/start bookkeeping inline for base LoggingContexts, only dispatching through Python for subclasses (BackgroundProcessLoggingContext) so their overrides run. start()/stop() now take an Optional[tuple[float, float]] instead of a struct_rusage, the get_thread_resource_usage/is_thread_resource_usage_supported/ get_thread_id module helpers are gone, LoggingContext.previous_context is now Optional[LoggingContext] (None where it used to hold SENTINEL_CONTEXT), and the nominally-private _resource_usage attribute is no longer exposed (nothing read it; use get_resource_usage()) — worth an upgrade note when this is released, as out-of-tree code may rely on the old shapes. - The switch path avoids per-operation allocation and Python round-trips: names are stored as Py<PyString> (LoggingContextFilter reads server_name and str(context) per log record process-wide, now INCREF-only), error messages materialise the context name only in the cold branches, and the thread id is read via PyThread_get_thread_ident (the exact value threading.get_ident() returns) rather than by calling into Python. - The attribute surface, method set and error-message wording are a compatibility contract, pinned by the characterization tests (which now exercise the tuple-based start/stop API). - The opt-in synapse.logging.context.debug switch traces are emitted from Rust via pyo3-log, whose level cache only refreshes on reset_logging_config(); docs/log_contexts.md documents the manhole procedure. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01JFbRtswu7rsHrttJFauUUb

Give tokio tasks a captured logcontext, resolving the module-doc TODO: - LogContextHandle is a cheap, clone-able, GIL-free handle in the same Option<Py<LoggingContext>> representation the storage slots use. create_deferred captures the caller's context at the FFI boundary and scopes it onto the spawned task via a tokio task-local, which rides with the task across .await points. current_context() gives the task-local read precedence, so log records emitted while a task is polled — via LoggingContextFilter and pyo3-log — are attributed to the captured context with no per-record stamping. - The switch primitive is only ever driven on reactor/threadpool threads, never during a tokio-scoped poll (where the write would be invisible to reads); swap_current_context enforces that invariant with an error log rather than trusting it. - run_python_awaitable restores the captured context on the reactor thread before driving the awaitable, so Python called back from Rust (e.g. DatabasePool.runInteraction from the Rust /versions handler) runs in — and accounts its DB usage against — the right request. The restore protocol lives in a new with_logcontext helper (the Rust equivalent of `with PreserveLoggingContext(...)`): an error cannot skip the restore (which would leak the context onto the reactor thread permanently), and a context that has already finished is not re-started (create_deferred does not propagate cancellation, so a task can outlive its request; see the TODO) — such work runs in the sentinel instead. - tests/synapse_rust/test_logcontext.py exercises both guarantees through real production code paths: reqwest's log records carry the caller's request id, and the /versions handler's DB transaction lands on the caller's usage accounting. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01JFbRtswu7rsHrttJFauUUb

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01JFbRtswu7rsHrttJFauUUb

The Rust `LoggingContext` requires `server_name` to be a `str`. Three test suites built a mock homeserver whose `hostname` was left as an auto-generated `Mock`, which flowed into `server_name` (via `DatabasePool`, `StateHandler` and `ApplicationServicesHandler`) and raised `TypeError: argument 'server_name': 'Mock' object is not an instance of 'str'` once a `LoggingContext`/`Measure` was constructed — 42 trial errors in CI. Set `hostname` to the server name each suite already uses, so the mocks match what production passes. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01VF56cZ93AqpuGCf8yguCcR

Copilot

Pull request overview

Ports Synapse’s logcontext machinery to a Rust-backed implementation so that the “current logcontext” is visible to both Python (reactor + threadpool) and Rust (tokio tasks), enabling correct attribution of logs and resource accounting across the language boundary.

Changes:

Introduces a Rust implementation of LoggingContext, ContextResourceUsage, and current-context storage with both OS-thread-local and tokio-task-local sources of truth.
Updates Python-facing wrappers (synapse.logging.context) and related types/docs to use the Rust extension while preserving existing observable behavior.
Adds characterization and integration tests to pin error-message shapes, filter behavior, and cross-language attribution guarantees.

Reviewed changes

Copilot reviewed 15 out of 16 changed files in this pull request and generated 1 comment.

Show a summary per file

File	Description
tests/util/test_logcontext.py	Adds characterization tests for `logcontext_error` messages and `LoggingContextFilter` behavior.
tests/test_state.py	Updates test setup to provide `hs.hostname` expected by updated logcontext usage.
tests/synapse_rust/test_logcontext.py	Adds integration tests validating Rust↔Python logcontext attribution via real code paths.
tests/storage/test_base.py	Adjusts `DatabasePool` test construction to provide a `hostname`.
tests/handlers/test_appservice.py	Updates mocked homeserver to provide `hostname` for background process/logcontext usage.
synapse/synapse_rust/logcontext.pyi	Adds typing stubs for the Rust `logcontext` module surface.
synapse/metrics/background_process_metrics.py	Updates `BackgroundProcessLoggingContext.start` rusage typing to the new `(utime, stime)` tuple shape.
synapse/logging/context.py	Switches Python logcontext implementation to wrappers over the Rust extension and re-exports Rust-backed classes/constants.
rust/src/logging/mod.rs	Adds Rust logging module namespace aligned with Python logger naming.
rust/src/logging/context.rs	Implements Rust storage, task-local scoping, and Rust-backed `LoggingContext`/`ContextResourceUsage`.
rust/src/lib.rs	Registers the Rust logcontext module with Python.
rust/src/deferred.rs	Captures/scopes logcontext onto spawned tokio tasks and restores it for Rust→Python callbacks.
rust/Cargo.toml	Adds `libc` dependency for `getrusage(RUSAGE_THREAD)` access.
docs/log_contexts.md	Documents the Rust-backed storage model and how to correctly spawn tokio tasks with captured logcontext.
changelog.d/19979.misc	Adds Towncrier newsfragment for the port.
Cargo.lock	Locks `libc` dependency addition.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

swap_current_context already detected being called while a tokio task-local logcontext is in scope, but after logging the error it wrote the thread-local slot anyway. The write is invisible to current_context() (the task-local has read precedence) — and permanent: the paired restore via set_current_context compares against the task-local, sees no change, and skips its swap, so the stray value stays in the slot (and its real occupant is dropped) after the scope ends. Everything the thread does next is misattributed to it, and the stray context is pinned alive on that thread. Bail out after logging instead, leaving the slot untouched, so the damage is confined to the scoped poll. Returns None in that case; the only caller (set_current_context) ignores the return value. Flagged by Copilot review on #19979. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01VF56cZ93AqpuGCf8yguCcR

anoadragon453

I'll admit I found this difficult to review with the LLM's writing style for comments and documentation. It used a lot of terminology we don't use in the team (i.e. "pinning behaviour" -> writing tests, "characterization tests", etc.).

It probably doesn't help that I'm not too familiar with logcontexts, so some of the unfamiliar terminology (switch, slots, etc.) may just be down to that.

Stopped partway through c3dfbfc.

swap_current_context already detected being called while a tokio task-local logcontext is in scope, but after logging the error it wrote the thread-local slot anyway. The write is invisible to current_context() (the task-local has read precedence) — and permanent: the paired restore via set_current_context compares against the task-local, sees no change, and skips its swap, so the stray value stays in the slot (and its real occupant is dropped) after the scope ends. Everything the thread does next is misattributed to it, and the stray context is pinned alive on that thread. Bail out after logging instead, leaving the slot untouched, so the damage is confined to the scoped poll. Returns None in that case; the only caller (set_current_context) ignores the return value. Flagged by Copilot review on #19979. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01VF56cZ93AqpuGCf8yguCcR

A slot was used to mean where we stored the current context and what was in it. That's confusing, so let's replace it with "context" or "current context", etc.

We should still run the code in the logcontext even if it has finished. This is fine, though will log an error (like in the Python impl). The logcontext should not have finished if there is Rust work still ongoing.

erikjohnston · 2026-08-05T15:54:50Z

I'll admit I found this difficult to review with the LLM's writing style for comments and documentation. It used a lot of terminology we don't use in the team (i.e. "pinning behaviour" -> writing tests, "characterization tests", etc.).

It probably doesn't help that I'm not too familiar with logcontexts, so some of the unfamiliar terminology (switch, slots, etc.) may just be down to that.

I've gone through and tried to rework the comments based on this feedback (which is valuable). In particular, terms that make sense to the author are easy to accept when actually they're new terms and their usage confuse reviewers.

eg the "characterisation tests" and "pinning behaviour" both make sense in what was trying to be achieved: adding tests to the existing unmodified code to ensure that there is no change in external behaviour after we port the code. Nonetheless, that's not an approach that we've really done before in Synapse.

(There was also some just downright confusing comments that I missed first time around).

Having carefully combed through things again, I also noticed some minor code issues that I've cleaned up as well.

anoadragon453

Apologies for the long wait on another round of review. This is a very large PR, and thus I felt I had to carve out a few hours for it whenever coming back it, which I often didn't get the chance for.

My initial difficulty with reading the comments also stemmed from no longer being intimately familiar with how log contexts worked. So I had to go on a journey there before coming back to this PR.

Thanks for improving the comments. Alas, I still had to wade through the initial ones to review commit-by-commit. Thankfully most of the clarifying comments that were pending I could delete after your changes.

My eyes still glazed over a bit towards the end, but I think I'm at a point where I'm happy to hand this back.

anoadragon453 · 2026-08-06T19:07:11Z

+/// Note that `get_ident` is *not* an OS-level tid. On Linux it returns the same
+/// value either side of a `fork()` call. Synapse forks in exactly one place, so
+/// contexts created before the fork still pass the `main_thread` check after
+/// it.


trivia: you can now use get_native_id to get the actual OS thread ID. https://stackoverflow.com/a/56101710

Oh right. Though with get_native_id you have to worry about when we do os.fork() I think?

anoadragon453 · 2026-09-07T17:57:13Z

+    /// The `threading.get_ident()` value of the thread this context was created
+    /// on (see [`get_thread_id`] for why it is not a real OS tid); activity on
+    /// any other thread is an error. Settable only so tests can simulate
+    /// activity on the wrong thread.
+    #[pyo3(get, set)]
+    main_thread: u64,


Feels like a bad smell to have a field that should only be set by tests.

Fair, I can either remove the tests or try and spin up a real thread?

anoadragon453 · 2026-09-07T18:03:48Z

+        // If we are on the correct thread and we're currently running then we can
+        // include resource usage so far.


Do we ever move back to the thread we started on? I thought tokio tasks just move around to whatever thread they like?

This only tracks CPU usage on the main python thread. I've added that to the docstring

anoadragon453 · 2026-09-07T19:12:46Z

+`set_current_context` only ever runs on a Python thread, i.e. the reactor or one
+of its thread pools, where it does the `getrusage` CPU accounting. It is never
+called from a tokio worker thread.


I thought we were doing the libc rusage stuff in Rust now?

(This may just be confusingly worded; mixing the calling of set_current_context with CPU accounting).

Yeah, so big note here is that we only do the tracking of when a logcontext comes in and out of scope (and therefore resource t racking) on python threads (i.e. where we use a thread local), and we don't when on tokio threads (i.e. when using task local).

We can't implement resource tracking in the same way when using task locals, as we don't have the correct hooks. We probably do want to track it, and we could probably do so by wrapping the tasks in a future wrapper that measured resource usage across .poll(..) invocations.

I'm not sure where best to add comments to make that clearer?

Co-authored-by: Andrew Morgan <1342360+anoadragon453@users.noreply.github.com>

erikjohnston · 2026-09-08T12:14:29Z

+        yield messages
+
+
+class LogContextErrorMessageTestCase(unittest.TestCase):


As discussed separately: do we care enough about these tests to keep them? Initially I kept them as "more tests better" (and Claude generated them so that the errors were kept the same during the port), but now I feel like maybe they're just a waste?

erikjohnston · 2026-09-08T12:16:40Z

Thanks for going through this! Appreciate that logcontexts are gnarly

erikjohnston and others added 4 commits July 17, 2026 11:14

erikjohnston changed the title ~~Erikj/logcontext rust p4 clean~~ Port LogContext to Rust Jul 17, 2026

erikjohnston and others added 2 commits July 17, 2026 15:22

Add changelog

42f5a32

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01JFbRtswu7rsHrttJFauUUb

MadLittleMods added A-Logging rust Z-Rust labels Jul 20, 2026

erikjohnston marked this pull request as ready for review July 21, 2026 08:24

erikjohnston requested a review from a team as a code owner July 21, 2026 08:24

erikjohnston requested a review from Copilot July 21, 2026 09:35

Copilot started reviewing on behalf of erikjohnston July 21, 2026 09:36 View session

Copilot AI reviewed Jul 21, 2026

View reviewed changes

Comment thread rust/src/logging/context.rs

anoadragon453 assigned anoadragon453 and unassigned anoadragon453 Jul 24, 2026

anoadragon453 reviewed Jul 31, 2026

View reviewed changes

erikjohnston force-pushed the erikj/logcontext-rust-p4-clean branch 2 times, most recently from 69ad4c7 to 17d583f Compare August 4, 2026 11:01

erikjohnston force-pushed the erikj/logcontext-rust-p4-clean branch from f20c3ac to 0916980 Compare August 5, 2026 13:54

erikjohnston force-pushed the erikj/logcontext-rust-p4-clean branch from 0916980 to c0204d4 Compare August 5, 2026 13:56

erikjohnston added 5 commits August 5, 2026 15:00

Clean up comments

2491618

Update comments

2654fc4

s/LogContextHandle::current()/LogContextHandle::task_current()/

efef006

Rename 'slot' functions

d565473

A slot was used to mean where we stored the current context and what was in it. That's confusing, so let's replace it with "context" or "current context", etc.

Reactivate dead logcontexts

fcb43c6

We should still run the code in the logcontext even if it has finished. This is fine, though will log an error (like in the Python impl). The logcontext should not have finished if there is Rust work still ongoing.

Use assertTrue

af4a615

erikjohnston force-pushed the erikj/logcontext-rust-p4-clean branch from c0204d4 to af4a615 Compare August 5, 2026 14:00

Simplify start/stop

d752be2

erikjohnston force-pushed the erikj/logcontext-rust-p4-clean branch from 580ebd5 to d752be2 Compare August 5, 2026 15:32

erikjohnston requested a review from anoadragon453 August 5, 2026 16:11

anoadragon453 requested changes Sep 7, 2026

View reviewed changes

erikjohnston and others added 5 commits September 8, 2026 12:23

Apply batched suggestions from code review

d6d1a3f

Co-authored-by: Andrew Morgan <1342360+anoadragon453@users.noreply.github.com>

Add comment that get_resource_usage only works on main thread

4494d6a

ContextResourceUsage docstrings

bfb3ba7

Move comment

0b39940

Add returns and unindent

39af8d4

erikjohnston commented Sep 8, 2026

View reviewed changes

Remove mention of where the code is

5632ef9

erikjohnston force-pushed the erikj/logcontext-rust-p4-clean branch from 31a65b7 to 5632ef9 Compare September 8, 2026 12:15

erikjohnston requested a review from anoadragon453 September 8, 2026 12:16

		// If we are on the correct thread and we're currently running then we can
		// include resource usage so far.

		yield messages


		class LogContextErrorMessageTestCase(unittest.TestCase):

Uh oh!

Conversation

erikjohnston commented Jul 17, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

Uh oh!

anoadragon453 left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

erikjohnston commented Aug 5, 2026

Uh oh!

anoadragon453 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

erikjohnston commented Sep 8, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

erikjohnston commented Jul 17, 2026 •

edited

Loading