All messages read in Signal-Desktop but not on Android #5052

hiqua · 2021-02-20T22:59:03Z

I have searched open and closed issues for duplicates

(honestly I'm sure there is one somewhere, I just cannot find it...)

Bug Description

State on desktop: nothing to read, up to date.
State on Android: 2 messages to read in a group (group V2). I had received these messages on Desktop. Both devices on the same (reliable) Internet connection.

I tried to restart signal desktop, but it didn't change anything. I sent messages from my Android / Desktop (from other discussions) and it was working, so no connection problem.

Steps to Reproduce

No reliable way, but:

receive messages in a group
read them on desktop

Actual Result:

I had two messages to read in a group on Android.

Expected Result:

All messages read on Desktop should appear read on Android.

Platform Info

Signal Version:

1.40

Operating System:

Debian

Linked Device Version:
5.3.12

Link to Debug Log

Before reading the messages on Android:
desktop: https://debuglogs.org/de1d908255d5490f2d45b742e5bf1bd6b41b7b46350f50480f6f5c7b6e35c7ae
android: https://debuglogs.org/d9dae580a765d8e90faf2be2feba07796e985ec09d4a031f7d9254f89a1fa0f0

After having read the messages on Android:
desktop: https://debuglogs.org/c91dccb8784a98d828d802f9b73eab773f2e534f4d41785c9df45c2bd7d94e70
android: https://debuglogs.org/29fab26c71c9b62769c272941df108f2c68dd29d185b0fd6acf6bdbc1fe8e7bb

hiqua · 2021-04-13T14:36:13Z

Just had this again. It only happened in group conversations (2 of them), maybe that only happens in this case.

desktop: https://debuglogs.org/dc1f0f0abd40d94f69f928fc78a312644f916b851b1e2f73879c27ca40fe4841
android: https://debuglogs.org/8377e73daae038228f30d7791f070cbfa994f0d31cc60ae27a7d6a45b6d24d29

Android: 5.6.4
Desktop: 5.0.0

EvanHahn-Signal · 2021-04-15T16:06:31Z

Thanks for sharing this.

You may already know this, but devices send "read syncs" to each other, effectively telling your other devices that you've read a message. From your logs, I'm not sure whether Desktop is failing to send read syncs or if Android is failing to receive them.

It'd be super helpful for us if you could get a reliable reproduction for this. It's helpful that it's happened in group conversations, but more specifics would be super useful.

hiqua · 2021-04-15T16:47:13Z

Nothing I can reproduce so far, and apparently it just happens once in a while so it's really low priority, I just want to document when it does happen, maybe I'll find a pattern eventually!

hiqua · 2021-04-23T16:09:44Z

Muted group. Phone was away so I'd guess the message was received later on Android than on Desktop.

The message was marked as read after I had reacted to it from Desktop.

Desktop
https://debuglogs.org/300e2b5b54391ae055fdede97da84528f09bae5198ad50c6da00543b10fc1057

Android, when message was not marked as read:
https://debuglogs.org/4b41ffec634451c45cc5230c112a7300b31ed04ad8a686c7b9c9c94cee4594df
Once message was marked as read, because of a reaction from Desktop:
https://debuglogs.org/909d500758bcb66417c0a0a1bc67213f84f714573f82aad175e47e0f179ce687

I managed to reproduce it a few times. Nothing to do with the muted status.

Interestingly, I had the case where the message was read on two linked devices: I read it on one, and it was then propagated to the other device, but not Android.

This happens more when I used the battery saver on Android, which shouldn't allow Signal to run in the background. So the bug would be something to do with receiving the message after a manual wake-up.

New example with the last Android version (5.8):
desktop: https://debuglogs.org/4882c3d66741bc5f303edb25a44688ec112d4372cb3e9b46333655b9bf583b14

android before reading: https://debuglogs.org/f46172af7177f9517934a4768190286b05004868c08729a5b63476b715521f90

android after reading: https://debuglogs.org/00c342efd3c2fa8dc9dffc38f472f3649bff3bbd8b9cec12a200b76808d1d6c8

greyson-signal · 2021-04-27T01:12:10Z

If you foreground the android app, do you receive the read syncs?

hiqua · 2021-04-27T05:15:30Z

@greyson-signal no, that's the part which surprises me.

hiqua · 2021-04-28T18:23:19Z

Desktop: https://debuglogs.org/dc02287cb50aa7cc209de187ff7698e5b0c71bf0b904b6f0ba6eb547995df57f

Android: https://debuglogs.org/5df295e155311d741e0b82335ae733f6b3a9a4cf35cc0adf87aa7a90858b3d76
Android after having read the two messages: https://debuglogs.org/c7caf6e889708ae7f106fb9f38787e9123129501c8ce0166a83b3a797a6ee2ba

3 messages from a group, sent at the same time from a contact. 2 messages marked as not read on Android.

In the Desktop log,

INFO  2021-04-28T18:08:25.452Z Sending 1 read syncs
INFO  2021-04-28T18:08:38.911Z Sending 2 read syncs

I think the 2 last read syncs failed at some point. I should check whether this only happens with multiple messages, maybe the bug doesn't happen if messages are sent or received one by one.

Other thing: when I open the group convo, it only said "1 unread message", contradicting the blue 2 in the main view. Not sure what's this about. But it could be just a UI bug (receiving read receipts would not trigger an update in the Android interface in some cases?)

scottnonnenberg-signal · 2021-04-30T01:05:50Z

@hiqua What do you mean by "I think the 2 last read syncs failed at some point."?

hiqua · 2021-04-30T07:10:03Z

I just meant that since I had two messages unread and that the timestamps seemed to match, the 2 read sync mentioned are probably the ones that are either:

not sent properly by desktop
not received by Android
not processed correctly by Android

scottnonnenberg-signal · 2021-04-30T17:03:35Z

One thing you can do to make sure you're in good shape for a future bug report is: making sure both sides are at zero unread. We have seen issues in the past where Desktop might fail to send a read sync, and then Android would never go mark that old message read, leading to confusing conversation badges on Android.

hiqua · 2021-04-30T18:22:19Z

So you mean:

open the conversations on desktop and android
double-check that there's no unread message within the conversation (on top of not having any badge in the first place)
then send messages to try to reproduce the bug

Is this what you mean?

scottnonnenberg-signal · 2021-04-30T23:13:13Z

@hiqua Yes, essentially start over from the clean slate to figure out what's really causing it.

hiqua · 2021-07-28T18:47:53Z

Sorry I haven't spent much more time trying to reproduce the issue, but I just encountered it again, so here are logs in case you added more information in new versions.

Before reading the faulty conversation:

After reading it on Android:

scottnonnenberg-signal · 2021-07-28T20:36:48Z

@hiqua Thanks for the updated log. If you can provide the 'sent id' for the message that wasn't marked read properly, that will help us zero in on the log. As always, you can grab it by going to message details for that message and grabbing the number next to the sent timestamp.

hiqua · 2021-07-28T21:02:57Z

Ah yeah sorry I forgot. Here is the info:

Conversation id: dd5

The three relevant messages:

1627497015385
1627497025003
1627497030992

See in desktop logs:

INFO  2021-07-28T18:47:07.543Z read sync +[REDACTED]443 [REDACTED]313 1627498025969 [REDACTED]327 for message 1627497015385
INFO  2021-07-28T18:47:07.544Z MessageReceiver.decryptAndCacheBatch fully processed
INFO  2021-07-28T18:47:07.547Z read sync +[REDACTED]443 [REDACTED]313 1627498025969 [REDACTED]327 for message 1627497025003
INFO  2021-07-28T18:47:07.559Z ts/sql/main: slow query saveMessage duration=12ms
INFO  2021-07-28T18:47:07.562Z incrementProgress: Message count is 480
INFO  2021-07-28T18:47:07.562Z read sync +[REDACTED]443 [REDACTED]313 1627498025969 [REDACTED]327 for message 1627497030992

scottnonnenberg-signal · 2021-07-28T21:31:40Z

Okay, to confirm. You read the message on Desktop, but that's not being reflected on Android?

Here are the three moments Desktop sent read syncs between its receipt of that first message you point to, and when it gets read sync messages from your Android:

// You got message 1627497015385
INFO  2021-07-28T18:30:16.471Z queueing envelope 1627497015385 (ec917dda160e4eb7929ddd42ead8a8fa)
INFO  2021-07-28T18:30:16.471Z MessageReceiver.decryptContentMessage 1627497015385 (ec917dda160e4eb7929ddd42ead8a8fa)
INFO  2021-07-28T18:30:16.471Z decrypt/1627497015385 (ec917dda160e4eb7929ddd42ead8a8fa): unidentified message
INFO  2021-07-28T18:30:16.473Z decrypt/[REDACTED]313.1 1627497015385 (ec917dda160e4eb7929ddd42ead8a8fa): unidentified message/passing to
INFO  2021-07-28T18:30:16.483Z queueing decrypted envelope [REDACTED]313.1 1627497015385 (ec917dda160e4eb7929ddd42ead8a8fa)
INFO  2021-07-28T18:30:16.484Z MessageReceiver.handleDataMessage [REDACTED]313.1 1627497015385 (ec917dda160e4eb7929ddd42ead8a8fa)
INFO  2021-07-28T18:30:16.484Z Starting handleDataMessage for message [REDACTED]313.1 1627497015385 in conversation groupv2([REDACTED]LB4=)
INFO  2021-07-28T18:30:16.484Z handleDataMessage: duplicate check db lookup needed [REDACTED]327.1-1627497015385
INFO  2021-07-28T18:30:16.487Z handleDataMessage: Batching save for 1627497015385
INFO  2021-07-28T18:30:16.573Z Message saved 1627497015385
...
// First read sync
INFO  2021-07-26T18:34:54.255Z markConversationRead {"conversationId":"[REDACTED]b08","newestUnreadId":1627323256415,"unreadMessages":1,"unreadReactions":0}
INFO  2021-07-26T18:34:54.266Z Sending 1 read syncs
...
// Second read sync send
INFO  2021-07-26T18:35:20.060Z markConversationRead {"conversationId":"[REDACTED]e42","newestUnreadId":1627323256416,"unreadMessages":1,"unreadReactions":3}
INFO  2021-07-26T18:35:20.070Z Sending 4 read syncs
...
// Third read sync send
INFO  2021-07-26T18:42:24.674Z markConversationRead {"conversationId":"[REDACTED]e42","newestUnreadId":1627323256436,"unreadMessages":9,"unreadReactions":0}
INFO  2021-07-26T18:42:24.749Z Sending 9 read syncs
...
// Got read sync from android
INFO  2021-07-28T18:47:07.543Z read sync +[REDACTED]443 [REDACTED]313 1627498025969 [REDACTED]327 for message 1627497015385

Based on that log, it's like you didn't read that conversation. Or is one of those read sync sends for the conversation in question?

hiqua · 2021-07-28T22:03:51Z

Okay, to confirm. You read the message on Desktop, but that's not being reflected on Android?

Yup

Based on that log, it's like you didn't read that conversation. Or is one of those read sync sends for the conversation in question?

The (truncated) conversation ID is dd5, so the first three don't match.

The last one (from Android) matches the phone number, and it's one of the messages.

I can confirm that the UI from Signal-Desktop was not indicating any unread message, but I didn't take screenshots, I'll try to do that next time.

Also to try next time for me: check what's the status in another signal-desktop instance, and if I can read it there.

Edit: for what it's worth, logs from another Signal-Desktop instance, after everything: https://debuglogs.org/96d4804d6158736f79d6a3fe42b68a155c770acefa7bf64569394de2b794173d.gz

hiqua · 2021-07-29T22:27:07Z

Just got another one, in a group.

Message id: 1627596271094

Android before reading from Android: https://debuglogs.org/b58410de733d27fcd5f28baa5c196ca8d575616b102abee11800962fe693cf8c
Android after reading from Android: https://debuglogs.org/e5817d242972e9e0ffc4e84447f7331f08ff4940d050afd7896383d5f73c6877
Desktop beta: https://debuglogs.org/09910cad9d7215092c9905353b01655203fc05543a5c1946265632d0edfb8994.gz
Desktop: https://debuglogs.org/fcb775c9e4ed3d19c3b2a3e0e65131bf291c1b7a16d20f5098b30e70a82034fe.gz

Desktop and Desktop beta agree with each other and consider everything as read, Android doesn't.

EvanHahn-Signal · 2021-07-30T15:22:49Z

v5.12.0-beta.1 has a change (see 18140c4) that will retry read syncs for ~24 hours. It seems like this might fix some of the problems you're having, as it seems like Desktop isn't fully sending read syncs in some cases. Does that sound right to you?

hiqua · 2021-07-30T16:08:30Z

Note that my previous comment mentions an occurrence of this bug on the version you're mentioning, v5.12.0-beta.1. So it looks like it doesn't fix it, at least not fast enough for me not to notice.

Regarding the fix itself, since we don't really know the origin I can't really judge whether it will change anything. Since the other instance of Signal-Desktop marked the message as read I would tend to say it's a bug on the Android side. Since I have a LineageOS there, it's also expected that it's less tested overall, while I don't expect my Debian to be particularly surprising for Signal-Desktop.

kaimast · 2021-08-24T18:20:58Z

I seem to have the same issue. No read notifications are synced from the Desktop client to Android.

My phone has Signal 5.21.5 and my Linux desktop machine is on 5.14.

Debug logs

Desktop: https://debuglogs.org/ee34c25fe29434d9e54bbefe9b15834aefaead85cb3a1abe6ffc6f94555b7587.gz
Phone: https://debuglogs.org/e46a6db141a02d8192344b0bafc1a94b5dc6678c6f670d741c1eb849cef07a93

hiqua · 2021-08-24T18:24:15Z

Linux desktop machine is on 5.12

You meant 5.14.0.

As the previous comments (e.g. #5052 (comment)) explained, it could help if you could add the IDs of some messages whose read receipts did not synchronize properly.

kaimast · 2021-08-24T18:26:05Z

Linux desktop machine is on 5.12

You meant 5.14.0.

Yes 🤦. I updated my post.

kaimast · 2021-09-30T04:43:58Z

This suddenly got worse for me.

Now, whenever I send a message, I get push notifications on my other devices.

hiqua · 2021-09-30T05:37:22Z

You meant that you get notifications for your own messages? That doesn't seem like it's related to my original post. If it's not, can you open a new thread?

kaimast · 2021-11-19T17:38:36Z

I recently factory reset my phone, restored signal from a backup, and re-linked Signal-desktop.

The problem seems to be gone now for me.

hiqua · 2022-01-08T19:09:11Z

Just happened again. All messages read on both signal-desktop instances, but not on Android

signal-desktop-beta

https://debuglogs.org/f0ea312c2c3a523e7f3e98f3fdf0c80a09e961d26dcf94e23d6fb8409b207fcc.gz

Sent Saturday, January 8, 2022 7:20 PM (1641666011043)
Received Saturday, January 8, 2022 7:20 PM (1641666012032)

signal-desktop stable

https://debuglogs.org/4f31b4283879cdc255703e2e475a6112e8d17d2b154dfef665426406cc3cd5c6.gz

Sent Saturday, January 8, 2022 7:20 PM (1641666011043)
Received Saturday, January 8, 2022 7:35 PM (1641666956706)

Android

Before opening the convo

https://debuglogs.org/7171ec8d5fd81202e4dfc89bbc7bf2002d0d47fd8e51ae88021e4a1247b32a80
unread message id: 1641666109986

After opening the convo

(and seeing that the unread message was indeed the last one of the convo):
https://debuglogs.org/f5e444f78ff49061a2b66c5b821f6f600a1943463dcca8f3c7fdccc53697b9dc

(N.B.: I updated from 5.28.5 -> 5.28.10 in the meantime)

greyson-signal · 2022-01-10T20:13:29Z

Hi there, Android 5.29 (currently in beta) has some updated logging for read syncs that will give us some more insight. Can you give us logs from that version if it happens again? Thanks!

hiqua · 2022-01-10T20:42:42Z

Awesome, will do, thanks!

hiqua · 2022-03-03T22:55:30Z

Desktop: https://debuglogs.org/desktop/5.35.0-beta.1/d1812ec1a2a437aa8753c6513fb19d58498c0b74556d76681988d9ce0df0cb2c.gz

Android (before opening the convo): https://debuglogs.org/android/5.32.14/486a090e3c7a059e38fe39552765e26911247eabd3dbf5776dd53af7d7fbc56d
Android (after): https://debuglogs.org/android/5.32.14/cea576eb0f42c5f34f8ba664174d50c2642c60fe0a5bf9d4b56e7c7407154968

Message on desktop:

Sent | Today 11:23 PM (1646346200001)

Received | Today 11:23 PM (1646346200184)

That happened just after I trashed my push message config on a phone where the issue hadn't happened before. It happened when I received dozens of messages at the same time when opening the app.

scottnonnenberg-signal · 2022-03-04T19:00:51Z

@hiqua There's clear evidence that the read sync was sent for that message:

========= User info =========
uuid: [REDACTED]8eb
...
INFO  2022-03-03T22:23:23.957Z read sync job queue, job ID [REDACTED]4e6, attempt 1: sending readSync(s) for timestamp(s) 1646346200001
INFO  2022-03-03T22:23:23.957Z read sync job queue, job ID [REDACTED]4e6, attempt 1: sleeping for 0
INFO  2022-03-03T22:23:23.959Z @signalapp/signal-client Building PreKeyWhisperMessage for: [REDACTED]8eb.4 with preKeyId: 13194686 libsignal_protocol::session_cipher rust/protocol/src/session_cipher.rs:55
...
INFO  2022-03-03T22:23:23.991Z PUT (WS) https://chat.signal.org/v1/messages/[REDACTED]8eb
INFO  2022-03-03T22:23:24.094Z PUT (WS) https://chat.signal.org/v1/messages/[REDACTED]8eb 200 Success
INFO  2022-03-03T22:23:24.106Z read sync job queue: job [REDACTED]4e6 succeeded on attempt 1

hiqua · 2022-03-07T15:11:28Z

@greyson-signal let me know if you need more info. My FCM is fixed now (after an update that registered Signal again) so I don't have the bug anymore, but I can just unregister Signal and I expect it to happen again.

hiqua · 2022-03-08T16:57:18Z

Actually just got one more with FCM fixed and in a 1:1 discussion (and at the same time in a group discussion where I was receiving big attachments).

Sent | Today 5:33 PM (1646757185251)
Received | Today 5:33 PM (1646757184447)

https://debuglogs.org/desktop/5.35.0-beta.1/a466a9cc02a2268c5780eba79e838d73d89a7b5997ade8b445123618f16da68c.gz

Android before opening the convo:
https://debuglogs.org/android/5.32.15/4e7975cc1015db6b8e4ab65f7d7870ae4455ae63555196a11bf4455506de322b
After:
https://debuglogs.org/android/5.32.15/0d7a467d85f36303e9c1b9db14cef512f74848e4823be39609b1bf77d60ece49

scottnonnenberg-signal · 2022-03-08T18:27:39Z

Desktop sent the read sync:

INFO  2022-03-08T16:33:12.198Z read sync job queue, job ID [REDACTED]101, attempt 1: sending readSync(s) for timestamp(s) 1646757185251
INFO  2022-03-08T16:33:12.198Z read sync job queue, job ID [REDACTED]101, attempt 1: sleeping for 0
INFO  2022-03-08T16:33:12.200Z @signalapp/signal-client Building PreKeyWhisperMessage for: [REDACTED]8eb.4 with preKeyId: 13194686 libsignal_protocol::session_cipher rust/protocol/src/session_cipher.rs:55
...
INFO  2022-03-08T16:33:12.201Z changedConvoBatcher: deduped 1 into 1
INFO  2022-03-08T16:33:12.239Z PUT (WS) https://chat.signal.org/v1/messages/[REDACTED]8eb
INFO  2022-03-08T16:33:12.351Z PUT (WS) https://chat.signal.org/v1/messages/[REDACTED]8eb 200 Success
INFO  2022-03-08T16:33:12.365Z read sync job queue: job [REDACTED]101 succeeded on attempt 1

hiqua · 2022-04-22T17:21:00Z

Got it again.

Android: https://debuglogs.org/android/5.35.3/81f91c443791d6bb1522e9c08005d43e980da0edba65a2baec68c36502745573
Desktop: https://debuglogs.org/desktop/5.41.0-beta.1/b48d53b32a5a0b3d2a64b19e9be7d51b3b5d5dab8aaf43fcc567d4acb4db93d9.gz

Sent | Today 6:38 PM (1650645480154)
Received | Today 7:18 PM (1650647907401)

@greyson-signal did you ever look into the logs?

I guess this bug can be moved to the Android repository.

cody-signal · 2022-04-28T16:59:21Z

Looks like a bug with Android's early receipt handling. We'll look into it.

2022-04-22 19:15:46.713 GMT+02:00 I IncomingMessageObserver Retrieved envelope! 1650645480154
...
2022-04-22 19:15:46.956 GMT+02:00 I MessageContentProcessor [1650645623182] Synchronize read message. Count: 1, Timestamps: [1650645480154]
...
2022-04-22 19:15:46.997 GMT+02:00 I MessageContentProcessor [1650645480154] Beginning message processing. Sender: RecipientId::17 (********-****-****-****-**********d2.1)
2022-04-22 19:15:46.997 GMT+02:00 I MessageContentProcessor [1650645480154] Text message.

EvanHahn-Signal added the Bug label Apr 15, 2021

kaimast mentioned this issue Aug 24, 2021

Notifications aren’t coming through. Neither are the calls. signalapp/Signal-iOS#5072

Closed

scottnonnenberg-signal added the Android Change Needed label Mar 4, 2022

kaimast mentioned this issue Apr 2, 2022

New messages are marked as read after ~10 seconds of watching at them #5749

Open

2 tasks

All messages read in Signal-Desktop but not on Android #5052

All messages read in Signal-Desktop but not on Android #5052

Comments

hiqua commented Feb 20, 2021 • edited

Bug Description

Steps to Reproduce

Platform Info

Link to Debug Log

hiqua commented Apr 13, 2021 • edited

EvanHahn-Signal commented Apr 15, 2021

hiqua commented Apr 15, 2021

hiqua commented Apr 23, 2021 • edited

greyson-signal commented Apr 27, 2021

hiqua commented Apr 27, 2021

hiqua commented Apr 28, 2021

scottnonnenberg-signal commented Apr 30, 2021

hiqua commented Apr 30, 2021 • edited

scottnonnenberg-signal commented Apr 30, 2021

hiqua commented Apr 30, 2021

scottnonnenberg-signal commented Apr 30, 2021

hiqua commented Jul 28, 2021 • edited

scottnonnenberg-signal commented Jul 28, 2021

hiqua commented Jul 28, 2021

scottnonnenberg-signal commented Jul 28, 2021

hiqua commented Jul 28, 2021 • edited

hiqua commented Jul 29, 2021

EvanHahn-Signal commented Jul 30, 2021

hiqua commented Jul 30, 2021

kaimast commented Aug 24, 2021 • edited

Debug logs

hiqua commented Aug 24, 2021 • edited

kaimast commented Aug 24, 2021

kaimast commented Sep 30, 2021

hiqua commented Sep 30, 2021

kaimast commented Nov 19, 2021

hiqua commented Jan 8, 2022

signal-desktop-beta

signal-desktop stable

Android

Before opening the convo

After opening the convo

greyson-signal commented Jan 10, 2022

hiqua commented Jan 10, 2022

hiqua commented Mar 3, 2022 • edited

scottnonnenberg-signal commented Mar 4, 2022

hiqua commented Mar 7, 2022

hiqua commented Mar 8, 2022 • edited

scottnonnenberg-signal commented Mar 8, 2022

hiqua commented Apr 22, 2022

cody-signal commented Apr 28, 2022

hiqua commented Feb 20, 2021 •

edited

hiqua commented Apr 13, 2021 •

edited

hiqua commented Apr 23, 2021 •

edited

hiqua commented Apr 30, 2021 •

edited

hiqua commented Jul 28, 2021 •

edited

hiqua commented Jul 28, 2021 •

edited

kaimast commented Aug 24, 2021 •

edited

hiqua commented Aug 24, 2021 •

edited

hiqua commented Mar 3, 2022 •

edited

hiqua commented Mar 8, 2022 •

edited