Every one to three hours at xx:05 'rocket-worker-thread' panicked at 'Error loading xxxx: DatabaseError(__Unknown, "database is locked")'

[firecat53]

Every one to three hours at 5 minutes after the hour, I get the following error:

Apr 25 14:05:29 homeserver docker[2998144]: [2022-04-25 14:05:29.567][panic][ERROR] thread 'rocket-worker-thread' panicked at 
'Error loading emergency_access: DatabaseError(__Unknown, "database is locked")': src/db/models/emergency_access.rs:241
Apr 25 14:05:29 homeserver docker[2998144]:    0: vaultwarden::init_logging::{{closure}}
Apr 25 14:05:29 homeserver docker[2998144]:    1: std::panicking::rust_panic_with_hook
Apr 25 14:05:29 homeserver docker[2998144]:    2: std::panicking::begin_panic_handler::{{closure}}
Apr 25 14:05:29 homeserver docker[2998144]:    3: std::sys_common::backtrace::__rust_end_short_backtrace
Apr 25 14:05:29 homeserver docker[2998144]:    4: rust_begin_unwind
Apr 25 14:05:29 homeserver docker[2998144]:    5: core::panicking::panic_fmt
Apr 25 14:05:29 homeserver docker[2998144]:    6: core::result::unwrap_failed
Apr 25 14:05:29 homeserver docker[2998144]:    7: tokio::runtime::enter::exit
Apr 25 14:05:29 homeserver docker[2998144]:    8: tokio::runtime::thread_pool::worker::block_in_place
Apr 25 14:05:29 homeserver docker[2998144]:    9: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
Apr 25 14:05:29 homeserver docker[2998144]:   10: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
Apr 25 14:05:29 homeserver docker[2998144]:   11: tokio::runtime::task::harness::poll_future
Apr 25 14:05:29 homeserver docker[2998144]:   12: tokio::runtime::task::harness::Harness<T,S>::poll
Apr 25 14:05:29 homeserver docker[2998144]:   13: std::thread::local::LocalKey<T>::with
Apr 25 14:05:29 homeserver docker[2998144]:   14: tokio::runtime::thread_pool::worker::Context::run_task
Apr 25 14:05:29 homeserver docker[2998144]:   15: tokio::runtime::thread_pool::worker::Context::run
Apr 25 14:05:29 homeserver docker[2998144]:   16: tokio::macros::scoped_tls::ScopedKey<T>::set
Apr 25 14:05:29 homeserver docker[2998144]:   17: tokio::runtime::thread_pool::worker::run
Apr 25 14:05:29 homeserver docker[2998144]:   18: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll
Apr 25 14:05:29 homeserver docker[2998144]:   19: tokio::runtime::task::harness::Harness<T,S>::poll
Apr 25 14:05:29 homeserver docker[2998144]:   20: tokio::runtime::blocking::pool::Inner::run
Apr 25 14:05:29 homeserver docker[2998144]:   21: std::sys_common::backtrace::__rust_begin_short_backtrace
Apr 25 14:05:29 homeserver docker[2998144]:   22: core::ops::function::FnOnce::call_once{{vtable.shim}}
Apr 25 14:05:29 homeserver docker[2998144]:   23: std::sys::unix::thread::Thread::new::thread_start
Apr 25 14:05:29 homeserver docker[2998144]:   24: start_thread
Apr 25 14:05:29 homeserver docker[2998144]:   25: clone

• Vaultwarden is running in a docker container built from the Dockerfiles for the web vault and vaultwarden on Github.
• There are no services or timers running on the host at xx:05 and I am the only user.
• The error always occurs at xx:05, no matter when the container has been restarted.
• The sqlite file is in a Docker volume which is local to the server.
• The container runs behind traefik and is accessible from the local LAN only.
• The service continues running and does not appear to restart the container or otherwise affect the functionality.
• Service file:

# /etc/systemd/system/vaultwarden.service
[Unit]
Description=Vaultwarden container
After=docker.service
Requires=docker.service

[Service]
Restart=always
RestartSec=10
ExecStartPre=-/usr/bin/docker rm vaultwarden_run
ExecStart=/usr/bin/docker run \
-e DOMAIN=https://domain.lan.net \
-e ROCKET_PORT=8080 \
--mount type=volume,source=bitwarden_data,target=/data \
-u 1000:100 \
-v /etc/localtime:/etc/localtime:ro \
-l traefik.enable=true \
-l traefik.http.routers.vaultwarden-run.rule=Host(`domain.lan.net`)  \
-l traefik.http.routers.vaultwarden-run.entrypoints=websecure \
-l traefik.http.routers.vaultwarden-run.tls.certResolver=le \
-l traefik.http.routers.vaultwarden-run.middlewares=headers \
-l traefik.http.services.vaultwarden-run.loadbalancer.server.port=8080 \
--init \
--name vaultwarden_run \
vaultwarden:latest
ExecStop=/usr/bin/docker stop vaultwarden_run

