Commit Graph

140 Commits

Author SHA1 Message Date
Richard van der Hoff
cb59e08062
Improve logging and opentracing for to-device message handling (#14598)
A batch of changes intended to make it easier to trace to-device messages through the system.

The intention here is that a client can set a property org.matrix.msgid in any to-device message it sends. That ID is then included in any tracing or logging related to the message. (Suggestions as to where this field should be documented welcome. I'm not enthusiastic about speccing it - it's very much an optional extra to help with debugging.)

I've also generally improved the data we send to opentracing for these messages.
2022-12-06 09:52:55 +00:00
Patrick Cloke
d8cc86eff4
Remove redundant types from comments. (#14412)
Remove type hints from comments which have been added
as Python type hints. This helps avoid drift between comments
and reality, as well as removing redundant information.

Also adds some missing type hints which were simple to fill in.
2022-11-16 15:25:24 +00:00
David Robertson
285d72556b
Update mypy and mypy-zope, attempt 3 (#13993)
Co-authored-by: Patrick Cloke <clokep@users.noreply.github.com>
2022-09-30 17:36:28 +01:00
David Robertson
8e52cb0bce
Revert "Update mypy and mypy-zope (#13925)"
This reverts commit 6d543d6d9f.
2022-09-30 16:37:48 +01:00
David Robertson
6d543d6d9f
Update mypy and mypy-zope (#13925)
* Update mypy and mypy-zope

* Unignore assigning to LogRecord attributes

Presumably https://github.com/python/typeshed/pull/8064 makes this ok

Cherry-picked from #13521

* Remove unused ignores due to mypy ParamSpec fixes

https://github.com/python/mypy/pull/12668

Cherry-picked from #13521

* Remove additional unused ignores

* Fix new mypy complaints related to `assertGreater`

Presumably due to https://github.com/python/typeshed/pull/8077

* Changelog

* Reword changelog

Co-authored-by: Patrick Cloke <clokep@users.noreply.github.com>

Co-authored-by: Patrick Cloke <clokep@users.noreply.github.com>
2022-09-30 16:34:47 +01:00
Eric Eastwood
a911ffb42c
Tag trace with instance name (#13761)
We tag the Synapse instance name so that it's an easy jumping off point into the logs. Can also be used to filter for an instance that is under load.

As suggested by @clokep and @reivilibre in,

 - https://github.com/matrix-org/synapse/pull/13729#discussion_r964719258
 - https://github.com/matrix-org/synapse/pull/13729#discussion_r964733578
2022-09-09 11:31:37 -05:00
Eric Eastwood
f694bb71b7
Strip number suffix from instance name to consolidate services that traces are spread over (#13729)
The problem with many services is that it makes it hard to find which service has the trace you want, see https://github.com/jaegertracing/jaeger-ui/issues/985

Previously, we split traces out into services based on their instance name like `matrix.org client_reader-1`, etc but there are many worker instances of the same `client_reader` so there is a lot to click through.

With this PR, all of the traces are just collected under the worker type like `client_reader`, `event_persister` 😇

Note: A Synapse worker instance name is an opaque string with the number convention only being our own thing for the `matrix.org` deployment. But seems pretty sensible to group things this way.
2022-09-09 11:30:06 -05:00
Eric Eastwood
0a4efbc1dd
Instrument the federation/backfill part of /messages (#13489)
Instrument the federation/backfill part of `/messages` so it's easier to follow what's going on in Jaeger when viewing a trace.

Split out from https://github.com/matrix-org/synapse/pull/13440

Follow-up from https://github.com/matrix-org/synapse/pull/13368

Part of https://github.com/matrix-org/synapse/issues/13356
2022-08-16 12:39:40 -05:00
David Robertson
19e5d44886
Revert "Update locked versions of mypy and mypy-zope (#13521)"
This reverts commit f383b9b3ec. Other PRs
were seeing mypy failures that looked to be related to mypy-zope.
Confusingly, we didn't see this on #13521.

Revert this for now and investigate later.
2022-08-15 14:51:05 +01:00
David Robertson
f383b9b3ec
Update locked versions of mypy and mypy-zope (#13521) 2022-08-15 11:32:30 +01:00
Eric Eastwood
1b09b0832e
Allow use of both @trace and @tag_args stacked on the same function (#13453)
```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.
```
2022-08-09 14:32:33 -05:00
Eric Eastwood
860fdd9098
Fix @tag_args being off-by-one (ahead) (#13452)
Fix @tag_args being off-by-one (ahead)

Example:

```
argspec.args=[
  'self',
  'room_id'
]

args=(
  <synapse.storage.databases.main.DataStore object at 0x10d0b8d00>,
  '!HBehERstyQBxyJDLfR:my.synapse.server'
)
```

---

The previous logic was also flawed and we can end up in a situation like this:

```
argspec.args=['self', 'dest', 'room_id', 'limit', 'extremities']

args=(<synapse.federation.federation_client.FederationClient object at 0x7f1651c18160>, 'hs1', '!jAEHKIubyIfuLOdfpY:hs1')
```

From this source:
```py
async def backfill(
    self, dest: str, room_id: str, limit: int, extremities: Collection[str]
) -> Optional[List[EventBase]]:
```

And this usage:
```py
events = await self._federation_client.backfill(
    dest, room_id, limit=limit, extremities=extremities
)
```

which would previously cause this error:
```
synapse_main | 2022-08-04 06:13:12,051 - synapse.handlers.federation - 424 - ERROR - GET-5 - Failed to backfill from hs1 because tuple index out of range
synapse_main | Traceback (most recent call last):
synapse_main |   File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation.py", line 392, in try_backfill
synapse_main |     await self._federation_event_handler.backfill(
synapse_main |   File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 828, in _wrapper
synapse_main |     return await func(*args, **kwargs)
synapse_main |   File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 593, in backfill
synapse_main |     events = await self._federation_client.backfill(
synapse_main |   File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 828, in _wrapper
synapse_main |     return await func(*args, **kwargs)
synapse_main |   File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 827, in _wrapper
synapse_main |     with wrapping_logic(func, *args, **kwargs):
synapse_main |   File "/usr/local/lib/python3.9/contextlib.py", line 119, in __enter__
synapse_main |     return next(self.gen)
synapse_main |   File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 922, in _wrapping_logic
synapse_main |     set_attribute("ARG_" + arg, str(args[i + 1]))  # type: ignore[index]
synapse_main | IndexError: tuple index out of range
```
2022-08-04 14:29:41 -05:00
Patrick Cloke
908aeac44a
Additional fixes for opentracing type hints. (#13362) 2022-07-25 08:34:06 -04:00
Patrick Cloke
50122754c8
Add missing types to opentracing. (#13345)
After this change `synapse.logging` is fully typed.
2022-07-21 12:01:52 +00:00
Patrick Cloke
a6895dd576
Add type annotations to trace decorator. (#13328)
Functions that are decorated with `trace` are now properly typed
and the type hints for them are fixed.
2022-07-19 14:14:30 -04:00
Patrick Cloke
6ad012ef89
More type hints for synapse.logging (#13103)
Completes type hints for synapse.logging.scopecontextmanager and (partially)
for synapse.logging.opentracing.
2022-06-30 13:05:06 +00:00
David Robertson
3503f42741
Easy type hints in synapse.logging.opentracing (#12894) 2022-05-27 11:17:33 +01:00
David Robertson
aec69d2481
Another batch of type annotations (#12726) 2022-05-13 12:35:31 +01:00
Patrick Cloke
7fbf42499d
Use getClientAddress instead of getClientIP. (#12599)
getClientIP was deprecated in Twisted 18.4.0, which also added
getClientAddress. The Synapse minimum version for Twisted is
currently 18.9.0, so all supported versions have the new API.
2022-05-04 14:11:21 -04:00
Sean Quah
78b99de7c2
Prefer make_awaitable over defer.succeed in tests (#12505)
When configuring the return values of mocks, prefer awaitables from
`make_awaitable` over `defer.succeed`. `Deferred`s are only awaitable
once, so it is inappropriate for a mock to return the same `Deferred`
multiple times.

Also update `run_in_background` to support functions that return
arbitrary awaitables.

Signed-off-by: Sean Quah <seanq@element.io>
2022-04-27 14:58:26 +01:00
Erik Johnston
d1cd96ce29
Add opentracing spans to calls to external cache (#12380) 2022-04-07 13:18:29 +01:00
Sean Quah
5627182788
Use ParamSpec in type hints for synapse.logging.context (#12150)
Signed-off-by: Sean Quah <seanq@element.io>
2022-03-08 15:58:14 +00:00
Patrick Cloke
e69f8f0a8e
Remove support for the legacy structured logging configuration. (#12008) 2022-02-17 13:32:18 +00:00
Richard van der Hoff
964f5b9324
Improve opentracing for federation requests (#11870)
The idea here is to set the parent span for incoming federation requests to the
*outgoing* span on the other end. That means that you can see (most of) the
full end-to-end flow when you have a process that includes federation requests.

However, in order not to lose information, we still want a link to the
`incoming-federation-request` span from the servlet, so we have to create
another span to do exactly that.
2022-02-03 12:29:16 +00:00
Richard van der Hoff
31b554c297
Fixes for opentracing scopes (#11869)
`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.
2022-02-02 22:41:57 +00:00
Andrew Morgan
7ad7a47e5a
Add missing auto_attribs=True to the _WrappedRustReporter class (#11768) 2022-01-19 12:39:11 +00:00
Richard van der Hoff
251b5567ec
Remove log_function and its uses (#11761)
I've never found this terribly useful. I think it was added in the early days
of Synapse, without much thought as to what would actually be useful to log,
and has just been cargo-culted ever since.

Rather, it tends to clutter up debug logs with useless information.
2022-01-18 13:06:04 +00:00
Patrick Cloke
10a88ba91c
Use auto_attribs/native type hints for attrs classes. (#11692) 2022-01-13 13:49:28 +00:00
Shay
fcfe67578f
Update to the current version of Black and run it on Synapse codebase (#11596)
* update black version

* run updated version of black on code

* newsfragment

* enumerate python versions
2021-12-23 20:22:15 -08:00
Patrick Cloke
66d7aa783a
Fix mypy error with opentracing.tags. (#11622) 2021-12-23 11:47:24 +00:00
Richard van der Hoff
60fa4935b5
Improve opentracing for incoming HTTP requests (#11618)
* remove `start_active_span_from_request`

Instead, pull out a separate function, `span_context_from_request`, to extract
the parent span, which we can then pass into `start_active_span` as
normal. This seems to be clearer all round.

* Remove redundant tags from `incoming-federation-request`

These are all wrapped up inside a parent span generated in AsyncResource, so
there's no point duplicating all the tags that are set there.

* Leave request spans open until the request completes

It may take some time for the response to be encoded into JSON, and that JSON
to be streamed back to the client, and really we want that inside the top-level
span, so let's hand responsibility for closure to the SynapseRequest.

* opentracing logs for HTTP request events

* changelog
2021-12-20 17:45:03 +00:00
Shay
8ad39438fa
Add opentracing types (#11603) 2021-12-20 12:18:09 +00:00
Sean Quah
0147b3de20
Add missing type hints to synapse.logging.context (#11556) 2021-12-14 17:35:28 +00:00
Patrick Cloke
5cace20bf1
Add missing type hints to synapse.app. (#11287) 2021-11-10 15:06:54 -05:00
David Robertson
1bfd141205
Type hints for the remaining two files in synapse.http. (#11164)
* Teach MyPy that the sentinel context is False

This means that if `ctx: LoggingContextOrSentinel`
then `bool(ctx)` narrows us to `ctx:LoggingContext`, which is a really
neat find!

* Annotate RequestMetrics

- Raise errors for sentry if we use the sentinel context
- Ensure we don't raise an error and carry on, but not recording stats
- Include stack trace in the error case to lower Sean's blood pressure

* Make mypy pass for synapse.http.request_metrics

* Make synapse.http.connectproxyclient pass mypy

Co-authored-by: reivilibre <oliverw@matrix.org>
2021-10-28 14:14:42 +01:00
reivilibre
75ca0a6168
Annotate log_function decorator (#10943)
Co-authored-by: Patrick Cloke <clokep@users.noreply.github.com>
2021-10-27 17:27:23 +01:00
Sean Quah
6b18eb4430
Fix opentracing and Prometheus metrics for replication requests (#10996)
This commit fixes two bugs to do with decorators not instrumenting
`ReplicationEndpoint`'s `send_request` correctly. There are two
decorators on `send_request`: Prometheus' `Gauge.track_inprogress()`
and Synapse's `opentracing.trace`.

`Gauge.track_inprogress()` does not have any support for async
functions when used as a decorator. Since async functions behave like
regular functions that return coroutines, only the creation of the
coroutine was covered by the metric and none of the actual body of
`send_request`.

`Gauge.track_inprogress()` returns a regular, non-async function
wrapping `send_request`, which is the source of the next bug.
The `opentracing.trace` decorator would normally handle async functions
correctly, but since the wrapped `send_request` is a non-async function,
the decorator ends up suffering from the same issue as
`Gauge.track_inprogress()`: the opentracing span only measures the
creation of the coroutine and none of the actual function body.

Using `Gauge.track_inprogress()` as a context manager instead of a
decorator resolves both bugs.
2021-10-12 11:23:46 +01:00
David Robertson
797ee7812d
Relax ignore-missing-imports for modules that have stubs now and update mypy (#11006)
Updating mypy past version 0.9 means that third-party stubs are no-longer distributed with typeshed. See http://mypy-lang.blogspot.com/2021/06/mypy-0900-released.html for details.
We therefore pull in stub packages in setup.py

Additionally, some modules that we were previously ignoring import failures for now have stubs. So let's use them.

The rest of this change consists of fixups to make the newer mypy + stubs pass CI.

Co-authored-by: Patrick Cloke <clokep@users.noreply.github.com>
2021-10-08 14:49:41 +01:00
Nick Barrett
bb228f3523
Include exception in json logging (#11028) 2021-10-08 13:08:25 +02:00
Sean Quah
660c8c1415
Log stack traces when a missing opentracing span is detected (#10983)
Make it easier to track down where opentracing spans are going missing
by including stack traces in the logs.
2021-10-05 12:23:25 +01:00
Patrick Cloke
bb7fdd821b
Use direct references for configuration variables (part 5). (#10897) 2021-09-24 07:25:21 -04:00
Patrick Cloke
01c88a09cd
Use direct references for some configuration variables (#10798)
Instead of proxying through the magic getter of the RootConfig
object. This should be more performant (and is more explicit).
2021-09-13 13:07:12 -04:00
Patrick Cloke
003846d68a
Use the BaseReporter super-class for _WrappedRustReporter. (#10799)
This fixes mypy errors with jaeger-client >= 4.7.0 and should be a no-op
for versions before that.
2021-09-13 08:54:01 -04:00
reivilibre
903db99ed5
Fix PeriodicallyFlushingMemoryHandler inhibiting application shutdown (#10517) 2021-08-03 14:28:30 +01:00
reivilibre
e16eab29d6
Add a PeriodicallyFlushingMemoryHandler to prevent logging silence (#10407)
Signed-off-by: Olivier Wilkinson (reivilibre) <olivier@librepush.net>
2021-07-27 14:32:05 +01:00
Richard van der Hoff
d8324b8238
Fix a handful of type annotations. (#10446)
* switch from `types.CoroutineType` to `typing.Coroutine`

these should be identical semantically, and since `defer.ensureDeferred` is
defined to take a `typing.Coroutine`, will keep mypy happy

* Fix some annotations on inlineCallbacks functions

* changelog
2021-07-22 12:00:16 +01:00
Jonathan de Jong
95e47b2e78
[pyupgrade] synapse/ (#10348)
This PR is tantamount to running 
```
pyupgrade --py36-plus --keep-percent-format `find synapse/ -type f -name "*.py"`
```

Part of #9744
2021-07-19 15:28:05 +01:00
Jonathan de Jong
bf72d10dbf
Use inline type hints in various other places (in synapse/) (#10380) 2021-07-15 11:02:43 +01:00
Richard van der Hoff
91fa9cca99
Expose opentracing trace id in response headers (#10199)
Fixes: #9480
2021-06-18 11:43:22 +01:00
Patrick Cloke
18edc9ab06
Improve comments in the structured logging code. (#10188) 2021-06-16 19:18:02 +01:00