Commit Graph

16 Commits

Author SHA1 Message Date
Erik Johnston ff034c1f62 Fix flakey test failing with "twisted.protocols.amp.TooLong" (#19832)
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>
2026-06-10 17:33:21 +01:00
dependabot[bot] 9d43bec326 Bump ruff from 0.7.3 to 0.11.10 (#18451)
Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>
Co-authored-by: Andrew Morgan <andrew@amorgan.xyz>
Co-authored-by: Andrew Morgan <1342360+anoadragon453@users.noreply.github.com>
2025-05-20 15:23:30 +01:00
Patrick Cloke 8e1e62c9e0 Update license headers 2023-11-21 15:29:58 -05:00
Eric Eastwood 30a5076da8 Log when events are (unexpectedly) filtered out of responses in tests (#14213)
See https://github.com/matrix-org/synapse/pull/14095#discussion_r990335492

This is useful because when see that a relevant event is an `outlier` or `soft-failed`, then that's a good unexpected indicator explaining why it's not showing up. `filter_events_for_client` is used in `/sync`, `/messages`, `/context` which are all common end-to-end assertion touch points (also notifications, relations).
2023-06-01 21:27:18 -05:00
Eric Eastwood 1903c7e5ed Remove duplicate timestamp from test logs (_trial_temp/test.log) (#15636)
Fix https://github.com/matrix-org/synapse/issues/15618

### Before

```
2023-05-17 22:51:36-0500 [-] 2023-05-17 22:51:36,889 - synapse.server - 338 - INFO - sentinel - Finished setting up.
```

### After

```
2023-05-19 18:16:20-0500 [-] synapse.server - 338 - INFO - sentinel - Finished setting up.
```


### Dev notes

The `Twisted.Logger` controls the `2023-05-19 18:16:20-0500 [-]` prefix, see : [`twisted/twisted` -> `src/twisted/logger/_format.py#L362-L374`](https://github.com/twisted/twisted/blob/34b161e66bc7c9f9efbb95e82c770a863933e498/src/twisted/logger/_format.py#L362-L374)

And we delegate our logs to the Twisted Logger for the tests which puts it in `_trial_temp/test.log`
2023-05-22 13:49:01 -05:00
Patrick Cloke 30509a1010 Add more missing type hints to tests. (#15028) 2023-02-08 16:29:49 -05:00
Patrick Cloke 8e9fc28c6a Reload the pyo3-log config when the Python logging config changes. (#14976)
Since pyo3-log is initialized very early in the Python start-up
it caches the state of the loggers before they're fully initialized
(and thus are essentially disabled). Whenever we reload the
logging configuration we now also tell pyo3-log to discard
any cached logging configuration it has; it will refetch the
current logging configuration from Python at the next point
it logs.

This fixes Rust log lines not appearing in the homeserver logs.
2023-02-03 08:27:31 -05:00
David Robertson 6463244375 Remove unused # type: ignores (#12531)
Over time we've begun to use newer versions of mypy, typeshed, stub
packages---and of course we've improved our own annotations. This makes
some type ignore comments no longer necessary. I have removed them.

There was one exception: a module that imports `select.epoll`. The
ignore is redundant on Linux, but I've kept it ignored for those of us
who work on the source tree using not-Linux. (#11771)

I'm more interested in the config line which enforces this. I want
unused ignores to be reported, because I think it's useful feedback when
annotating to know when you've fixed a problem you had to previously
ignore.

* Installing extras before typechecking

Lacking an easy way to install all extras generically, let's bite the bullet and
make install the hand-maintained `all` extra before typechecking.

Now that https://github.com/matrix-org/backend-meta/pull/6 is merged to
the release/v1 branch.
2022-04-27 14:03:44 +01:00
Jonathan de Jong 4b965c862d Remove redundant "coding: utf-8" lines (#9786)
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>`
2021-04-14 15:34:27 +01:00
Patrick Cloke 7fdc6cefb3 Fix additional type hints. (#9543)
Type hint fixes due to Twisted 21.2.0 adding type hints.
2021-03-09 07:41:32 -05:00
Patrick Cloke 1619802228 Various clean-ups to the logging context code (#8935) 2020-12-14 14:19:47 -05:00
Jonathan de Jong 7c407efdc8 Update test logging to be able to accept braces (#8335) 2020-09-18 07:56:40 -04:00
Amber Brown 463b072b12 Move logging utilities out of the side drawer of util/ and into logging/ (#5606) 2019-07-04 00:07:04 +10:00
Amber Brown 32e7c9e7f2 Run Black. (#5482) 2019-06-20 19:32:02 +10:00
Amber Brown b36c82576e Run Black on the tests again (#5170) 2019-05-10 00:12:11 -05:00
Richard van der Hoff 5488cadaae Enable configuring test log level via env var (#4506)
I got fed up with always adding '@unittest.DEBUG' every time I needed to debug a test.
2019-01-29 12:07:00 +00:00