One emitter now sends both Python's and Rust's spans to the Jaeger
agent. `init_tracer` sets the tracer up as before, with
`initialize_tracer` (its sampler, remote or not, its throttler, its
logging reporter, and the first-homeserver-wins guard), then swaps
jaeger-client's reporter for one whose `report_span` converts the
finished span into the Rust reporter's form, with the GIL held (a few
attribute reads), and queues it. The encoding and the UDP send happen
on the reporter thread, as for Rust's spans. Support for the external
`rust_python_jaeger_reporter` package is removed. If tracing in Rust
cannot start, jaeger-client's reporter stays.
The conversion follows jaeger-client's `make_jaeger_batch`, so the
datagrams are what jaeger-client sent, trace IDs from a remote context
wider than 128 bits included: a test encodes spans of every shape (all
tag types, logs, follows-from references, IDs at or above 2^63) both
ways and compares the bytes. A failure to convert is logged with its
traceback once, then at debug level.
One jaeger `PrometheusMetricsFactory` serves the process, as each
registers its metrics globally. jaeger-client's `reporter_*` options
and metrics no longer apply: the docs say what the Rust reporter does
instead. Tests run `init_tracer` and check that a Python span and a
Rust span under it arrive in one datagram, and that `logging: true`
keeps jaeger-client's logging reporter.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01W4zxygfJC93SsugxskhoJG
Sliding sync requests computed in Rust now report spans under the
request's Python span, one per step the handler calls:
`sliding_sync.load_connection_state`, `sliding_sync.interested_rooms`,
`sliding_sync.room_entries` (with the room count), and
`sliding_sync.finish_request`. Inside the room entries, a
`sliding_sync.room` per room is tagged `room_id` and its `outcome`
(`entry`, `fallback` or `error`, marked with the `error` tag), with
that room's reads under it. `sliding_sync.encode` covers encoding the
rooms, which runs on a threadpool thread whose logcontext carries the
request's Python span (`encode_json_response`).
A trial test makes a sliding sync request over two rooms with tracing
on and checks that each step is under the servlet's Python span, that
each room is under `sliding_sync.room_entries`, and that the rooms'
reads are under them.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01W4zxygfJC93SsugxskhoJG
- `state.resolve` around a state resolution on the database, tagged
`room_id`, `state_sets` and, once done, the resolution's database and
auth chain time. It covers the handler's resolutions and the
persister's, under `persist.state_res`. A room without a chain cover
index is tagged `fallback`, not an error: the caller resolves its
state in Python.
- `events.load` around an event load, tagged with the number of events
asked for, `reload`, and on success how many this load read from the
database (`fetched`) and how many it did not (`cached`, which counts
events another load was already reading). Its `db.*` spans nest
under it.
- `outgoing-client-request` around a request of the Rust HTTP client
(MAS introspection), with the tags Python's `SimpleHttpClient` span
has: `span.kind`, `http.method`, `http.url` (without credentials or
query) and `http.status_code`. As in Python, an error status is the
caller's to judge, so only a failure to get a response is marked as
an error, before the conversion to a Python exception.
A trial test loads an uncached event with tracing on and checks that
`events.load` is under the caller's Python span, with the event fetched
and its reads under it. Rust tests check `state.resolve` on a failed
resolution and the HTTP client span against a local server.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01W4zxygfJC93SsugxskhoJG
The legacy /sync work done in Rust now reports spans under the
request's Python span:
- `sync.room_changes`, working out which rooms changed;
- `sync.room_entries` (with the room count), and inside it a
`sync.room` per room, tagged `room_id` and its `outcome` (`entry`,
`fallback` to Python, or `error`, with the error as a log);
- `sync.encode` (with the room count), encoding the entries on the
reactor thread under the request's span.
The room spans are created in the task, so the per-room loop's ten
concurrent rooms each nest under `sync.room_entries`, and their
`db.*` spans under them.
A trial test syncs two rooms with tracing on and checks the tree that
reaches the agent: `sync.room_entries` under the servlet's Python span,
a `sync.room` per room with its reads under it, and `sync.encode` in
the same trace. The tracing set-up of the persist test moves to a base
class both share.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01W4zxygfJC93SsugxskhoJG
The persister's entry points and stages now have spans, so the `db.*`
spans of the earlier commits nest under the step that made them:
- `persist.prepare_chunk` and `persist.write_chunk` (with `room_id`
and `events`), created in the functions both the chunk entry points
and the batch call, so they have them at every
`rust_event_persistence` level; `persist.batch_next`,
`persist.batch_abort` and `persist.update_current_state`;
- inside a prepare: `persist.state_delta` (which includes the
extremities), `persist.state_res` (with the resolution's total and
database time), `persist.chain_cover`, `persist.sliding_sync` and
`persist.sticky`;
- inside the write transaction: `persist.txn.read`,
`persist.txn.store_events`, `persist.txn.auth_chain`,
`persist.txn.metadata`, `persist.txn.current_state` and
`persist.txn.sliding_sync`. Most steps only queue their writes, so
their spans time the step's own work, and the writes are timed in
the next round trip's `db.query`.
The spans are created inside the task, so their parent is the Python
span active when the persist was started. `TxnTimings` stay as they
are: Python still needs them for its metrics, which are not sampled.
A trial test makes the test tracer the global one, as `init_tracer`
does, persists a message through the Rust persister and checks what
reaches the agent's UDP port: `persist.batch_next` under the persist
queue's Python span and in its trace, the chunk's steps under it, and
`persist.write_chunk` → `db.persist_events` → `db.connection` →
`db.txn`, with the transaction's steps and `db.query` round trips
carrying queued writes and the COMMIT under it.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01W4zxygfJC93SsugxskhoJG
Rust code now creates spans with the `tracing` crate.
`JaegerLayer` gives each span Jaeger IDs and reports sampled ones
through the homeserver's UDP reporter when they close.
A span's parent is its `tracing` parent, else (for a span with no
explicit parent) the Python span that was active when its task was
spawned, from the task's logcontext handle, else the Python span set
for the thread by `with_py_parent`. With no parent, the configured
`const` or `probabilistic` sampler decides, and a sampled root gets
jaeger-client's `sampler.type` and `sampler.param` tags. A child
copies its parent's trace ID, flags and baggage, so sampling is
decided once per trace and `force_tracing` carries over.
A span ends when it is last exited, or when it closes if it was never
entered. The registry keeps a parent open until its children close, so
its duration must not be taken at close. Work that outlives its parent
should start a trace with `parent: None` and `follows_from`.
Span fields become tags (strings cut to 1024 bytes, as jaeger-client
does), `otel.name` sets the operation name, and events inside a span
become logs. Only Synapse's own spans and events are recorded, not
those of hyper, h2 and other dependencies.
The layer is the process-wide subscriber. It reports to the first
homeserver that enables tracing until that homeserver shuts down or is
dropped. Spans are disabled while no reporter is attached, so they
cost almost nothing with tracing off.
`is_sampled`, `span_context`, `inject_headers` (`uber-trace-id` plus
`uberctx-*` baggage, as jaeger-client's HTTP codec writes them) and
`follows_from` are there for the instrumentation that follows.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01W4zxygfJC93SsugxskhoJG
`enable_tracing` now starts a reporter for the homeserver. A finished
span is queued on a bounded channel and dropped if the queue is full,
so reporting never blocks. A `jaeger-reporter` std thread encodes the
spans and sends them as `emitBatch` datagrams to the agent the Python
tracer uses. A batch goes when the next span would not fit in a 65000
byte datagram, at 100 spans, or a second after its first span. Every
batch carries the Python tracer's service name and process tags.
Like jaeger-client, the reporter sends from an unconnected socket and
resolves the agent's host name when it sends: again every 30 seconds
and after a failed send. A name that does not resolve at startup, or an
agent that moves, does not lose Rust spans for good, and an ICMP error
from a down agent cannot fail a later send.
Homeserver shutdown sends the queued spans, waiting up to a second.
The counters are exported as `synapse_rust_tracing_*` metrics, and a
changed send error is logged.
Nothing reports spans yet: the span API comes next.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01W4zxygfJC93SsugxskhoJG
Rust work spawned from Python needs the caller's span as the parent of
the spans it will report. `LogContextHandle::capture` now reads the
active span's context (trace ID, span ID, flags, baggage) off the
logcontext's scope, but only once a homeserver has enabled tracing.
Otherwise a capture costs one relaxed atomic load. A capture inside a
task copies the task's handle, so the span stays the one the task was
spawned under.
The `_blocking` entry points ran their futures on the reactor thread
with no handle at all. They now go through
`RustRuntime.block_on_scoped`, which spawns the future with a captured
handle and blocks on the join, the same as `create_deferred`.
`init_tracer` hands the Jaeger tracer's service name, process tags,
agent address and sampler to `RustRuntime.enable_tracing`, which stores
them for the reporter that follows.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01W4zxygfJC93SsugxskhoJG
This was all done through claude.
## Fix flaky `test_edu_large_messages_not_splitting_one_user` (`TooLong`
under `trial -jN`)
### Problem
The "Build .deb packages" CI step intermittently failed with:
```
twisted.protocols.amp.TooLong
...in
tests.rest.client.test_sendtodevice.SendToDeviceTestCase.test_edu_large_messages_not_splitting_one_user
```
The deb build runs the suite with `twisted.trial -j2`. In that mode,
worker log events are shipped to the manager process over Twisted's AMP
protocol, which encodes each value with a 2-byte length prefix — so any
single log line of **64 KiB or more** raises `TooLong`.
### Root cause
Not a bug in the to-device/EDU logic, and **not** debug logging enabled
by the build (it runs at the default `ERROR` level). It's a **log-level
leak between tests sharing a `-j2` worker**:
- `tests/logging/test_loggers.py::ExplicitlyConfiguredLoggerTestCase`
calls `root_logger.setLevel(logging.DEBUG)` directly and never restores
it (no `setUp`/`tearDown`/`addCleanup`).
- When that test runs before
`test_edu_large_messages_not_splitting_one_user` **in the same worker
process**, the root logger is left at `DEBUG`.
- That test deliberately builds an EDU of exactly `SOFT_MAX_EDU_SIZE -
1` (65 535) bytes. Storing it triggers `synapse/storage/database.py`'s
`[SQL values]` DEBUG log, which dumps the full query params — producing
a **65 708-byte**
line that overflows AMP's cap.
It looks "flaky" purely because of `-j2` scheduling: whether the two
tests land on the same worker, and in what order.
### Fix
Three commits:
1. **Restore the root logger level in
`ExplicitlyConfiguredLoggerTestCase`** — `addCleanup` to put the level
back. Fixes the root cause.
2. **Truncate oversized log lines in the test log handler**
(`ToTwistedHandler.emit`) — caps lines at 1000 chars so no debug line
can break `trial -jN`, regardless of which query is logged (defense in
depth).
3. **Truncate values in `[SQL values]` debug logging** — caps the logged
param repr at 1000 chars (guarded by `isEnabledFor(DEBUG)` to keep the
hot path lazy). Keeps production debug logs sane too.
### Testing
- The reproduction (`trial -j2 tests.logging.test_loggers <the EDU
test>`) went from **~3/8 failing** to **10/10 passing**.
- Confirmed the root level is restored after the logging tests, and that
the `[SQL values]` line is now capped (~50 KB with a `[truncated]`
marker, was 65 708).
- `ruff` + `mypy` clean; `tests.logging.test_loggers` and
`tests.rest.client.test_sendtodevice` pass (14/14).
---------
Co-authored-by: Claude Opus 4.8 <noreply@anthropic.com>
Co-authored-by: Eric Eastwood <erice@element.io>
This changes the arguments in clock functions to be `Duration` and
converts call sites and constants into `Duration`. There are still some
more functions around that should be converted (e.g.
`timeout_deferred`), but we leave that to another PR.
We also changes `.as_secs()` to return a float, as the rounding broke
things subtly. The only reason to keep it (its the same as
`timedelta.total_seconds()`) is for symmetry with `as_millis()`.
Follows on from https://github.com/element-hq/synapse/pull/19223
Revert https://github.com/element-hq/synapse/pull/18849
Go back to our custom `LogContextScopeManager` after trying
OpenTracing's `ContextVarsScopeManager`.
Fix https://github.com/element-hq/synapse/issues/19004
### Why revert?
For reference, with the normal reactor, `ContextVarsScopeManager` worked
just as good as our custom `LogContextScopeManager` as far as I can tell
(and even better in some cases). But since Twisted appears to not fully
support `ContextVar`'s, it doesn't work as expected in all cases.
Compounding things, `ContextVarsScopeManager` was causing errors with
the experimental `SYNAPSE_ASYNC_IO_REACTOR` option.
Since we're not getting the full benefit that we originally desired, we
might as well revert and figure out alternatives for extending the
logcontext lifetimes to support the use case we were trying to unlock
(c.f. https://github.com/element-hq/synapse/pull/18804).
See
https://github.com/element-hq/synapse/issues/19004#issuecomment-3358052171
for more info.
### Does this require backporting and patch releases?
No. Since `ContextVarsScopeManager` operates just as good with the
normal reactor and was only causing actual errors with the experimental
`SYNAPSE_ASYNC_IO_REACTOR` option, I don't think this requires us to
backport and make patch releases at all.
### Maintain cross-links between main trace and background process work
In order to maintain the functionality introduced in https://github.com/element-hq/synapse/pull/18932 (cross-links between the background process trace and currently active trace), we also needed a small change.
Previously, when we were using `ContextVarsScopeManager`, it tracked the tracing scope across the logcontext changes without issue. Now that we're using our own custom `LogContextScopeManager` again, we need to capture the active span from the logcontext before we reset to the sentinel context because of the `PreserveLoggingContext()` below.
Added some tests to ensure we maintain the `run_as_background` tracing behavior regardless of the tracing scope manager we use.
### Background
As part of Element's plan to support a light form of vhosting (virtual
host) (multiple instances of Synapse in the same Python process), we're
currently diving into the details and implications of running multiple
instances of Synapse in the same Python process.
"Per-tenant logging" tracked internally by
https://github.com/element-hq/synapse-small-hosts/issues/48
### Prior art
Previously, we exposed `server_name` by providing a static logging
`MetadataFilter` that injected the values:
https://github.com/element-hq/synapse/blob/205d9e4fc4774850f34971469ae500e70119d17a/synapse/config/logger.py#L216
While this can work fine for the normal case of one Synapse instance per
Python process, this configures things globally and isn't compatible
when we try to start multiple Synapse instances because each subsequent
tenant will overwrite the previous tenant.
### What does this PR do?
We remove the `MetadataFilter` and replace it by tracking the
`server_name` in the `LoggingContext` and expose it with our existing
[`LoggingContextFilter`](https://github.com/element-hq/synapse/blob/205d9e4fc4774850f34971469ae500e70119d17a/synapse/logging/context.py#L584-L622)
that we already use to expose information about the `request`.
This means that the `server_name` value follows wherever we log as
expected even when we have multiple Synapse instances running in the
same process.
### A note on logcontext
Anywhere, Synapse mistakenly uses the `sentinel` logcontext to log
something, we won't know which server sent the log. We've been fixing up
`sentinel` logcontext usage as tracked by
https://github.com/element-hq/synapse/issues/18905
Any further `sentinel` logcontext usage we find in the future can be
fixed piecemeal as normal.
https://github.com/element-hq/synapse/blob/d2a966f922fdc95bc86f7fe55b7b54a9ab3f25c1/docs/log_contexts.md#L71-L81
### Testing strategy
1. Adjust your logging config to include `%(server_name)s` in the format
```yaml
formatters:
precise:
format: '%(asctime)s - %(server_name)s - %(name)s - %(lineno)d -
%(levelname)s - %(request)s - %(message)s'
```
1. Start Synapse: `poetry run synapse_homeserver --config-path
homeserver.yaml`
1. Make some requests (`curl
http://localhost:8008/_matrix/client/versions`, etc)
1. Open the homeserver logs and notice the `server_name` in the logs as
expected. `unknown_server_from_sentinel_context` is expected for the
`sentinel` logcontext (things outside of Synapse).
Introduce `Clock.call_when_running(...)` to wrap startup code in a
logcontext, ensuring we can identify which server generated the logs.
Background:
> Ideally, nothing from the Synapse homeserver would be logged against the `sentinel`
> logcontext as we want to know which server the logs came from. In practice, this is not
> always the case yet especially outside of request handling.
>
> Global things outside of Synapse (e.g. Twisted reactor code) should run in the
> `sentinel` logcontext. It's only when it calls into application code that a logcontext
> gets activated. This means the reactor should be started in the `sentinel` logcontext,
> and any time an awaitable yields control back to the reactor, it should reset the
> logcontext to be the `sentinel` logcontext. This is important to avoid leaking the
> current logcontext to the reactor (which would then get picked up and associated with
> the next thing the reactor does).
>
> *-- `docs/log_contexts.md`
Also adds a lint to prefer `Clock.call_when_running(...)` over
`reactor.callWhenRunning(...)`
Part of https://github.com/element-hq/synapse/issues/18905
Switch to OpenTracing's `ContextVarsScopeManager` instead of our own
custom `LogContextScopeManager`.
This is now possible because the linked Twisted issue from the comment
in our custom `LogContextScopeManager` is resolved:
https://twistedmatrix.com/trac/ticket/10301
This PR is spawning from exploring different possibilities to solve the
`scope` loss problem I was encountering in
https://github.com/element-hq/synapse/pull/18804#discussion_r2268254424.
This appears to solve the problem and I've added the additional test
from there to this PR ✅
Bulk refactor `Counter` metrics to be homeserver-scoped. We also add
lints to make sure that new `Counter` metrics don't sneak in without
using the `server_name` label (`SERVER_NAME_LABEL`).
All of the "Fill in" commits are just bulk refactor.
Part of https://github.com/element-hq/synapse/issues/18592
### Testing strategy
1. Add the `metrics` listener in your `homeserver.yaml`
```yaml
listeners:
# This is just showing how to configure metrics either way
#
# `http` `metrics` resource
- port: 9322
type: http
bind_addresses: ['127.0.0.1']
resources:
- names: [metrics]
compress: false
# `metrics` listener
- port: 9323
type: metrics
bind_addresses: ['127.0.0.1']
```
1. Start the homeserver: `poetry run synapse_homeserver --config-path
homeserver.yaml`
1. Fetch `http://localhost:9322/_synapse/metrics` and/or
`http://localhost:9323/metrics`
1. Observe response includes the `synapse_user_registrations_total`,
`synapse_http_server_response_count_total`, etc metrics with the
`server_name` label
Spawning from getting `HMAC incorrect` errors that seem unexplainable
except for the `registration_shared_secret` being misconfigured. It's
also possible my HMAC calculation is incorrect but every time I
double-check the result with the [known-good Python
example](https://github.com/element-hq/synapse/blob/553e124f766584456fbdb6d1aa37fdd12ad54dad/docs/admin_api/register_api.md)
(which matches [Synapse's
source](https://github.com/element-hq/synapse/blob/24e849e483820762fa2d231ad702e6aeaa23829c/synapse/rest/admin/users.py#L618-L633)),
it's as expected.
With these logs, we can actually debug whether
`registration_shared_secret` is being configured correctly or not.
It also helps specifically when using `registration_shared_secret_path`
since the default Synapse behavior (of creating the file and secret if
it doesn't exist) can mask deployment race condition where we would
start up Synapse before the `registration_shared_secret_path` file was
put in place:
> **`registration_shared_secret_path`**
>
> [...]
>
> If this file does not exist, Synapse will create a new shared secret
on startup and store it in this file.
>
> *-- [Synapse config
docs](https://github.com/element-hq/synapse/blob/6521406a37a40a490a1a435f3616c02cfcbbac16/docs/usage/configuration/config_documentation.md#registration_shared_secret_path)*
This only applies to the [`POST
/_synapse/admin/v1/register`](https://github.com/element-hq/synapse/blob/553e124f766584456fbdb6d1aa37fdd12ad54dad/docs/admin_api/register_api.md)
endpoint but does log very sensitive information so we've made it so you
have to explicitly enable the logs by configuring
`synapse.rest.admin.users.registration_debug` (does not inherit root log
level) (via our new `ExplicitlyConfiguredLogger`)
`homeserver.yaml`
```yaml
log_config: "/myserver.log.config.yaml"
```
`myserver.log.config.yaml`
```yaml
version: 1
formatters:
precise:
format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s - %(message)s'
handlers:
# ... file/buffer handler (see `sample_log_config.yaml`)
# A handler that writes logs to stderr. Unused by default, but can be used
# instead of "buffer" and "file" in the logger handlers.
console:
class: logging.StreamHandler
formatter: precise
loggers:
synapse.storage.SQL:
# beware: increasing this to DEBUG will make synapse log sensitive
# information such as access tokens.
level: INFO
# Has to be explicitly configured as such. Will not inherit from the root level even if it's set to DEBUG
synapse.rest.admin.users.registration_debug:
level: DEBUG
root:
level: INFO
handlers: [console]
disable_existing_loggers: false
```
During the migration the automated script to update the copyright
headers accidentally got rid of some of the existing copyright lines.
Reinstate them.
* Update mypy and mypy-zope
* Remove unused ignores
These used to suppress
```
synapse/storage/engines/__init__.py:28: error: "__new__" must return a
class instance (got "NoReturn") [misc]
```
and
```
synapse/http/matrixfederationclient.py:1270: error: "BaseException" has no attribute "reasons" [attr-defined]
```
(note that we check `hasattr(e, "reasons")` above)
* Avoid empty body warnings, sometimes by marking methods as abstract
E.g.
```
tests/handlers/test_register.py:58: error: Missing return statement [empty-body]
tests/handlers/test_register.py:108: error: Missing return statement [empty-body]
```
* Suppress false positive about `JaegerConfig`
Complaint was
```
synapse/logging/opentracing.py:450: error: Function "Type[Config]" could always be true in boolean context [truthy-function]
```
* Fix not calling `is_state()`
Oops!
```
tests/rest/client/test_third_party_rules.py:428: error: Function "Callable[[], bool]" could always be true in boolean context [truthy-function]
```
* Suppress false positives from ParamSpecs
````
synapse/logging/opentracing.py:971: error: Argument 2 to "_custom_sync_async_decorator" has incompatible type "Callable[[Arg(Callable[P, R], 'func'), **P], _GeneratorContextManager[None]]"; expected "Callable[[Callable[P, R], **P], _GeneratorContextManager[None]]" [arg-type]
synapse/logging/opentracing.py:1017: error: Argument 2 to "_custom_sync_async_decorator" has incompatible type "Callable[[Arg(Callable[P, R], 'func'), **P], _GeneratorContextManager[None]]"; expected "Callable[[Callable[P, R], **P], _GeneratorContextManager[None]]" [arg-type]
````
* Drive-by improvement to `wrapping_logic` annotation
* Workaround false "unreachable" positives
See https://github.com/Shoobx/mypy-zope/issues/91
```
tests/http/test_proxyagent.py:626: error: Statement is unreachable [unreachable]
tests/http/test_proxyagent.py:762: error: Statement is unreachable [unreachable]
tests/http/test_proxyagent.py:826: error: Statement is unreachable [unreachable]
tests/http/test_proxyagent.py:838: error: Statement is unreachable [unreachable]
tests/http/test_proxyagent.py:845: error: Statement is unreachable [unreachable]
tests/http/federation/test_matrix_federation_agent.py:151: error: Statement is unreachable [unreachable]
tests/http/federation/test_matrix_federation_agent.py:452: error: Statement is unreachable [unreachable]
tests/logging/test_remote_handler.py:60: error: Statement is unreachable [unreachable]
tests/logging/test_remote_handler.py:93: error: Statement is unreachable [unreachable]
tests/logging/test_remote_handler.py:127: error: Statement is unreachable [unreachable]
tests/logging/test_remote_handler.py:152: error: Statement is unreachable [unreachable]
```
* Changelog
* Tweak DBAPI2 Protocol to be accepted by mypy 1.0
Some extra context in:
- https://github.com/matrix-org/python-canonicaljson/pull/57
- https://github.com/python/mypy/issues/6002
- https://mypy.readthedocs.io/en/latest/common_issues.html#covariant-subtyping-of-mutable-protocol-members-is-rejected
* Pull in updated canonicaljson lib
so the protocol check just works
* Improve comments in opentracing
I tried to workaround the ignores but found it too much trouble.
I think the corresponding issue is
https://github.com/python/mypy/issues/12909. The mypy repo has a PR
claiming to fix this (https://github.com/python/mypy/pull/14677) which
might mean this gets resolved soon?
* Better annotation for INTERACTIVE_AUTH_CHECKERS
* Drive-by AUTH_TYPE annotation, to remove an ignore
```py
@trace
@tag_args
async def get_oldest_event_ids_with_depth_in_room(...)
...
```
Before this PR, you would see a warning in the logs and the span was not exported:
```
2022-08-03 19:11:59,383 - synapse.logging.opentracing - 835 - ERROR - GET-0 - @trace may not have wrapped EventFederationWorkerStore.get_oldest_event_ids_with_depth_in_room correctly! The function is not async but returned a coroutine.
```
`start_active_span` was inconsistent as to whether it would activate the span
immediately, or wait for `scope.__enter__` to happen (it depended on whether
the current logcontext already had an associated scope). The inconsistency was
rather confusing if you were hoping to set up a couple of separate spans before
activating either.
Looking at the other implementations of opentracing `ScopeManager`s, the
intention is that it *should* be activated immediately, as the name
implies. Indeed, the idea is that you don't have to use the scope as a
contextmanager at all - you can just call `.close` on the result. Hence, our
cleanup has to happen in `.close` rather than `.__exit__`.
So, the main change here is to ensure that `start_active_span` does activate
the span, and that `scope.close()` does close the scope.
We also add some tests, which requires a `tracer` param so that we don't have
to rely on the global variable in unit tests.
As far as I can tell our logging contexts are meant to log the request ID, or sometimes the request ID followed by a suffix (this is generally stored in the name field of LoggingContext). There's also code to log the name@memory location, but I'm not sure this is ever used.
This simplifies the code paths to require every logging context to have a name and use that in logging. For sub-contexts (created via nested_logging_contexts, defer_to_threadpool, Measure) we use the current context's str (which becomes their name or the string "sentinel") and then potentially modify that (e.g. add a suffix).
Part of #9744
Removes all redundant `# -*- coding: utf-8 -*-` lines from files, as python 3 automatically reads source code as utf-8 now.
`Signed-off-by: Jonathan de Jong <jonathan@automatia.nl>`
This modifies the configuration of structured logging to be usable from
the standard Python logging configuration.
This also separates the formatting of logs from the transport allowing
JSON logs to files or standard logs to sockets.
