Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

Message to self could not be delivered #229

Open
Schmiddiii opened this issue Jan 14, 2024 · 2 comments
Open

Message to self could not be delivered #229

Schmiddiii opened this issue Jan 14, 2024 · 2 comments
Assignees
@boxdot

Comments

@Schmiddiii
Copy link
Contributor

Schmiddiii commented Jan 14, 2024 •
edited
Loading

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
Copy link
Contributor Author

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
Copy link
Collaborator

boxdot commented Jun 18, 2024 •
edited
Loading

I have the same problem in gurk. I will monitor the logs there.

@boxdot boxdot self-assigned this Jun 18, 2024
@boxdot boxdot mentioned this issue Jul 3, 2024
Open
@0xErnie 0xErnie mentioned this issue Sep 17, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@boxdot boxdot

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@boxdot @Schmiddiii