Messages sent from Signal Desktop do not appear in Signal for Android, instead a notification about "message not being able to be decrypted" appears

derMart commented 2 years ago

[x] I have searched open and closed issues for duplicates
[x] I am using Signal-Desktop as provided by the Signal team, not a 3rd-party package.

Bug Description

Since I suppose Signal Desktop 5.61.1 for Linux (using snap package), every time I send a message from desktop to somebody, this message does not get synced to my Android instance. Instead I receive a notification in the Android app, that a message sent from myself (supposedly the desktop instance) can not be decrypted. This did not happen for 5.59

Steps to Reproduce

Send a Message from Signal Desktop

Actual Result:

A notification on Signal Android appears as described above. But the message sent from desktop does not appear in the respective chat.

Expected Result:

No notification on Signal Android should appear, instead the sent message should be shown in the respective chat.

Platform Info

Signal Desktop Version: 5.61.1

Operating System:

Ubuntu 22.04

Linked Device Version:

Signal Android Version: 5.51.6.0

Debug Log

This is the relevant log on the Desktop side:

INFO PUT (WS) https://chat.signal.org/v1/messages/[REDACTED] 200 Success
INFO Message.tsx: Rendered 'send complete' for message [REDACTED]; took 496ms
INFO conversation job queue: job [REDACTED] succeeded on attempt 1
INFO changedConvoBatcher: deduped 1 into 1
INFO checkExpiringMessages: checking for expiring messages
INFO checkExpiringMessages: found no messages to expire
INFO RetryPlaceholders.getExpiredAndRemove: Found 0 expired items
INFO retryPlaceholders/interval: Found 0 expired items
INFO attachment_downloads/_maybeStartJob: no attachment jobs to run
INFO NotificationService: clearing notification and requesting an update
INFO markConversationRead {"conversationId":"[REDACTED] ([REDACTED])","newestSentAt":[REDACTED],"newestUnreadAt":[REDACTED],"unreadMessages":0,"unreadReactions":0}
INFO Updating BrowserWindow config: %s {"maximized":false,"autoHideMenuBar":false,"fullscreen":false,"width":1121,"height":614,"x":228,"y":283}
INFO config/set: Saving ephemeral config to disk
INFO config/set: Saved ephemeral config to disk
INFO NotificationService not updating notifications. Notifications are enabled; app is focused; there is no notification data
INFO changedConvoBatcher: deduped 1 into 1
INFO CompositionInput: Submitting message [REDACTED] with 0 mentions
INFO Send pre-checks took 6 milliseconds
INFO Sending message to conversation [REDACTED] ([REDACTED]) with timestamp [REDACTED]
WARN lookupOrCreate: Called with neither e164 nor uuid!
INFO enqueueMessageForSend: saving message [REDACTED] and job [REDACTED]
INFO JobQueueDatabaseStore adding job [REDACTED] to queue "conversation"
INFO conversation job queue: added new job [REDACTED]
INFO conversation job queue: enqueuing job [REDACTED]
INFO conversation job queue: running job [REDACTED], attempt 1 of 110
INFO conversation job queue, job ID [REDACTED], attempt 1: calculating timeRemaining and shouldContinue...
INFO ConversationModel([REDACTED] ([REDACTED]).sendMessage([REDACTED]): render save took 106ms
INFO conversation job queue, job ID [REDACTED], attempt 1: sleeping for 0
INFO Our profile key service: kicking off a new fetch
INFO Our profile key service: waiting for 0 promises before fetching
INFO Our profile key service: fetching profile key from storage
INFO conversation job queue, job ID [REDACTED], attempt 1: sending sync message only
INFO Sending a message with 0 mentions and 0 placeholders
INFO commitZoneChanges(storeSession): pending sender keys 0, pending sessions 1, pending unprocessed 0
INFO PUT (WS) https://chat.signal.org/v1/messages/[REDACTED]
INFO markConversationRead {"conversationId":"[REDACTED] ([REDACTED])","newestSentAt":[REDACTED],"newestUnreadAt":[REDACTED],"unreadMessages":0,"unreadReactions":0}
INFO PUT (WS) https://chat.signal.org/v1/messages/[REDACTED] 200 Success
INFO changedConvoBatcher: deduped 1 into 1
INFO Message.tsx: Rendered 'send complete' for message [REDACTED]; took 481ms
INFO conversation job queue: job [REDACTED] succeeded on attempt 1
INFO changedConvoBatcher: deduped 1 into 1
INFO checkExpiringMessages: checking for expiring messages
INFO checkExpiringMessages: found no messages to expire
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO attachment_downloads/_maybeStartJob: no attachment jobs to run
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO attachment_downloads/_maybeStartJob: no attachment jobs to run
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO attachment_downloads/_maybeStartJob: no attachment jobs to run
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO attachment_downloads/_maybeStartJob: no attachment jobs to run
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO WebSocketResources: Sending a keepalive message
INFO SocketManager: shutting down unauthenticated socket after timeout
INFO WebSocketResource: no active requests, closing
INFO WebSocketResource.close()
INFO SocketManager: connecting unauthenticated socket
WARN WebSocketResource: Socket closed

This should be the relevant lines on Android side when the message is trying to be synced:

10-06 31933 D IncomingMessageObserver: Network: true, Foreground: true, FCM: true, Stay open requests: [], Censored: false, Registered: true, Proxy: false
10-06 31886 31933 D IncomingMessageObserver: Reading message...
10-06 31886 31940 I libsignal: rust/protocol/src/session_cipher.rs:639: [REDACTED] creating new chains.
10-06 31886 31940 I libsignal: rust/protocol/src/state/session.rs:239: Trimming excessive receiver_chain for session with base key [REDACTED], chain count: 6
10-06 31886 31940 W libsignal: rust/protocol/src/protocol.rs:152: Bad Mac! Their Mac: [REDACTED] Our Mac: [REDACTED]
10-06 31886 31940 W libsignal: rust/protocol/src/session_cipher.rs:405: Failed to decrypt Whisper message with ratchet key: [REDACTED] and counter: 26. Session loaded for [REDACTED] Local session has base key: [REDACTED] and counter: 106. invalid Whisper message: MAC verification failed
10-06 31886 31940 E libsignal: rust/protocol/src/session_cipher.rs:504: No valid session for recipient: [REDACTED], current session base key [REDACTED], number of previous states: 0
10-06 31886 31940 E libsignal: rust/protocol/src/session_cipher.rs:518: Message from [REDACTED] failed to decrypt; sender ratchet public key [REDACTED] message counter 26
10-06 31886 31940 E libsignal: Candidate session 0 failed with 'invalid Whisper message: MAC verification failed', had 5 receiver chains
10-06 31886 31940 E libsignal: Receiver chain with sender ratchet public key [REDACTED] chain key index 3
10-06 31886 31940 E libsignal: Receiver chain with sender ratchet public key [REDACTED] chain key index 1
10-06 31886 31940 E libsignal: Receiver chain with sender ratchet public key [REDACTED] chain key index 5
10-06 31886 31940 E libsignal: Receiver chain with sender ratchet public key [REDACTED] chain key index 1
10-06 31886 31940 E libsignal: Receiver chain with sender ratchet public key [REDACTED] chain key index 3
10-06 31886 31940 W MessageDecryptionUtil: [REDACTED]
10-06 31886 31940 W MessageDecryptionUtil: org.signal.libsignal.metadata.ProtocolInvalidMessageException: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
10-06 31886 31940 W MessageDecryptionUtil:  at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:230)
10-06 31886 31940 W MessageDecryptionUtil:  at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:147)
10-06 31886 31940 W MessageDecryptionUtil:  at org.thoughtcrime.securesms.messages.MessageDecryptionUtil.decrypt(MessageDecryptionUtil.java:121)
10-06 31886 31940 W MessageDecryptionUtil:  at org.thoughtcrime.securesms.jobs.PushDecryptMessageJob.onRun(PushDecryptMessageJob.java:103)
10-06 31886 31940 W MessageDecryptionUtil:  at org.thoughtcrime.securesms.jobs.BaseJob.run(BaseJob.java:32)
10-06 31886 31940 W MessageDecryptionUtil:  at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:86)
10-06 31886 31940 W MessageDecryptionUtil:  at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:49)
10-06 31886 31940 W MessageDecryptionUtil: Caused by: org.signal.libsignal.protocol.InvalidMessageException: invalid Whisper message: decryption failed
10-06 31886 31940 W MessageDecryptionUtil:  at org.signal.libsignal.internal.Native.SessionCipher_DecryptSignalMessage(Native Method)
10-06 31886 31940 W MessageDecryptionUtil:  at org.signal.libsignal.protocol.SessionCipher.decrypt(SessionCipher.java:131)
10-06 31886 31940 W MessageDecryptionUtil:  at org.whispersystems.signalservice.api.crypto.SignalSessionCipher.decrypt(SignalSessionCipher.java:44)
10-06 31886 31940 W MessageDecryptionUtil:  at org.whispersystems.signalservice.api.crypto.SignalServiceCipher.decrypt(SignalServiceCipher.java:194)
10-06 31886 31940 W MessageDecryptionUtil:  ... 6 more
10-06 31886 31940 W MessageDecryptionUtil: [[REDACTED]] Could not decrypt a message with a type of DEFAULT
10-06 31886 31940 W MessageDecryptionUtil: [[REDACTED]] Inserting an error right away because it's DEFAULT

