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.06k stars 288 forks source link

InvalidSessionException: Session not found. #1481

Open cuu508 opened 4 months ago

cuu508 commented 4 months ago

In the past couple days I've seen two cases of signal-cli RPC returning error code "-32603". In both cases, in signal-cli logs I see a traceback:

org.signal.libsignal.protocol.InvalidSessionException: Session not found.
        at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.encrypt(SignalServiceCipher.java:128)
        at org.whispersystems.signalservice.api.SignalServiceMessageSender.getEncryptedMessage(SignalServiceMessageSender.java:2641)
        at org.whispersystems.signalservice.api.SignalServiceMessageSender.getEncryptedMessages(SignalServiceMessageSender.java:2599)
        at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendMessage(SignalServiceMessageSender.java:2196)
        at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendContent(SignalServiceMessageSender.java:499)
        at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendDataMessage(SignalServiceMessageSender.java:452)
        at org.asamk.signal.manager.helper.SendHelper.lambda$sendMessage$20(SendHelper.java:669)
        at org.asamk.signal.manager.helper.SendHelper.handleSendMessage(SendHelper.java:697)
        at org.asamk.signal.manager.helper.SendHelper.sendMessage(SendHelper.java:667)
        at org.asamk.signal.manager.helper.SendHelper.sendMessage(SendHelper.java:96)
        at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:589)
        at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:563)
        at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:691)
        at org.asamk.signal.commands.SendCommand.handleCommand(SendCommand.java:243)
        at org.asamk.signal.commands.JsonRpcLocalCommand.handleCommand(JsonRpcLocalCommand.java:25)
        at org.asamk.signal.commands.JsonRpcLocalCommand.handleCommand(JsonRpcLocalCommand.java:15)
        at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler$CommandRunnerImpl.handleCommand(SignalJsonRpcCommandHandler.java:153)
        at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.parseParamsAndRunCommand(SignalJsonRpcCommandHandler.java:272)
        at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.runCommand(SignalJsonRpcCommandHandler.java:212)
        at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.handleRequest(SignalJsonRpcCommandHandler.java:90)
        at org.asamk.signal.jsonrpc.SignalJsonRpcDispatcherHandler.lambda$handleConnection$4(SignalJsonRpcDispatcherHandler.java:137)
        at org.asamk.signal.jsonrpc.JsonRpcReader.handleRequest(JsonRpcReader.java:134)
        at org.asamk.signal.jsonrpc.JsonRpcReader.handleMessage(JsonRpcReader.java:85)
        at org.asamk.signal.jsonrpc.JsonRpcReader.lambda$readMessages$0(JsonRpcReader.java:72)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1583)

I first saw this error while running signal-cli 0.13.0. I upgraded to 0.13.1, but recently saw it again.

The recipient is a phone number (not a group).

cuu508 commented 4 months ago

Another observation, both errors were for the same recipient. But, between the failures there was also one successful delivery:

AsamK commented 4 months ago

Hard to say what's going on, when sending a new session should be created automatically ... Maybe some inconsistency with aci/pni stores.

cuu508 commented 3 months ago

I noticed a different, but similar traceback. Just in case it has any clues, here it is:

