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

Intermittent sqlite3.OperationalError: table background_updates already exists on startup #14460

Closed
Yoric opened this issue Nov 16, 2022 · 11 comments
Closed

Intermittent sqlite3.OperationalError: table background_updates already exists on startup #14460

Yoric opened this issue Nov 16, 2022 · 11 comments
Labels
A-Database DB stuff like queries, migrations, new/remove columns, indexes, unexpected entries in the db A-SQLite Database issues specific to SQLite O-Uncommon Most users are unlikely to come across this or unexpected workflow S-Tolerable Minor significance, cosmetic issues, low or no impact to users. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. Z-Dev-Wishlist Makes developers' lives better, but doesn't have direct user impact

Comments

@Yoric
Copy link
Contributor

Yoric commented Nov 16, 2022 •
edited
Loading

Description

I'm using Synapse in CI for testing a variety of tools (bots, modules, AppServices).

Recently, I've been seeing error sqlite3.OperationalError: table background_updates already exists on some startups of Synapse. It seems non-deterministic but it makes my life quite complicated, as my CI may fail for reasons unrelated to the code I'm testing.

Reproduced on GitLab CI and GitHub CI.

Steps to reproduce

Trying to find simple STRs.

Right now, the simplest I have is that https://github.com/matrix-org/mx-tester/ on CI sometimes exhibits the problem, e.g. https://github.com/matrix-org/mx-tester/actions/runs/3478612923 .

Homeserver

CI

Synapse Version

1.71.0

Installation Method

No response

Platform

Running on a container created with the following Dockerfile.

# A custom Dockerfile to rebuild synapse from the official release + plugins

FROM matrixdotorg/synapse:latest

VOLUME ["/data", "/conf/workers", "/etc/nginx/conf.d", "/etc/supervisor/conf.d", "/var/log/workers"]

# We're not running as root, to avoid messing up with the host
# filesystem, so we need a proper user. We give it the current
# use's uid to make sure that files written by this Docker image
# can be read and removed by the host's user.
# Note that we need tty to workaround the following Docker issue:
# https://github.com/moby/moby/issues/31243#issuecomment-406825071
RUN useradd mx-tester --uid 1001 --groups sudo,tty

# Add a password, to be able to run sudo. We'll use it to
# chmod files.
RUN echo "mx-tester:password" | chpasswd

# Show the Synapse version, to aid with debugging.
RUN pip show matrix-synapse



# Copy and install custom modules.
RUN mkdir /mx-tester






ENTRYPOINT []

EXPOSE 8008/tcp 8009/tcp 8448/tcp

Relevant log output