The problem can also be reproduced by trying to send a message to self from desktop to android instance. This is what I did to generate above logs.

cheers

derMart commented 2 years ago

Looks kind of similar to https://github.com/signalapp/Signal-Desktop/issues/1296

scottnonnenberg-signal commented 2 years ago

We need the full log to be sure, but it's highly likely that you have two Desktops that are conflicting with each other, both trying to be the same device. Your phone thinks it's talking to one of them, then the other, and that causes decryption errors. Did you happen to copy your Desktop information from one computer to another?

derMart commented 2 years ago

@scottnonnenberg-signal Thanks for the analysis, but what you describe is not the case. I do only have one instance of Signal Desktop installed and running (that is one instance in total over all my machines). I also thus never copied the data of one instance to another. Maybe during the automatic snap update something gone wrong?

I am very hesitant to give you a full log of the desktop app. There is loads of loads of meta information in there (timestamps when messages were sent, parts of IDs etc), which may be used to identify me, so probably I won't release this to the public. I am sure you can understand this. What information exactly are you interested in in the full log? I will then give you this information if not problematic.

derMart commented 2 years ago

What I can tell you is the number of processes the snap version of Signal Desktop is starting:

      8886  0.6  1.3 39037720 224884 ?     SLl  08:27   0:11 /snap/signal-desktop/398/opt/Signal/signal-desktop --use-tray-icon --no-sandbox --no-sandbox --enable-crashpad
      9003  0.0  0.2 33958320 47476 ?      S    08:27   0:00 /snap/signal-desktop/398/opt/Signal/signal-desktop --type=zygote --no-zygote-sandbox --no-sandbox --enable-crashpad --enable-crashpad
      9004  0.0  0.2 33958308 46100 ?      S    08:27   0:00 /snap/signal-desktop/398/opt/Signal/signal-desktop --type=zygote --no-sandbox --enable-crashpad --enable-crashpad
      9070  0.1  0.5 34145540 83264 ?      Sl   08:27   0:02 /snap/signal-desktop/398/opt/Signal/signal-desktop --type=gpu-process --no-sandbox --enable-crashpad --enable-crash-reporter=[REDACTED],no_channel --user-data-dir=/home/[REDACTED]/snap/signal-desktop/398/.config/Signal --gpu-preferences=[REDACTED] --shared-files --field-trial-handle=[REDACTED] --disable-features=HardwareMediaKeyHandling,SpareRendererForSitePerProcess
      9077  0.0  0.3 34024000 58668 ?      Sl   08:27   0:00 /snap/signal-desktop/398/opt/Signal/signal-desktop --type=utility --utility-sub-type=network.mojom.NetworkService --lang=en-US --service-sandbox-type=none --no-sandbox --enable-crashpad --enable-crash-reporter=[REDACTED],no_channel --user-data-dir=/home/[REDACTED]/snap/signal-desktop/398/.config/Signal --shared-files=v8_context_snapshot_data:100 --field-trial-handle=[REDACTED] --disable-features=HardwareMediaKeyHandling,SpareRendererForSitePerProcess --enable-crashpad
      9108  4.4  1.6 43229188 271740 ?     Sl   08:27   1:16 /snap/signal-desktop/398/opt/Signal/signal-desktop --type=renderer --enable-crashpad --enable-crash-reporter=[REDACTED],no_channel --user-data-dir=/home/[REDACTED]/snap/signal-desktop/398/.config/Signal --app-path=/snap/signal-desktop/398/opt/Signal/resources/app.asar --no-sandbox --no-zygote --disable-blink-features=Accelerated2dCanvas,AcceleratedSmallCanvases --no-sandbox --lang=en-US --num-raster-threads=4 --enable-main-frame-before-activation --renderer-client-id=4 --launch-time-ticks=48865183 --shared-files=v8_context_snapshot_data:100 --field-trial-handle=[REDACTED] --disable-features=HardwareMediaKeyHandling,SpareRendererForSitePerProcess --enable-crashpad
      9244  0.0  0.3 34114984 54336 ?      Sl   08:27   0:00 /snap/signal-desktop/398/opt/Signal/signal-desktop --type=utility --utility-sub-type=audio.mojom.AudioService --lang=en-US --service-sandbox-type=none --no-sandbox --enable-crashpad --enable-crash-reporter=[REDACTED],no_channel --user-data-dir=/home/[REDACTED]/snap/signal-desktop/398/.config/Signal --shared-files=v8_context_snapshot_data:100 --field-trial-handle=[REDACTED] --disable-features=HardwareMediaKeyHandling,SpareRendererForSitePerProcess --enable-crashpad

