The operator methods take `other: &ContextResourceUsage`, so passing
`&other` to `add_assign`/`sub_assign` (which already take a reference) is a
double-borrow that fails `cargo clippy -- -D warnings`. Drop the `&`.
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01JFbRtswu7rsHrttJFauUUb
Update `docs/log_contexts.md` for the logcontext port: the "current" logcontext
now lives in the Rust extension (resolved from the current tokio task, else the
current OS thread) rather than a Python thread-local, and add a "The Rust side"
section covering the one rule Rust code must follow — capture and scope the
caller's logcontext onto spawned tokio tasks (as `create_deferred` does) rather
than using a bare `tokio::spawn` — so logging is attributed correctly on worker
threads. The Python API (`current_context`/`set_current_context`) is unchanged.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011LnJSXQ86AAWNtihR4C5PH
Port `set_current_context` — the logcontext switch primitive, on the hottest
path in the logging system — from Python into Rust, and read the thread CPU
usage directly via `getrusage(RUSAGE_THREAD)` (libc) instead of through the
`resource` module. This removes the per-switch Python frame, the `stop`/`start`
method dispatch, and the `struct_rusage` object allocated on every switch;
`current.stop()`/`context.start()` for the common base-`LoggingContext` case
now run inline in Rust.
`usage_start` becomes a private native `(ru_utime, ru_stime)` snapshot rather
than a Python `struct_rusage` — nothing outside the module read it. The
`start`/`stop` methods keep their abuse-detection behaviour (thread affinity,
double-start, stop-without-start) via a shared native core (`start_inner`/
`stop_inner`) that both the pymethods and the switch fast path call, so those
checks still run on every switch. `_get_cputime` folds into a native
`cputime_delta` helper.
Subclasses (`BackgroundProcessLoggingContext`) still work unchanged: the switch
dispatches to them through Python (`obj.start(rusage)` / `obj.stop(rusage)`),
materialising the rusage as a plain `(utime, stime)` tuple only on that
off-hot-path branch, so their overrides run. `getrusage(RUSAGE_THREAD)` is
Linux-only; other platforms return `None` (no per-context CPU accounting), as
before.
Removes the now-dead Python rusage plumbing (`get_thread_resource_usage`, the
`RUSAGE_THREAD` support probe, `is_thread_resource_usage_supported`) — Rust owns
rusage now. The Phase 0 characterization test's rusage stand-in changes from an
opaque `object()` to a `(0.0, 0.0)` tuple to match the native representation;
it still pins the same observable abuse-detection behaviour.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011LnJSXQ86AAWNtihR4C5PH
Move `LoggingContext` from a pure-Python class to a native `#[pyclass]` in
`rust/src/logcontext.rs`, re-exported from `synapse.logging.context`. The
attribute surface, methods, error-message wording and abuse-detection
behaviour are all preserved, so callers — and the Python subclass
`BackgroundProcessLoggingContext` — are unaffected.
`set_current_context` stays in Python for now: it still calls `ctx.start`/
`ctx.stop` via normal attribute dispatch, so subclass overrides continue to
work. The native switch primitive (with in-Rust `getrusage`) is a later
increment.
Notes on the port:
- Construction is split between `__new__` (allocates a blank instance) and
`__init__` (does the real work), mirroring a pure-Python class. This is what
lets `BackgroundProcessLoggingContext`, which composes a name and then calls
`super().__init__(name=..., server_name=...)`, keep working unchanged.
- Methods that both mutate `self` and call back into Python (`start`, `stop`,
`__enter__`, `__exit__`) take an owned `Bound<Self>` and only hold a
`borrow_mut()` across the field write itself, never across a Python call, so
a re-entrant log record (which resolves the current context and reads this
object's getters) cannot hit an "already borrowed" error.
- `logcontext_error`, `set_current_context`, `logger` and
`logcontext_debug_logger` are re-resolved through the module on every call so
that test patches take effect.
- `__traverse__`/`__clear__` cover `previous_context`/`parent_context`/
`request`/`scope` for the cyclic GC (scope <-> context is a real cycle).
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011LnJSXQ86AAWNtihR4C5PH
Replace the Python `ContextResourceUsage` class with a native `#[pyclass]`
(exposed via `synapse.synapse_rust.logcontext`, re-exported under the same name
from `synapse.logging.context`). The public surface is preserved drop-in:
the six get/set attributes, `copy`/`reset`, `+`/`-`/`+=`/`-=`, the
`ContextResourceUsage(copy_from=...)` constructor and the exact `repr`.
This is the first step of moving the logcontext machinery to Rust: keeping the
usage accounting in a native struct lets the switch path (a later commit) do
its rusage bookkeeping without allocating a Python object per operation.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011LnJSXQ86AAWNtihR4C5PH
Move the "current logcontext" storage out of the Python `threading.local`
and into a Rust slot (`rust/src/logcontext.rs`, exposed as
`synapse.synapse_rust.logcontext`). `current_context()` now consults the
tokio task-local first, then the OS thread-local, then the sentinel.
This makes a single source of truth visible from both worlds:
- Log records emitted from Rust while a tokio task is being polled (e.g.
reqwest connecting, and any `log::` records from our async code or its
dependencies) resolve `current_context()` to the context that was current
when Python called into Rust, so `LoggingContextFilter` attributes them
correctly — no per-record stamping machinery, pyo3-log unchanged.
- `run_python_awaitable` now restores that captured context on the reactor
thread before driving the awaitable, so Python invoked from Rust (e.g.
`DatabasePool.runInteraction` from the native `/versions` handler) runs in
the right logcontext and its DB-transaction accounting lands on the right
request. Resolves the FIXME at deferred.rs:223.
`create_deferred` captures the caller's context at the FFI boundary and
scopes it onto the spawned task. Python keeps the accounting policy:
`set_current_context` still does the `getrusage` start/stop bookkeeping and
only delegates the raw slot write to `swap_current_context`. The sentinel is
pushed into Rust at import (`register_sentinel`) so `context is
SENTINEL_CONTEXT` identity and `bool(context)` semantics are preserved, and
Rust never imports `synapse.logging.context` (no circular import).
Tests: Rust unit tests for the slot/lookup precedence; a trial test that a
Rust-origin log record is attributed to the caller's logcontext; and a trial
test that the `/versions` per-user DB lookup is accounted against the caller's
logcontext (the resolved FIXME). Existing tests/util/test_logcontext.py and
tests/synapse_rust pass unmodified.
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011LnJSXQ86AAWNtihR4C5PH
Pin down behaviour that later refactors (notably porting the switch machinery
to Rust) must preserve but which the suite didn't yet cover:
- the exact `logcontext_error` message shapes and the conditions that trigger
them: wrong previous context on enter; lost/mismatched context on exit and
in PreserveLoggingContext; start/stop on the wrong thread; re-starting a
finished or already-active context; stop without a recorded start.
- LoggingContextFilter: fills record attributes from a real logcontext, and
under the sentinel only sets defaults for attributes not already present
(the `safe_set` no-clobber contract that 3rd-party log records rely on).
These strings are load-bearing for downstream log scraping, so we assert them
verbatim (reconstructing `%r` interpolations from the same live objects rather
than hard-coding addresses).
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011LnJSXQ86AAWNtihR4C5PH
Introduced in: #19473
Noticed in:
https://github.com/element-hq/synapse/pull/19556#discussion_r3505783541
I have not experienced the bug in the real world, it's just something I
noticed by reading.
--
Fix bug in `_prune_device_lists_changes_in_room` when transaction is
retried
The `nonlocal` variable is a footgun as it increments the counter even
though the transaction did not commit yet and may still be retried.
---------
Signed-off-by: Olivier 'reivilibre <oliverw@matrix.org>
If presence is disabled after having been enabled, the presence states
in the database (and hence on clients) are frozen at whatever they were
when presence was last enabled: nothing writes to the presence stream
any more and /sync omits the presence section entirely, so clients show
the old presence states forever.
Fix this in two parts:
1. At startup, if presence is disabled but the database still contains
non-offline presence states, the presence writer sends out one final
round of updates marking those users as offline.
2. /sync no longer unconditionally omits presence when presence is
disabled: incremental syncs whose since token is behind the presence
stream still get the straggling updates. As the stream doesn't advance
while presence is disabled, clients catch up once and the check then
short-circuits to a token comparison.
Remote servers already handle this themselves by timing out our users
([`FEDERATION_TIMEOUT`](https://github.com/element-hq/synapse/blob/4d8905a15a417ed0054ec2533d243932d890bbbd/synapse/handlers/presence.py#L194-L198)),
so no federation changes are needed.
Note that this only fixes the issue if presence is fully disabled. If
set to `untracked` we still have the same issue, however since modules
would still write to presence we can't just clobber everything like we
do in this patch.
This does two things, first it adds a config flag to ignore rooms for
the purposes of presence routing.
Secondly, it changes the caching behaviour to try and improve the cache
hit ratio. Previously, the size of the `do_users_share_a_room` cache
(which stores pairs of users) needs to `O(n²)` for the number of online
users, which is infeasible for large servers.
Instead, we call `get_users_in_room` for both the syncing and updated
users. This sounds more expensive, but a) we will already have cached
the syncing user's rooms, and b) we will only calculate the updated
user's rooms once (rather than once per syncing user).
---------
Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
- Impose limit of scheduled delayed events
- Update error codes to match latest draft of MSC4140
---------
Co-authored-by: Eric Eastwood <madlittlemods@gmail.com>
Sync workers proxied a full `ReplicationPresenceSetState` call to the
presence writer on every sync request with `affect_presence=True` (via
`user_syncing`), and a `ReplicationBumpPresenceActiveTime` call on every
user action, even though the writer's presence timers only need feeding
every `SYNC_ONLINE_TIMEOUT` / `LAST_ACTIVE_GRANULARITY`. On busy clients
this amounts to tens of no-op replication calls per user per minute, and
the resulting per-update work is the dominant CPU cost on saturated
presence writers.
Track the last relayed `(state, timestamp)` per `(user, device)` on the
worker and suppress unchanged sync-driven repeats within a 25s relay
interval - deliberately below `SYNC_ONLINE_TIMEOUT` (30s) so the
writer's device `last_sync_ts`/`last_active_ts` timers stay fed and
users neither flap offline nor bounce `currently_active`. Genuine state
changes are relayed immediately, explicit (non-sync) set_state calls
always go through and reset the throttle, bumps that might un-idle a
device bypass it, and entries are evicted when a `USER_SYNC` stop is
sent so reconnecting devices are relayed afresh.
This gives the writer-CPU benefit that deployments currently obtain by
tightening `rc_presence` to ~1/29s, without dropping real presence
transitions.
---------
Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
Co-authored-by: Quentin Gliech <quenting@element.io>
A handful of places in the storage layer bound a value whose Python type
didn't match the declared column type — an `int` into a `TEXT` column,
or a `str` into a `BIGINT` column — and relied on psycopg2's loose
coercion to paper over the mismatch. These are latent correctness bugs:
they only work because the driver silently converts, and a stricter
driver that binds typed parameters rejects them outright.
Found during a Rust port of the database pool where the driver does not
coerce automatically.
Each fix binds the value with the type the column actually declares,
rather than depending on driver-specific coercion. All changes are
behaviour-preserving on psycopg2 and sqlite.
There is also a fix to the multi-writer id-gen tests where we forgot to
commit. This is tangential, but was found during the same effort.
### Changes
- **`device_lists_remote_extremeties.stream_id (TEXT)`** —
`_update_remote_device_list_cache_txn` (typed `stream_id: int`) bound an
int; store it as a string, matching the column and the sibling
`_update_remote_device_list_cache_entry_txn` (typed `stream_id: str`).
The old mismatch, when rejected, was swallowed inside the device-list
resync and hung `query_devices`.
- **`user_filters.filter_id (BIGINT)`** — `get_user_filter` bound the
raw `int | str` (a string, from sync requests). It already validates via
`int(filter_id)`; bind that int so it matches the column.
- **`rejections.last_check (TEXT)`** — both writers stored
`clock.time_msec()` (an int); store the timestamp as a string.
- **user-directory temp position** — the `populate_user_directory`
background update's staging column
`_temp_populate_user_directory_position.position` was `TEXT` but held an
int (read back into a `BIGINT` column). Declare it `BIGINT`. The temp
table is created and dropped within the background update, so there's no
migration.
- **`test_batched_state_group_storing`** — selected from
`state_group_edges` with a stringified `state_group`; bind the int
directly (the column is an integer).
- **Multi-writer id-generator tests** — constructing a
`MultiWriterIdGenerator` prunes stale `stream_positions` rows, but the
harness never committed, so the cleanup only survived because adbapi
keeps one connection per thread with its transaction open. Commit after
construction so it persists regardless of pool semantics (the delete is
legitimate work that should be committed anyway).
This speeds up the cascading delete from
`sliding_sync_connection_positions`, which without an index on
`connection_position` requires a sequential scan of the whole table for
each deleted position.
Co-authored-by: Claude Opus 4.8 <noreply@anthropic.com>
Adds `last_active_granularity`, `sync_online_timeout` and `idle_timeout`
options to the `presence` config section, controlling the previously
hard-coded `LAST_ACTIVE_GRANULARITY`, `SYNC_ONLINE_TIMEOUT` and
`IDLE_TIMER` constants (which remain as the defaults).
This is mainly useful on deployments that ratelimit how often syncs can
affect presence (`rc_presence`): the sync timeout must exceed the
ratelimit interval or users flap offline between syncs, so tuning down
presence traffic currently requires squeezing under the fixed 30s limit.
---------
Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
Fix https://github.com/element-hq/synapse/issues/19907
The flake manifested as a failure pointing at
`TestMessagesOverFederation/Backfill_from_nearby_backward_extremities_past_token`
but was actually caused by some cross-test pollution from an earlier
test (`TestOIDCProviderUnavailable`) causing some workers to be
temporarily unavailable.
As explained in
https://github.com/element-hq/synapse/issues/19907#issuecomment-4917362461,
> ### Cross-test pollution
>
> When I point an LLM at the logs, it points to
`TestOIDCProviderUnavailable` being the culprit because of the server
restarts polluting this test. When this flake happens, we can indeed see
that `TestOIDCProviderUnavailable` runs before
`TestMessagesOverFederation`.
>
> ```
> PASS TestEventBetweenMakeJoinAndSendJoinIsNotLost 15.08s
> PASS TestFederation/parallel/HS2_->_HS1 1.5s
> PASS TestFederation/parallel/HS1_->_HS2 1.51s
> PASS TestFederation/parallel 0s
> PASS TestFederation 15.12s
> PASS TestOIDCProviderUnavailable//login/sso/redirect_shows_HTML_error
0.02s
> PASS TestOIDCProviderUnavailable 8.62s
> FAIL
TestMessagesOverFederation/Backfill_from_nearby_backward_extremities_past_token
0.89s
> FAIL TestMessagesOverFederation 1.1s
> PASS TestSynapseVersion/Synapse_version_matches_current_git_checkout
0.97s
> PASS TestSynapseVersion 0.97s
> ```
>
> The pollution happens because we enable
[`COMPLEMENT_ENABLE_DIRTY_RUNS`](https://github.com/element-hq/synapse/blob/c63d77a79d7157f26f849684520ba9e99f4d07c0/scripts-dev/complement.sh#L309-L311)
([docs](https://github.com/matrix-org/complement/blob/0e6f8552ff0c99fddb97222399efed3e1f0cb91a/ENVIRONMENT.md#complement_enable_dirty_runs))
which means Complement will reuse deployments (shares homeservers
between tests).
>
> During the `TestOIDCProviderUnavailable` test, there are some stray
federation requests that hit the homeserver while it's still booting
which marks the nginx upstream as unavailable for 10 seconds. nginx has
a default of
[`max_fails=1`](https://nginx.org/en/docs/http/ngx_http_upstream_module.html#max_fails)
and
[`fail_timeout=10s`](https://nginx.org/en/docs/http/ngx_http_upstream_module.html#fail_timeout).
Then when `TestMessagesOverFederation` starts, we're still in the 10
second unavailable window and nginx doesn't even try to connect at all.
>
> <details>
> <summary>LLM summary of the logs and how this happens in
practice</summary>
>
> 1. **19:52:10–11** — the previous federation test finishes:
`user-3:hs2` does a faster-join (`send_join?omit_members=true`) to
`!YnyCRpCLIpimppIreR:hs1`, so `hs2` kicks off a
`sync_partial_state_room` background resync that is still running when
the test ends.
> 2. **19:52:11.6** — `TestOIDCProviderUnavailable` starts and calls
`deployment.StopServer(t, "hs1")` / `StartServer`
(`complement/tests/oidc_test.go:78-80`) to apply an OIDC config
fragment. `hs1` gets `SIGTERM`; new supervisord at 19:52:13.3. `hs2` is
not restarted and keeps retrying its unfinished work.
> 3. **19:52:14** — `hs1`'s nginx is up, but the Synapse workers aren't:
`federation_inbound` only listens on `18015` at 19:52:18.7,
`federation_reader` on `18016` at 19:52:19.0.
> 4. **19:52:15–16** — `hs2`'s retries arrive in that gap: `PUT
/_matrix/federation/v1/send/…` → `18015` refused; `GET
/state_ids/!YnyCRpCLIpimppIreR:hs1` → `18016` refused. With nginx
defaults (`max_fails=1`, `fail_timeout=10s`) and only one server per
upstream block, both upstreams are now marked down until ~19:52:25/26.
(Side casualty: `hs2`'s partial-state resync gives up — "We can't get
valid state history" — and puts `hs1` on a 10-minute federation
backoff.)
> 5. **19:52:21.5** — the failing test's `make_join` for
`@user-5-bob:hs2` reaches `hs1`'s nginx → `no live upstreams` → `502` →
the join fails, even though the worker has been listening for 2.5
seconds by then.
> 6. **19:52:22** — `TestSynapseVersion`'s `GET
/_matrix/federation/v1/version` hits the same dead upstream → `502` → it
fails too.
>
> So it's a flake caused by a race between the OIDC test's container
restart, hs2's background federation retries, and nginx's passive
health-check — not anything wrong with the backfill logic under test.
>
> </details>
>
>
> We can indeed confirm this suspicion with these logs
>
> ❌https://github.com/element-hq/synapse/actions/runs/28888070856/job/85701936736
(archive:
[85701936736.log](https://github.com/user-attachments/files/29809986/85701936736.log)):
> ```
> Error: 2026/07/07 19:52:20 [error] 34#34: *1 no live upstreams while
connecting to upstream, client: 172.18.0.3, server: localhost, request:
"PUT /_matrix/federation/v1/send/1783453927718 HTTP/1.1", upstream:
"http://federation_inbound/_matrix/federation/v1/send/1783453927718",
host: "hs1"
> ...
>
> Error: 2026/07/07 19:52:21 [error] 33#33: *4 no live upstreams while
connecting to upstream, client: 172.18.0.3, server: localhost, request:
"GET
/_matrix/federation/v1/make_join/%21scAbyTQDdaauGYicpU%3Ahs1/%40user-5-bob%3Ahs2?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=7&ver=8&ver=9&ver=10&ver=11&ver=12&ver=org.matrix.msc3757.10&ver=org.matrix.msc3757.11&ver=org.matrix.hydra.11
HTTP/1.1", upstream:
"http://federation_reader/_matrix/federation/v1/make_join/%21scAbyTQDdaauGYicpU%3Ahs1/%40user-5-bob%3Ahs2?ver=1&ver=2&ver=3&ver=4&ver=5&ver=6&ver=7&ver=8&ver=9&ver=10&ver=11&ver=12&ver=org.matrix.msc3757.10&ver=org.matrix.msc3757.11&ver=org.matrix.hydra.11",
host: "hs1"
> ```
>
> The fix here would be to disable nginx's unavailable upstream behavior
by configuring `max_fails=0` in the upstream block:
https://github.com/element-hq/synapse/blob/c63d77a79d7157f26f849684520ba9e99f4d07c0/docker/configure_workers_and_start.py#L374-L378
`test_lock_contention` is a performance-regression canary (#16840): the
pathological behaviour it guards against spent ~30s spinning the CPU, vs
~0.5s when healthy. The 5s wall-clock alarm it used was calibrated on
SQLite, but against PostgreSQL a healthy run already takes 3-4s of
wall-clock time (500 sequential acquire/release cycles, each a real
database round-trip), so any CI load pushed it over the limit.
Add a `cpu_time` mode to `tests/utils.py`'s test_timeout, implemented
with
[`setitimer(ITIMER_PROF)`](https://docs.python.org/3/library/signal.html#signal.setitimer),
which budgets process CPU time instead of wall-clock time. Time spent
blocked on the database or lost to a loaded CI runner no longer counts,
while a regression to CPU-spinning still trips the alarm mid-spin. A
healthy run costs <1s of CPU on either database engine; the budget is
10s.
This also subsumes the RISC-V wall-clock carve-out from #18430, which is
removed.
---------
Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
This is a stepping stone before we can go full Rust everywhere. We're
providing a generic interface as we want database access to work in
Synapse and `synapse-rust-apps`. In `synapse-rust-apps`, we will use a
`tokio-postgres` based database connection pool so it's full Rust.
We want to avoid the situation where we have two database connection
pools (one for Python, one for Rust) as we've run into connection
exhaustion problems on Matrix.org before.
As an example of using it and sanity check for all this work (including
tests), I've also ported over the `/versions` handler to the Rust side
with database access. The `/versions` endpoint is the simplest endpoint
I could find that still had some database access. Hopefully the refactor
on `/versions` isn't that controversial as it's not really the point of
this PR. We can always remove it from this PR but it's just here as a
sanity check that all of this works.
### Why `runInteraction(...)`?
Using the same `runInteraction` pattern that we already have in Synapse
means we can port over existing Synapse code/endpoints without much
thought. But this pattern also makes sense because we want[^1]
transactions to have repeatable-read isolation (easy to think about,
less foot-guns). Having everything thappen in a function callback means
we can do retries for serialization/deadlock errors.
[^1]: To note: Ideally, we'd want the least isolation possible but the
problem is that there is no tooling to yell at you when your
queries/logic is wrong so repeatable-read isolation is a great balance.
> When an application receives this error message, it should abort the
current transaction and retry the whole transaction from the beginning.
The second time through, the transaction will see the
previously-committed change as part of its initial view of the database,
so there is no logical conflict in using the new version of the row as
the starting point for the new transaction's update.
>
> Note that only updating transactions might need to be retried;
read-only transactions will never have serialization conflicts.
>
> *--
https://www.postgresql.org/docs/current/transaction-iso.html#XACT-REPEATABLE-READ*
As a note, this strategy is less of an impedance mismatch (aligns more
closely) with Synapse so the glue code for the `python_db_pool` should
also be simpler.
### How does this interact with logcontext (`LoggingContext`)?
See [docs on log
contexts](https://github.com/element-hq/synapse/blob/4e9f7757f17ba81b8747b7f8f9646d17df145aa3/docs/log_contexts.md)
for more background.
We already support normal logging from Rust -> Python with `pyo3-log`
and `log` but as soon as we pass a thread boundary, everything is logged
against the `sentinel` log context. Normally, we want logs and CPU/DB
usage correlated with the request that spawned the work.
You can see how I took a stab at fixing this in
https://github.com/element-hq/synapse/pull/19846 by capturing the
logcontext in a Tokio task local and re-activating as necessary. For
example, in that PR, I reactivated the logcontext in
`run_python_awaitable(...)` which we use to call `runInteraction(...)`
from the Rust side which means all of the database usage is correlated
with the request as expected. It also means any `log:info!(...)` done in
`run_interaction(...)` is correlated correctly. But there needs to be a
better story for when you want to log everywhere else.
I haven't explored tracking CPU usage on the Rust side.
I've left all of this out of this PR as I think it will be better to
tackle this as a dedicated follow-up. For example, I'm thinking about
instead creating a new `LoggingContext` with the `parent_context` set to
the calling context and try to avoid needing to call
`set_current_context(...)` on the Python side where possible (like
tracking CPU).
### Testing strategy
Added some tests that exercise some `async` Rust handlers for the
`/versions` endpoint:
```
SYNAPSE_TEST_LOG_LEVEL=INFO poetry run trial tests.rest.client.test_versions.VersionsTestCase
```
Real-world:
1. `poetry run synapse_homeserver --config-path homeserver.yaml`
1. `GET http://localhost:8008/_matrix/client/versions`
The port of event serialization to Rust (#19837) removed
`format_event_raw`, `format_event_for_client_v1`,
`format_event_for_client_v2` and
`format_event_for_client_v2_without_room_id` from
`synapse.events.utils`, but there are modules in the wild that import
them from there.
Reimplement them as standalone pyfunctions in Rust, operating directly
on the Python dict so the original semantics are preserved exactly
(in-place mutation, returning the same dict, arbitrary non-JSON values
passing through, KeyError on a missing `unsigned` in the v1 format), and
re-export them from `synapse.events.utils`.
---------
Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
### Summary
This moves the synchronous core of client event serialization out of
`synapse/events/utils.py` and into Rust
(`rust/src/events/serialize.rs`).
Event serialization is on the hot path for `/sync`, `/messages`, and
most client-facing endpoints. Previously it was a recursive pure-Python
routine (`_serialize_event` / `_inject_bundled_aggregations` /
`only_fields`) that interleaved
CPU-bound formatting with `async` DB/IO. This PR separates those two
concerns and moves the CPU-bound half to Rust:
- **Async prep stays in Python.**
`EventClientSerializer._prepare_serialization` does all DB/IO up front:
batch-fetching redaction events and running the registered module
`unsigned`-callback hooks, for the top-level events *and* every bundled
sub-event (edits and thread latest events, which are themselves
serialized). The admin/MSC4354 config is resolved once via
`_update_config`, rather than re-checked on every recursive call as the
old code did.
- **The synchronous core moves to Rust.** Given an event plus the
pre-fetched `redaction_map`, `unsigned_additions`, and
`bundle_aggregations`, the Rust code produces the client JSON entirely
in Rust — including the v1/v2 format transforms, `only_event_fields`
filtering, redaction handling, and recursive bundled aggregations.
### Details
- The Rust entry point is a single batch function, `serialize_events`,
taking a list of `(event, membership)` pairs. The three lookup maps are
shared across the whole batch, so they're read out of Python and
converted to Rust
structures **once** per batch rather than once per event.
`EventClientSerializer.serialize_event` (singular) is a thin wrapper
that calls it with a one-element list.
- `SerializeEventConfig` is now a Rust `pyclass`, and the old
`event_format` callable is replaced by the `EventFormat` enum (`Raw` /
`ClientV1` / `ClientV2` / `ClientV2WithoutRoomId`). Call sites in
`rest/admin/events.py` and
`rest/client/{notifications,room,sync}.py` are updated to pass the enum.
`make_config_for_admin` and MSC4354 enablement now go through
`SerializeEventConfig.for_admin()` / `with_msc4354()`.
- New accessors on `EventInternalMetadata` (`redacted_by`, `txn_id`,
`device_id`, `token_id`, `delay_id`, `soft_failed`,
`policy_server_spammy`) expose to Rust the fields the serializer reads.
- The `_split_field` unit tests move from `tests/events/test_utils.py`
to a Rust test in `serialize.rs`, since the implementation moved.
### Behaviour
This is intended to be a behaviour-preserving refactor — the Rust core
mirrors the previous Python output (field ordering, v1 key promotion,
redaction placement per room version, null-`redacts` handling,
transaction-ID gating).
Existing serialization, relations, and sync tests pass unchanged.
---------
Co-authored-by: Claude Opus 4.8 <noreply@anthropic.com>
Co-authored-by: Eric Eastwood <madlittlemods@gmail.com>
Co-authored-by: Eric Eastwood <erice@element.io>
Speeds up finding and deleting expired sliding sync connections in
`delete_old_sliding_sync_connections`, which previously required a
sequential scan.
On matrix.org I have a suspicion that this might end up blocking some
SSS connections during the delete, which can take minutes. Specifically,
I think the deletion blocks this delete:
https://github.com/element-hq/synapse/blob/ff19c034d300869e64878a15aed9a97f1cec59e4/synapse/storage/databases/main/sliding_sync.py#L233-L241
We didn't previously have an index because we wanted the postgres HOT
updates, however we also limit the update frequency to once every 5
minutes, so hopefully this is fine.
---------
Co-authored-by: Claude Opus 4.8 <noreply@anthropic.com>
This means you can use `get_success(...)` anywhere regardless
of what kind of work needs to be done.
Spawning from adding some more async Rust things in
https://github.com/element-hq/synapse/pull/19846 and wanting something
more standard instead of the custom `till_deferred_has_result(...)` that
has crept in to a few files.
Alternative to https://github.com/element-hq/synapse/pull/19867 spurred
on by [this
comment](https://github.com/element-hq/synapse/pull/19867#discussion_r3441774685)
from @erikjohnston
### How does this work?
Previously, `get_success(...)` just ran in a hot-loop advancing the
Twisted reactor clock which didn't give any time for other threads to do
some work or acquire the GIL if necessary (whenever there is a hand-off
from Rust to Python, we need the GIL).
Now, `get_success(...)` loops until we see a result (until we hit the
~0.1s real-time timeout). In the loop, we call
[`time.sleep(0)`](https://docs.python.org/3/library/time.html#time.sleep)
which will "Suspend execution of the calling thread [...]" (CPU and GIL)
to allow other threads to do some work. Then like before, we advance the
Twisted reactor clock to run any scheduled callbacks which includes
anything the other threads may have scheduled.
### Does this slow down the entire test suite?
Seems just as fast as before. There is minutes variance in what we had
before and after but both are within the same range of each other.
(see PR for actual before/after timings)
The `flag_existing_quarantined_media` background update (added in
#19558, shipped in v1.152.0) back-populates the
`quarantined_media_changes` table with media that was already
quarantined. It has two bugs.
### 1. Some quarantined remote media is silently skipped
The remote-media query paged through `remote_media_cache` with:
```sql
WHERE quarantined_by IS NOT NULL
AND media_origin >= ? AND media_id > ?
```
This ANDs the two key columns independently rather than comparing them
as a tuple. Once an origin has been fully processed (e.g. `media_id`
reaches `zzz` for origin `a.example`), rows in a *later* origin whose
`media_id` is `<=` the last processed `media_id` (e.g. `b.example` /
`aaa`) fail the `media_id > ?` test and are never flagged.
Fixed by using a proper row-value tuple comparison:
```sql
WHERE quarantined_by IS NOT NULL
AND (media_origin, media_id) > (?, ?)
```
Both the minimum supported SQLite (3.37.2) and PostgreSQL support
row-value comparisons.
### 2. Exhausted queries keep re-running every iteration
`flag_quarantined` ran *both* the local and remote queries on every
iteration. When one table was exhausted but the other still had rows,
the update kept returning a positive count, so the finished table's (now
empty) query needlessly re-ran on every subsequent iteration until the
whole update completed.
This could add significant time to the transaction, as since the rows
were deleted it could scan a significant portion of the table each time.
Fixed by tracking per-table completion (`local_done` / `remote_done`) in
the background-update progress and skipping a table's query once it has
returned an empty batch. The progress dict was also restructured into an
incremental build for readability.
Introduced in: #17847
This 10-second wall-clock timeout was troublesome as it fails flakily on
slow/struggling CI runners, like the
default ones for private GitHub repositories.
The loop also silently relied on the reactor advance in `make_request`,
whereas we could just deterministically advance the reactor the known
amount of times
instead.
---------
Signed-off-by: Olivier 'reivilibre <oliverw@matrix.org>
Got paged today for this. The sliding sync worker in question had loads
of deadlocks in the logs.
I restarted it and it got unwedged, but we should have a more robust
defence, which this PR proposes.
```
psycopg2.errors.DeadlockDetected: deadlock detected
DETAIL: Process 257324 waits for ShareLock on transaction 688227036; blocked by process 254908.
Process 254908 waits for ShareLock on transaction 688222971; blocked by process 256179.
Process 256179 waits for ExclusiveLock on tuple (302352,92) of relation 2962200779 of database 16403; blocked by process 257213.
Process 257213 waits for ShareLock on transaction 688225005; blocked by process 254905.
Process 254905 waits for ShareLock on transaction 688228814; blocked by process 257324.
HINT: See server log for query details.
CONTEXT: while inserting index tuple (183070,103) in relation "sliding_sync_connection_lazy_members"
```
I wonder if an unfortunate side effect is that these repeated attempts
leave a lot of dead tuples on the table,
which would then harm the performance of the next attempt to insert the
tuples,
I suspect making it more likely that they will deadlock again (?).
---
By acquring a `FOR NO KEY UPDATE` lock upfront before beginning work, we
can ensure that one
of the transactions gets queued behind the other one, meaning the first
one can succeed unimpeded.
`FOR NO KEY UPDATE` blocks other `FOR NO KEY UPDATE` locks and is the
weakest lock level that blocks itself.
---------
Signed-off-by: Olivier 'reivilibre <oliverw@matrix.org>
