Skip to content

Port LogContext to Rust#19979

Open
erikjohnston wants to merge 7 commits into
developfrom
erikj/logcontext-rust-p4-clean
Open

Port LogContext to Rust#19979
erikjohnston wants to merge 7 commits into
developfrom
erikj/logcontext-rust-p4-clean

Conversation

@erikjohnston

@erikjohnston erikjohnston commented Jul 17, 2026

Copy link
Copy Markdown
Member

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:

  1. 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.
  2. Port ContextResourceUsage to a Rust pyclass — self-contained: the new synapse_rust.logcontext module, the class, its stub and the re-export.
  3. 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.
  4. Attribute Rust-spawned work to the caller's logcontextcreate_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.

erikjohnston and others added 4 commits July 17, 2026 11:14
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
@erikjohnston 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
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
@erikjohnston
erikjohnston marked this pull request as ready for review July 21, 2026 08:24
@erikjohnston
erikjohnston requested a review from a team as a code owner July 21, 2026 08:24
@erikjohnston
erikjohnston requested a review from Copilot July 21, 2026 09:35

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

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.

Comment thread rust/src/logging/context.rs
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
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.

3 participants