derMart commented 2 years ago

@scottnonnenberg-signal As a workaround I would like to recouple the Desktop instance with the Android instance. But I am unable to find a menu entry in the Desktop instance. Could you guide me to the relevant menu? EDIT: So essentially what I am looking for is how to show the current qr code with the current private key to be scanned on the android device. But I have trouble to find the relevant menu item which does this on Desktop... EDIT2: Or even just verify somehow if coupling got corrupted would be nice ...

scottnonnenberg-signal commented 2 years ago

If you go to the Linked Devices section of Signal Android, you can remove your linked desktop, and desktop will discover this and present you with a QR code again.

We very much need the full log to make progress on deep issues like this - I'm going to close this bug without that.

Would you consider sending logs to us directly?

scottnonnenberg-signal commented 2 years ago

One more thing, in case it helps: restoring from a backup can also cause these kinds of problems.

derMart commented 2 years ago

One more thing, in case it helps: restoring from a backup can also cause these kinds of problems.

I did not restore from backup. The problem appeared out of nowhere after an automatic update of signal desktop. Nothing else changed.

Would you consider sending logs to us directly?

Of course not! As said, the logs contain a lot of meta information able to identify me. I won't share this private information with anybody. Actually, I am very concerned that you even ask for this. Signal, at least that was my impression, is an app which respects privacy, but such behavior is sadly showing opposite...