ERROR SignalJsonRpcDispatcherHandler - Command execution failed
java.lang.IllegalStateException: No session for (********-****-****-****-**********82.3)!
        at org.signal.libsignal.protocol.SessionCipher.getRemoteRegistrationId(SessionCipher.java:166)
        at org.signal.libsignal.metadata.SealedSessionCipher.getRemoteRegistrationId(SealedSessionCipher.java:247)
        at org.whispersystems.signalservice.api.crypto.SignalSealedSessionCipher.getRemoteRegistrationId(SignalSealedSessionCipher.java:82)
        at org.whispersystems.signalservice.api.crypto.EnvelopeContent$Encrypted.processSealedSender(EnvelopeContent.java:92)
        at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.encrypt(SignalServiceCipher.java:123)
        at org.whispersystems.signalservice.api.SignalServiceMessageSender.getEncryptedMessage(SignalServiceMessageSender.java:2641)
        at org.whispersystems.signalservice.api.SignalServiceMessageSender.getEncryptedMessages(SignalServiceMessageSender.java:2599)
        at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendMessage(SignalServiceMessageSender.java:2196)
        at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendContent(SignalServiceMessageSender.java:499)
        at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendDataMessage(SignalServiceMessageSender.java:452)
        at org.asamk.signal.manager.helper.SendHelper.lambda$sendMessage$20(SendHelper.java:669)
        at org.asamk.signal.manager.helper.SendHelper.handleSendMessage(SendHelper.java:697)
        at org.asamk.signal.manager.helper.SendHelper.sendMessage(SendHelper.java:667)
        at org.asamk.signal.manager.helper.SendHelper.sendMessage(SendHelper.java:96)
        at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:589)
        at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:563)
        at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:691)
        at org.asamk.signal.commands.SendCommand.handleCommand(SendCommand.java:243)
        at org.asamk.signal.commands.JsonRpcLocalCommand.handleCommand(JsonRpcLocalCommand.java:25)
        at org.asamk.signal.commands.JsonRpcLocalCommand.handleCommand(JsonRpcLocalCommand.java:15)
        at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler$CommandRunnerImpl.handleCommand(SignalJsonRpcCommandHandler.java:153)
        at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.parseParamsAndRunCommand(SignalJsonRpcCommandHandler.java:272)
        at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.runCommand(SignalJsonRpcCommandHandler.java:212)
        at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.handleRequest(SignalJsonRpcCommandHandler.java:90)
        at org.asamk.signal.jsonrpc.SignalJsonRpcDispatcherHandler.lambda$handleConnection$4(SignalJsonRpcDispatcherHandler.java:137)
        at org.asamk.signal.jsonrpc.JsonRpcReader.handleRequest(JsonRpcReader.java:134)
        at org.asamk.signal.jsonrpc.JsonRpcReader.handleMessage(JsonRpcReader.java:85)
        at org.asamk.signal.jsonrpc.JsonRpcReader.lambda$readMessages$0(JsonRpcReader.java:72)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1583)

(produced by signal-cli 0.13.1)

AsamK commented 3 months ago

Thanks, I think I found the issue. In Signal-Android new sessions are cached in BufferedSessionStore, so signal-cli has to do the same.

cuu508 commented 1 month ago

Sorry to bring this up again, but I noticed a similar but slightly different traceback:

May 25 09:55:02 signal-cli[853367]: INFO  SocketHandler - Accepted new client connection 7111:  UnixDomainPrincipal[user=nobody, group=nogroup]
May 25 09:55:03 signal-cli[853367]: ERROR SignalJsonRpcDispatcherHandler - Command execution failed
May 25 09:55:03 signal-cli[853367]: org.signal.libsignal.protocol.InvalidSessionException: Session not found.
May 25 09:55:03 signal-cli[853367]:         at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.encrypt(SignalServiceCipher.java:128)
May 25 09:55:03 signal-cli[853367]:         at org.whispersystems.signalservice.api.SignalServiceMessageSender.getEncryptedMessage(SignalServiceMessageSender.java:2978)
May 25 09:55:03 signal-cli[853367]:         at org.whispersystems.signalservice.api.SignalServiceMessageSender.getEncryptedMessages(SignalServiceMessageSender.java:2936)
May 25 09:55:03 signal-cli[853367]:         at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendMessage(SignalServiceMessageSender.java:2231)
May 25 09:55:03 signal-cli[853367]:         at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendContent(SignalServiceMessageSender.java:512)
May 25 09:55:03 signal-cli[853367]:         at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendDataMessage(SignalServiceMessageSender.java:467)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.manager.helper.SendHelper.lambda$sendMessage$20(SendHelper.java:657)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.manager.helper.SendHelper.handleSendMessage(SendHelper.java:685)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.manager.helper.SendHelper.sendMessage(SendHelper.java:655)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.manager.helper.SendHelper.sendMessage(SendHelper.java:96)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:617)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:591)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:719)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.commands.SendCommand.handleCommand(SendCommand.java:245)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.commands.JsonRpcLocalCommand.handleCommand(JsonRpcLocalCommand.java:25)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.commands.JsonRpcLocalCommand.handleCommand(JsonRpcLocalCommand.java:15)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler$CommandRunnerImpl.handleCommand(SignalJsonRpcCommandHandler.java:153)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.parseParamsAndRunCommand(SignalJsonRpcCommandHandler.java:272)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.runCommand(SignalJsonRpcCommandHandler.java:212)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.handleRequest(SignalJsonRpcCommandHandler.java:90)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.jsonrpc.SignalJsonRpcDispatcherHandler.lambda$handleConnection$4(SignalJsonRpcDispatcherHandler.java:137)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.jsonrpc.JsonRpcReader.handleRequest(JsonRpcReader.java:134)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.jsonrpc.JsonRpcReader.handleMessage(JsonRpcReader.java:85)
May 25 09:55:03 signal-cli[853367]:         at org.asamk.signal.jsonrpc.JsonRpcReader.lambda$readMessages$0(JsonRpcReader.java:72)
May 25 09:55:03 signal-cli[853367]:         at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
May 25 09:55:03 signal-cli[853367]:         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
May 25 09:55:03 signal-cli[853367]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
May 25 09:55:03 signal-cli[853367]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
May 25 09:55:03 signal-cli[853367]:         at java.base/java.lang.Thread.run(Thread.java:1583)
May 25 09:55:03 signal-cli[853367]: INFO  SocketHandler - Connection 7111 closed:  UnixDomainPrincipal[user=nobody, group=nogroup]

