From 429baac202c8ffbde79d0779982336f1916ddbff Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 16 Jul 2026 15:54:48 +0000 Subject: [PATCH] Fix up comments and docstrings from review - get_thread_id/main_thread claimed to return an 'OS thread id'; restore the historical caveat that threading.get_ident is not an OS tid and is stable across Synapse's single fork() (which is also why the new per-thread cache stays correct across it). - Explain skip_from_py_object on ContextResourceUsage (pyo3 0.28 makes the Clone-pyclass FromPyObject opt-in/out explicit; we build -D warnings). - Note that __repr__ diverges from the historical Python repr for exponent-form floats, and that main_thread is settable only for tests. - Promote create_deferred's cancellation limitation to a TODO and cross-reference run_python_awaitable's finished-context defence. - Carry the dropped Python docstrings into the .pyi stub (start/stop 'do not call directly', get_resource_usage returns a *copy*, __init__ args, the sentinel usage guidance), and note that tag is typed str while the runtime deliberately also accepts None. - tests: fix the stale rust/src/logcontext.rs path, explain why 'synapse' is in _RUST_LOGGER_ROOTS (the crate is named synapse) and the Python- namespace collision hazard, drop a stale deferred.rs:223 FIXME reference, explain the 50000-iteration pump bound, and rename prepare's parameter to match the base class (pyright). - docs: name the helper (LogContext::capture/scope) instead of 'the provided helper'. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01JFbRtswu7rsHrttJFauUUb --- docs/log_contexts.md | 7 +-- rust/src/deferred.rs | 8 +++- rust/src/logging/context.rs | 24 ++++++++-- synapse/synapse_rust/logcontext.pyi | 69 +++++++++++++++++++++++---- tests/synapse_rust/test_logcontext.py | 32 +++++++++---- 5 files changed, 114 insertions(+), 26 deletions(-) diff --git a/docs/log_contexts.md b/docs/log_contexts.md index c5258c29ef..2904fc8517 100644 --- a/docs/log_contexts.md +++ b/docs/log_contexts.md @@ -572,9 +572,10 @@ What Rust code *does* need to be aware of: when you spawn a future onto the toki runtime, the current logcontext must be captured and carried along so that log records emitted while the future is polled (including any `log::` records from dependencies, and any Python invoked back from Rust) are attributed correctly. -Use the provided helper that captures the caller's logcontext at the FFI boundary -and scopes it onto the spawned task (this is what `create_deferred` does) rather -than a bare `tokio::spawn`. `current_context()` resolves the task's captured +Use the provided helper — `LogContext::capture(py)` plus `LogContext::scope` in +`rust/src/logging/context.rs` — which captures the caller's logcontext at the FFI +boundary and scopes it onto the spawned task (this is what `create_deferred` +does), rather than a bare `tokio::spawn`. `current_context()` resolves the task's captured context first, so `LoggingContextFilter` — and therefore `pyo3-log` — just works on worker threads, with no per-log-record stamping. diff --git a/rust/src/deferred.rs b/rust/src/deferred.rs index e0fb4caa92..d621d54370 100644 --- a/rust/src/deferred.rs +++ b/rust/src/deferred.rs @@ -73,7 +73,13 @@ fn logging_context_module(py: Python<'_>) -> PyResult<&Bound<'_, PyAny>> { /// Creates a twisted deferred from the given future, spawning the task on the /// tokio runtime. /// -/// Does not handle deferred cancellation or contextvars. +/// Does not handle contextvars. +/// +/// TODO: propagate deferred cancellation to the tokio task (via +/// `JoinHandle::abort`). Until then a cancelled request leaves its task +/// running, so the task can outlive the request's logcontext — +/// `run_python_awaitable` defends against the resulting finished-context case, +/// but the work itself is wasted. pub fn create_deferred<'py, F, O>( py: Python<'py>, reactor: &Bound<'py, PyAny>, diff --git a/rust/src/logging/context.rs b/rust/src/logging/context.rs index e3e58c6f87..b431705bf2 100644 --- a/rust/src/logging/context.rs +++ b/rust/src/logging/context.rs @@ -213,6 +213,10 @@ impl LogContext { /// (Measure, request/background-process metrics, task scheduler, ...) are /// unaffected. Keeping this native lets the switch machinery do its rusage /// accounting without allocating a Python object per operation. +// `skip_from_py_object`: pyo3 0.28 requires `Clone` pyclasses to explicitly +// opt in or out of a generated extract-by-clone `FromPyObject` (a bare +// `#[pyclass]` is a deprecation warning, and we build with `-D warnings`). +// Nothing extracts this type by value, so opt out. #[pyclass(skip_from_py_object, get_all, set_all)] #[derive(Clone, Default)] pub struct ContextResourceUsage { @@ -272,7 +276,10 @@ impl ContextResourceUsage { fn __repr__(&self) -> String { // Matches the historical Python `__repr__` (values were interpolated with - // `%r`, i.e. `repr()`, inside single quotes). + // `%r`, i.e. `repr()`, inside single quotes) — except Rust's float + // formatting for exponent-form values (`1e-7` where Python writes + // `1e-07`). The only consumer of the string form is Measure's "Failed to + // save metrics!" warning, so we don't chase exact parity there. format!( "> = const { Cell::new(None) }; } -/// The current OS thread id, matching Python's `threading.get_ident()`. +/// This thread's `threading.get_ident()` value. +/// +/// Note that (as the historical Python comment warned) `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` affinity check after it — and for the same +/// reason the per-thread cache below stays correct across that fork. Getting a +/// real tid isn't worth the hoop-jumping. fn get_thread_id(py: Python<'_>) -> PyResult { CACHED_THREAD_ID.with(|cell| { if let Some(id) = cell.get() { @@ -459,8 +473,10 @@ pub struct LoggingContext { /// string for the same reason as `name` (read per log record). #[pyo3(get, set)] server_name: Py, - /// The OS thread id (`threading.get_ident()`) this context was created on; - /// activity on any other thread is an error. + /// 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, /// Whether `__exit__` has run. Re-activating a finished context is an error. diff --git a/synapse/synapse_rust/logcontext.pyi b/synapse/synapse_rust/logcontext.pyi index 75b0f8c4f1..c6be259dc3 100644 --- a/synapse/synapse_rust/logcontext.pyi +++ b/synapse/synapse_rust/logcontext.pyi @@ -58,6 +58,8 @@ class LoggingContext: main_thread: int finished: bool request: Optional[ContextRequest] + # Deliberately 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]" _resource_usage: ContextResourceUsage @@ -69,7 +71,17 @@ class LoggingContext: server_name: str, parent_context: "Optional[LoggingContext]" = None, request: Optional[ContextRequest] = None, - ) -> 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__( @@ -78,17 +90,56 @@ class LoggingContext: value: Optional[BaseException], traceback: Optional[TracebackType], ) -> None: ... - def start(self, rusage: "Optional[tuple[float, float]]") -> None: ... - def stop(self, rusage: "Optional[tuple[float, float]]") -> None: ... - def get_resource_usage(self) -> ContextResourceUsage: ... - def add_cputime(self, utime_delta: float, stime_delta: float) -> None: ... - def add_database_transaction(self, duration_sec: float) -> None: ... - def add_database_scheduled(self, sched_sec: float) -> None: ... - def record_event_fetch(self, event_count: int) -> 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.""" class _Sentinel: """The root "no logcontext" marker. A falsy singleton (see `SENTINEL_CONTEXT`) - whose fields are inert defaults and whose methods are no-ops.""" + whose fields are inert defaults and whose methods are no-ops. + + This should only be used for tasks outside of Synapse, like when we yield + control back to the Twisted reactor (event loop), so we don't leak the + current logging context to other tasks that are scheduled next. Nothing from + the Synapse homeserver should be logged with the sentinel context — we + should always know which server the logs are coming from.""" previous_context: None finished: bool diff --git a/tests/synapse_rust/test_logcontext.py b/tests/synapse_rust/test_logcontext.py index 0f8334209d..bb740c3796 100644 --- a/tests/synapse_rust/test_logcontext.py +++ b/tests/synapse_rust/test_logcontext.py @@ -13,9 +13,9 @@ """Cross-language logcontext attribution for Rust. The current logcontext lives in the Rust slot (`synapse.synapse_rust.logcontext` -/ `rust/src/logcontext.rs`), visible from both Python (reactor/threadpool threads) -and Rust (tokio tasks). These tests exercise the two guarantees that gives us, -through real production code paths: +/ `rust/src/logging/context.rs`), visible from both Python (reactor/threadpool +threads) and Rust (tokio tasks). These tests exercise the two guarantees that +gives us, through real production code paths: 1. Log records emitted from Rust while a task is being polled (e.g. reqwest connecting) are attributed to the logcontext that was current when Python @@ -51,9 +51,17 @@ from tests.unittest import HomeserverTestCase logger = logging.getLogger(__name__) -# Loggers whose records originate on tokio worker threads inside Rust. Anything -# emitted here while a task is being polled should be attributed to the caller's -# logcontext, never the sentinel. +# Log-target roots that Rust code emits under while running on tokio worker +# threads: the reqwest dependency stack, plus "synapse"/"synapse_rust" because +# the Rust crate is itself named `synapse` (see rust/Cargo.toml). Anything +# emitted under these while a task is being polled should be attributed to the +# caller's logcontext, never the sentinel. +# +# NB: bare "synapse" also matches every *Python* `synapse.*` record, so the +# attribution assertion below implicitly relies on nothing else logging during +# the pump (MemoryReactor with `advance(0)`, so no timed background work fires). +# If this test starts flaking on unrelated records, tighten this filter rather +# than weakening the assertion. _RUST_LOGGER_ROOTS = frozenset( {"reqwest", "hyper", "hyper_util", "h2", "rustls", "synapse_rust", "synapse"} ) @@ -92,7 +100,9 @@ class RustLogContextTestCase(HomeserverTestCase): for callbable, args, kwargs in triggers: callbable(*args, **kwargs) - def prepare(self, reactor: MemoryReactor, clock: Clock, hs: HomeServer) -> None: + def prepare( + self, reactor: MemoryReactor, clock: Clock, homeserver: HomeServer + ) -> None: self.user_id = self.register_user("user1", "pass") def _check_current_logcontext(self, expected: str) -> None: @@ -116,6 +126,9 @@ class RustLogContextTestCase(HomeserverTestCase): body(result) with PreserveLoggingContext(): + # Generous upper bound (the work is a real HTTP round-trip or DB + # hop on a possibly-loaded CI box); the loop exits early via + # `result["done"]`, and we fail below if it never gets set. for _ in range(50000): if result.get("done"): break @@ -207,8 +220,9 @@ class RustLogContextTestCase(HomeserverTestCase): def test_db_callback_runs_in_caller_logcontext(self) -> None: """The Rust `/versions` handler's per-user feature lookup calls back into Python via `run_python_awaitable`; the DB transaction it runs must be - accounted against the caller's logcontext (the resolved - `deferred.rs:223` FIXME).""" + accounted against the caller's logcontext. (Before the Rust storage + port, a FIXME in `run_python_awaitable` meant this ran in the + sentinel and the accounting was lost.)""" versions_handler = self.hs.get_rust_handlers().versions def body(result: dict[str, object]) -> None: