element-hq / element-hq/synapse

Federation workers continue accepting events after the event persister crashes, losing them

Open
#14,924 0 comments 0 reactions 0 assignees View on GitHub
A-Federation A-Workers O-Uncommon S-Major T-Defect
Dominant language
Python
Stars
4.6k
Forks
600
Avg merge
5d 22h
Merged PRs (30d)
51

Description

This issue has been migrated from [#14924](https://github.com/matrix-org/synapse/issues/14924).

---

### Description

My event persister crashes at inopportune times like 2am, but the federation worker (a combined reader and inbound worker in my setup) continues to accept transactions, 200 OKing them. My guess is the worker thinks the persister is online, sees events in the transaction, queues the events, 200 OK's the transaction, persister ends up not being online so the replication calls fail.

This has the effect where your server only sees the last 10 events in a room *when someone else sends an event* (as the server is now backfilling the `prev_events`). For rooms where your server is not likely to receive another event (DMs), your only option is to go around asking people to "resend" or otherwise send a message in the room.

### Steps to reproduce

* Set up at least a federation inbound worker and event persister
* Kill your event persister
* Receive events over federation
* Restart Synapse to recover your event persister
* :(

### Homeserver

t2l.io

### Synapse Version

{"server_version":"1.75.0","python_version":"3.10.6"}

### Installation Method

Other (please mention below)

### Database

postgresql - no split db, restored from sqlite an eternity ago

### Workers

Multiple workers

### Platform

Ubuntu droplet on digital ocean

### Configuration

Not applicable.

### Relevant log output

```shell
[federation_reader_1] 2023-01-26 13:59:31,155 - synapse.federation.federation_server - 1221 - INFO - _process_incoming_pdus_in_room_inner-5846- handling received PDU in room !fLeHeojWgBGJlLNdLC:matrix.org:
[federation_reader_1] 2023-01-26 13:59:31,234 - synapse.handlers.federation_event - 266 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI- Acquiring room lock to fetch 1 missing prev_events: ['$2fWcbKbztz66GHmXPQf3whytBpwKA1DsLGx656tRuEs']
[federation_reader_1] 2023-01-26 13:59:31,234 - synapse.handlers.federation_event - 272 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI- Acquired room lock to fetch 1 missing prev_events
[federation_reader_1] 2023-01-26 13:59:31,262 - synapse.handlers.federation_event - 689 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI- Requesting missing events between ['$Bm3Fvkhvl8T65KNEmMVVbzgMn7POhmXjvzgrU8QfwIU'] and $weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI
[federation_reader_1] 2023-01-26 13:59:31,384 - synapse.http.matrixfederationclient - 299 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI- {POST-O-20667} [matrix.org] Completed request: 200 OK in 0.12 secs, got 8003 bytes - POST matrix://matrix.org/_matrix/federation/v1/get_missing_events/%21fLeHeojWgBGJlLNdLC%3Amatrix.org
[federation_reader_1] 2023-01-26 13:59:31,392 - synapse.handlers.federation_event - 760 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI- Got 10 prev_events
[federation_reader_1] 2023-01-26 13:59:31,426 - synapse.handlers.federation_event - 868 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI-$gIjhjD3MhzlotyC3LeBk-MNoNfxQ2xFItdiUaHJ182c- Processing pulled event
[federation_reader_1] 2023-01-26 13:59:31,453 - synapse.handlers.federation_event - 1018 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI-$gIjhjD3MhzlotyC3LeBk-MNoNfxQ2xFItdiUaHJ182c- Event $gIjhjD3MhzlotyC3LeBk-MNoNfxQ2xFItdiUaHJ182c is missing prev_events ['$bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64']: calculating state for a backwards extremity
[federation_reader_1] 2023-01-26 13:59:31,453 - synapse.handlers.federation_event - 1048 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI-$gIjhjD3MhzlotyC3LeBk-MNoNfxQ2xFItdiUaHJ182c- Requesting state after missing prev_event $bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64
[federation_reader_1] 2023-01-26 13:59:31,990 - synapse.http.matrixfederationclient - 299 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI-$gIjhjD3MhzlotyC3LeBk-MNoNfxQ2xFItdiUaHJ182c-$bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64- {GET-O-20668} [matrix.org] Completed request: 200 OK in 0.54 secs, got 77629 bytes - GET matrix://matrix.org/_matrix/federation/v1/state_ids/%21fLeHeojWgBGJlLNdLC%3Amatrix.org?event_id=%24bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64
[federation_reader_1] 2023-01-26 13:59:32,959 - synapse.http.matrixfederationclient - 299 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI-$gIjhjD3MhzlotyC3LeBk-MNoNfxQ2xFItdiUaHJ182c-$bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64-$bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64- {GET-O-20672} [matrix.org] Completed request: 200 OK in 0.11 secs, got 935 bytes - GET matrix://matrix.org/_matrix/federation/v1/event/%24bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64
[federation_reader_1] 2023-01-26 13:59:32,963 - synapse.handlers.federation_event - 1609 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI-$gIjhjD3MhzlotyC3LeBk-MNoNfxQ2xFItdiUaHJ182c-$bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64- Fetched 1 events of 1 requested
[federation_reader_1] 2023-01-26 13:59:32,964 - synapse.handlers.federation_event - 1673 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI-$gIjhjD3MhzlotyC3LeBk-MNoNfxQ2xFItdiUaHJ182c-$bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64- Persisting 1 of 1 remaining outliers: ['$bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64']
[federation_reader_1] 2023-01-26 13:59:33,307 - synapse.http.client - 469 - INFO - _process_incoming_pdus_in_room_inner-5846-$weVjhE57ZCE4mT7MieAEZMP92esMet55ZTy0yhv1OBI-$gIjhjD3MhzlotyC3LeBk-MNoNfxQ2xFItdiUaHJ182c-$bPUqYUaxmqufnN9eckAUwuOjbhKGNBxncVFqmTJgU64- Error sending request to POST http://127.0.0.1:9070/_synapse/replication/fed_send_events/GHqwAIrARt: ConnectionRefusedError Connection refused
```

### Anything else that would be useful to know?

It appears the federation worker is aware that it's unable to persist events, and is pulling prev_events for events it's receiving.

My server is installed from git tags with pip, and although is currently on a faster joins RC this problem has been happening for >1 year.

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.