[Install]
WantedBy=multi-user.target

Any ideas what could be causing this? Is it worthy of a bug report?

Thanks!

[BlackDex]

Could you try the latest testing tagged version to see if that solves the issue.

[firecat53]

I'm on the latest commit as of April 22nd. I'm not sure what you mean by latest testing tagged version, as I don't see a testing branch (unless I am truly blind!).

$ ./vaultwarden --version
vaultwarden 1.24.0-3abf173d

This has been going on for quite some time. Honestly not sure when it started, since it hasn't caused crashes or anything. I just noticed a week or so ago going through my server logs.

[BlackDex]

Strange, since the stuff you posted contained latest and not testing as the image which is used.

For some reason the database is locked/in use.

[firecat53]

Is there more I can check to give you better information? I build the image using the docker_image module with Ansible and restart it every time after a rebuild. These errors have been occurring at least as far back as April 5th (as far back as my journal goes). Rebuilds happen on any new vaultwarden or web vault tag.

The only hourly task on my server is a btrbk snapshot, but that is completing typically over 10 minutes before the vaultwarden errors.

No other processes or containers access the bitwarden_data volume except for a once-a-day backup using the sqlite3 .backup command.

What could possibly be accessing that file on such a regular basis?? That's so weird!

[jjlin]

Most of the Vaultwarden scheduled jobs are run 5 minutes after the hour, so there's no question at all about the timing, just why this issue has started happening since the async transition.

[firecat53]

Ahh, ok, thanks for the info! Should this be migrated to a bug report then, or just left here?

[BlackDex]

I was just looking at my logs, but doesn't look like I'm able to reproduce it.

It could be some query takes a long time and for some reasons holds the lock on the database.

For now to mitigate it i suggest to change the timings of those schedules to not take place at the exact same time.

What the environment variables are and what there defaults can be seen here https://github.com/dani-garcia/vaultwarden/blob/main/.env.template#L84..L100

I do have some thoughts on how you could try and debug it. But that would mean modifying some code and probably having a lot of extra logging. It will also make the instance slower because of this logging.

And other thing you could try to do now i think of it, is too try and VACUUM the database. You could do this your self, or use the backup function located into the /admin interface. After the backup is created you need to restore that backup which should be a vacuumed copy of the current running database. I do suggest to keep the original also btw, just rename it or something.

[jjlin]

I don't think the schedule should matter -- multiple jobs scheduled for the same time run serially anyway. The fact is this didn't seem to happen before the async transition, so it's most likely a side effect of that. I haven't had time so far to look into why, though.

[BlackDex]

Well they are spawned into an async task so i actually think they run parallel and not serial. Before async that wasn't the case at all.

[jjlin]

Hmm, I see. Well, that would explain why there are conflicts then. The default job schedules were designed with the intention of running serially, Perhaps a mutex should be added to serialize the execution then, as users ideally shouldn't need to understand that level of detail to avoid issues.

[BlackDex]

Ok, i did a quick test and set the scheduler to write every second something to the database and to the exact same table with 3 different scheduled jobs. During that writing i was also performing full syncs on two different users in a while-loop to stress the database, and i was downloading a lot of icons at the same time.

I was unable to exactly reproduce this specific issue, but, with my tests i didn't used a container, so that could be a difference here.

But, what i did found was that with the default settings, i would get a different amount of added entries from the 3 different functions. Which shouldn't be the case of course. A difference of 1 or 2 i can understand because i press ctrl+c and that could prevent one or two items from being added.

But... this seems to be solved if when i configured DATABASE_MAX_CONNS=1.
Now, for SQLite i can really understand that 1 is probably all we can get.

So, i suggest to try and change the config to add DATABASE_MAX_CONNS=1 and let us know if that works.
It could be a bug in the sqlite library, or in Diesel.

If i only were able to reproduce it, that would make it a lot easier.

[firecat53]

Nope, no snapshots during those times. The snapshots are done hourly but are finished typically 6-10 minutes before the vaultwarden errors.

[firecat53]

DATABASE_MAX_CONNS=1 seems to fix the issue. I'm guessing it's not a long term or scalable solution though?

Let me know if there's anything else I can do to help troubleshoot. Thanks!

[jjlin]

@firecat53 Since it seems you're able to easily reproduce this issue, it would help if you could build and test https://github.com/jjlin/vaultwarden/tree/db-conn-init. Make sure to first revert any changes to DATABASE_MAX_CONNS. Thanks.

[firecat53]

@jjlin That seems to work. Ran overnight with no errors!

[jjlin]

Great, thanks for the confirmation.