This is from 2 days ago, running signal-cli 0.13.3

AsamK commented 1 month ago

From the code I can't see how this can happen, there's a containsSession check before loading the session. A verbose log might show more details on what's going on here.

cuu508 commented 3 weeks ago

I haven't seen "Session not found." in the last couple of weeks, so not much to do here, I'll close this.

I added the --verbose flag so hopefully will have more logs if I do see it again.

cuu508 commented 1 week ago

I saw another "Session not found" error. This is on Ubuntu 24.04 running signal-cli 0.13.4. The signal-cli instance is a linked device, and it was set up and linked less than a month ago (i.e., it is not an old instance that has gone through several signal-cli versions).

Logs:

2024-07-03T06:00:05.557+0200 [daemon-listener] INFO  o.asamk.signal.jsonrpc.SocketHandler - Accepted new client connection 2461:  UnixDomainPrincipal[user=nobody, group=nogroup]
2024-07-03T06:00:05.557+0200 [pool-2466-thread-1] DEBUG o.asamk.signal.jsonrpc.JsonRpcReader - Received json rpc request, method: send
2024-07-03T06:00:05.558+0200 [pool-2466-thread-1] WARN  LibSignal - [PhoneNumberFormatter]: Got local CC: US
2024-07-03T06:00:05.656+0200 [RxCachedThreadScheduler-3442] DEBUG o.a.s.m.s.i.IdentityKeyStore - Storing new identity for recipient ********-****-****-****-**********7b with trust TRUSTED_UNVERIFIED
2024-07-03T06:00:05.756+0200 [RxCachedThreadScheduler-3442] DEBUG o.a.s.m.s.recipients.RecipientStore - Marking RecipientId[id=1434] as registered=true
2024-07-03T06:00:05.757+0200 [pool-2466-thread-1] DEBUG o.a.s.m.s.i.IdentityKeyStore - Storing new identity for recipient ********-****-****-****-**********7b with trust TRUSTED_UNVERIFIED
2024-07-03T06:00:05.878+0200 [pool-1-thread-33] INFO  LibSignal - [libsignal]: rust/protocol/src/state/session.rs:697: Skipping archive, current session state is fresh
2024-07-03T06:00:05.912+0200 [pool-2466-thread-1] WARN  LibSignal - [SignalServiceMessageSender]: [sendMessage][1719979205558] Handling stale devices. (StatusCode: 410)
2024-07-03T06:00:05.912+0200 [pool-2466-thread-1] WARN  LibSignal - [SignalServiceMessageSender]: [handleStaleDevices] Address: ********-****-****-****-**********7b, StaleDevices: [1]
2024-07-03T06:00:05.921+0200 [pool-2466-thread-1] INFO  LibSignal - [libsignal]: rust/protocol/src/state/session.rs:697: Skipping archive, current session state is fresh
2024-07-03T06:00:06.344+0200 [pool-2466-thread-1] INFO  LibSignal - [libsignal]: rust/protocol/src/session.rs:209: set_unacknowledged_pre_key_message for: ********-****-****-****-**********7b.1 with preKeyId: 10051125
2024-07-03T06:00:06.345+0200 [pool-2466-thread-1] DEBUG o.a.s.m.s.i.IdentityKeyStore - Storing new identity for recipient ********-****-****-****-**********7b with trust TRUSTED_UNVERIFIED
2024-07-03T06:00:06.395+0200 [pool-1-thread-33] INFO  LibSignal - [libsignal]: rust/protocol/src/state/session.rs:697: Skipping archive, current session state is fresh
2024-07-03T06:00:06.470+0200 [pool-2466-thread-1] ERROR o.a.s.j.SignalJsonRpcDispatcherHandler - Command execution failed
org.signal.libsignal.protocol.InvalidSessionException: Session not found.
     at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.encrypt(SignalServiceCipher.java:128)
     at org.whispersystems.signalservice.api.SignalServiceMessageSender.getEncryptedMessage(SignalServiceMessageSender.java:2982)
     at org.whispersystems.signalservice.api.SignalServiceMessageSender.getEncryptedMessages(SignalServiceMessageSender.java:2940)
     at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendMessage(SignalServiceMessageSender.java:2235)
     at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendContent(SignalServiceMessageSender.java:511)
     at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendDataMessage(SignalServiceMessageSender.java:466)
     at org.asamk.signal.manager.helper.SendHelper.lambda$sendMessage$20(SendHelper.java:657)
     at org.asamk.signal.manager.helper.SendHelper.handleSendMessage(SendHelper.java:685)
     at org.asamk.signal.manager.helper.SendHelper.sendMessage(SendHelper.java:655)
     at org.asamk.signal.manager.helper.SendHelper.sendMessage(SendHelper.java:96)
     at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:624)
     at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:598)
     at org.asamk.signal.manager.internal.ManagerImpl.sendMessage(ManagerImpl.java:726)
     at org.asamk.signal.commands.SendCommand.handleCommand(SendCommand.java:245)
     at org.asamk.signal.commands.JsonRpcLocalCommand.handleCommand(JsonRpcLocalCommand.java:25)
     at org.asamk.signal.commands.JsonRpcLocalCommand.handleCommand(JsonRpcLocalCommand.java:15)
     at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler$CommandRunnerImpl.handleCommand(SignalJsonRpcCommandHandler.java:153)
     at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.parseParamsAndRunCommand(SignalJsonRpcCommandHandler.java:272)
     at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.runCommand(SignalJsonRpcCommandHandler.java:212)
     at org.asamk.signal.jsonrpc.SignalJsonRpcCommandHandler.handleRequest(SignalJsonRpcCommandHandler.java:90)
     at org.asamk.signal.jsonrpc.SignalJsonRpcDispatcherHandler.lambda$handleConnection$4(SignalJsonRpcDispatcherHandler.java:137)
     at org.asamk.signal.jsonrpc.JsonRpcReader.handleRequest(JsonRpcReader.java:134)
     at org.asamk.signal.jsonrpc.JsonRpcReader.handleMessage(JsonRpcReader.java:85)
     at org.asamk.signal.jsonrpc.JsonRpcReader.lambda$readMessages$0(JsonRpcReader.java:72)
     at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
     at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
     at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
     at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
     at java.base/java.lang.Thread.run(Thread.java:1583)
2024-07-03T06:00:06.472+0200 [pool-4-thread-1799] INFO  o.asamk.signal.jsonrpc.SocketHandler - Connection 2461 closed:  UnixDomainPrincipal[user=nobody, group=nogroup]