Background update error in Synapse/sqlite after updating from 1.53.0 -> 1.54.0

[kavemang]

Hi guys, getting rolling errors on latest build after rebuild. Is my sqlite db fucked? already tried restarting or rolling back to 1.53.0

KeyError: 'event_search_sqlite_delete_non_strings'
2022-03-08 21:01:33,236 - synapse.storage.background_updates - 269 - ERROR - background_updates-0 - Error doing update
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 267, in run_background_updates
    result = await self.do_next_background_update(sleep)
  File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 383, in do_next_background_update
    update_info = self._background_update_handlers[self._current_background_update]
KeyError: 'event_search_sqlite_delete_non_strings'
2022-03-08 21:01:33,237 - synapse.storage.background_updates - 269 - ERROR - background_updates-0 - Error doing update
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 267, in run_background_updates
    result = await self.do_next_background_update(sleep)
  File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 383, in do_next_background_update
    update_info = self._background_update_handlers[self._current_background_update]
KeyError: 'event_search_sqlite_delete_non_strings'
2022-03-08 21:01:33,237 - synapse.storage.background_updates - 269 - ERROR - background_updates-0 - Error doing update
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 267, in run_background_updates
    result = await self.do_next_background_update(sleep)
  File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 383, in do_next_background_update
    update_info = self._background_update_handlers[self._current_background_update]
KeyError: 'event_search_sqlite_delete_non_strings'

[H-Shay]

Hi there: just to be crystal clear, you started experiencing this error after upgrading from Synapse v1.53.0 to v1.54.0? While I'm asking, could you let us know the install method and platform the homeserver is running on? Is this an error that occurs on startup and did it persist when you rolled back to 1.53.0?

[kavemang]

Hi there: just to be crystal clear, you started experiencing this error after upgrading from Synapse v1.53.0 to v1.54.0? While I'm asking, could you let us know the install method and platform the homeserver is running on? Is this an error that occurs on startup and did it persist when you rolled back to 1.53.0?

sorry for the lack of details

• docker setup using sqlite and the matrixdotorg dockerhub image
• watchtower rebuilt container going from 1.53 -> 1.54 at which point the errors started and rooms became unresponsive
• tried a container restart, no luck
• tried rolling back to 1.53 and the errors persisted

at this point I've rebuilt my setup with postgresql and am working on configuring my rooms and whatnot, but figured I should post this up as there may be a possibility the 1.53 -> 1.54 is breaking sqlite DBs (I know were not supposed to use them in production, learned my lesson lol)

[H-Shay]

Thanks for responding promptly and filing the issue! On first glace it looks like a background update job was not correctly registered with the update handler so it shouldn't mean that the DB is corrupted, but I need to take a deeper look. Either way, it's useful for us to know.

[kavemang]

Thanks for responding promptly and filing the issue! On first glace it looks like a background update job was not correctly registered with the update handler so it shouldn't mean that the DB is corrupted, but I need to take a deeper look. Either way, it's useful for us to know.

hopefully it helps, I'm probably not the only one being lazy and leaving it on sqlite for ages, as a side note when I got home and checked the machine it was running from there was a python process using a full core on its own, something like "python app.homeserver.matrix" whenever the error looping was going that process was hogging CPU at the same time, anyways im already up and running with a new setup and proper DB

[H-Shay]

I spent some time trying to reproduce this and was unable to do so-I didn't faff about with watchtower, however. I am going to leave this open for the meantime and see if anyone else experiences this error.

[DataWraith]

I just upgraded from 1.53 to 1.54 and got the exact same error.

• Platform is a Ubuntu 20.04.4 LTS (GNU/Linux 5.4.0-104-generic x86_64) VPS
• Installation was done via the matrix-synapse-py3 .deb packages
• I first noticed something was wrong when synapse did not respond; then I noticed that the disk was full.
• The error messages in the homeserver log had filled up the entire disk
• I stopped synapse and deleted the log file
• After some fruitless experimentation, I restored a backup of the database, but that didn't help, the same error message fills the logfile again when synapse is started

I can't seem to downgrade currently (E: Version '1.53.0+focal1' for 'matrix-synapse-py3' was not found); I haven't been able to fix this yet (apt only seems to see the latest version); will report back if I manage to downgrade.

Edit: Managed to manually download and install the 1.53 .deb. No change whatsoever though, the error persists.

Relevant bits from the log:

2022-03-12 10:46:23,483 - synapse.storage.prepare_database - 412 - INFO - main - Applying schema deltas for v68
2022-03-12 10:46:23,484 - synapse.storage.prepare_database - 547 - INFO - main - Schema now up to date
2022-03-12 10:46:23,488 - synapse.storage.databases - 84 - INFO - main - [database config 'master']: Starting 'main' database

[...]

2022-03-12 10:46:23,507 - synapse.storage.databases - 101 - INFO - main - [database config 'master']: Starting 'state' database
2022-03-12 10:46:23,507 - synapse.storage.databases - 116 - INFO - main - [database config 'master']: prepared

[...]

2022-03-12 10:46:23,560 - synapse.app.homeserver - 176 - INFO - sentinel - Synapse now listening on TCP port 8008
2022-03-12 10:46:23,561 - synapse.app.homeserver - 209 - INFO - sentinel - Scheduling stats reporting for 3 hour intervals
2022-03-12 10:46:23,634 - synapse.storage.background_updates - 264 - INFO - background_updates-0 - Starting background schema updates
2022-03-12 10:46:23,635 - synapse.handlers.deactivate_account - 230 - INFO - user_parter_loop-0 - User parter finished: stopping
2022-03-12 10:46:23,641 - synapse.storage.background_updates - 269 - ERROR - background_updates-0 - Error doing update
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 267, in run_background_updates
    result = await self.do_next_background_update(sleep)
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 383, in do_next_background_update
    update_info = self._background_update_handlers[self._current_background_update]
KeyError: 'event_search_sqlite_delete_non_strings'
2022-03-12 10:46:23,641 - synapse.storage.background_updates - 269 - ERROR - background_updates-0 - Error doing update
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 267, in run_background_updates
    result = await self.do_next_background_update(sleep)
  File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 383, in do_next_background_update
    update_info = self._background_update_handlers[self._current_background_update]
KeyError: 'event_search_sqlite_delete_non_strings'

(...Ad infinitum)

[H-Shay]

Thank you for your report, looks like this is indeed a regression, introduced in #12037.