Message to self could not be delivered
Schmiddiii opened this issue · 7 comments
Schmiddiii commented
I am getting repeated mentions of an issue that some messages don't get delivered to the main device (note: not only in note-to-self but also with contacts and groups), leading to the "A message from ... could not be delivered" in the note-to-self chat. Also got reports about "Invalid MMS message" and "chat session refreshed" on Signal Android. So it seens like not everything is working as it should right now.
From my testing, I got the "chat session refreshed" once while sending a message that did not arrive on the main device, any subsequent messages worked again.
Schmiddiii commented
I also recently had the issue and was able to get some logs from Signal Android:
[6.41.3] [7956 ] 2024-01-27 16:07:52.299 GMT+01:00 W libsignal: rust/protocol/src/protocol.rs:154: Bad Mac! Their Mac: 861d1678927e19d3 Our Mac: 6b7d7f64f84ab9af
[6.41.3] [7956 ] 2024-01-27 16:07:52.299 GMT+01:00 W libsignal: rust/protocol/src/session_cipher.rs:419: Failed to decrypt Whisper message with ratchet key: b9cd78604137e1cba9fbd26b218cc58da903724680400621419605b46e42000c and counter: 2. Session loaded for ********-****-****-****-*********c77.5. Local session has base key: 701fc10bea5dbfff747e779a86e22eb47f2fc5935fe815c0bcda493e1e234c2c and counter: 3. invalid Whisper message: MAC verification failed
(these three messages repeat a bunch of times with different keys and counters)
[6.41.3] [7956 ] 2024-01-27 16:07:52.381 GMT+01:00 W libsignal: rust/protocol/src/session_cipher.rs:419: Failed to decrypt Whisper message with ratchet key: a9cd78604137e1cba9fbd26b218cc58da903724680400621419605b46e42000c and counter: 2. Session loaded for ********-****-****-****-*********c76.5. Local session has base key: ad1c8f7ef494a488bf10208980cb1a15a342a822c2605891f903d6c8c3bf0571 and counter: 0. unrecognized message version <4>
(this also repeats a few times with different keys and counters)
Candidate session 0 failed with 'invalid Whisper message: MAC verification failed', had 5 receiver chains
Receiver chain with sender ratchet public key 0
1569cee6227c5be662ff77e24798276fc5527b4a4c26b7b3c383217dac66e3b403 chain key index 2
(repeats)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: [1706368070860] ********-****-****-****-*********c77:5 | Decryption error!
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: org.signal.libsignal.metadata.ProtocolInvalidMessageException: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decryptInternal(SignalServiceCipher.java:226)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:139)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.messages.MessageDecryptor.decrypt(MessageDecryptor.kt:138)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.messages.IncomingMessageObserver.processMessage(IncomingMessageObserver.kt:290)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.messages.IncomingMessageObserver.processEnvelope(IncomingMessageObserver.kt:278)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.messages.IncomingMessageObserver$MessageRetrievalThread$run$hasMore$1$1$1$1$followUpOperations$1.invoke(IncomingMessageObserver.kt:398)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.messages.IncomingMessageObserver$MessageRetrievalThread$run$hasMore$1$1$1$1$followUpOperations$1.invoke(IncomingMessageObserver.kt:397)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.database.SignalDatabase$Companion$runInTransaction$1.invoke(SignalDatabase.kt:346)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.database.SignalDatabase$Companion$runInTransaction$1.invoke(SignalDatabase.kt:345)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.signal.core.util.SQLiteDatabaseExtensionsKt.withinTransaction(SQLiteDatabaseExtensions.kt:20)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.database.SignalDatabase$Companion.runInTransaction(SignalDatabase.kt:345)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.messages.IncomingMessageObserver$MessageRetrievalThread.run$lambda$4(IncomingMessageObserver.kt:397)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.messages.IncomingMessageObserver$MessageRetrievalThread.$r8$lambda$pFsjOAfLHhrQuHtltxbtS8c-x88(IncomingMessageObserver.kt:0)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.messages.IncomingMessageObserver$MessageRetrievalThread$$ExternalSyntheticLambda0.onMessageBatch(R8$$SyntheticClass:0)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.whispersystems.signalservice.api.SignalWebSocket.readMessageBatch(SignalWebSocket.java:276)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.thoughtcrime.securesms.messages.IncomingMessageObserver$MessageRetrievalThread.run(IncomingMessageObserver.kt:388)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: Caused by: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.signal.libsignal.internal.Native.SessionCipher_DecryptSignalMessage(Native Method)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.signal.libsignal.protocol.SessionCipher.decrypt(SessionCipher.java:156)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.whispersystems.signalservice.api.crypto.SignalSessionCipher.decrypt(SignalSessionCipher.java:44)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decryptInternal(SignalServiceCipher.java:190)
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor: ... 15 more
[6.41.3] [7956 ] 2024-01-27 16:07:52.391 GMT+01:00 W MessageDecryptor:
[6.41.3] [7956 ] 2024-01-27 16:07:52.393 GMT+01:00 W MessageDecryptor: [1706368070860] ********-****-****-****-*********c77:5 | Decryption error for a sync message! Enqueuing a session reset job.
(...)
[6.41.3] [7972 ] 2024-01-27 16:07:52.787 GMT+01:00 W SignalServiceMessageSender: [sendMessage][1706368072508] Handling mismatched devices. (StatusCode: 409)
[6.41.3] [7972 ] 2024-01-27 16:07:52.787 GMT+01:00 W SignalServiceMessageSender: [handleMismatchedDevices] Address: ********-****-****-****-*********c77, ExtraDevices: [], MissingDevices: [1, 5]
[6.41.3] [7972 ] 2024-01-27 16:07:52.788 GMT+01:00 D PushServiceSocket: Fetching prekeys for ********-****-****-****-*********c76.1, i.e. GET /v2/keys/********-****-****-****-*********c77/1?pq=true
[6.41.3] [7972 ] 2024-01-27 16:07:53.702 GMT+01:00 I libsignal: rust/protocol/src/session.rs:211: set_unacknowledged_pre_key_message for: ********-****-****-****-*********c77.1 with preKeyId: 96996
[6.41.3] [7972 ] 2024-01-27 16:07:53.708 GMT+01:00 D PushServiceSocket: Fetching prekeys for ********-****-****-****-*********c76.5, i.e. GET /v2/keys/********-****-****-****-*********c77/5?pq=true
[6.41.3] [7972 ] 2024-01-27 16:07:53.847 GMT+01:00 I libsignal: rust/protocol/src/session.rs:211: set_unacknowledged_pre_key_message for: ********-****-****-****-*********c77.5 with preKeyId: 92
[6.41.3] [7972 ] 2024-01-27 16:07:53.848 GMT+01:00 I libsignal: rust/protocol/src/state/session.rs:668: Skipping archive, current session state is fresh
[6.41.3] [7972 ] 2024-01-27 16:07:53.893 GMT+01:00 I libsignal: rust/protocol/src/session_cipher.rs:73: Building PreKeyWhisperMessage for: ********-****-****-****-*********c77.5 with preKeyId: 92
(repeats)
[6.41.3] [7972 ] 2024-01-27 16:07:54.858 GMT+01:00 W BaseJob: [JOB::ee06efbb-9332-46cc-be28-25c266065ff7][AutomaticSessionResetJob] Encountered a failing exception. (Time Since Submission: 2462 ms, Lifespan: Immortal, Run Attempt: 1/1, Queue: __PUSH_PROCESS_JOB__RecipientId::1)
[6.41.3] [7972 ] 2024-01-27 16:07:54.858 GMT+01:00 W BaseJob: java.io.IOException: Failed to resolve conflicts after 4 attempts!
[6.41.3] [7972 ] 2024-01-27 16:07:54.858 GMT+01:00 W BaseJob: at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendMessage(SignalServiceMessageSender.java:2090)
[6.41.3] [7972 ] 2024-01-27 16:07:54.858 GMT+01:00 W BaseJob: at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendNullMessage(SignalServiceMessageSender.java:936)
[6.41.3] [7972 ] 2024-01-27 16:07:54.858 GMT+01:00 W BaseJob: at org.thoughtcrime.securesms.jobs.AutomaticSessionResetJob.sendNullMessage(AutomaticSessionResetJob.java:144)
[6.41.3] [7972 ] 2024-01-27 16:07:54.858 GMT+01:00 W BaseJob: at org.thoughtcrime.securesms.jobs.AutomaticSessionResetJob.onRun(AutomaticSessionResetJob.java:107)
[6.41.3] [7972 ] 2024-01-27 16:07:54.858 GMT+01:00 W BaseJob: at org.thoughtcrime.securesms.jobs.BaseJob.run(BaseJob.java:31)
[6.41.3] [7972 ] 2024-01-27 16:07:54.858 GMT+01:00 W BaseJob: at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:86)
[6.41.3] [7972 ] 2024-01-27 16:07:54.858 GMT+01:00 W BaseJob: at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:49)
[6.41.3] [7972 ] 2024-01-27 16:07:54.858 GMT+01:00 W BaseJob:
[6.41.3] [7972 ] 2024-01-27 16:07:54.860 GMT+01:00 W JobRunner: [JOB::ee06efbb-9332-46cc-be28-25c266065ff7][AutomaticSessionResetJob][4] Job failed. (Time Since Submission: 2463 ms, Lifespan: Immortal, Run Attempt: 1/1, Queue: __PUSH_PROCESS_JOB__RecipientId::1)
The key points seem to be an invalid MAC and an unrecognized message version.
As I don't have too much in-depth knowledge about the Signal protocol, I don't know how to debug this further. @gferon could you maybe look at the logs if you have some time; I can also send you the full logs if required.
boxdot commented
I have the same problem in gurk. I will monitor the logs there.
hrdl-github commented
boxdot/gurk-rs#234 (comment) tentatively suggests that this could be a downstream issue due to using multiple identified websockets. I'm not sure if your client exhibits similar behaviour.
Schmiddiii commented
I don't think we normally use multiple identified websockets at the same time.
We only request contact sync:
- Directly after linking, but before
receive_messages. - When initiated by the user via a menu entry; this could in theory have multiple opened websockets, but this menu entry is not easily discoverable and I doubt it was used on every startup where this issue was reported to me.
I don't know where else multiple websockets are opened though.
gferon commented
We have recently fixed a bunch of other issues. @Schmiddiii are you still having this particular issue? The multiple websockets are an issue specific with gurk.
Schmiddiii commented
I'm not sure, I just merged updating to the latest presage commit to master and did not even release that yet.
But I have not heared anyone having this issue for some quite some time.
I'll release the presage update probably this weekend.
In the meantime, I will close this issue and if someone again reports this on the new version, I will reopen it again.
hrdl-github commented
I've summarised my latest findings in boxdot/gurk-rs#234 (comment), which is still relevant for presage.