2022-11-16 10:44:42,541 - root - 345 - WARNING - main - ***** STARTING SERVER *****
2022-11-16 10:44:42,543 - root - 346 - WARNING - main - Server /usr/local/lib/python3.9/site-packages/synapse/app/homeserver.py version 1.71.0
2022-11-16 10:44:42,543 - root - 351 - INFO - main - Server hostname: localhost:4349
2022-11-16 10:44:42,544 - root - 352 - INFO - main - Instance name: master
2022-11-16 10:44:42,544 - root - 353 - INFO - main - Twisted reactor: EPollReactor
2022-11-16 10:44:42,545 - synapse.app.homeserver - 364 - INFO - main - Setting up server
2022-11-16 10:44:42,546 - synapse.server - 307 - INFO - main - Setting up.
2022-11-16 10:44:42,547 - synapse.storage.databases - 66 - INFO - main - [database config 'master']: Checking database server
2022-11-16 10:44:42,548 - synapse.storage.databases - 69 - INFO - main - [database config 'master']: Preparing for databases ['main', 'state']
2022-11-16 10:44:42,549 - synapse.storage.prepare_database - 115 - INFO - main - ['main', 'state']: Checking existing schema version
2022-11-16 10:44:42,551 - synapse.storage.prepare_database - 145 - INFO - main - ['main', 'state']: Initialising new database
2022-11-16 10:44:42,552 - synapse.app._base - 205 - ERROR - main - Exception during startup
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/synapse/app/homeserver.py", line 367, in setup
    hs.setup()
  File "/usr/local/lib/python3.9/site-packages/synapse/server.py", line 309, in setup
    self.datastores = Databases(self.DATASTORE_CLASS, self)
  File "/usr/local/lib/python3.9/site-packages/synapse/storage/databases/__init__.py", line 74, in __init__
    prepare_database(
  File "/usr/local/lib/python3.9/site-packages/synapse/storage/prepare_database.py", line 152, in prepare_database
    _setup_new_database(cur, database_engine, databases=databases)
  File "/usr/local/lib/python3.9/site-packages/synapse/storage/prepare_database.py", line 269, in _setup_new_database
    database_engine.execute_script_file(cur, entry.absolute_path)
  File "/usr/local/lib/python3.9/site-packages/synapse/storage/engines/_base.py", line 145, in execute_script_file
    cls.executescript(cursor, f.read())
  File "/usr/local/lib/python3.9/site-packages/synapse/storage/engines/sqlite.py", line 144, in executescript
    cursor.executescript(script)
  File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 395, in executescript
    self._do_execute(self.txn.executescript, sql)  # type: ignore[attr-defined]
  File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 436, in _do_execute
    return func(sql, *args, **kwargs)
sqlite3.OperationalError: table background_updates already exists
********************************************
 Error during initialisation:
    table background_updates already exists
 There may be more information in the logs.
********************************************

Anything else that would be useful to know?

No response
@Yoric
Copy link
Contributor Author

Yoric commented Nov 16, 2022 •
edited
Loading

homeserver.yaml

server_name: localhost:9999
pid_file: /data/homeserver.pid
listeners:
- port: 8008
  tls: false
  type: http
  bind_addresses:
  - '::'
  x_forwarded: false
  resources:
  - names:
    - client
    compress: true
  - names:
    - federation
    compress: false
database:
  name: sqlite3
  args:
    database: /data/homeserver.db
log_config: /data/localhost:9999.log.config
media_store_path: /data/media_store
registration_shared_secret: XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
report_stats: false
macaroon_secret_key: XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
form_secret: XXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
signing_key_path: /data/localhost:9999.signing.key
trusted_key_servers:
- server_name: matrix.org
public_baseurl: http://localhost:9999
enable_registration_without_verification: true
app_service_config_files:
- /appservice/integration.yml
rc_message:
  per_second: 1000000000
  burst_count: 1000000000
rc_registration:
  per_second: 1000000000
  burst_count: 1000000000
rc_admin_redaction:
  per_second: 1000000000
  burst_count: 1000000000
rc_login:
  address:
    per_second: 1000000000
    burst_count: 1000000000
  account:
    per_second: 1000000000
    burst_count: 1000000000
  failed_attempts:
    per_second: 1000000000
    burst_count: 1000000000
rc_invites:
  per_room:
    per_second: 1000000000
    burst_count: 1000000000
  per_user:
    per_second: 1000000000
    burst_count: 1000000000
  per_sender:
    per_second: 1000000000
    burst_count: 1000000000
modules: []

@Yoric
Copy link
Contributor Author

Yoric commented Nov 16, 2022 •
edited
Loading

Also witnessed on Mjölnir CI a few times:

These instances also make use of mx-tester (as we're using mx-tester for everything), so it's possible that mx-tester is the culprit.

@DMRobertson
Copy link
Contributor

Does your setup persist and reuse the database in any way?

@Yoric
Copy link
Contributor Author

Yoric commented Nov 16, 2022 •
edited
Loading

Does your setup persist and reuse the database in any way?

Not as far as I can tell. I do not go to specific lengths to ensure that there is no database file, though.

@DMRobertson DMRobertson added S-Tolerable Minor significance, cosmetic issues, low or no impact to users. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. A-Database DB stuff like queries, migrations, new/remove columns, indexes, unexpected entries in the db Z-Dev-Wishlist Makes developers' lives better, but doesn't have direct user impact O-Uncommon Most users are unlikely to come across this or unexpected workflow A-SQLite Database issues specific to SQLite labels Nov 17, 2022
@Yoric
Copy link
Contributor Author

Yoric commented Nov 18, 2022

@DMRobertson Shouldn't this work even when there is a database, though?

@DMRobertson
Copy link
Contributor

Yes. But it's possible Synapse might have been killed midway through enforcing a schema dump, which is the only way I can imagine this state arising. We should make the db migrations transactional (cf #14401)

Yoric added a commit to matrix-org/mx-tester that referenced this issue Dec 12, 2022
@Yoric
Work harder at cleaning up leftovers, in an attempt to work around "t…
28e5201 
…able background_updates already exists"

We regularly encounter issue matrix-org/synapse#14460

This PR attempts harder to cleanup leftovers from previous runs, in particular `homeserver.db`,
hoping that this will help make startup more reliable.
Yoric added a commit to matrix-org/mx-tester that referenced this issue Dec 12, 2022
@Yoric
Work harder at cleaning up leftovers, in an attempt to work around "t…
abe75e4 
…able background_updates already exists"

We regularly encounter issue matrix-org/synapse#14460

This PR attempts harder to cleanup leftovers from previous runs, in particular `homeserver.db`,
hoping that this will help make startup more reliable.
Yoric added a commit to matrix-org/mx-tester that referenced this issue Dec 12, 2022
@Yoric
Work harder at cleaning up leftovers, in an attempt to work around "t…
ab9f9e2 
…able background_updates already exists"

We regularly encounter issue matrix-org/synapse#14460

This PR attempts harder to cleanup leftovers from previous runs, in particular `homeserver.db`,
hoping that this will help make startup more reliable.
Yoric added a commit to matrix-org/mx-tester that referenced this issue Dec 12, 2022
@Yoric
Work harder at cleaning up leftovers, in an attempt to work around "t…
cedcdb3 
…able background_updates already exists"

We regularly encounter issue matrix-org/synapse#14460

This PR attempts harder to cleanup leftovers from previous runs, in particular `homeserver.db`,
hoping that this will help make startup more reliable.
@Yoric
Copy link
Contributor Author

Yoric commented Dec 19, 2022

I've seen this happen more and more often.

Is there a way to make sure that all databases are created properly before shutting down an instance of Synapse?

@squahtx
Copy link
Contributor

squahtx commented Dec 19, 2022

By the time synapse.server - 310 - INFO - main - Finished setting up. is printed, the database has been initialized for the first time. This is very early on, before Synapse even starts accepting requests. Are you sure you're killing Synapse that early in CI?

@Yoric
Copy link
Contributor Author

Yoric commented Dec 19, 2022

I'm not sure, but that's what I'm investigating at the moment.

@richvdh
Copy link
Member

richvdh commented Jan 21, 2023

This feels a bit like #6467, but we fixed that...

@richvdh richvdh changed the title Irregular sqlite3.OperationalError: table background_updates already exists on startup Intermittent sqlite3.OperationalError: table background_updates already exists on startup Jan 21, 2023
@squahtx squahtx mentioned this issue Jan 24, 2023
Closed
@squahtx
Copy link
Contributor

squahtx commented Jan 24, 2023

I'm going to assume that this is due to a combination of #14909 (#6467 regression) and CI killing and restarting Synapse.

I shall close this in favour of #14909.

@squahtx squahtx closed this as not planned Won't fix, can't repro, duplicate, stale Jan 24, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
A-Database DB stuff like queries, migrations, new/remove columns, indexes, unexpected entries in the db A-SQLite Database issues specific to SQLite O-Uncommon Most users are unlikely to come across this or unexpected workflow S-Tolerable Minor significance, cosmetic issues, low or no impact to users. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. Z-Dev-Wishlist Makes developers' lives better, but doesn't have direct user impact
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@Yoric @richvdh @squahtx @DMRobertson