We very much need the full log to make progress on deep issues like this - I'm going to close this bug without that.

Please don't close this issue. The issue is not solved. This is bad practice. Forcing users to reveal private information and using the closing of an issue as pressure to do so is very concerning too IMHO.

I would very much help you out on this. I am willing to help debugging with all my possibilities and non private information I can give you. So again, I am asking you: What are you looking for in those logs? Another thing which you can do, and what I would do If such bug occurs is to think about the places in the code and the changes done between 5.59 and 5.61 which could have caused this behavior.

scottnonnenberg-signal commented 2 years ago

The logs are redacted, expire after 30 days, and have only very limited metadata. Without those logs, we will not be able to make progress on this issue. Encryption errors in the Signal protocol are related to the state stored from previous messages, so historical interactions are extremely important. That's why this issue is closed.

derMart commented 2 years ago

Just tell me what you would do if you receive this log. I will be happy to do this for you and do the analysis you ask for.

EDIT: And just to clarify. What you write is sadly just not true. Yes, some portions of the logs are redacted. So not all parts of the keys are shown. But the logs do contain more than enough information for anybody who has access to your server to identify the public key, so the identity of my signal registration by just matching the timestamps to your server logs timestamps. So in essence with this log you will be able to get my phone number and what not. I hope that you see that it is very reasonable to not give this information away, especially to the administrators of the signal servers.

scottnonnenberg-signal commented 2 years ago

@derMart The analysis process is quite complicated, and just this back and forth on this issue is more time than we spend on the average bug. I'm sorry that your risk profile prevents us from moving forward. Once more, I suggest that you unlink and re-link in you mobile device, and things should work going forward.

scottnonnenberg-signal commented 2 years ago

@derMart Also, we'd love to hear your thoughts on how we could better redact the log. The stuff that isn't redacted that you mentioned - what is it?

derMart commented 2 years ago

@scottnonnenberg-signal Well if "this back and forth" we had right now is more time than you spend on the average bug, then the analysis process can't be that complicated. And also really, you started this back and forth, sorry. I mentioned in my second post that I won't give away the logs. At that point you would not have needed to ask for them again. So actually, I am sorry that you don't take my offer of my time and skill to help you with this bug. We both would probably learn something out of it, which would be beneficial for future issues, and I could help even more then. This is all I can offer and it is actually sad that you don't take it.

As for the logs, I am not sure (and also didn't say) that it might be even possible to render them anonymously. But if one would try, at first it would be good to remove the ISO time strings at the start of each line. Then there are unix timestamps, which also act as message ids? Then, I also see some IDs of other things which are not redacted. Of course, I am not sure if these are just local IDs or if they are persistent, but I guess if they are just local they might be redacted away anyway. And then the IDs which are redacted are not completely redacted, so they might be used for matching.
But even if all of this is done, so that there are no IDs and no timestamps in the logs, then there is still the information about the order of events, which might be used for matching with the data on the server. So question would be how hard it is to match this with the server data.

EDIT: To give you an example of what timestamps and IDs I am talking about, here is a (semantically changed) log line:

INFO  1984-12-07T01:23:71.871Z MessageReceiver.unsealEnvelope(> [REDACTED]abc 100000000000 (8fe4...)): unidentified message

So you got an ISO datetime, then I guess a suffix of some id ('abc'), then a unix timestamp (1000...) and then some hash I guess (8fe4...). This is just one example...

derMart commented 2 years ago

For anyone else reading this: Unlinking and relinking seems to be a workaround for me. Happily this does not delete existing messages in Signal Desktop which is very nice. But of course, it is not a fix for the underlying issue and it might happen again for me or somebody else.

signalapp / Signal-Desktop