element-hq / element-hq/synapse
SQL transaction retry not always rolling back
- Dominant language
- Python
- Stars
- 4.6k
- Forks
- 600
- Avg merge
- 5d 22h
- Merged PRs (30d)
- 51
Description
### Description
When debugging some Postgres (performance) issues, I noticed Synapse has a few transactions of well over an hour open, with one also a really big difference between when the last transaction and the last query was started. When searching through the logs, all timestamps seem to correlate to a `TXN OPERROR`, and the transaction start specifically seems to match up with lines ending with `5/5`.
I traced the logging back to [`new_transaction`](https://github.com/element-hq/synapse/blob/e8c6cb3d9e4cc5a20c40f9b6d79d5bfdfa73fcab/synapse/storage/database.py#L719). We are running v1.136.0, but this function seems to be identical compared to the most recent commit.
There is some code to retry 5 times. However, `i` is incremented inside the if statement along with the rollback, causing the rollback to not be executed at the final retry.
https://github.com/element-hq/synapse/blob/322481cd2d694eb5fe6107f3c0cd8d48252439bc/synapse/storage/database.py#L823-L841
In the `finally` catch the cursor is closed, but no explicit rollback is performed. I'm not really familiar with Python database libraries, but the psycopg documentation states the following
> The connection is responsible for terminating its transaction, calling either the [commit()](https://www.psycopg.org/docs/connection.html#connection.commit) or [rollback()](https://www.psycopg.org/docs/connection.html#connection.rollback) method.
\- https://www.psycopg.org/docs/usage.html#transactions-control
If I'm reading that correctly, closing the cursor does not rollback the transaction, and would keep the connection in a faulty state. This does correlate with my observations, where the transaction start timestamp roughly correlates with a retry-exhaustion (5/5).
### Steps to reproduce
- Use Postgres
- Have a query using `new_transaction` fail with an `OperationalError` (statement timeout in my case) until all retries are exhausted
- Monitor open transactions using `SELECT * FROM pg_stat_activity ORDER BY xact_start;`
### Homeserver
integrations.snt.utwente.nl
### Synapse Version
1.136.0
### Installation Method
pip (from PyPI)
### Database
PostgreSQL, single server, not as far as I know, idem
### Workers
Multiple workers
### Platform
Running in a Debian VM
### Configuration
_No response_
### Relevant log output
```shell
Nov 18 15:37:49 matrix-integrations matrix-synapse[719220]: synapse.storage.txn - 834 - WARNING - _process_incoming_pdus_in_room_inner-3633-$IstxYJKLf5Fj28DxWo1saXyidsLEeLyFdG2FLfAb7HA-$zUS6fcAI3uWw4BCGqnKDwL2WMaBiZCoegw0hDTU2_Uo- [TXN OPERROR] {_get_state_groups_from_groups-7148fe} canceling statement due to statement timeout
```
### Anything else that would be useful to know?
_No response_
Contributor guide
Assessment
This issue has not been assessed yet.