Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

signal-cli in jsonRpc mode started consuming 100% CPU #1585

Open
uriinf opened this issue Sep 11, 2024 · 11 comments
Open

signal-cli in jsonRpc mode started consuming 100% CPU #1585

uriinf opened this issue Sep 11, 2024 · 11 comments

Comments

@uriinf
Copy link

uriinf commented Sep 11, 2024

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.

@AsamK
Copy link
Owner

AsamK commented Sep 12, 2024

Not much to go on here.
Please run the signal-cli command with -vv parameter to get more detailed logging.

@uriinf
Copy link
Author

uriinf commented Sep 21, 2024

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.

@AsamK
Copy link
Owner

AsamK commented Sep 21, 2024

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/

@uriinf
Copy link
Author

uriinf commented Sep 23, 2024

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

@jooray
Copy link
Contributor

jooray commented Nov 12, 2024

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.

@gwillem
Copy link

gwillem commented Nov 21, 2024

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

@AsamK
Copy link
Owner

AsamK commented Nov 21, 2024

@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?

@jooray
Copy link
Contributor

jooray commented Nov 21, 2024

For me it was definitely not catching up, I encountered the problem several times in one day and it processed recent messages.

@gwillem
Copy link

gwillem commented Nov 21, 2024

@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

@AsamK
Copy link
Owner

AsamK commented Nov 21, 2024

@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.

@gwillem
Copy link

gwillem commented Nov 21, 2024

Thanks @AsamK that worked for us!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants