signal-cli
signal-cli copied to clipboard
AsamK
signal-cli in jsonRpc mode started consuming 100% CPU
I'm running signal-cli-rest-api with json-rpc mode. After some time (about 3 months) signal-cli starts consuming whole CPU, which causing slow responses, e.g. send command takes 5-30 minutes. In the same time in command-line mode it works as usual - no high CPU usage, send command takes 3-5 seconds.
The only thing which helps - wipe out signal-api account data and link device from scratch.
signal-cli version 0.13.5
CPU usage 97.4%
root@d537c7e30ae3:/# ps aux|grep java
signal-+ 40 97.4 2.8 8672972 240936 ? Sl 09:32 25:58 java -classpath /opt/signal-cli-0.13.5/lib/signal-cli-0.13.5.jar:/opt/signal-cli-0.13.5/lib/lib.jar:/opt/signal-cli-0.13.5/lib/bcprov-jdk18on-1.78.1.jar:/opt/signal-cli-0.13.5/lib/signal-service-java-2.15.3_unofficial_105.jar:/opt/signal-cli-0.13.5/lib/jackson-module-kotlin-2.17.2.jar:/opt/signal-cli-0.13.5/lib/jackson-annotations-2.17.2.jar:/opt/signal-cli-0.13.5/lib/jackson-core-2.17.2.jar:/opt/signal-cli-0.13.5/lib/jackson-databind-2.17.2.jar:/opt/signal-cli-0.13.5/lib/argparse4j-0.9.0.jar:/opt/signal-cli-0.13.5/lib/dbus-java-transport-native-unixsocket-5.0.0.jar:/opt/signal-cli-0.13.5/lib/jul-to-slf4j-2.0.13.jar:/opt/signal-cli-0.13.5/lib/logback-classic-1.5.6.jar:/opt/signal-cli-0.13.5/lib/dbus-java-core-5.0.0.jar:/opt/signal-cli-0.13.5/lib/sqlite-jdbc-3.46.0.0.jar:/opt/signal-cli-0.13.5/lib/HikariCP-5.1.0.jar:/opt/signal-cli-0.13.5/lib/slf4j-api-2.0.13.jar:/opt/signal-cli-0.13.5/lib/logback-core-1.5.6.jar:/opt/signal-cli-0.13.5/lib/jsr305-3.0.2.jar:/opt/signal-cli-0.13.5/lib/okhttp-4.12.0.jar:/opt/signal-cli-0.13.5/lib/wire-runtime-jvm-4.4.3.jar:/opt/signal-cli-0.13.5/lib/core-util-jvm-2.15.3_unofficial_105.jar:/opt/signal-cli-0.13.5/lib/kotlin-stdlib-jdk7-1.9.20.jar:/opt/signal-cli-0.13.5/lib/okio-jvm-3.9.0.jar:/opt/signal-cli-0.13.5/lib/kotlin-reflect-1.9.20.jar:/opt/signal-cli-0.13.5/lib/kotlin-stdlib-1.9.21.jar:/opt/signal-cli-0.13.5/lib/kotlin-stdlib-jdk8-1.9.20.jar:/opt/signal-cli-0.13.5/lib/libphonenumber-8.13.40.jar:/opt/signal-cli-0.13.5/lib/libsignal-client-0.52.2.jar:/opt/signal-cli-0.13.5/lib/rxjava-3.0.13.jar:/opt/signal-cli-0.13.5/lib/reactive-streams-1.0.3.jar:/opt/signal-cli-0.13.5/lib/annotations-13.0.jar org.asamk.signal.Main --output=json --config /home/.local/share/signal-cli/ jsonRpc
json-rpc send command debug
$ signal-cli --output=json --config /home/.local/share/signal-cli jsonRpc
{"jsonrpc":"2.0","method":"send","id":"8bb5d0ef-891e-44b8-adce-2d98671e93b1","params":{"recipient":["+RECIPIENT"],"message":"CURL vs mode json-rpc v0.84","notify-self":true,"account":"+ACCOUNT"}}
{"jsonrpc":"2.0","method":"receive","params":{"exception":{"message":"org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed","type":"ProtocolInvalidMessageException"},"envelope":{"source":"ANOTHER_NUMBER","sourceNumber":"ANOTHER_NUMBER","sourceUuid":"79f4d969-c699-45ca-9573-172af79d96b1","sourceName":"????? ?.","sourceDevice":1,"timestamp":1715959293759},"account":"+ACCOUNT"}}
{"jsonrpc":"2.0","result":{"timestamp":1718700182064,"results":[{"recipientAddress":{"uuid":"005ba546-2683-4b1f-aae6-50c20ca07dde","number":"+RECIPIENT"},"type":"SUCCESS"}]},"id":"8bb5d0ef-891e-44b8-adce-2d98671e93b1"}
{"jsonrpc":"2.0","result":{"timestamp":1718700247577,"results":[{"recipientAddress":{"uuid":"005ba546-2683-4b1f-aae6-50c20ca07dde","number":"+RECIPIENT"},"type":"SUCCESS"}]},"id":"8bb5d0ef-891e-44b8-adce-2d98671e93b1"}
{"jsonrpc":"2.0","method":"receive","params":{"exception":{"message":"org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed","type":"ProtocolInvalidMessageException"},"envelope":{"source":"ANOTHER_NUMBER","sourceNumber":"ANOTHER_NUMBER","sourceUuid":"79f4d969-c699-45ca-9573-172af79d96b1","sourceName":"????? ?.","sourceDevice":1,"timestamp":1715959293793},"account":"+ACCOUNT"}}
Here is related issue in signal-cli-rest-api repo
Please let me know if any additional information needed.
Not much to go on here.
Please run the signal-cli command with -vv parameter to get more detailed logging.
Start signal-cli in jsonRpc mode with -vvv verbosity
$ signal-cli -vvv --output=json --config /home/.local/share/signal-cli jsonRpc
2024-09-21T10:47:01.049Z [main] DEBUG java.lang.ProcessBuilder - ProcessBuilder.start(): pid: 551, dir: null, cmd: "/usr/bin/sh" "-c" "stty -a < /dev/tty"
java.lang.RuntimeException: ProcessBuilder.start() debug
at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1147)
at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1089)
at net.sourceforge.argparse4j.internal.TerminalWidth.getTerminalWidth2(TerminalWidth.java:74)
at net.sourceforge.argparse4j.internal.TerminalWidth.getTerminalWidth(TerminalWidth.java:54)
at net.sourceforge.argparse4j.ArgumentParserBuilder.getFormatWidth(ArgumentParserBuilder.java:282)
at net.sourceforge.argparse4j.ArgumentParserBuilder.config(ArgumentParserBuilder.java:270)
at net.sourceforge.argparse4j.ArgumentParserBuilder.build(ArgumentParserBuilder.java:264)
at org.asamk.signal.App.buildArgumentParser(App.java:52)
at org.asamk.signal.Main.main(Main.java:51)
2024-09-21T10:47:01.152Z [main] DEBUG org.asamk.signal.util.IOUtils - XDG_RUNTIME_DIR not set, falling back to temp dir
2024-09-21T10:47:01.179Z [main] DEBUG org.asamk.signal.App - Starting signal-cli 0.13.5
2024-09-21T10:47:01.890Z [main] TRACE org.asamk.signal.manager.Manager - Expected exception when checking libsignal-client: Failed to deserialize zkgroup::api::groups::uuid_ciphertext::UuidCiphertext
2024-09-21T10:47:02.208Z [main] TRACE o.a.s.manager.storage.SignalAccount - Opening account file
2024-09-21T10:47:02.214Z [main] TRACE o.a.s.manager.storage.SignalAccount - Loading account file 274284
2024-09-21T10:47:02.400Z [main] DEBUG com.zaxxer.hikari.HikariConfig - HikariPool-1 - configuration:
2024-09-21T10:47:02.433Z [main] DEBUG com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
2024-09-21T10:47:02.435Z [main] DEBUG com.zaxxer.hikari.HikariConfig - autoCommit......................true
2024-09-21T10:47:02.435Z [main] DEBUG com.zaxxer.hikari.HikariConfig - catalog.........................none
2024-09-21T10:47:02.436Z [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionInitSql..............."PRAGMA foreign_keys=ON"
2024-09-21T10:47:02.437Z [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
2024-09-21T10:47:02.441Z [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionTimeout...............30000
2024-09-21T10:47:02.442Z [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSource......................none
2024-09-21T10:47:02.443Z [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none
2024-09-21T10:47:02.444Z [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
2024-09-21T10:47:02.446Z [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceProperties............{open_mode=70, transaction_mode=IMMEDIATE, password=<masked>, date_precision=MILLISECONDS, busy_timeout=60000, date_string_format=yyyy-MM-dd HH:mm:ss.SSS, jdbc.explicit_readonly=false, date_class=INTEGER, shared_cache=false}
2024-09-21T10:47:02.447Z [main] DEBUG com.zaxxer.hikari.HikariConfig - driverClassName.................none
2024-09-21T10:47:02.448Z [main] DEBUG com.zaxxer.hikari.HikariConfig - exceptionOverrideClassName......none
2024-09-21T10:47:02.449Z [main] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
2024-09-21T10:47:02.450Z [main] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
2024-09-21T10:47:02.451Z [main] DEBUG com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
2024-09-21T10:47:02.452Z [main] DEBUG com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
2024-09-21T10:47:02.453Z [main] DEBUG com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
2024-09-21T10:47:02.455Z [main] DEBUG com.zaxxer.hikari.HikariConfig - jdbcUrl.........................jdbc:sqlite:/home/.local/share/signal-cli/data/274284.d/account.db
2024-09-21T10:47:02.456Z [main] DEBUG com.zaxxer.hikari.HikariConfig - keepaliveTime...................0
2024-09-21T10:47:02.458Z [main] DEBUG com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........0
2024-09-21T10:47:02.459Z [main] DEBUG com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
2024-09-21T10:47:02.460Z [main] DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize.................10
2024-09-21T10:47:02.460Z [main] DEBUG com.zaxxer.hikari.HikariConfig - metricRegistry..................none
2024-09-21T10:47:02.462Z [main] DEBUG com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
2024-09-21T10:47:02.462Z [main] DEBUG com.zaxxer.hikari.HikariConfig - minimumIdle.....................1
2024-09-21T10:47:02.463Z [main] DEBUG com.zaxxer.hikari.HikariConfig - password........................<masked>
2024-09-21T10:47:02.464Z [main] DEBUG com.zaxxer.hikari.HikariConfig - poolName........................"HikariPool-1"
2024-09-21T10:47:02.466Z [main] DEBUG com.zaxxer.hikari.HikariConfig - readOnly........................false
2024-09-21T10:47:02.467Z [main] DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans..................false
2024-09-21T10:47:02.467Z [main] DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
2024-09-21T10:47:02.468Z [main] DEBUG com.zaxxer.hikari.HikariConfig - schema..........................none
2024-09-21T10:47:02.468Z [main] DEBUG com.zaxxer.hikari.HikariConfig - threadFactory...................internal
2024-09-21T10:47:02.469Z [main] DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............default
2024-09-21T10:47:02.469Z [main] DEBUG com.zaxxer.hikari.HikariConfig - username........................none
2024-09-21T10:47:02.469Z [main] DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
2024-09-21T10:47:02.508Z [main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
2024-09-21T10:47:02.528Z [main] DEBUG c.z.hikari.util.DriverDataSource - Loaded driver with class name org.sqlite.JDBC for jdbcUrl=jdbc:sqlite:/home/.local/share/signal-cli/data/274284.d/account.db
2024-09-21T10:47:02.606Z [main] DEBUG java.lang.ProcessBuilder - ProcessBuilder.start(): pid: 560, dir: null, cmd: "uname" "-o"
java.lang.RuntimeException: ProcessBuilder.start() debug
at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1147)
at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1089)
at java.base/java.lang.Runtime.exec(Runtime.java:681)
at java.base/java.lang.Runtime.exec(Runtime.java:491)
at java.base/java.lang.Runtime.exec(Runtime.java:366)
at org.sqlite.util.ProcessRunner.runAndWaitFor(ProcessRunner.java:10)
at org.sqlite.util.OSInfo.isAndroidTermux(OSInfo.java:125)
at org.sqlite.util.OSInfo.isAndroid(OSInfo.java:116)
at org.sqlite.util.OSInfo.translateOSNameToFolderName(OSInfo.java:261)
at org.sqlite.util.OSInfo.getOSName(OSInfo.java:112)
at org.sqlite.util.OSInfo.getNativeLibFolderPathForCurrentOS(OSInfo.java:108)
at org.sqlite.util.LibraryLoaderUtil.getNativeLibResourcePath(LibraryLoaderUtil.java:16)
at org.sqlite.SQLiteJDBCLoader.loadSQLiteNativeLibrary(SQLiteJDBCLoader.java:322)
at org.sqlite.SQLiteJDBCLoader.initialize(SQLiteJDBCLoader.java:75)
at org.sqlite.core.NativeDB.load(NativeDB.java:69)
at org.sqlite.SQLiteConnection.open(SQLiteConnection.java:280)
at org.sqlite.SQLiteConnection.<init>(SQLiteConnection.java:67)
at org.sqlite.jdbc3.JDBC3Connection.<init>(JDBC3Connection.java:28)
at org.sqlite.jdbc4.JDBC4Connection.<init>(JDBC4Connection.java:19)
at org.sqlite.JDBC.createConnection(JDBC.java:106)
at org.sqlite.JDBC.connect(JDBC.java:79)
at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:120)
at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:360)
at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:202)
at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:461)
at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:550)
at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:98)
at com.zaxxer.hikari.HikariDataSource.<init>(HikariDataSource.java:80)
at org.asamk.signal.manager.storage.Database.getHikariDataSource(Database.java:101)
at org.asamk.signal.manager.storage.Database.initDatabase(Database.java:32)
at org.asamk.signal.manager.storage.AccountDatabase.init(AccountDatabase.java:43)
at org.asamk.signal.manager.storage.SignalAccount.lambda$getAccountDatabase$24(SignalAccount.java:1275)
at org.asamk.signal.manager.storage.SignalAccount.getOrCreate(SignalAccount.java:1735)
at org.asamk.signal.manager.storage.SignalAccount.getAccountDatabase(SignalAccount.java:1273)
at org.asamk.signal.manager.storage.SignalAccount.lambda$getRecipientStore$10(SignalAccount.java:1239)
at org.asamk.signal.manager.storage.SignalAccount.getOrCreate(SignalAccount.java:1735)
at org.asamk.signal.manager.storage.SignalAccount.getRecipientStore(SignalAccount.java:1235)
at org.asamk.signal.manager.storage.recipients.RecipientTrustedResolver$RecipientTrustedResolverWrapper.resolveSelfRecipientTrusted(RecipientTrustedResolver.java:32)
at org.asamk.signal.manager.storage.SignalAccount.init(SignalAccount.java:367)
at org.asamk.signal.manager.storage.SignalAccount.load(SignalAccount.java:201)
at org.asamk.signal.manager.SignalAccountFiles.initManager(SignalAccountFiles.java:97)
at org.asamk.signal.manager.SignalAccountFiles.lambda$initMultiAccountManager$1(SignalAccountFiles.java:69)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
at java.base/java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1715)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
at java.base/java.util.stream.Nodes$CollectorTask.doLeaf(Nodes.java:2192)
at java.base/java.util.stream.Nodes$CollectorTask$OfRef.doLeaf(Nodes.java:2202)
at java.base/java.util.stream.AbstractTask.compute(AbstractTask.java:327)
at java.base/java.util.concurrent.CountedCompleter.exec(CountedCompleter.java:754)
at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387)
at java.base/java.util.concurrent.ForkJoinTask.invoke(ForkJoinTask.java:667)
at java.base/java.util.stream.Nodes.collect(Nodes.java:328)
at java.base/java.util.stream.ReferencePipeline.evaluateToNode(ReferencePipeline.java:111)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:570)
at java.base/java.util.stream.AbstractPipeline.evaluateToArrayNode(AbstractPipeline.java:260)
at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:616)
at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:622)
at java.base/java.util.stream.ReferencePipeline.toList(ReferencePipeline.java:627)
at org.asamk.signal.manager.SignalAccountFiles.initMultiAccountManager(SignalAccountFiles.java:77)
at org.asamk.signal.App.handleMultiLocalCommand(App.java:287)
at org.asamk.signal.App.handleCommand(App.java:164)
at org.asamk.signal.App.init(App.java:144)
at org.asamk.signal.Main.main(Main.java:56)
2024-09-21T10:47:02.898Z [main] INFO com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-21T10:47:02.904Z [main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
2024-09-21T10:47:02.941Z [main] TRACE o.a.s.m.storage.AccountDatabase - Current database version: 26 Program database version: 26
2024-09-21T10:47:02.987Z [main] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-21T10:47:03.006Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=1, active=1, idle=0, waiting=0)
2024-09-21T10:47:03.011Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup stats (total=1, active=1, idle=0, waiting=0)
2024-09-21T10:47:03.020Z [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.sqlite.jdbc4.JDBC4Connection@334fed60
2024-09-21T10:47:03.045Z [main] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-21T10:47:03.051Z [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=2, active=0, idle=2, waiting=0)
2024-09-21T10:47:06.532Z [main] DEBUG okhttp3.internal.http2.Http2 - >> CONNECTION 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a
2024-09-21T10:47:06.534Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000000 6 SETTINGS
2024-09-21T10:47:06.534Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000000 4 WINDOW_UPDATE
2024-09-21T10:47:06.536Z [main] DEBUG o.internal.concurrent.TaskRunner - Q10014 scheduled after 0 µs: OkHttp chat.signal.org
2024-09-21T10:47:06.538Z [main] DEBUG o.internal.concurrent.TaskRunner - Q10001 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-21T10:47:06.538Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10014 starting : OkHttp chat.signal.org
2024-09-21T10:47:06.539Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-21T10:47:06.540Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10001 run again after 45 s : OkHttp ConnectionPool
2024-09-21T10:47:06.540Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 1 ms: OkHttp ConnectionPool
2024-09-21T10:47:06.555Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000003 219 HEADERS END_HEADERS
2024-09-21T10:47:06.562Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000003 438 DATA END_STREAM
2024-09-21T10:47:06.737Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000000 18 SETTINGS
2024-09-21T10:47:06.738Z [OkHttp chat.signal.org] DEBUG o.internal.concurrent.TaskRunner - Q10011 scheduled after 0 µs: OkHttp chat.signal.org applyAndAckSettings
2024-09-21T10:47:06.738Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000000 4 WINDOW_UPDATE
2024-09-21T10:47:06.739Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000000 0 SETTINGS ACK
2024-09-21T10:47:06.769Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10011 starting : OkHttp chat.signal.org applyAndAckSettings
2024-09-21T10:47:06.770Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000003 64 HEADERS END_STREAM|END_HEADERS
2024-09-21T10:47:06.773Z [OkHttp chat.signal.org applyAndAckSettings] DEBUG o.internal.concurrent.TaskRunner - Q10013 scheduled after 0 µs: OkHttp chat.signal.org onSettings
2024-09-21T10:47:06.774Z [OkHttp chat.signal.org applyAndAckSettings] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000000 0 SETTINGS ACK
2024-09-21T10:47:06.775Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10011 finished run in 36 ms: OkHttp chat.signal.org applyAndAckSettings
2024-09-21T10:47:06.775Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10013 starting : OkHttp chat.signal.org onSettings
2024-09-21T10:47:06.775Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10013 finished run in 492 µs: OkHttp chat.signal.org onSettings
2024-09-21T10:47:06.778Z [main] DEBUG o.internal.concurrent.TaskRunner - Q10001 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-21T10:47:06.779Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-21T10:47:06.779Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10001 run again after 45 s : OkHttp ConnectionPool
2024-09-21T10:47:06.779Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 651 µs: OkHttp ConnectionPool
2024-09-21T10:47:06.789Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000005 25 HEADERS END_STREAM|END_HEADERS
2024-09-21T10:47:07.075Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000005 87 HEADERS END_HEADERS
2024-09-21T10:47:07.077Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000005 25 DATA END_STREAM
2024-09-21T10:47:07.078Z [main] DEBUG o.internal.concurrent.TaskRunner - Q10001 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-21T10:47:07.078Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-21T10:47:07.079Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10001 run again after 45 s : OkHttp ConnectionPool
2024-09-21T10:47:07.079Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 749 µs: OkHttp ConnectionPool
2024-09-21T10:47:07.108Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000007 25 HEADERS END_STREAM|END_HEADERS
2024-09-21T10:47:07.245Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000007 35 HEADERS END_HEADERS
2024-09-21T10:47:07.246Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000007 27 DATA END_STREAM
2024-09-21T10:47:07.247Z [main] DEBUG o.internal.concurrent.TaskRunner - Q10001 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-21T10:47:07.247Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-21T10:47:07.248Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10001 run again after 45 s : OkHttp ConnectionPool
2024-09-21T10:47:07.248Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 559 µs: OkHttp ConnectionPool
2024-09-21T10:47:07.279Z [receive-0] DEBUG o.a.s.manager.internal.ManagerImpl - Starting receiving messages
2024-09-21T10:47:07.584Z [receive-0] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:1002285469] connect()
2024-09-21T10:47:07.604Z [receive-0] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:311595524] connect()
2024-09-21T10:47:07.627Z [receive-0] TRACE o.a.s.manager.util.MessageCacheUtils - Reading cached envelope file with version 9 (current: 9)
2024-09-21T10:47:07.678Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-21T10:47:08.016Z [OkHttp https://chat.signal.org/...] DEBUG o.internal.concurrent.TaskRunner - Q10017 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-21T10:47:08.017Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10017 starting : OkHttp ConnectionPool
2024-09-21T10:47:08.019Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10017 run again after 300 s : OkHttp ConnectionPool
2024-09-21T10:47:08.020Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10017 finished run in 3 ms: OkHttp ConnectionPool
2024-09-21T10:47:08.030Z [OkHttp https://chat.signal.org/...] DEBUG o.internal.concurrent.TaskRunner - Q10020 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-21T10:47:08.031Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10020 starting : OkHttp ConnectionPool
2024-09-21T10:47:08.032Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10020 run again after 300 s : OkHttp ConnectionPool
2024-09-21T10:47:08.032Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10020 finished run in 732 µs: OkHttp ConnectionPool
2024-09-21T10:47:08.177Z [OkHttp https://chat.signal.org/...] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:1002285469] onOpen() connected
2024-09-21T10:47:08.178Z [RxComputationThreadPool-4] DEBUG o.a.s.m.i.SignalWebSocketHealthMonitor - WebSocket is now connected
2024-09-21T10:47:08.195Z [OkHttp https://chat.signal.org/...] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:311595524] onOpen() connected
2024-09-21T10:47:08.196Z [RxComputationThreadPool-5] DEBUG o.a.s.m.i.SignalWebSocketHealthMonitor - WebSocket is now connected
2024-09-21T10:47:33.016Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=2, active=0, idle=2, waiting=0)
2024-09-21T10:47:33.017Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup stats (total=2, active=0, idle=2, waiting=0)
2024-09-21T10:47:33.017Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2024-09-21T10:47:37.246Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000000 20 GOAWAY
2024-09-21T10:47:37.251Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10014 finished run in 31 s : OkHttp chat.signal.org
2024-09-21T10:47:38.181Z [Thread-1] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:1002285469] Sending keep alive...
2024-09-21T10:47:38.189Z [Thread-1] DEBUG o.internal.concurrent.TaskRunner - Q10018 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.189Z [Thread-1] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:311595524] Sending keep alive...
2024-09-21T10:47:38.189Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.189Z [Thread-1] DEBUG o.internal.concurrent.TaskRunner - Q10021 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.190Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.191Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10021 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.192Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10018 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.192Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 2 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.192Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 3 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.192Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.192Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.192Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 323 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:38.193Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 476 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:47:52.248Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-21T10:47:52.249Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 715 µs: OkHttp ConnectionPool
2024-09-21T10:48:03.017Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=2, active=0, idle=2, waiting=0)
2024-09-21T10:48:03.018Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup stats (total=2, active=0, idle=2, waiting=0)
2024-09-21T10:48:03.018Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2024-09-21T10:48:08.190Z [Thread-1] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:1002285469] Sending keep alive...
2024-09-21T10:48:08.191Z [Thread-1] DEBUG o.internal.concurrent.TaskRunner - Q10018 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.191Z [Thread-1] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:311595524] Sending keep alive...
2024-09-21T10:48:08.192Z [Thread-1] DEBUG o.internal.concurrent.TaskRunner - Q10021 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.192Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.192Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.194Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10018 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.194Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 2 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.194Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10021 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.195Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 2 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.195Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.195Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.195Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 184 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-21T10:48:08.195Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 202 µs: OkHttp WebSocket https://chat.signal.org/... writer
Just after start signal-cli is consuming 100% CPU
$ ps -w -p 2256079 -o %cpu,%mem,cmd
%CPU %MEM CMD
105 2.7 java -classpath /opt/signal-cli-0.13.5/lib/signal-cli-0.13.5.jar:/opt/signal-cli-0.13.5/lib/lib.jar:/opt/signal-cli-0.13.5/lib/bcprov-jdk18on-1.78.1.jar:/opt/signal-cli
Sqlite database size
Here is database on the "sick" instance
-rw-r--r-- 1 signal-api signal-api 17M Sep 21 13:52 /home/.local/share/signal-cli/data/274284.d/account.db
And here is databases on "healthy" instances
-rw-r--r-- 1 signal-api signal-api 2.0M Sep 21 13:54 /home/.local/share/signal-cli/data/134513.d/account.db
-rw-r--r-- 1 signal-api signal-api 1.9M Sep 21 13:54 /home/.local/share/signal-cli/data/626266.d/account.db
So it's probably some big table[s] in accont.db causing overloading. Last time I've reinstalled signal-cli about 3 months ago when had the same issue.
Thanks for the log. It's possible that inefficient queries cause slow down, but I don't see that consuming 100% CPU.
Suspicious is the following receive thread log entry: Reading cached envelope file, which is not followed by a checking for new messages log entry.
Can you try moving or deleting the following folder? (That contains messages received from user's that changed their safety numbers)
/home/.local/share/signal-cli/data/274284.d/msg-cache/
Removing of msg-cache didn't help. CPU usage is still 100%.
signal-cli -vvv --output=json --config /home/.local/share/signal-cli jsonRpc
2024-09-23T05:14:06.925Z [main] DEBUG java.lang.ProcessBuilder - ProcessBuilder.start(): pid: 77, dir: null, cmd: "/usr/bin/sh" "-c" "stty -a < /dev/tty"
java.lang.RuntimeException: ProcessBuilder.start() debug
at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1147)
at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1089)
at net.sourceforge.argparse4j.internal.TerminalWidth.getTerminalWidth2(TerminalWidth.java:74)
at net.sourceforge.argparse4j.internal.TerminalWidth.getTerminalWidth(TerminalWidth.java:54)
at net.sourceforge.argparse4j.ArgumentParserBuilder.getFormatWidth(ArgumentParserBuilder.java:282)
at net.sourceforge.argparse4j.ArgumentParserBuilder.config(ArgumentParserBuilder.java:270)
at net.sourceforge.argparse4j.ArgumentParserBuilder.build(ArgumentParserBuilder.java:264)
at org.asamk.signal.App.buildArgumentParser(App.java:52)
at org.asamk.signal.Main.main(Main.java:51)
2024-09-23T05:14:07.083Z [main] DEBUG org.asamk.signal.util.IOUtils - XDG_RUNTIME_DIR not set, falling back to temp dir
2024-09-23T05:14:07.108Z [main] DEBUG org.asamk.signal.App - Starting signal-cli 0.13.5
2024-09-23T05:14:08.229Z [main] TRACE org.asamk.signal.manager.Manager - Expected exception when checking libsignal-client: Failed to deserialize zkgroup::api::groups::uuid_ciphertext::UuidCiphertext
2024-09-23T05:14:09.226Z [main] TRACE o.a.s.manager.storage.SignalAccount - Opening account file
2024-09-23T05:14:09.270Z [main] TRACE o.a.s.manager.storage.SignalAccount - Loading account file 274284
2024-09-23T05:14:09.526Z [main] DEBUG com.zaxxer.hikari.HikariConfig - HikariPool-1 - configuration:
2024-09-23T05:14:09.549Z [main] DEBUG com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
2024-09-23T05:14:09.550Z [main] DEBUG com.zaxxer.hikari.HikariConfig - autoCommit......................true
2024-09-23T05:14:09.551Z [main] DEBUG com.zaxxer.hikari.HikariConfig - catalog.........................none
2024-09-23T05:14:09.552Z [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionInitSql..............."PRAGMA foreign_keys=ON"
2024-09-23T05:14:09.553Z [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
2024-09-23T05:14:09.556Z [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionTimeout...............30000
2024-09-23T05:14:09.556Z [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSource......................none
2024-09-23T05:14:09.557Z [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none
2024-09-23T05:14:09.557Z [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
2024-09-23T05:14:09.559Z [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceProperties............{open_mode=70, transaction_mode=IMMEDIATE, password=<masked>, date_precision=MILLISECONDS, busy_timeout=60000, date_string_format=yyyy-MM-dd HH:mm:ss.SSS, jdbc.explicit_readonly=false, date_class=INTEGER, shared_cache=false}
2024-09-23T05:14:09.559Z [main] DEBUG com.zaxxer.hikari.HikariConfig - driverClassName.................none
2024-09-23T05:14:09.560Z [main] DEBUG com.zaxxer.hikari.HikariConfig - exceptionOverrideClassName......none
2024-09-23T05:14:09.560Z [main] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
2024-09-23T05:14:09.561Z [main] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
2024-09-23T05:14:09.562Z [main] DEBUG com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
2024-09-23T05:14:09.562Z [main] DEBUG com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
2024-09-23T05:14:09.563Z [main] DEBUG com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
2024-09-23T05:14:09.564Z [main] DEBUG com.zaxxer.hikari.HikariConfig - jdbcUrl.........................jdbc:sqlite:/home/.local/share/signal-cli/data/274284.d/account.db
2024-09-23T05:14:09.565Z [main] DEBUG com.zaxxer.hikari.HikariConfig - keepaliveTime...................0
2024-09-23T05:14:09.565Z [main] DEBUG com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........0
2024-09-23T05:14:09.566Z [main] DEBUG com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
2024-09-23T05:14:09.566Z [main] DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize.................10
2024-09-23T05:14:09.567Z [main] DEBUG com.zaxxer.hikari.HikariConfig - metricRegistry..................none
2024-09-23T05:14:09.567Z [main] DEBUG com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
2024-09-23T05:14:09.568Z [main] DEBUG com.zaxxer.hikari.HikariConfig - minimumIdle.....................1
2024-09-23T05:14:09.568Z [main] DEBUG com.zaxxer.hikari.HikariConfig - password........................<masked>
2024-09-23T05:14:09.569Z [main] DEBUG com.zaxxer.hikari.HikariConfig - poolName........................"HikariPool-1"
2024-09-23T05:14:09.569Z [main] DEBUG com.zaxxer.hikari.HikariConfig - readOnly........................false
2024-09-23T05:14:09.570Z [main] DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans..................false
2024-09-23T05:14:09.571Z [main] DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
2024-09-23T05:14:09.572Z [main] DEBUG com.zaxxer.hikari.HikariConfig - schema..........................none
2024-09-23T05:14:09.572Z [main] DEBUG com.zaxxer.hikari.HikariConfig - threadFactory...................internal
2024-09-23T05:14:09.573Z [main] DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............default
2024-09-23T05:14:09.573Z [main] DEBUG com.zaxxer.hikari.HikariConfig - username........................none
2024-09-23T05:14:09.574Z [main] DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
2024-09-23T05:14:09.606Z [main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
2024-09-23T05:14:09.647Z [main] DEBUG c.z.hikari.util.DriverDataSource - Loaded driver with class name org.sqlite.JDBC for jdbcUrl=jdbc:sqlite:/home/.local/share/signal-cli/data/274284.d/account.db
2024-09-23T05:14:09.758Z [main] DEBUG java.lang.ProcessBuilder - ProcessBuilder.start(): pid: 85, dir: null, cmd: "uname" "-o"
java.lang.RuntimeException: ProcessBuilder.start() debug
at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1147)
at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1089)
at java.base/java.lang.Runtime.exec(Runtime.java:681)
at java.base/java.lang.Runtime.exec(Runtime.java:491)
at java.base/java.lang.Runtime.exec(Runtime.java:366)
at org.sqlite.util.ProcessRunner.runAndWaitFor(ProcessRunner.java:10)
at org.sqlite.util.OSInfo.isAndroidTermux(OSInfo.java:125)
at org.sqlite.util.OSInfo.isAndroid(OSInfo.java:116)
at org.sqlite.util.OSInfo.translateOSNameToFolderName(OSInfo.java:261)
at org.sqlite.util.OSInfo.getOSName(OSInfo.java:112)
at org.sqlite.util.OSInfo.getNativeLibFolderPathForCurrentOS(OSInfo.java:108)
at org.sqlite.util.LibraryLoaderUtil.getNativeLibResourcePath(LibraryLoaderUtil.java:16)
at org.sqlite.SQLiteJDBCLoader.loadSQLiteNativeLibrary(SQLiteJDBCLoader.java:322)
at org.sqlite.SQLiteJDBCLoader.initialize(SQLiteJDBCLoader.java:75)
at org.sqlite.core.NativeDB.load(NativeDB.java:69)
at org.sqlite.SQLiteConnection.open(SQLiteConnection.java:280)
at org.sqlite.SQLiteConnection.<init>(SQLiteConnection.java:67)
at org.sqlite.jdbc3.JDBC3Connection.<init>(JDBC3Connection.java:28)
at org.sqlite.jdbc4.JDBC4Connection.<init>(JDBC4Connection.java:19)
at org.sqlite.JDBC.createConnection(JDBC.java:106)
at org.sqlite.JDBC.connect(JDBC.java:79)
at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:120)
at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:360)
at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:202)
at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:461)
at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:550)
at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:98)
at com.zaxxer.hikari.HikariDataSource.<init>(HikariDataSource.java:80)
at org.asamk.signal.manager.storage.Database.getHikariDataSource(Database.java:101)
at org.asamk.signal.manager.storage.Database.initDatabase(Database.java:32)
at org.asamk.signal.manager.storage.AccountDatabase.init(AccountDatabase.java:43)
at org.asamk.signal.manager.storage.SignalAccount.lambda$getAccountDatabase$24(SignalAccount.java:1275)
at org.asamk.signal.manager.storage.SignalAccount.getOrCreate(SignalAccount.java:1735)
at org.asamk.signal.manager.storage.SignalAccount.getAccountDatabase(SignalAccount.java:1273)
at org.asamk.signal.manager.storage.SignalAccount.lambda$getRecipientStore$10(SignalAccount.java:1239)
at org.asamk.signal.manager.storage.SignalAccount.getOrCreate(SignalAccount.java:1735)
at org.asamk.signal.manager.storage.SignalAccount.getRecipientStore(SignalAccount.java:1235)
at org.asamk.signal.manager.storage.recipients.RecipientTrustedResolver$RecipientTrustedResolverWrapper.resolveSelfRecipientTrusted(RecipientTrustedResolver.java:32)
at org.asamk.signal.manager.storage.SignalAccount.init(SignalAccount.java:367)
at org.asamk.signal.manager.storage.SignalAccount.load(SignalAccount.java:201)
at org.asamk.signal.manager.SignalAccountFiles.initManager(SignalAccountFiles.java:97)
at org.asamk.signal.manager.SignalAccountFiles.lambda$initMultiAccountManager$1(SignalAccountFiles.java:69)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
at java.base/java.util.HashMap$KeySpliterator.forEachRemaining(HashMap.java:1715)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
at java.base/java.util.stream.Nodes$CollectorTask.doLeaf(Nodes.java:2192)
at java.base/java.util.stream.Nodes$CollectorTask$OfRef.doLeaf(Nodes.java:2202)
at java.base/java.util.stream.AbstractTask.compute(AbstractTask.java:327)
at java.base/java.util.concurrent.CountedCompleter.exec(CountedCompleter.java:754)
at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387)
at java.base/java.util.concurrent.ForkJoinTask.invoke(ForkJoinTask.java:667)
at java.base/java.util.stream.Nodes.collect(Nodes.java:328)
at java.base/java.util.stream.ReferencePipeline.evaluateToNode(ReferencePipeline.java:111)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:570)
at java.base/java.util.stream.AbstractPipeline.evaluateToArrayNode(AbstractPipeline.java:260)
at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:616)
at java.base/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:622)
at java.base/java.util.stream.ReferencePipeline.toList(ReferencePipeline.java:627)
at org.asamk.signal.manager.SignalAccountFiles.initMultiAccountManager(SignalAccountFiles.java:77)
at org.asamk.signal.App.handleMultiLocalCommand(App.java:287)
at org.asamk.signal.App.handleCommand(App.java:164)
at org.asamk.signal.App.init(App.java:144)
at org.asamk.signal.Main.main(Main.java:56)
2024-09-23T05:14:10.033Z [main] INFO com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:10.038Z [main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
2024-09-23T05:14:10.060Z [main] TRACE o.a.s.m.storage.AccountDatabase - Current database version: 26 Program database version: 26
2024-09-23T05:14:10.088Z [main] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:10.118Z [main] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:10.139Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=1, active=0, idle=1, waiting=0)
2024-09-23T05:14:10.143Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup stats (total=1, active=0, idle=1, waiting=0)
2024-09-23T05:14:10.143Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2024-09-23T05:14:14.992Z [main] DEBUG okhttp3.internal.http2.Http2 - >> CONNECTION 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a
2024-09-23T05:14:14.996Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000000 6 SETTINGS
2024-09-23T05:14:14.997Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000000 4 WINDOW_UPDATE
2024-09-23T05:14:15.001Z [main] DEBUG o.internal.concurrent.TaskRunner - Q10014 scheduled after 0 µs: OkHttp chat.signal.org
2024-09-23T05:14:15.003Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10014 starting : OkHttp chat.signal.org
2024-09-23T05:14:15.003Z [main] DEBUG o.internal.concurrent.TaskRunner - Q10001 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-23T05:14:15.006Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-23T05:14:15.006Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10001 run again after 45 s : OkHttp ConnectionPool
2024-09-23T05:14:15.006Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 888 µs: OkHttp ConnectionPool
2024-09-23T05:14:15.045Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000003 219 HEADERS END_HEADERS
2024-09-23T05:14:15.049Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000003 438 DATA END_STREAM
2024-09-23T05:14:15.181Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000000 18 SETTINGS
2024-09-23T05:14:15.182Z [OkHttp chat.signal.org] DEBUG o.internal.concurrent.TaskRunner - Q10011 scheduled after 0 µs: OkHttp chat.signal.org applyAndAckSettings
2024-09-23T05:14:15.182Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000000 4 WINDOW_UPDATE
2024-09-23T05:14:15.183Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000000 0 SETTINGS ACK
2024-09-23T05:14:15.183Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10011 starting : OkHttp chat.signal.org applyAndAckSettings
2024-09-23T05:14:15.185Z [OkHttp chat.signal.org applyAndAckSettings] DEBUG o.internal.concurrent.TaskRunner - Q10013 scheduled after 0 µs: OkHttp chat.signal.org onSettings
2024-09-23T05:14:15.185Z [OkHttp chat.signal.org applyAndAckSettings] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000000 0 SETTINGS ACK
2024-09-23T05:14:15.186Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10013 starting : OkHttp chat.signal.org onSettings
2024-09-23T05:14:15.186Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10011 finished run in 2 ms: OkHttp chat.signal.org applyAndAckSettings
2024-09-23T05:14:15.186Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10013 finished run in 304 µs: OkHttp chat.signal.org onSettings
2024-09-23T05:14:15.322Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000003 64 HEADERS END_STREAM|END_HEADERS
2024-09-23T05:14:15.330Z [main] DEBUG o.internal.concurrent.TaskRunner - Q10001 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-23T05:14:15.331Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-23T05:14:15.331Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10001 run again after 45 s : OkHttp ConnectionPool
2024-09-23T05:14:15.331Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 729 µs: OkHttp ConnectionPool
2024-09-23T05:14:15.340Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000005 25 HEADERS END_STREAM|END_HEADERS
2024-09-23T05:14:15.627Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000005 65 HEADERS END_HEADERS
2024-09-23T05:14:15.628Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000005 25 DATA END_STREAM
2024-09-23T05:14:15.628Z [main] DEBUG o.internal.concurrent.TaskRunner - Q10001 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-23T05:14:15.629Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-23T05:14:15.629Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10001 run again after 45 s : OkHttp ConnectionPool
2024-09-23T05:14:15.629Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 673 µs: OkHttp ConnectionPool
2024-09-23T05:14:15.651Z [main] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000007 25 HEADERS END_STREAM|END_HEADERS
2024-09-23T05:14:15.792Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000007 35 HEADERS END_HEADERS
2024-09-23T05:14:15.793Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000007 27 DATA END_STREAM
2024-09-23T05:14:15.794Z [main] DEBUG o.internal.concurrent.TaskRunner - Q10001 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-23T05:14:15.795Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-23T05:14:15.795Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10001 run again after 45 s : OkHttp ConnectionPool
2024-09-23T05:14:15.796Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 763 µs: OkHttp ConnectionPool
2024-09-23T05:14:15.838Z [receive-0] DEBUG o.a.s.manager.internal.ManagerImpl - Starting receiving messages
2024-09-23T05:14:15.852Z [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.sqlite.jdbc4.JDBC4Connection@4f70eba8
2024-09-23T05:14:15.883Z [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Connection not added, stats (total=2, active=1, idle=1, waiting=0)
2024-09-23T05:14:16.342Z [receive-0] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:522400663] connect()
2024-09-23T05:14:16.378Z [receive-0] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:2029171867] connect()
2024-09-23T05:14:16.393Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Handling message actions
2024-09-23T05:14:16.774Z [OkHttp https://chat.signal.org/...] DEBUG o.internal.concurrent.TaskRunner - Q10017 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-23T05:14:16.775Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10017 starting : OkHttp ConnectionPool
2024-09-23T05:14:16.775Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10017 run again after 300 s : OkHttp ConnectionPool
2024-09-23T05:14:16.775Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10017 finished run in 662 µs: OkHttp ConnectionPool
2024-09-23T05:14:16.776Z [OkHttp https://chat.signal.org/...] DEBUG o.internal.concurrent.TaskRunner - Q10020 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-23T05:14:16.776Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10020 starting : OkHttp ConnectionPool
2024-09-23T05:14:16.777Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10020 run again after 300 s : OkHttp ConnectionPool
2024-09-23T05:14:16.777Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10020 finished run in 524 µs: OkHttp ConnectionPool
2024-09-23T05:14:16.963Z [OkHttp https://chat.signal.org/...] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:2029171867] onOpen() connected
2024-09-23T05:14:16.963Z [OkHttp https://chat.signal.org/...] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:522400663] onOpen() connected
2024-09-23T05:14:16.964Z [RxComputationThreadPool-4] DEBUG o.a.s.m.i.SignalWebSocketHealthMonitor - WebSocket is now connected
2024-09-23T05:14:16.966Z [RxComputationThreadPool-5] DEBUG o.a.s.m.i.SignalWebSocketHealthMonitor - WebSocket is now connected
2024-09-23T05:14:17.054Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-09-23T05:14:17.222Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-09-23T05:14:17.225Z [receive-0] TRACE o.a.s.manager.helper.ReceiveHelper - Storing new message from null
2024-09-23T05:14:17.240Z [receive-0] DEBUG o.internal.concurrent.TaskRunner - Q10018 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:17.241Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
2024-09-23T05:14:17.241Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:17.244Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10018 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:17.244Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 3 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:17.245Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:17.245Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 331 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:17.261Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:17.924Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Failed to decrypt incoming message
org.signal.libsignal.metadata.ProtocolInvalidMessageException: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:232)
at org.whispersystems.signalservice.api.crypto.SignalSealedSessionCipher.decrypt(SignalSealedSessionCipher.java:70)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decryptInternal(SignalServiceCipher.java:202)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:144)
at org.asamk.signal.manager.helper.IncomingMessageHandler.handleEnvelope(IncomingMessageHandler.java:145)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesInternal(ReceiveHelper.java:213)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessages(ReceiveHelper.java:104)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesContinuously(ReceiveHelper.java:77)
at org.asamk.signal.manager.internal.ManagerImpl.lambda$startReceiveThreadIfRequired$12(ManagerImpl.java:1181)
at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.internal.Native.SessionCipher_DecryptSignalMessage(Native Method)
at org.signal.libsignal.protocol.SessionCipher.lambda$decrypt$2(SessionCipher.java:176)
at org.signal.libsignal.internal.FilterExceptions.filterExceptions(FilterExceptions.java:361)
at org.signal.libsignal.protocol.SessionCipher.decrypt(SessionCipher.java:169)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:275)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:230)
... 9 common frames omitted
2024-09-23T05:14:17.927Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:17.932Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Received invalid message, requesting message resend.
2024-09-23T05:14:17.940Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:17.957Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:17.975Z [receive-0] TRACE o.a.s.m.h.UnidentifiedAccessHelper - Using phone number privacy sender certificate for message to RecipientId[id=23]
2024-09-23T05:14:17.983Z [receive-0] DEBUG okhttp3.internal.http2.Http2 - >> 0x00000009 39 HEADERS END_STREAM|END_HEADERS
2024-09-23T05:14:18.117Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000009 64 HEADERS END_HEADERS
2024-09-23T05:14:18.117Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000009 330 DATA END_STREAM
2024-09-23T05:14:18.119Z [receive-0] DEBUG o.internal.concurrent.TaskRunner - Q10001 scheduled after 0 µs: OkHttp ConnectionPool
2024-09-23T05:14:18.120Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-23T05:14:18.121Z [OkHttp ConnectionPool] DEBUG o.internal.concurrent.TaskRunner - Q10001 run again after 45 s : OkHttp ConnectionPool
2024-09-23T05:14:18.121Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 807 µs: OkHttp ConnectionPool
2024-09-23T05:14:18.141Z [receive-0] TRACE o.a.s.manager.helper.ProfileHelper - Retrieving profile for RecipientId[id=23] with profile key
2024-09-23T05:14:18.195Z [receive-0] TRACE org.asamk.signal.manager.util.Utils - Using default locale: en_US (en-US)
2024-09-23T05:14:18.274Z [receive-0] DEBUG o.internal.concurrent.TaskRunner - Q10021 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:18.274Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:18.276Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10021 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:18.276Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 2 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:18.276Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:18.277Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 185 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:18.463Z [RxCachedThreadScheduler-2] TRACE o.a.s.manager.helper.ProfileHelper - Got new profile for RecipientId[id=23]
2024-09-23T05:14:18.466Z [RxCachedThreadScheduler-2] TRACE o.a.s.manager.helper.ProfileHelper - Storing profile credential
2024-09-23T05:14:18.468Z [RxCachedThreadScheduler-2] TRACE o.a.s.manager.helper.ProfileHelper - Decrypting profile
2024-09-23T05:14:18.477Z [RxCachedThreadScheduler-2] TRACE o.a.s.manager.helper.ProfileHelper - Storing identity
2024-09-23T05:14:18.482Z [RxCachedThreadScheduler-2] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient cf12e943-1ae7-4b22-83c1-2dbbdd959c81, identity already stored
2024-09-23T05:14:18.482Z [RxCachedThreadScheduler-2] TRACE o.a.s.manager.helper.ProfileHelper - Storing profile
2024-09-23T05:14:19.072Z [RxCachedThreadScheduler-2] DEBUG o.a.s.m.s.recipients.RecipientStore - Marking RecipientId[id=23] as registered=true
2024-09-23T05:14:19.073Z [RxCachedThreadScheduler-2] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:19.073Z [RxCachedThreadScheduler-2] TRACE o.a.s.manager.helper.ProfileHelper - Done handling retrieved profile
{"jsonrpc":"2.0","method":"receive","params":{"exception":{"message":"org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed","type":"ProtocolInvalidMessageException"},"envelope":{"source":"cf12e943-1ae7-4b22-83c1-2dbbdd959c81","sourceNumber":null,"sourceUuid":"cf12e943-1ae7-4b22-83c1-2dbbdd959c81","sourceName":"Ormat","sourceDevice":5,"timestamp":1724371143350},"account":"+XXXX"}}
2024-09-23T05:14:19.237Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-09-23T05:14:19.237Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-09-23T05:14:19.238Z [receive-0] TRACE o.a.s.manager.helper.ReceiveHelper - Storing new message from null
2024-09-23T05:14:19.239Z [receive-0] DEBUG o.internal.concurrent.TaskRunner - Q10018 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.239Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
2024-09-23T05:14:19.240Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:19.240Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.241Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10018 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.242Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 2 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.243Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.243Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 656 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.839Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Failed to decrypt incoming message
org.signal.libsignal.metadata.ProtocolInvalidMessageException: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:232)
at org.whispersystems.signalservice.api.crypto.SignalSealedSessionCipher.decrypt(SignalSealedSessionCipher.java:70)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decryptInternal(SignalServiceCipher.java:202)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:144)
at org.asamk.signal.manager.helper.IncomingMessageHandler.handleEnvelope(IncomingMessageHandler.java:145)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesInternal(ReceiveHelper.java:213)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessages(ReceiveHelper.java:104)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesContinuously(ReceiveHelper.java:77)
at org.asamk.signal.manager.internal.ManagerImpl.lambda$startReceiveThreadIfRequired$12(ManagerImpl.java:1181)
at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.internal.Native.SessionCipher_DecryptSignalMessage(Native Method)
at org.signal.libsignal.protocol.SessionCipher.lambda$decrypt$2(SessionCipher.java:176)
at org.signal.libsignal.internal.FilterExceptions.filterExceptions(FilterExceptions.java:361)
at org.signal.libsignal.protocol.SessionCipher.decrypt(SessionCipher.java:169)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:275)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:230)
... 9 common frames omitted
2024-09-23T05:14:19.840Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:19.841Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Received invalid message, requesting message resend.
2024-09-23T05:14:19.842Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:19.843Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
{"jsonrpc":"2.0","method":"receive","params":{"exception":{"message":"org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed","type":"ProtocolInvalidMessageException"},"envelope":{"source":"cf12e943-1ae7-4b22-83c1-2dbbdd959c81","sourceNumber":null,"sourceUuid":"cf12e943-1ae7-4b22-83c1-2dbbdd959c81","sourceName":"Ormat","sourceDevice":5,"timestamp":1724371150734},"account":"+XXXXX"}}
2024-09-23T05:14:19.852Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-09-23T05:14:19.852Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-09-23T05:14:19.852Z [receive-0] TRACE o.a.s.manager.helper.ReceiveHelper - Storing new message from null
2024-09-23T05:14:19.853Z [receive-0] DEBUG o.internal.concurrent.TaskRunner - Q10018 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.854Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
2024-09-23T05:14:19.854Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.854Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:19.855Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10018 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.855Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 1 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.855Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.856Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 213 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.856Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Dropping unidentified message from self.
2024-09-23T05:14:19.857Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-09-23T05:14:19.857Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-09-23T05:14:19.857Z [receive-0] TRACE o.a.s.manager.helper.ReceiveHelper - Storing new message from null
2024-09-23T05:14:19.858Z [receive-0] DEBUG o.internal.concurrent.TaskRunner - Q10018 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.859Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.859Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
2024-09-23T05:14:19.859Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10018 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.860Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:19.860Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 866 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.860Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.860Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 224 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.862Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Dropping unidentified message from self.
2024-09-23T05:14:19.863Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-09-23T05:14:19.863Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-09-23T05:14:19.864Z [receive-0] TRACE o.a.s.manager.helper.ReceiveHelper - Storing new message from null
2024-09-23T05:14:19.864Z [receive-0] DEBUG o.internal.concurrent.TaskRunner - Q10018 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.865Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
2024-09-23T05:14:19.865Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.865Z [receive-0] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.sqlite.jdbc4.JDBC4Connection@625abb97
2024-09-23T05:14:19.865Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10018 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.866Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 852 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.866Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:19.866Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 172 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:40.143Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=2, active=0, idle=2, waiting=0)
2024-09-23T05:14:40.144Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup stats (total=2, active=0, idle=2, waiting=0)
2024-09-23T05:14:40.144Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2024-09-23T05:14:46.967Z [Thread-1] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:522400663] Sending keep alive...
2024-09-23T05:14:46.967Z [Thread-1] DEBUG o.internal.concurrent.TaskRunner - Q10018 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.968Z [Thread-1] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:2029171867] Sending keep alive...
2024-09-23T05:14:46.968Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.968Z [Thread-1] DEBUG o.internal.concurrent.TaskRunner - Q10021 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.969Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.969Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10018 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.969Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 981 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.969Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10021 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.970Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 970 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.970Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.970Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.970Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 179 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:46.970Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 172 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:14:48.117Z [OkHttp chat.signal.org] DEBUG okhttp3.internal.http2.Http2 - << 0x00000000 20 GOAWAY
2024-09-23T05:14:48.127Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10014 finished run in 33 s : OkHttp chat.signal.org
2024-09-23T05:15:03.120Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 starting : OkHttp ConnectionPool
2024-09-23T05:15:03.120Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10001 finished run in 603 µs: OkHttp ConnectionPool
2024-09-23T05:15:10.144Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=2, active=0, idle=2, waiting=0)
2024-09-23T05:15:10.145Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup stats (total=2, active=0, idle=2, waiting=0)
2024-09-23T05:15:10.145Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2024-09-23T05:15:16.969Z [Thread-1] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:522400663] Sending keep alive...
2024-09-23T05:15:16.969Z [Thread-1] DEBUG o.internal.concurrent.TaskRunner - Q10018 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.969Z [Thread-1] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:2029171867] Sending keep alive...
2024-09-23T05:15:16.970Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.970Z [Thread-1] DEBUG o.internal.concurrent.TaskRunner - Q10021 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.970Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.971Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10018 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.971Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 1 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.971Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10021 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.971Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 1 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.971Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.971Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.972Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 141 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:16.972Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 208 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:40.145Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Before cleanup stats (total=2, active=0, idle=2, waiting=0)
2024-09-23T05:15:40.146Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After cleanup stats (total=2, active=0, idle=2, waiting=0)
2024-09-23T05:15:40.146Z [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled.
2024-09-23T05:15:46.970Z [Thread-1] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:522400663] Sending keep alive...
2024-09-23T05:15:46.971Z [Thread-1] DEBUG o.internal.concurrent.TaskRunner - Q10018 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.971Z [Thread-1] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:2029171867] Sending keep alive...
2024-09-23T05:15:46.971Z [Thread-1] DEBUG o.internal.concurrent.TaskRunner - Q10021 scheduled after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.972Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.972Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.973Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10021 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.973Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 1 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.974Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.974Z [OkHttp WebSocket https://chat.signal.org/... writer] DEBUG o.internal.concurrent.TaskRunner - Q10018 run again after 0 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.974Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10021 finished run in 576 µs: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.974Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 starting : OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.974Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 2 ms: OkHttp WebSocket https://chat.signal.org/... writer
2024-09-23T05:15:46.975Z [OkHttp TaskRunner] DEBUG o.internal.concurrent.TaskRunner - Q10018 finished run in 177 µs: OkHttp WebSocket https://chat.signal.org/... writer
I have the same problem with signal-cli in jsonRpc mode taking 100% CPU to the extent that I cannot login. It happened three times already for me.
The account has joined groups with ~800 users, but there's not a lot of traffic, it's maybe 200-300 messages per day in all groups combined.
Here's my debug, also 100% cpu with jsonRpc. Several invalid whisper messages reported.
# /usr/local/bin/signal-cli -vv -a +316xxxxxxxx daemon --tcp x.x.x.x:7583 --ignore-attachments --ignore-stories --send-read-receipts | tee /tmp/debug.log
2024-11-21T14:37:54.329Z [main] DEBUG org.asamk.signal.App - Starting signal-cli 0.13.9
2024-11-21T14:37:54.620Z [main] TRACE org.asamk.signal.manager.Manager - Expected exception when checking libsignal-client: Failed to deserialize zkgroup::api::groups::uuid_ciphertext::UuidCiphertext
2024-11-21T14:37:54.620Z [main] DEBUG org.asamk.signal.util.IOUtils - XDG_DATA_HOME not set, falling back to home dir
2024-11-21T14:37:54.636Z [main] TRACE org.asamk.signal.App - Loading account file for +316XXXXXXXXX
2024-11-21T14:37:54.639Z [main] TRACE o.a.s.manager.storage.SignalAccount - Opening account file
2024-11-21T14:37:54.639Z [main] TRACE o.a.s.manager.storage.SignalAccount - Loading account file 701838
2024-11-21T14:37:54.643Z [main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
2024-11-21T14:37:54.716Z [main] INFO com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.sqlite.jdbc4.JDBC4Connection@75173fc7
2024-11-21T14:37:54.716Z [main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
2024-11-21T14:37:54.716Z [main] TRACE o.a.s.m.storage.AccountDatabase - Current database version: 27 Program database version: 27
2024-11-21T14:37:55.415Z [main] INFO o.a.signal.commands.DaemonCommand - Starting daemon in single-account mode for +316XXXXXXXXX
2024-11-21T14:37:55.416Z [main] DEBUG org.asamk.signal.util.IOUtils - Listening on socket: /10.10.10.10:7583
2024-11-21T14:37:55.417Z [main] DEBUG o.asamk.signal.jsonrpc.SocketHandler - Starting JSON-RPC server on /10.10.10.10:7583
2024-11-21T14:37:55.416Z [receive-0] DEBUG o.a.s.manager.internal.ManagerImpl - Starting receiving messages
2024-11-21T14:37:55.418Z [daemon-listener] INFO o.asamk.signal.jsonrpc.SocketHandler - Started JSON-RPC server on /10.10.10.10:7583
2024-11-21T14:37:55.428Z [receive-0] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:1258492061] connect()
2024-11-21T14:37:55.432Z [receive-0] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:565912228] connect()
2024-11-21T14:37:55.436Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Handling message actions
2024-11-21T14:37:55.447Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-11-21T14:37:55.726Z [OkHttp https://chat.signal.org/...] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:1258492061] onOpen() connected
2024-11-21T14:37:55.726Z [RxComputationThreadPool-2] DEBUG o.a.s.m.i.SignalWebSocketHealthMonitor - WebSocket is now connected
2024-11-21T14:37:55.732Z [OkHttp https://chat.signal.org/...] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:565912228] onOpen() connected
2024-11-21T14:37:55.732Z [RxComputationThreadPool-2] DEBUG o.a.s.m.i.SignalWebSocketHealthMonitor - WebSocket is now connected
2024-11-21T14:37:55.778Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-11-21T14:37:55.778Z [receive-0] TRACE o.a.s.manager.helper.ReceiveHelper - Storing new message from null
2024-11-21T14:37:55.778Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
2024-11-21T14:37:55.997Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Failed to decrypt incoming message
org.signal.libsignal.metadata.ProtocolInvalidMessageException: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:232)
at org.whispersystems.signalservice.api.crypto.SignalSealedSessionCipher.decrypt(SignalSealedSessionCipher.java:70)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decryptInternal(SignalServiceCipher.java:202)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:144)
at org.asamk.signal.manager.helper.IncomingMessageHandler.handleEnvelope(IncomingMessageHandler.java:145)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesInternal(ReceiveHelper.java:213)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessages(ReceiveHelper.java:104)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesContinuously(ReceiveHelper.java:77)
at org.asamk.signal.manager.internal.ManagerImpl.lambda$startReceiveThreadIfRequired$12(ManagerImpl.java:1193)
at [email protected]/java.lang.Thread.runWith(Thread.java:1596)
at [email protected]/java.lang.Thread.run(Thread.java:1583)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:896)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:872)
Caused by: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.internal.Native.SessionCipher_DecryptSignalMessage(Native Method)
at org.signal.libsignal.protocol.SessionCipher.lambda$decrypt$2(SessionCipher.java:176)
at org.signal.libsignal.internal.FilterExceptions.filterExceptions(FilterExceptions.java:362)
at org.signal.libsignal.protocol.SessionCipher.decrypt(SessionCipher.java:169)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:275)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:230)
... 12 common frames omitted
2024-11-21T14:37:55.998Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Received invalid message, requesting message resend.
Envelope from: "xxx" xxx-xx-xxx (device: 1) to +316XXXXXXXXX
Timestamp: 1730020528058 (2024-10-27T09:15:28.058Z)
Server timestamps: received: 1731653442560 (2024-11-15T06:50:42.560Z) delivered: 1732199875729 (2024-11-21T14:37:55.729Z)
Sent by unidentified/sealed sender
Exception: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed (ProtocolInvalidMessageException)
2024-11-21T14:37:56.000Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-11-21T14:37:56.000Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-11-21T14:37:56.000Z [receive-0] TRACE o.a.s.manager.helper.ReceiveHelper - Storing new message from null
2024-11-21T14:37:56.000Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
2024-11-21T14:37:58.640Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Failed to decrypt incoming message
org.signal.libsignal.metadata.ProtocolInvalidMessageException: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:232)
at org.whispersystems.signalservice.api.crypto.SignalSealedSessionCipher.decrypt(SignalSealedSessionCipher.java:70)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decryptInternal(SignalServiceCipher.java:202)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:144)
at org.asamk.signal.manager.helper.IncomingMessageHandler.handleEnvelope(IncomingMessageHandler.java:145)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesInternal(ReceiveHelper.java:213)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessages(ReceiveHelper.java:104)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesContinuously(ReceiveHelper.java:77)
at org.asamk.signal.manager.internal.ManagerImpl.lambda$startReceiveThreadIfRequired$12(ManagerImpl.java:1193)
at [email protected]/java.lang.Thread.runWith(Thread.java:1596)
at [email protected]/java.lang.Thread.run(Thread.java:1583)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:896)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:872)
Caused by: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.internal.Native.SessionCipher_DecryptSignalMessage(Native Method)
at org.signal.libsignal.protocol.SessionCipher.lambda$decrypt$2(SessionCipher.java:176)
at org.signal.libsignal.internal.FilterExceptions.filterExceptions(FilterExceptions.java:362)
at org.signal.libsignal.protocol.SessionCipher.decrypt(SessionCipher.java:169)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:275)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:230)
... 12 common frames omitted
2024-11-21T14:37:58.642Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Received invalid message, requesting message resend.
Envelope from: "xxx" xxx-xx-xxx (device: 1) to +316XXXXXXXXX
Timestamp: 1729884604753 (2024-10-25T19:30:04.753Z)
Server timestamps: received: 1731653442598 (2024-11-15T06:50:42.598Z) delivered: 1732199875729 (2024-11-21T14:37:55.729Z)
Sent by unidentified/sealed sender
Exception: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed (ProtocolInvalidMessageException)
2024-11-21T14:37:58.644Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-11-21T14:37:58.644Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-11-21T14:37:58.644Z [receive-0] TRACE o.a.s.manager.helper.ReceiveHelper - Storing new message from null
2024-11-21T14:37:58.644Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
2024-11-21T14:37:58.789Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Failed to decrypt incoming message
org.signal.libsignal.metadata.ProtocolInvalidMessageException: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:232)
at org.whispersystems.signalservice.api.crypto.SignalSealedSessionCipher.decrypt(SignalSealedSessionCipher.java:70)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decryptInternal(SignalServiceCipher.java:202)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:144)
at org.asamk.signal.manager.helper.IncomingMessageHandler.handleEnvelope(IncomingMessageHandler.java:145)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesInternal(ReceiveHelper.java:213)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessages(ReceiveHelper.java:104)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesContinuously(ReceiveHelper.java:77)
at org.asamk.signal.manager.internal.ManagerImpl.lambda$startReceiveThreadIfRequired$12(ManagerImpl.java:1193)
at [email protected]/java.lang.Thread.runWith(Thread.java:1596)
at [email protected]/java.lang.Thread.run(Thread.java:1583)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:896)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:872)
Caused by: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.internal.Native.SessionCipher_DecryptSignalMessage(Native Method)
at org.signal.libsignal.protocol.SessionCipher.lambda$decrypt$2(SessionCipher.java:176)
at org.signal.libsignal.internal.FilterExceptions.filterExceptions(FilterExceptions.java:362)
at org.signal.libsignal.protocol.SessionCipher.decrypt(SessionCipher.java:169)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:275)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:230)
... 12 common frames omitted
2024-11-21T14:37:58.790Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Received invalid message, requesting message resend.
Envelope from: "xxx" xxx-xx-xxx (device: 1) to +316XXXXXXXXX
Timestamp: 1729611648440 (2024-10-22T15:40:48.440Z)
Server timestamps: received: 1731653442705 (2024-11-15T06:50:42.705Z) delivered: 1732199875729 (2024-11-21T14:37:55.729Z)
Sent by unidentified/sealed sender
Exception: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed (ProtocolInvalidMessageException)
2024-11-21T14:37:58.791Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-11-21T14:37:58.791Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-11-21T14:37:58.791Z [receive-0] TRACE o.a.s.manager.helper.ReceiveHelper - Storing new message from null
2024-11-21T14:37:58.791Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
2024-11-21T14:38:01.427Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Failed to decrypt incoming message
org.signal.libsignal.metadata.ProtocolInvalidMessageException: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:232)
at org.whispersystems.signalservice.api.crypto.SignalSealedSessionCipher.decrypt(SignalSealedSessionCipher.java:70)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decryptInternal(SignalServiceCipher.java:202)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:144)
at org.asamk.signal.manager.helper.IncomingMessageHandler.handleEnvelope(IncomingMessageHandler.java:145)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesInternal(ReceiveHelper.java:213)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessages(ReceiveHelper.java:104)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesContinuously(ReceiveHelper.java:77)
at org.asamk.signal.manager.internal.ManagerImpl.lambda$startReceiveThreadIfRequired$12(ManagerImpl.java:1193)
at [email protected]/java.lang.Thread.runWith(Thread.java:1596)
at [email protected]/java.lang.Thread.run(Thread.java:1583)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:896)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:872)
Caused by: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.internal.Native.SessionCipher_DecryptSignalMessage(Native Method)
at org.signal.libsignal.protocol.SessionCipher.lambda$decrypt$2(SessionCipher.java:176)
at org.signal.libsignal.internal.FilterExceptions.filterExceptions(FilterExceptions.java:362)
at org.signal.libsignal.protocol.SessionCipher.decrypt(SessionCipher.java:169)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:275)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:230)
... 12 common frames omitted
2024-11-21T14:38:01.427Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Received invalid message, requesting message resend.
Envelope from: "xxx" xxx-xx-xxx (device: 1) to +316XXXXXXXXX
2024-11-21T14:38:01.428Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Checking for new message from server
2024-11-21T14:38:01.428Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Retrieved 1 envelopes!
2024-11-21T14:38:01.428Z [receive-0] TRACE o.a.s.manager.helper.ReceiveHelper - Storing new message from null
2024-11-21T14:38:01.428Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - New message received from server
Timestamp: 1729541415983 (2024-10-21T20:10:15.983Z)
Server timestamps: received: 1731653442708 (2024-11-15T06:50:42.708Z) delivered: 1732199875729 (2024-11-21T14:37:55.729Z)
Sent by unidentified/sealed sender
Exception: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed (ProtocolInvalidMessageException)
^C2024-11-21T14:38:03.442Z [SIGINT handler] INFO org.asamk.signal.Shutdown - Received SIGINT signal, shutting down ...
2024-11-21T14:38:03.443Z [SIGINT handler] DEBUG org.asamk.signal.Shutdown - Triggering shutdown.
2024-11-21T14:38:03.444Z [daemon-listener] TRACE o.asamk.signal.jsonrpc.SocketHandler - Listening socket has been closed
2024-11-21T14:38:03.996Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Failed to decrypt incoming message
org.signal.libsignal.metadata.ProtocolInvalidMessageException: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:232)
at org.whispersystems.signalservice.api.crypto.SignalSealedSessionCipher.decrypt(SignalSealedSessionCipher.java:70)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decryptInternal(SignalServiceCipher.java:202)
at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:144)
at org.asamk.signal.manager.helper.IncomingMessageHandler.handleEnvelope(IncomingMessageHandler.java:145)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesInternal(ReceiveHelper.java:213)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessages(ReceiveHelper.java:104)
at org.asamk.signal.manager.helper.ReceiveHelper.receiveMessagesContinuously(ReceiveHelper.java:77)
at org.asamk.signal.manager.internal.ManagerImpl.lambda$startReceiveThreadIfRequired$12(ManagerImpl.java:1193)
at [email protected]/java.lang.Thread.runWith(Thread.java:1596)
at [email protected]/java.lang.Thread.run(Thread.java:1583)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:896)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:872)
Caused by: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
at org.signal.libsignal.internal.Native.SessionCipher_DecryptSignalMessage(Native Method)
at org.signal.libsignal.protocol.SessionCipher.lambda$decrypt$2(SessionCipher.java:176)
at org.signal.libsignal.internal.FilterExceptions.filterExceptions(FilterExceptions.java:362)
at org.signal.libsignal.protocol.SessionCipher.decrypt(SessionCipher.java:169)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:275)
at org.signal.libsignal.metadata.SealedSessionCipher.decrypt(SealedSessionCipher.java:230)
... 12 common frames omitted
2024-11-21T14:38:03.997Z [receive-0] DEBUG o.a.s.m.h.IncomingMessageHandler - Received invalid message, requesting message resend.
2024-11-21T14:38:03.997Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Handling message actions
2024-11-21T14:38:03.997Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Executing action SendRetryMessageRequestAction
2024-11-21T14:38:04.013Z [receive-0] DEBUG o.a.signal.manager.helper.SendHelper - Sending retry receipt for 1729611648440 to RecipientId[id=5], device: 1
2024-11-21T14:38:04.015Z [receive-0] TRACE o.a.s.m.h.UnidentifiedAccessHelper - Using phone number privacy sender certificate for message to RecipientId[id=5]
2024-11-21T14:38:04.116Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 13538cde-3e27-4227-a317-83aea27eaf90.1: true (active: false)
2024-11-21T14:38:04.576Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Trusting identity for 13538cde-3e27-4227-a317-83aea27eaf90 for SENDING: true
2024-11-21T14:38:04.579Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient 13538cde-3e27-4227-a317-83aea27eaf90, identity already stored
2024-11-21T14:38:04.587Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Trusting identity for 13538cde-3e27-4227-a317-83aea27eaf90 for SENDING: true
2024-11-21T14:38:04.590Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient 13538cde-3e27-4227-a317-83aea27eaf90, identity already stored
2024-11-21T14:38:04.597Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 13538cde-3e27-4227-a317-83aea27eaf90.1: true (active: true)
2024-11-21T14:38:04.597Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 13538cde-3e27-4227-a317-83aea27eaf90.2: true (active: true)
2024-11-21T14:38:04.597Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 13538cde-3e27-4227-a317-83aea27eaf90.2: true (active: true)
2024-11-21T14:38:04.598Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 13538cde-3e27-4227-a317-83aea27eaf90.2: true (active: true)
2024-11-21T14:38:04.719Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Executing action SendRetryMessageRequestAction
2024-11-21T14:38:04.730Z [receive-0] DEBUG o.a.signal.manager.helper.SendHelper - Sending retry receipt for 1729541415983 to RecipientId[id=3], device: 1
2024-11-21T14:38:04.732Z [receive-0] TRACE o.a.s.m.h.UnidentifiedAccessHelper - Using phone number privacy sender certificate for message to RecipientId[id=3]
2024-11-21T14:38:04.732Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.1: true (active: false)
2024-11-21T14:38:04.844Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Trusting identity for 25e3d605-ee4a-4f48-b24e-a12afa2cb328 for SENDING: true
2024-11-21T14:38:04.846Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient 25e3d605-ee4a-4f48-b24e-a12afa2cb328, identity already stored
2024-11-21T14:38:04.853Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Trusting identity for 25e3d605-ee4a-4f48-b24e-a12afa2cb328 for SENDING: true
2024-11-21T14:38:04.855Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient 25e3d605-ee4a-4f48-b24e-a12afa2cb328, identity already stored
2024-11-21T14:38:04.862Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.1: true (active: true)
2024-11-21T14:38:04.862Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.2: true (active: true)
2024-11-21T14:38:04.862Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.2: true (active: true)
2024-11-21T14:38:04.862Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.2: true (active: true)
2024-11-21T14:38:04.963Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Executing action SendRetryMessageRequestAction
2024-11-21T14:38:04.970Z [receive-0] DEBUG o.a.signal.manager.helper.SendHelper - Sending retry receipt for 1730402416243 to RecipientId[id=3], device: 1
2024-11-21T14:38:04.971Z [receive-0] TRACE o.a.s.m.h.UnidentifiedAccessHelper - Using phone number privacy sender certificate for message to RecipientId[id=3]
2024-11-21T14:38:04.972Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.1: true (active: false)
2024-11-21T14:38:05.080Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Trusting identity for 25e3d605-ee4a-4f48-b24e-a12afa2cb328 for SENDING: true
2024-11-21T14:38:05.081Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient 25e3d605-ee4a-4f48-b24e-a12afa2cb328, identity already stored
2024-11-21T14:38:05.085Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Trusting identity for 25e3d605-ee4a-4f48-b24e-a12afa2cb328 for SENDING: true
2024-11-21T14:38:05.086Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient 25e3d605-ee4a-4f48-b24e-a12afa2cb328, identity already stored
2024-11-21T14:38:05.090Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.1: true (active: true)
2024-11-21T14:38:05.090Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.2: true (active: true)
2024-11-21T14:38:05.090Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.2: true (active: true)
2024-11-21T14:38:05.091Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.2: true (active: true)
2024-11-21T14:38:05.189Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Executing action SendRetryMessageRequestAction
2024-11-21T14:38:05.196Z [receive-0] DEBUG o.a.signal.manager.helper.SendHelper - Sending retry receipt for 1730020528058 to RecipientId[id=5], device: 1
2024-11-21T14:38:05.198Z [receive-0] TRACE o.a.s.m.h.UnidentifiedAccessHelper - Using phone number privacy sender certificate for message to RecipientId[id=5]
2024-11-21T14:38:05.199Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 13538cde-3e27-4227-a317-83aea27eaf90.1: true (active: false)
2024-11-21T14:38:05.309Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Trusting identity for 13538cde-3e27-4227-a317-83aea27eaf90 for SENDING: true
2024-11-21T14:38:05.313Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient 13538cde-3e27-4227-a317-83aea27eaf90, identity already stored
2024-11-21T14:38:05.321Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Trusting identity for 13538cde-3e27-4227-a317-83aea27eaf90 for SENDING: true
2024-11-21T14:38:05.324Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient 13538cde-3e27-4227-a317-83aea27eaf90, identity already stored
2024-11-21T14:38:05.331Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 13538cde-3e27-4227-a317-83aea27eaf90.1: true (active: true)
2024-11-21T14:38:05.332Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 13538cde-3e27-4227-a317-83aea27eaf90.2: true (active: true)
2024-11-21T14:38:05.332Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 13538cde-3e27-4227-a317-83aea27eaf90.2: true (active: true)
2024-11-21T14:38:05.333Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 13538cde-3e27-4227-a317-83aea27eaf90.2: true (active: true)
2024-11-21T14:38:05.431Z [receive-0] DEBUG o.a.s.manager.helper.ReceiveHelper - Executing action SendRetryMessageRequestAction
2024-11-21T14:38:05.439Z [receive-0] DEBUG o.a.signal.manager.helper.SendHelper - Sending retry receipt for 1729884604753 to RecipientId[id=3], device: 1
2024-11-21T14:38:05.439Z [receive-0] TRACE o.a.s.m.h.UnidentifiedAccessHelper - Using phone number privacy sender certificate for message to RecipientId[id=3]
2024-11-21T14:38:05.440Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.1: true (active: false)
2024-11-21T14:38:05.548Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Trusting identity for 25e3d605-ee4a-4f48-b24e-a12afa2cb328 for SENDING: true
2024-11-21T14:38:05.550Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient 25e3d605-ee4a-4f48-b24e-a12afa2cb328, identity already stored
2024-11-21T14:38:05.558Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Trusting identity for 25e3d605-ee4a-4f48-b24e-a12afa2cb328 for SENDING: true
2024-11-21T14:38:05.561Z [receive-0] TRACE o.a.s.m.s.i.IdentityKeyStore - Not storing new identity for recipient 25e3d605-ee4a-4f48-b24e-a12afa2cb328, identity already stored
2024-11-21T14:38:05.569Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.1: true (active: true)
2024-11-21T14:38:05.569Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.2: true (active: true)
2024-11-21T14:38:05.569Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.2: true (active: true)
2024-11-21T14:38:05.570Z [receive-0] TRACE o.a.s.m.s.sessions.SessionStore - Contains session 25e3d605-ee4a-4f48-b24e-a12afa2cb328.2: true (active: true)
2024-11-21T14:38:05.668Z [receive-0] INFO LibSignal - [OkHttpWebSocketConnection]: [normal:1258492061] disconnect()
2024-11-21T14:38:05.669Z [receive-0] INFO LibSignal - [OkHttpWebSocketConnection]: [unidentified:565912228] disconnect()
2024-11-21T14:38:05.669Z [receive-0] DEBUG o.a.s.manager.internal.ManagerImpl - Finished receiving messages
2024-11-21T14:38:05.669Z [main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown initiated...
2024-11-21T14:38:05.671Z [main] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown completed.
2024-11-21T14:38:05.671Z [main] DEBUG org.asamk.signal.Shutdown - Triggering shutdown.
2024-11-21T14:38:05.671Z [Thread-1] DEBUG org.asamk.signal.Shutdown - JVM is shutting down
2024-11-21T14:38:05.671Z [Thread-1] DEBUG org.asamk.signal.Shutdown - Waiting for app to shut down
2024-11-21T14:38:05.671Z [Thread-1] DEBUG org.asamk.signal.Shutdown - Exiting
@gwillem in your case signal-cli seems to still be catching up with old messages from a month ago. Is it still at 100% cpu when all messages have been received?
For me it was definitely not catching up, I encountered the problem several times in one day and it processed recent messages.
@AsamK, we use signal-cli for sending-only in our (low traffic, 3p) group chat. We ran it for 2 months in daemon mode with --receive-mode=manual, then we got Signal protocol expects that incoming messages are regularly received so we removed that option (2w ago). Yet, messages seem to be coming in at a rate of 1 per 6-7 seconds at 100% cpu. The timestamps are unordered so I cannot tell how many are left, or whether they are perhaps being retried (because of InvalidMessageException?)
Is there a way to flush the backlog?
PS. Thanks for creating and maintaining signal-cli <3
@gwillem you could reregister the account, that should clear the message queue on the server.
signal-cli register --reregister
If you have set a pin (signal-cli setPin) that should work without captcha and sms verification.
I just experienced this. signal-cli via https://github.com/bbernhard/signal-cli-rest-api/ in docker on a Debian host. No/very little message traffic on Signal chats, no large groups. Has been working fine for months.
The worst thing is that somehow the high sustained load killed the IPv6 network for the host. I've not brought signal-cli it back up yet, I'll do some digging and get back here soon.
Edit/Update: I rebooted the VPS, and the container came back up just fine (not 100% sustained) without any changes to config or container files. After testing messages sending fine I added the following into the docker-compose to prevent this odd bug maxing the CPU (or triggering an IPv6 failure somehow).
As a preventative measure I added this to the end of 'signal-cli-rest-api' docker compose. It will limit the container to half a CPU and half a gig of RAM:
deploy:
resources:
limits:
cpus: '0.5'
memory: 500M
For anyone hunting down this bug in the future, disk read metrics went through the roof at the same time as the CPU spike.