search

AsamK / signal-cli

signal-cli provides an unofficial commandline, JSON-RPC and dbus interface for the Signal messenger.
GNU General Public License v3.0
3.17k stars 301 forks source link

[SQLITE_BUSY] The database file is locked error since signal-cli 0.13.0 #1483

Closed Lukom closed 3 weeks ago

Lukom commented 7 months ago

I've started receiving [SQLITE_BUSY] The database file is locked error recently after update to signal-cli 0.13.0 and it fails on 0.13.1 as well. To reproduce just run this:

JAVA_HOME=/usr/local/Cellar/openjdk/21.0.2/libexec/openjdk.jdk/Contents/Home /Users/username/Downloads/signal-cli-0.13.1/bin/signal-cli -a +380631234567 --output json daemon --socket

and after couple of minutes it happens (there should be also some messages flying around for this to happen). It shows such error in output:

java.lang.RuntimeException: Failed read from session store
...
Caused by: org.sqlite.SQLiteException: [SQLITE_BUSY] The database file is locked (database is locked)
...

full output is here: https://gist.github.com/Lukom/71fbd2f643b32a12a253beee5b1b452a

It happens on my macbook and on Ubuntu 22 server as well, both openjdk-21. On Ubuntu server I have a lot of traffic inside signal and this error is triggered every 2 minutes. I'm sure I have enough space on devices, and also there are no any tricky manipulations with session database - everything was working fine before 0.13.0.

I've found similar closed issues: SQLITE_BUSY The database file is locked (database is locked) SQLite locks when messages are sent concurrently but suggested fix of adding --disable-send-log isn't helping.

Lukom commented 3 months ago

I've tried v0.13.4 on another macbook – it's not linking the device, it throws this error:

❯ java --version
openjdk 22.0.1 2024-04-16
OpenJDK Runtime Environment Homebrew (build 22.0.1)
OpenJDK 64-Bit Server VM Homebrew (build 22.0.1, mixed mode, sharing)
❯ signal-cli-0.13.4/bin/signal-cli link -n "some-name" | tee >(xargs -L 1 qrencode -t utf8)
...
(after scanning QR-code)
INFO  ProvisioningManagerImpl - Received link information from +380631234567, linking in progress ...
io.reactivex.rxjava3.exceptions.OnErrorNotImplementedException: The exception was not handled due to missing onError handler in the subscribe() method call. Further reading: https://github.com/ReactiveX/RxJava/wiki/Error-Handling | java.lang.RuntimeException: Failed update session store
    at io.reactivex.rxjava3.internal.functions.Functions$OnErrorMissingConsumer.accept(Functions.java:718)
    at io.reactivex.rxjava3.internal.functions.Functions$OnErrorMissingConsumer.accept(Functions.java:715)
    at io.reactivex.rxjava3.internal.observers.LambdaObserver.onError(LambdaObserver.java:77)
    at io.reactivex.rxjava3.internal.observers.LambdaObserver.onNext(LambdaObserver.java:67)
    at io.reactivex.rxjava3.internal.operators.observable.ObservableObserveOn$ObserveOnObserver.drainNormal(ObservableObserveOn.java:201)
    at io.reactivex.rxjava3.internal.operators.observable.ObservableObserveOn$ObserveOnObserver.run(ObservableObserveOn.java:255)
    at io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:322)
    at io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.runEager(ExecutorScheduler.java:287)
    at io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:248)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
    at java.base/java.lang.Thread.run(Thread.java:1570)
Caused by: java.lang.RuntimeException: Failed update session store
    at org.asamk.signal.manager.storage.sessions.SessionStore.archiveSessions(SessionStore.java:283)
    at org.asamk.signal.manager.internal.ManagerImpl.lambda$new$1(ManagerImpl.java:213)
    at io.reactivex.rxjava3.internal.observers.LambdaObserver.onNext(LambdaObserver.java:63)
    ... 8 more
Caused by: org.sqlite.SQLiteException: [SQLITE_BUSY] The database file is locked (database is locked)
    at org.sqlite.core.DB.newSQLException(DB.java:1179)
    at org.sqlite.core.DB.newSQLException(DB.java:1190)
    at org.sqlite.core.DB.throwex(DB.java:1150)
    at org.sqlite.core.DB.exec(DB.java:198)
    at org.sqlite.SQLiteConnection.setAutoCommit(SQLiteConnection.java:369)
    at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:402)
    at com.zaxxer.hikari.pool.HikariProxyConnection.setAutoCommit(HikariProxyConnection.java)
    at org.asamk.signal.manager.storage.sessions.SessionStore.archiveSessions(SessionStore.java:267)
    ... 10 more
