element-hq / element-hq/synapse

SQL transaction retry not always rolling back

Open
#19,202 0 comments 0 reactions 0 assignees View on GitHub
A-Database T-Defect
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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.