mirror of
https://github.com/element-hq/synapse.git
synced 2026-11-11 16:37:42 +00:00
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.
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
`LoggingContext`s, 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 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.
178 lines
6.6 KiB
Python
178 lines
6.6 KiB
Python
# This file is licensed under the Affero General Public License (AGPL) version 3.
|
|
#
|
|
# Copyright (C) 2026 Element Creations Ltd
|
|
#
|
|
# This program is free software: you can redistribute it and/or modify
|
|
# it under the terms of the GNU Affero General Public License as
|
|
# published by the Free Software Foundation, either version 3 of the
|
|
# License, or (at your option) any later version.
|
|
#
|
|
# See the GNU Affero General Public License for more details:
|
|
# <https://www.gnu.org/licenses/agpl-3.0.html>.
|
|
|
|
from types import TracebackType
|
|
from typing import TYPE_CHECKING, Optional
|
|
|
|
from synapse.logging.context import ContextRequest
|
|
|
|
if TYPE_CHECKING:
|
|
from synapse.logging.scopecontextmanager import _LogContextScope
|
|
|
|
DEBUG_LOGGER_NAME: str
|
|
"""Name of the opt-in logger for debugging when the logcontext switches
|
|
(`synapse.logging.context.debug`). Shared with the Rust `debug!` target so the
|
|
names stay in sync."""
|
|
|
|
class ContextResourceUsage:
|
|
"""Tracks the resources used by a log context.
|
|
|
|
The attributes, operators and `repr` format are relied on by Python callers
|
|
(`Measure`, request and background-process metrics, the task scheduler,
|
|
etc). Implemented in Rust so that `set_current_context` can update the
|
|
counters without allocating a Python object each time.
|
|
"""
|
|
|
|
ru_stime: float
|
|
"""System CPU time, in seconds."""
|
|
ru_utime: float
|
|
"""User CPU time, in seconds."""
|
|
db_txn_count: int
|
|
"""Number of database transactions done."""
|
|
db_txn_duration_sec: float
|
|
"""Time spent doing database transactions (excluding scheduling), in seconds."""
|
|
db_sched_duration_sec: float
|
|
"""Time spent waiting for a database connection, in seconds."""
|
|
evt_db_fetch_count: int
|
|
"""Number of events requested from the database."""
|
|
|
|
def __init__(self, copy_from: "Optional[ContextResourceUsage]" = None) -> None:
|
|
"""If `copy_from` is given, copy its stats; otherwise start at zero."""
|
|
|
|
def copy(self) -> "ContextResourceUsage":
|
|
"""Return a copy of this object."""
|
|
|
|
def reset(self) -> None:
|
|
"""Reset all stats to zero."""
|
|
|
|
def __iadd__(self, other: "ContextResourceUsage") -> "ContextResourceUsage":
|
|
"""`self += other`, mutating in place."""
|
|
|
|
def __isub__(self, other: "ContextResourceUsage") -> "ContextResourceUsage":
|
|
"""`self -= other`, mutating in place."""
|
|
|
|
def __add__(self, other: "ContextResourceUsage") -> "ContextResourceUsage":
|
|
"""`self + other`, returning a new object."""
|
|
|
|
def __sub__(self, other: "ContextResourceUsage") -> "ContextResourceUsage":
|
|
"""`self - other`, returning a new object."""
|
|
|
|
class LoggingContext:
|
|
"""Additional context for log formatting. Contexts are scoped within a
|
|
"with" block.
|
|
|
|
If a parent is given when creating a new context, then:
|
|
- logging fields are copied from the parent to the new context on entry
|
|
- when the new context exits, the cpu usage stats are copied from the
|
|
child to the parent
|
|
"""
|
|
|
|
# The context that was current when this one was created. None means the
|
|
# sentinel.
|
|
previous_context: Optional[LoggingContext]
|
|
name: str
|
|
server_name: str
|
|
parent_context: "Optional[LoggingContext]"
|
|
main_thread: int
|
|
finished: bool
|
|
request: Optional[ContextRequest]
|
|
# Narrower than the runtime: the setter also accepts None (see the Rust
|
|
# field docs for why), but all in-tree code treats this as str.
|
|
tag: str
|
|
scope: "Optional[_LogContextScope]"
|
|
|
|
def __init__(
|
|
self,
|
|
*,
|
|
name: str,
|
|
server_name: str,
|
|
parent_context: "Optional[LoggingContext]" = None,
|
|
request: Optional[ContextRequest] = None,
|
|
) -> None:
|
|
"""
|
|
Args:
|
|
name: Name for the context for logging.
|
|
server_name: The name of the server this context is associated with
|
|
(`config.server.server_name` or `hs.hostname`).
|
|
parent_context: The parent of the new context.
|
|
request: Synapse Request Context object. Useful to associate all the
|
|
logs happening to a given request.
|
|
"""
|
|
|
|
def __str__(self) -> str: ...
|
|
def __enter__(self) -> "LoggingContext": ...
|
|
def __exit__(
|
|
self,
|
|
type: Optional[type[BaseException]],
|
|
value: Optional[BaseException],
|
|
traceback: Optional[TracebackType],
|
|
) -> None: ...
|
|
def start(self, rusage: "Optional[tuple[float, float]]") -> None:
|
|
"""Record that this logcontext is currently running.
|
|
|
|
Should not be called directly: use `set_current_context`.
|
|
|
|
Args:
|
|
rusage: The thread CPU usage `(ru_utime, ru_stime)` at the point of
|
|
switching to this context, or None if the platform doesn't
|
|
track it.
|
|
"""
|
|
|
|
def stop(self, rusage: "Optional[tuple[float, float]]") -> None:
|
|
"""Record that this logcontext is no longer running.
|
|
|
|
Should not be called directly: use `set_current_context`.
|
|
|
|
Args:
|
|
rusage: The thread CPU usage `(ru_utime, ru_stime)` at the point of
|
|
switching away from this context, or None if the platform
|
|
doesn't track it.
|
|
"""
|
|
|
|
def get_resource_usage(self) -> ContextResourceUsage:
|
|
"""Get the resources used by this logcontext so far.
|
|
|
|
Returns:
|
|
A *copy* of the object tracking resource usage so far.
|
|
"""
|
|
|
|
def add_cputime(self, utime_delta: float, stime_delta: float) -> None:
|
|
"""Update the CPU time usage of this context (and any parents, recursively)."""
|
|
|
|
def add_database_transaction(self, duration_sec: float) -> None:
|
|
"""Record the use of a database transaction and how long it took."""
|
|
|
|
def add_database_scheduled(self, sched_sec: float) -> None:
|
|
"""Record a use of the database pool (the time taken to get a connection)."""
|
|
|
|
def record_event_fetch(self, event_count: int) -> None:
|
|
"""Record a number of events being fetched from the db."""
|
|
|
|
def current_context() -> Optional[LoggingContext]:
|
|
"""Get the current logging context, or None for the sentinel.
|
|
|
|
This is not the Python-facing API.
|
|
`synapse.logging.context.current_context` wraps this and returns
|
|
`SENTINEL_CONTEXT` instead of `None`.
|
|
"""
|
|
|
|
def set_current_context(
|
|
context: Optional[LoggingContext],
|
|
) -> Optional[LoggingContext]:
|
|
"""Set the current logging context, returning the context that was
|
|
previously current. `None` means the sentinel, in both directions.
|
|
|
|
This is not the Python-facing API.
|
|
`synapse.logging.context.set_current_context` wraps this, converting between
|
|
`SENTINEL_CONTEXT` and `None`.
|
|
"""
|