Exception in thread "pool-1-thread-1" io.reactivex.rxjava3.exceptions.OnErrorNotImplementedException: The exception was not handled due to missing onError handler in the subscribe() method call. Further reading: https://github.com/ReactiveX/RxJava/wiki/Error-Handling | java.lang.RuntimeException: Failed update session store
    at io.reactivex.rxjava3.internal.functions.Functions$OnErrorMissingConsumer.accept(Functions.java:718)
    at io.reactivex.rxjava3.internal.functions.Functions$OnErrorMissingConsumer.accept(Functions.java:715)
    at io.reactivex.rxjava3.internal.observers.LambdaObserver.onError(LambdaObserver.java:77)
    at io.reactivex.rxjava3.internal.observers.LambdaObserver.onNext(LambdaObserver.java:67)
    at io.reactivex.rxjava3.internal.operators.observable.ObservableObserveOn$ObserveOnObserver.drainNormal(ObservableObserveOn.java:201)
    at io.reactivex.rxjava3.internal.operators.observable.ObservableObserveOn$ObserveOnObserver.run(ObservableObserveOn.java:255)
    at io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:322)
    at io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.runEager(ExecutorScheduler.java:287)
    at io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:248)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
    at java.base/java.lang.Thread.run(Thread.java:1570)
Caused by: java.lang.RuntimeException: Failed update session store
    at org.asamk.signal.manager.storage.sessions.SessionStore.archiveSessions(SessionStore.java:283)
    at org.asamk.signal.manager.internal.ManagerImpl.lambda$new$1(ManagerImpl.java:213)
    at io.reactivex.rxjava3.internal.observers.LambdaObserver.onNext(LambdaObserver.java:63)
    ... 8 more
Caused by: org.sqlite.SQLiteException: [SQLITE_BUSY] The database file is locked (database is locked)
    at org.sqlite.core.DB.newSQLException(DB.java:1179)
    at org.sqlite.core.DB.newSQLException(DB.java:1190)
    at org.sqlite.core.DB.throwex(DB.java:1150)
    at org.sqlite.core.DB.exec(DB.java:198)
    at org.sqlite.SQLiteConnection.setAutoCommit(SQLiteConnection.java:369)
    at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:402)
    at com.zaxxer.hikari.pool.HikariProxyConnection.setAutoCommit(HikariProxyConnection.java)
    at org.asamk.signal.manager.storage.sessions.SessionStore.archiveSessions(SessionStore.java:267)
    ... 10 more
WARN  JobExecutor - Job SyncStorageJob failed
java.lang.RuntimeException: Failed read from group store
    at org.asamk.signal.manager.storage.groups.GroupStore.getGroup(GroupStore.java:207)
    at org.asamk.signal.manager.storage.groups.GroupStore.getGroupOrPartialMigrate(GroupStore.java:274)
    at org.asamk.signal.manager.storage.groups.GroupStore.getGroupOrPartialMigrate(GroupStore.java:258)
    at org.asamk.signal.manager.syncStorage.GroupV2RecordProcessor.updateLocal(GroupV2RecordProcessor.java:93)
    at org.asamk.signal.manager.syncStorage.GroupV2RecordProcessor.insertLocal(GroupV2RecordProcessor.java:85)
    at org.asamk.signal.manager.syncStorage.GroupV2RecordProcessor.insertLocal(GroupV2RecordProcessor.java:16)
    at org.asamk.signal.manager.syncStorage.DefaultStorageRecordProcessor.process(DefaultStorageRecordProcessor.java:53)
    at org.asamk.signal.manager.syncStorage.GroupV2RecordProcessor.process(GroupV2RecordProcessor.java:16)
    at org.asamk.signal.manager.helper.StorageHelper.processKnownRecords(StorageHelper.java:537)
    at org.asamk.signal.manager.helper.StorageHelper.readDataFromStorage(StorageHelper.java:175)
    at org.asamk.signal.manager.helper.StorageHelper.syncDataWithStorage(StorageHelper.java:92)
    at org.asamk.signal.manager.jobs.SyncStorageJob.run(SyncStorageJob.java:17)
    at org.asamk.signal.manager.internal.JobExecutor.lambda$runNextJob$0(JobExecutor.java:59)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
    at java.base/java.lang.Thread.run(Thread.java:1570)
Caused by: org.sqlite.SQLiteException: [SQLITE_BUSY] The database file is locked (database is locked)
    at org.sqlite.core.DB.newSQLException(DB.java:1179)
    at org.sqlite.core.DB.newSQLException(DB.java:1190)
    at org.sqlite.core.DB.execute(DB.java:985)
    at org.sqlite.jdbc3.JDBC3PreparedStatement.lambda$executeQuery$1(JDBC3PreparedStatement.java:92)
    at org.sqlite.jdbc3.JDBC3Statement.withConnectionTimeout(JDBC3Statement.java:454)
    at org.sqlite.jdbc3.JDBC3PreparedStatement.executeQuery(JDBC3PreparedStatement.java:87)
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
    at org.asamk.signal.manager.storage.Utils.executeQueryForOptional(Utils.java:87)
    at org.asamk.signal.manager.storage.groups.GroupStore.getGroup(GroupStore.java:573)
    at org.asamk.signal.manager.storage.groups.GroupStore.getGroup(GroupStore.java:221)
    at org.asamk.signal.manager.storage.groups.GroupStore.getGroup(GroupStore.java:205)
    ... 15 common frames omitted
Associated with: +380631234567

Also since I've tried this on different machines and with 2 different accounts I suspect that the reason could be in some Groups which belong to both accounts I'm using. These couple of groups are big ~900 users each.

AsamK commented 3 weeks ago

Thanks for reporting! I found the cause for the database lock. Should be fixed in the next version.