search

AsamK / signal-cli

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

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

Open uriinf opened 2 months ago

uriinf commented 2 months ago

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 commented 2 months ago

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

uriinf commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

Removing of msg-cache didn't help. CPU usage is still 100%.

signal-cli -vvv --output=json --config /home/.local/share/signal-cli jsonRpc ```sh 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=, 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........................ 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.(SQLiteConnection.java:67) at org.sqlite.jdbc3.JDBC3Connection.(JDBC3Connection.java:28) at org.sqlite.jdbc4.JDBC4Connection.(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.(HikariPool.java:98) at com.zaxxer.hikari.HikariDataSource.(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 commented 5 days ago

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.