AssertionError prev_stream_id <= max_stream_id

[V02460]

Description

Since updating to 1.21.0rc1 I get spammed with the two following errors. This looks a lot like #7840, but the suggested fix does not work and even though #8402 landed, startup of Synapse is not prevented.

synapse.metrics.background_process_metrics: [user_directory.notify_new_event-213] Background process 'user_directory.notify_new_event' threw an exception
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/synapse/metrics/background_process_metrics.py", line 205, in run
    result = await result
  File "/usr/lib/python3.8/site-packages/synapse/handlers/user_directory.py", line 103, in process
    await self._unsafe_process()
  File "/usr/lib/python3.8/site-packages/synapse/handlers/user_directory.py", line 149, in _unsafe_process
    max_pos, deltas = await self.store.get_current_state_deltas(
  File "/usr/lib/python3.8/site-packages/synapse/storage/databases/main/state_deltas.py", line 54, in get_current_state_deltas
    assert prev_stream_id <= max_stream_id
AssertionError
synapse.metrics.background_process_metrics: [stats.notify_new_event-213] Background process 'stats.notify_new_event' threw an exception
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/synapse/metrics/background_process_metrics.py", line 205, in run
    result = await result
  File "/usr/lib/python3.8/site-packages/synapse/handlers/stats.py", line 69, in process
    await self._unsafe_process()
  File "/usr/lib/python3.8/site-packages/synapse/handlers/stats.py", line 93, in _unsafe_process
    max_pos, deltas = await self.store.get_current_state_deltas(
  File "/usr/lib/python3.8/site-packages/synapse/storage/databases/main/state_deltas.py", line 54, in get_current_state_deltas
    assert prev_stream_id <= max_stream_id
AssertionError

Steps to reproduce

• (Have a corrupt database?)
• Start Synapse
• Observe the two errors whenever an event is received

Version information

• Homeserver: nasnotfound.de

• Version: 1.21.0rc1

• Install method: self-built rpm

• Platform: Fedora 32

[erikjohnston]

This is odd, and I'd expect it to have quickly corrected itself. Basically, this is the background task that keeps the room stats up to date by processing the events stream, and the prev_stream_id should be where it got up to last time.

Can you run the following in your DB and report the output?

SELECT * FROM stats_incremental_position;
SELECT MAX(stream_ordering) from events;

[V02460]

I can no longer reproduce the issue and your suggested queries now produce the same result. Maybe the update fixed something broken and it just needed a while to correct. Whatever the cause, I can't help triaging anymore :(

[z3ntu]

I'm seeing the same exception with Synapse 1.22.1 on my homeserver.

Nov 24 19:14:52 arch-vps synapse[277897]: 2020-11-24 19:14:52,081 - synapse.metrics.background_process_metrics - 210 - ERROR - stats.notify_new_event-167- Background process 'stats.notify_new_event' threw an exception
Nov 24 19:14:52 arch-vps synapse[277897]: Traceback (most recent call last):        
Nov 24 19:14:52 arch-vps synapse[277897]:   File "/usr/lib/python3.8/site-packages/synapse/metrics/background_process_metrics.py", line 206, in run                                                                                                          
Nov 24 19:14:52 arch-vps synapse[277897]:     result = await result                                                                                                                                                                                          
Nov 24 19:14:52 arch-vps synapse[277897]:   File "/usr/lib/python3.8/site-packages/synapse/handlers/stats.py", line 69, in process                                                                                                                           
Nov 24 19:14:52 arch-vps synapse[277897]:     await self._unsafe_process()                                                                                                                                                                                   
Nov 24 19:14:52 arch-vps synapse[277897]:   File "/usr/lib/python3.8/site-packages/synapse/handlers/stats.py", line 93, in _unsafe_process                                                                                                                   
Nov 24 19:14:52 arch-vps synapse[277897]:     max_pos, deltas = await self.store.get_current_state_deltas(                                                                                                                                                   
Nov 24 19:14:52 arch-vps synapse[277897]:   File "/usr/lib/python3.8/site-packages/synapse/storage/databases/main/state_deltas.py", line 54, in get_current_state_deltas                                                                                     
Nov 24 19:14:52 arch-vps synapse[277897]:     assert prev_stream_id <= max_stream_id                                                                                                                                                                         
Nov 24 19:14:52 arch-vps synapse[277897]: AssertionError

The sql output from the commands above:

synapse=# SELECT * FROM stats_incremental_position;
 lock | stream_id 
------+-----------
 X    |   2006288
(1 row)

synapse=# SELECT MAX(stream_ordering) from events;
   max   
---------
 2006288
(1 row)

I've just upgraded from 1.21.2, where I've tried unsuccessfully to join #irc:matrix.org several times which lead to some other exceptions (irrelevant here I believe, but still posting them)

Nov 24 18:53:32 arch-vps synapse[800]: twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'psycopg2.errors.UniqueViolation'>: duplicate key value violates unique constraint "event_edges_event_id_prev_event_id_room_id_is_state_key"
Nov 24 18:53:32 arch-vps synapse[800]: DETAIL:  Key (event_id, prev_event_id, room_id, is_state)=($SfXO2hDufYCjdIZUOSJCKhXdUhhJoT03JP//kcBX05c, $dXIvbZ+qSFPbtcnC9p3GA2hW89M6t6UBoy0dtdQMAtc, !BAXLHOFjvDKUeLafmO:matrix.org, f) already exists.

edit: it seems to have resolved itself after 6 minutes of spewing exceptions I believe (19:09:22 -> 19:15:30)

[clokep]

@z3ntu Sounds like it fixed itself, if you see the error again please open a new issue and reference this one!