search

signalapp / Signal-Android

A private messenger for Android.
https://signal.org
GNU Affero General Public License v3.0
25.43k stars 6.09k forks source link

Delayed messages using WebSocket connection #13640

Open DiGitHubCap opened 1 month ago

DiGitHubCap commented 1 month ago

Bug description

Sometimes messages arrive long after they are sent. I'm sure this is an issue on my end, not the sender's end, because the issue also occurs in group chats where other participants receive the messages before I do.

I suspect what's happening is that the WebSocket connection becomes broken or inactive somehow, which results in not receiving any messages. When Signal enters this broken state, sometimes the issue will resolve itself after minutes or hours. Opening the Signal app also fixes the issue, and I immediately receive any messages that had been delayed.

When this happens, I am still connected to Wi-Fi and I can still receive emails in K-9 Mail, so I'm sure this is a Signal issue.

I have battery optimizations for Signal disabled.

Steps to reproduce

Actual result: Messages are sometimes delayed Expected result: Messages are received immediately

Device info

Device: Google Pixel 7 Android version: 14 Signal version: 7.12.3

Link to debug log

https://debuglogs.org/android/7.12.3/8a11c98ad8161e4430500414dbc103933f6c932a2cdd83d4d56d471540999dc2

greyson-signal commented 1 month ago

I looked through your logs. I don't see any chronic or persistent issues. The websocket is regularly sending keep-alives and I see some envelopes get pulled occasionally. I do see a network issue here or there, but nothing that's happening all the time.

When I was scrolling through, I did see that just after 2024-08-03 10:32:40.611 EDT, there is a 2 hour gap in the logs. So the application wasn't active during that time, but I didn't see any crashes or anything. At this moment I can't say for sure what is wrong, but for future delayed messages, it'd be helpful if you shared the timestamp of that message. You can get it by long-pressing > Info, then long-pressing the sent timestamp (it should toast 'copied to clipboard'). If you share that timestamp and a fresh log, I can follow it in the log and get a better idea of what happened.

DiGitHubCap commented 1 month ago

I submitted that log right after I received a delayed message. That message was sent 1722781960601 (Aug 4, 2024, 10:32:40 EDT) and received 1722791962819 (Aug 4, 2024, 13:19:22 EDT).

I'll submit another log when this issue happens again along with the message timestamps, although, since this issue is intermittent, I don't know when that will happen again.

DiGitHubCap commented 1 month ago

It just happened again. This time, I opened the Signal app about a minute after the messages were sent and received them as soon as I opened it, so the delay isn't very long.

https://debuglogs.org/android/7.12.3/0a270df747b638d745737343ec31be0ebb9a2d3c1a017cfe78ad1a45e739e33e

1st message: sent 1722881928934, received 1722882042699 2nd message: sent 1722881940294, received 1722882042794

DiGitHubCap commented 1 month ago

Here's another instance: https://debuglogs.org/android/7.13.3/f0fbd33877b1ffd7add9ff76c0e4f64e7f0f88ef2631aadfb20017823decd25b

1st message: sent 1723393645965, received 1723396381847 2nd message: sent 1723393697312, received 1723396381926

greyson-signal commented 1 month ago

Ok, gave another look through the latest log, and I think I see the shape of the problem. We only try to keep the websocket open if we think you have network. It looks around 2024-08-11 11:34:24.166 EDT we think we have no network, and therefore stop trying to keep the connection alive. And unfortunately our app is not told of any network changes for the next 30 minutes. Instead, something else happens to wake the app up, and at that point we are able to connect and fetch new messages.

We do have network listeners registered, so I wonder if something is happening where they're not firing? Still unclear.