Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Error on background update 'remove_stale_pushers' #10824

Closed
mlaily opened this issue Sep 15, 2021 · 1 comment · Fixed by #10843
Closed

Error on background update 'remove_stale_pushers' #10824

mlaily opened this issue Sep 15, 2021 · 1 comment · Fixed by #10843
Assignees
@reivilibre
Labels
S-Minor Blocks non-critical functionality, workarounds exist. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.

Comments

@mlaily
Copy link

mlaily commented Sep 15, 2021 •
edited
Loading

Description

Error on background update 'remove_stale_pushers' after upgrading synapse from 1.28.0 to 1.42.0.

I just upgraded my home server from 1.28.0 to 1.42.0 (I use the docker image), and I get the same error looping about every second in my log:

synapse    | 2021-09-15 06:15:16,111 - synapse.storage.background_updates - 230 - INFO - background_updates-0 - Starting update batch on background update 'remove_stale_pushers'
synapse    | 2021-09-15 06:15:16,124 - synapse.storage.background_updates - 117 - ERROR - background_updates-0 - Error doing update
synapse    | Traceback (most recent call last):
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 113, in run_background_updates
synapse    |     result = await self.do_next_background_update(
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 224, in do_next_background_update
synapse    |     await self._do_background_update(desired_duration_ms)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 261, in _do_background_update
synapse    |     items_updated = await update_handler(progress, batch_size)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/databases/main/pusher.py", line 387, in _remove_stale_pushers
synapse    |     number_deleted = await self.db_pool.runInteraction(
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 686, in runInteraction
synapse    |     result = await self.runWithConnection(
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 791, in runWithConnection
synapse    |     return await make_deferred_yieldable(
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/threadpool.py", line 238, in inContext
synapse    |     result = inContext.theWork()  # type: ignore[attr-defined]
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/threadpool.py", line 254, in <lambda>
synapse    |     inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/context.py", line 118, in callWithContext
synapse    |     return self.currentContext().callWithContext(ctx, func, *args, **kw)
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/context.py", line 83, in callWithContext
synapse    |     return func(*args, **kw)
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/enterprise/adbapi.py", line 293, in _runWithConnection
synapse    |     compat.reraise(excValue, excTraceback)
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/deprecate.py", line 298, in deprecatedFunction
synapse    |     return function(*args, **kwargs)
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/compat.py", line 404, in reraise
synapse    |     raise exception.with_traceback(traceback)
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/enterprise/adbapi.py", line 284, in _runWithConnection
synapse    |     result = func(conn, *args, **kw)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 786, in inner_func
synapse    |     return func(db_conn, *args, **kwargs)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 554, in new_transaction
synapse    |     r = func(cursor, *args, **kwargs)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/databases/main/pusher.py", line 372, in _delete_pushers
synapse    |     self.db_pool.simple_delete_many_txn(
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 1902, in simple_delete_many_txn
synapse    |     txn.execute(sql, values)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 298, in execute
synapse    |     self._do_execute(self.txn.execute, sql, *args)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 331, in _do_execute
synapse    |     return func(sql, *args)
synapse    | sqlite3.ProgrammingError: Incorrect number of bindings supplied. The current statement uses 8, and there are 0 supplied.
synapse    | 2021-09-15 06:15:17,129 - synapse.storage.background_updates - 230 - INFO - background_updates-0 - Starting update batch on background update 'remove_stale_pushers'
synapse    | 2021-09-15 06:15:17,141 - synapse.storage.background_updates - 117 - ERROR - background_updates-0 - Error doing update
synapse    | Traceback (most recent call last):
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 113, in run_background_updates
synapse    |     result = await self.do_next_background_update(
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 224, in do_next_background_update
synapse    |     await self._do_background_update(desired_duration_ms)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/background_updates.py", line 261, in _do_background_update
synapse    |     items_updated = await update_handler(progress, batch_size)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/databases/main/pusher.py", line 387, in _remove_stale_pushers
synapse    |     number_deleted = await self.db_pool.runInteraction(
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 686, in runInteraction
synapse    |     result = await self.runWithConnection(
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 791, in runWithConnection
synapse    |     return await make_deferred_yieldable(
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/threadpool.py", line 238, in inContext
synapse    |     result = inContext.theWork()  # type: ignore[attr-defined]
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/threadpool.py", line 254, in <lambda>
synapse    |     inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/context.py", line 118, in callWithContext
synapse    |     return self.currentContext().callWithContext(ctx, func, *args, **kw)
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/context.py", line 83, in callWithContext
synapse    |     return func(*args, **kw)
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/enterprise/adbapi.py", line 293, in _runWithConnection
synapse    |     compat.reraise(excValue, excTraceback)
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/deprecate.py", line 298, in deprecatedFunction
synapse    |     return function(*args, **kwargs)
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/python/compat.py", line 404, in reraise
synapse    |     raise exception.with_traceback(traceback)
synapse    |   File "/usr/local/lib/python3.8/site-packages/twisted/enterprise/adbapi.py", line 284, in _runWithConnection
synapse    |     result = func(conn, *args, **kw)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 786, in inner_func
synapse    |     return func(db_conn, *args, **kwargs)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 554, in new_transaction
synapse    |     r = func(cursor, *args, **kwargs)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/databases/main/pusher.py", line 372, in _delete_pushers
synapse    |     self.db_pool.simple_delete_many_txn(
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 1902, in simple_delete_many_txn
synapse    |     txn.execute(sql, values)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 298, in execute
synapse    |     self._do_execute(self.txn.execute, sql, *args)
synapse    |   File "/usr/local/lib/python3.8/site-packages/synapse/storage/database.py", line 331, in _do_execute
synapse    |     return func(sql, *args)
synapse    | sqlite3.ProgrammingError: Incorrect number of bindings supplied. The current statement uses 8, and there are 0 supplied.

I use an SQLite database.

Everything else seems fine (I'm able to connect to and use the server with Element).

FWIW I ran the same migration (from docker image 1.28.0 to 1.42.0) on a test server before, without any problem. The test server had an almost empty database though, so it's probably related...

I tried rolling back to 1.41.0 but I get the same looping error, so I stayed on 1.42.0.
I tried restarting the container but the error stayed.

Version information

  • Homeserver: My own private home server...

  • Version: {
    "server_version": "1.42.0",
    "python_version": "3.8.12"
    }

SQLite database.

  • Platform: docker container on Ubuntu 18.04.5 LTS

Is there a way to fix my database? Or does this isssue require a synapse patch?

EDIT: for now, I just removed the failing task (delete from background_updates where update_name = "remove_stale_pushers";)...
I tried to investigate a bit, but didn't get very far. I suspect the problem was introduced in #9536.
@reivilibre reivilibre mentioned this issue Sep 17, 2021
Merged
@reivilibre
Copy link
Contributor

reivilibre commented Sep 17, 2021 •
edited
Loading

Hi @mlaily — thanks for spotting and reporting this!

Your database is fine. It won't be the end of the world if you don't run this background job (it seems to remove pushers for sessions that logged out). If this hasn't been a problem until now, it's unlikely to be a problem now, either. (I'm guessing that they now get removed on log-out since 1.29, so this is only about old pushers.)

#10843 has a fix for this, which I guess will go in to v1.44 (it missed the window for v1.43). At this point, once you are running v1.44 or later, if you are still keen on running the background job, you could issue this SQL to your database to start it again:

INSERT INTO background_updates (ordering, update_name, progress_json) VALUES
  (5908, 'remove_stale_pushers', '{}'); -- for future reference only -- ignore me

EDIT: The original bug (which meant that this job was needed) only occurs if you are running Synapse with workers. If you're using SQLite, I doubt you are using workers, so you have no need to run this job.

Thanks!

@reivilibre reivilibre added T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. S-Minor Blocks non-critical functionality, workarounds exist. and removed X-Needs-Discussion labels Sep 17, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@reivilibre reivilibre

Labels
S-Minor Blocks non-critical functionality, workarounds exist. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix remove_stale_pushers job on SQLite. matrix-org/synapse
4 participants
@mlaily @DMRobertson @reivilibre and others