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.

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

Message delivery and fetching messages delayed #8604

Closed
4 tasks done
Esokrates opened this issue Feb 10, 2019 · 56 comments
Closed
4 tasks done

Message delivery and fetching messages delayed #8604

Esokrates opened this issue Feb 10, 2019 · 56 comments

Comments

@Esokrates
Copy link


Bug description

In the past month the experience using Signal got really bad for me. Very often when sending messages I would only see one see one tick despite the message being received and read by my chat partner already. Furthermore even when the app is open and my partner is writing me I get the messages delayed and often many at the same time due the delay. Very often I only see a notification stating something like "Fetching message" and I do not actually receive the message until I force quit the app and restart.

Only very seldom I get messages on time and without actively opening Signal to check.

Device

Google Pixel 2016, fully updated, latest Signal

Link to debug log

https://debuglogs.org/6bc6d8c8e8d6612c4da8188b0961087d6e3939231c5886447fb0d39ca5cc03bc

@greyson-signal
Copy link
Contributor

greyson-signal commented Feb 10, 2019

Some issues I'm seeing, for reference:

2019-02-10 15:11:23.868 MEZ I Job: [a8aae91e-09bd-4f5a-bc3f-5c837600d51c] PushNotificationReceiveJob :: Retrying after a retryable exception. (Time since submission: 41303 ms, Run attempt: 1, isStopped: true)
2019-02-10 15:11:23.868 MEZ I Job: org.whispersystems.signalservice.api.push.exceptions.PushNetworkException: java.net.UnknownHostException: Unable to resolve host "textsecure-service.whispersystems.org": No address associated with hostname
2019-02-10 15:11:23.868 MEZ I Job: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.getServiceConnection(PushServiceSocket.java:917)
2019-02-10 15:11:23.868 MEZ I Job: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.makeServiceRequest(PushServiceSocket.java:778)
2019-02-10 15:11:23.868 MEZ I Job: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.makeServiceRequest(PushServiceSocket.java:766)
2019-02-10 15:11:23.868 MEZ I Job: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.getMessages(PushServiceSocket.java:232)
2019-02-10 15:11:23.868 MEZ I Job: 	at org.whispersystems.signalservice.api.SignalServiceMessageReceiver.retrieveMessages(SignalServiceMessageReceiver.java:172)
2019-02-10 15:11:23.868 MEZ I Job: 	at org.thoughtcrime.securesms.jobs.PushNotificationReceiveJob.pullAndProcessMessages(PushNotificationReceiveJob.java:60)
2019-02-10 15:11:23.868 MEZ I Job: 	at org.thoughtcrime.securesms.jobs.PushNotificationReceiveJob.onRun(PushNotificationReceiveJob.java:55)
2019-02-10 15:11:23.868 MEZ I Job: 	at org.thoughtcrime.securesms.jobmanager.Job.doWorkInternal(Job.java:111)
2019-02-10 15:11:23.868 MEZ I Job: 	at org.thoughtcrime.securesms.jobmanager.Job.doWork(Job.java:64)
2019-02-10 15:11:23.868 MEZ I Job: 	at androidx.work.Worker$1.run(Worker.java:84)
2019-02-10 15:11:23.868 MEZ I Job: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
2019-02-10 15:11:23.868 MEZ I Job: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
2019-02-10 15:11:23.868 MEZ I Job: 	at java.lang.Thread.run(Thread.java:764)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: Failed to retrieve the envelope. Scheduling on JobManager.
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: org.whispersystems.signalservice.api.push.exceptions.PushNetworkException: java.net.SocketTimeoutException: timeout
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.getServiceConnection(PushServiceSocket.java:917)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.makeServiceRequest(PushServiceSocket.java:778)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.makeServiceRequest(PushServiceSocket.java:766)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.getMessages(PushServiceSocket.java:232)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at org.whispersystems.signalservice.api.SignalServiceMessageReceiver.retrieveMessages(SignalServiceMessageReceiver.java:172)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at org.thoughtcrime.securesms.jobs.PushNotificationReceiveJob.pullAndProcessMessages(PushNotificationReceiveJob.java:60)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at org.thoughtcrime.securesms.gcm.GcmBroadcastReceiver.lambda$handleReceivedNotification$0$GcmBroadcastReceiver(GcmBroadcastReceiver.java:94)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at org.thoughtcrime.securesms.gcm.GcmBroadcastReceiver$$Lambda$0.run(Unknown Source:14)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
2019-02-10 15:10:42.532 MEZ I GcmBroadcastReceiver: 	at java.lang.Thread.run(Thread.java:764)

It looks like you're phone is consistently having trouble connecting to Signal's servers. Either the connection is timing out, or our hostname can't be resolved at all. This would result in the 'Retrieving a message notification', which only shows when Signal is having trouble establishing a connection.

Honestly if we're getting low-level network errors like this, there isn't much we can do. One way to lower the impact of this might be to lower the socket timeout, allowing the system to fail (and therefore retry) more quickly when it gets into this state.

@Esokrates
Copy link
Author

Hmm, thanks for having a look that quickly. I have been using Signal for years and never had any comparable problems. I've been using Signal on the Pixel since March without changing anything network related since the upgrade to pie (I've been using cloudflare dns over tlp in the android settings since pie came out). I am not using anything related to modifying network traffic. Problems happen both on mobile and Wifi.

Do you have any idea what I could try in order to resolve this? I am not completely sure when the problem started, but from my gut feeling with the beginning of the new year.

@greyson-signal greyson-signal changed the title Google Pixel 1: Message delivery and fetching messages delayed Message delivery and fetching messages delayed Feb 19, 2019
@greyson-signal
Copy link
Contributor

@Esokrates I'm pretty sure this is a result of changes they made to Android P, with Google trying to be more and more clever about 'battery optimizations'. For a (bad) short-term remedy, you can force-stop the app if you notice that the 'retrieving messages' notification is getting stuck. When Signal is re-opened, everything should be reset.

In the meantime, I have a potential solution that I'm hopefully going to try out in 4.35.x.

@aliceell
Copy link

I'm having the same problem. I have a Samsung j7 Prime, fully updated. It started recently for me too-- it feels a little bit more recently than the new year, but it's possible I just didn't notice until now (I got into a fairly active groupchat a few weeks ago). It happens regardless of whether I'm connected to wifi or not. I do use the NetGuard VPN but I've tried disabling it and it happens then too. Not sure how helpful this is but figured I'd mention that someone else is having the same problem, since this is a pretty recent thread.

Interestingly, the timestamps are all correct. They just don't come at that time.

@Esokrates
Copy link
Author

Esokrates commented Feb 21, 2019

I just had a conversation with a colleague and noticed, that the messages were slowly reaching him on his end, but I did not further think about it. After a while he sent me a screenshot showing the "Fetching Message" notification and complaining that he could not download files. He is using a Samsung Galaxy J7 2016 with Android 8.1.

@Esokrates
Copy link
Author

@Esokrates
Copy link
Author

As for the battery optimization: I have always had Signal white listed from battery optimization to make sure this does not interfere with getting messages promptly.

@emilpaw
Copy link

emilpaw commented Feb 22, 2019

Me and my chart partner have similar problems. Messages sometimes take really long to reach, but the timestamp is correct when the finally arrive. Also like described before by others the status of the message does not update correctly. Signal worked without an issue and started to behave this way lately.

@greyson-signal I have an Android 7.1.1 device so the problem is probably not caused by an Android update, at least not on my phone.

@Esokrates
Copy link
Author

Any progress? Situation did not improve, still getting delayed messages.

@211217613
Copy link

Have been having similar issues. It's not for all contacts though so my first hypothesis is that it is not network related. I'll get a burst of messages at around 440am for one contact while another contact says he doesn't receive messages or notifications until he opens the signal app.

https://debuglogs.org/f2cd0c5576a328ce2048f2b46bf0468b8edcfeefea66603951d8f0da0b9ab85e

@Matthias84
Copy link

+1 on LineageOS 14.1 / Android 7.1.2 with microG (no GCM) and whitelisted Signal battery power etc.
Only I can tell, is that Desktop client hasn't that kind of delay 🤔

@nehresma
Copy link

Just reporting another "me too" here. Signal Android is sometimes 6+ hours behind in receiving messages already received on signal desktop. I just double checked and I do indeed still have Signal whitelisted for battery optimizations.

Since I use Signal desktop heavily, this sometimes results in HUNDREDS of delayed notifications on my phone which then pops up notifications one after the other constantly for MINUTES, making general use of my phone during this time difficult to say the least.

I'm running Signal Android 4.39.4 from May 6th, but this has been happening to me for months.

@zecsn
Copy link

zecsn commented May 21, 2019

Having the same problem with only one contact. I do have more than 20,000+ messages and 1000+ media with that contact. I'm confident that it is because of the huge amount of messages (Whatsapp works fine even with millions of messages with a contact). Other contacts with fewer messages are working fine.
https://debuglogs.org/b89c21e35fc815e502ea3fa795074d4a32671d6a767a7de712c36d92f905aa79

@211217613
Copy link

I've noticed that it only happens with some of my non US contacts.

@Esokrates
Copy link
Author

This issue is not dependent on the contact for me. Happens for all of my contacts. Sometimes notifications are on time, sometimes they are not.
Most of the time they are not, Signal is completely unreliable for me now for half a year.

@ozgurakyazi
Copy link

ozgurakyazi commented May 27, 2019

I believe there are other issues describing this one. #8692 , #8824 , #8597, #8517, #8400 , maybe #8804 , #8675.

You can see my comment on signal forum here. Edit: There are debug logs.

Please put this issue to your "important and immediate to-do" :)

Edit: A new issue: #8841

@aliceell
Copy link

aliceell commented May 29, 2019 via email

@Signaluser1
Copy link

Signaluser1 commented Jun 1, 2019

Hello. Same problem here. The notifications are only displayed when the app is opened. Both Samsung A8 Duos 2018 (Android 9).
On an iPhone there is the problem too. What we have done so far:
Mobile phone restarted.
App stopped
Signal removed from power save mode.

Without success.

@arcivanov
Copy link

Same issue here on Pixel 3XL Android 9.

@diogodh
Copy link

diogodh commented Jul 6, 2019

Same problem here. Only started about 1 month ago.
I have 2 debug logs. Shall i post them so anyone can analyze?

@deutrino
Copy link

A few days ago Signal stopped receiving messages until the app is opened. I'm on LineageOS 14.1 (Android 7.1.2) with no Gapps. No idea what caused the change but it drastically impacts the usefulness of the app since 90% of my contacts are using signal. Desktop is not affected.

@Marc2112
Copy link

Same here with an HTC U11 and Android 8.0.0 and a Samsung Galaxy Note 9 with Android 9.

Some messages arrive instantly. Some messages - sometimes in batches - only arrive after unlocking the phone and/or opening Signal. That can be hours late. The timestamps are correct (sending time) though. Can't see any reason for this behaviour.

@nehresma
Copy link

Bought a new phone. Running Android 9 now (my previous report of this was for 8.1). Signal 4.43. It's still happening to me too.

@rsbowen
Copy link

rsbowen commented Jul 28, 2019

I'm seeing this as well. Signal 4.43.8, Android 9.

@rsbowen
Copy link

rsbowen commented Aug 4, 2019

More information: I only ever see this with a person who uses iOS.

Is there any movement on this bug? I've had to move off Signal to less secure solutions after missing meeting someone's flight because of this bug.

I found this error in the logs around the time I stopped being able to receive messages:

2019-08-04 13:00:29.540 EDT I ThumbnailView: loading part with id content://org.thoughtcrime.securesms/part/1564784228396/64, progress 0, fast preflight id: -1456397812879586489
2019-08-04 13:00:29.694 EDT I EncryptedBitmapResourceEncoder: Encrypted resource encoder running: /data/user/0/org.thoughtcrime.securesms/cache/image_manager_disk_cache/adfcb888c9a522961dff9aaf73da2c5b5911fdc33a32a775aed40e9ee9814b07.0.tmp
2019-08-04 13:00:29.900 EDT W IncomingMessageObserver: Application level read timeout...
2019-08-04 13:00:29.901 EDT D IncomingMessageObserver: Network requirement: true, app visible: true, gcm disabled: false
2019-08-04 13:00:29.901 EDT I IncomingMessageObserver: Reading message...
2019-08-04 13:00:47.768 EDT D ConversationAdapter: Inflate time: 9
2019-08-04 13:00:49.221 EDT I PassphraseRequiredActionBarActivity: onPause()
2019-08-04 13:00:49.923 EDT I ApplicationContext: App is no longer visible.
2019-08-04 13:01:24.923 EDT W WebSocketConnection: onFailure()
2019-08-04 13:01:24.924 EDT W WebSocketConnection: onFailure()
2019-08-04 13:01:24.926 EDT W WebSocketConnection: java.io.EOFException
at okio.RealBufferedSource.require(RealBufferedSource.java:61)
at okio.RealBufferedSource.readByte(RealBufferedSource.java:74)
at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:117)
at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:101)
at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.java:274)
at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:214)
at okhttp3.RealCall$AsyncCall.execute(RealCall.java:206)
at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:764)

2019-08-04 13:01:24.927 EDT W WebSocketConnection: java.io.EOFException
at okio.RealBufferedSource.require(RealBufferedSource.java:61)
at okio.RealBufferedSource.readByte(RealBufferedSource.java:74)
at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:117)
at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:101)
at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.java:274)
at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:214)
at okhttp3.RealCall$AsyncCall.execute(RealCall.java:206)
at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:764)

2019-08-04 13:01:24.927 EDT W WebSocketConnection: onClose()...
2019-08-04 13:01:24.927 EDT W ApplicationDependencyPr: onDisconnected()
2019-08-04 13:01:24.928 EDT W WebSocketConnection: onClose()...
2019-08-04 13:01:24.928 EDT W ApplicationDependencyPr: onDisconnected()
2019-08-04 13:01:25.202 EDT W WebSocketConnection: WSC connect()...
2019-08-04 13:01:25.203 EDT W WebSocketConnection: WSC connect()...
2019-08-04 13:01:25.208 EDT I ApplicationDependencyPr: onConnecting()
2019-08-04 13:01:25.210 EDT I ApplicationDependencyPr: onConnecting()
2019-08-04 13:01:25.364 EDT W WebSocketConnection: onConnected()
2019-08-04 13:01:25.368 EDT I ApplicationDependencyPr: onConnected()
2019-08-04 13:01:25.369 EDT W WebSocketConnection: WSC onMessage()
2019-08-04 13:01:25.370 EDT W WebSocketConnection: Message Type: 1
2019-08-04 13:01:25.373 EDT W WebSocketConnection: onConnected()
2019-08-04 13:01:25.374 EDT I ApplicationDependencyPr: onConnected()
2019-08-04 13:02:25.484 EDT W WebSocketConnection: onFailure()
2019-08-04 13:02:25.485 EDT W WebSocketConnection: onFailure()
2019-08-04 13:02:25.485 EDT W WebSocketConnection: java.io.EOFException
at okio.RealBufferedSource.require(RealBufferedSource.java:61)
at okio.RealBufferedSource.readByte(RealBufferedSource.java:74)
at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:117)
at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:101)
at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.java:274)
at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:214)
at okhttp3.RealCall$AsyncCall.execute(RealCall.java:206)
at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:764)

2019-08-04 13:02:25.486 EDT W WebSocketConnection: onClose()...
2019-08-04 13:02:25.486 EDT W ApplicationDependencyPr: onDisconnected()
2019-08-04 13:02:25.486 EDT W WebSocketConnection: java.io.EOFException
at okio.RealBufferedSource.require(RealBufferedSource.java:61)
at okio.RealBufferedSource.readByte(RealBufferedSource.java:74)
at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:117)
at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:101)
at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.java:274)
at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:214)
at okhttp3.RealCall$AsyncCall.execute(RealCall.java:206)
at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:764)

2019-08-04 13:02:25.486 EDT W WebSocketConnection: onClose()...
2019-08-04 13:02:25.486 EDT W ApplicationDependencyPr: onDisconnected()
2019-08-04 13:02:25.702 EDT W WebSocketConnection: WSC connect()...
2019-08-04 13:02:30.108 EDT I ApplicationDependencyPr: onConnecting()
2019-08-04 13:02:30.108 EDT W WebSocketConnection: WSC connect()...
2019-08-04 13:02:30.111 EDT W WebSocketConnection: Sending keep alive...
2019-08-04 13:02:30.112 EDT W WebSocketConnection: Sending keep alive...
2019-08-04 13:02:30.112 EDT I ApplicationDependencyPr: onConnecting()
2019-08-04 13:02:30.113 EDT W IncomingMessageObserver: Application level read timeout...
2019-08-04 13:02:30.113 EDT D IncomingMessageObserver: Network requirement: true, app visible: false, gcm disabled: false
2019-08-04 13:02:30.113 EDT W IncomingMessageObserver: Shutting down pipe...
2019-08-04 13:02:30.113 EDT W WebSocketConnection: WSC disconnect()...
2019-08-04 13:02:30.114 EDT W WebSocketConnection: WSC disconnect()...
2019-08-04 13:02:30.114 EDT I IncomingMessageObserver: Looping...
2019-08-04 13:02:30.114 EDT I IncomingMessageObserver: Waiting for websocket state change....
2019-08-04 13:02:30.114 EDT D IncomingMessageObserver: Network requirement: true, app visible: false, gcm disabled: false
2019-08-04 13:02:30.271 EDT W WebSocketConnection: WSC onMessage()
2019-08-04 13:02:30.272 EDT W WebSocketConnection: Message Type: 1
2019-08-04 13:02:30.365 EDT W WebSocketConnection: onClosing()!...
2019-08-04 13:02:30.367 EDT W WebSocketConnection: onClose()...
2019-08-04 13:02:30.368 EDT W ApplicationDependencyPr: onDisconnected()
2019-08-04 13:02:30.368 EDT W WebSocketConnection: onClosing()!...
2019-08-04 13:02:30.368 EDT W WebSocketConnection: onClose()...
2019-08-04 13:02:30.369 EDT W ApplicationDependencyPr: onDisconnected()

@diogodh
Copy link

diogodh commented Aug 9, 2019

@zell-mbc
Copy link

zell-mbc commented Aug 9, 2019

I got contacted today by someone who I talked into using Signal a while ago with the same complaint. Messages take hours, sometimes days to arrive. I asked to send me the link to the logfile once this issue happens again so I can post it here, but I am getting worried this is going to drive people away from using Signal if it's not fixed quickly.
He also said he doesnt see any notifications that a message arrived without opening Signal. Android phone, don't have more details yet...

@greyson-signal
Copy link
Contributor

greyson-signal commented Aug 9, 2019

For context, there's two ways messages could be delayed.

  1. We get an FCM message, but for whatever reason, we're unable to make the network request to fetch the messages. It seems like some devices can put apps in a state where network access is restricted -- usually when the phone is unused and motionless. This is not just regular doze mode, this is something else. This is where I've been focusing most of my efforts, and I think I have something that should help that we're looking to ship in 4.46.x.

  2. The system doesn't give us the FCM message. This one is pretty much out of our hands, as far as I can tell. If we don't get an FCM message, our app doesn't wake up. I've seen plenty of evidence of devices batching our FCM messages together, causing delays. This does seem to be a problem that is alleviated by turning off battery optimizations though. So it might be more of a thing where we identify it's happening and try to educate the user or something.

https://debuglogs.org/bc99de56ba9a85611b4d7aab05cccd45830f4cb3b88e5534d740681c644321f6

This is an example of situation # 1.

2019-07-11 00:31:19.578 GMT+01:00 I FcmService: org.whispersystems.signalservice.api.push.exceptions.PushNetworkException: java.net.ConnectException: Failed to connect to textsecure-service.whispersystems.org/34.196.194.172:443
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.getServiceConnection(PushServiceSocket.java:926)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.makeServiceRequest(PushServiceSocket.java:785)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.makeServiceRequest(PushServiceSocket.java:761)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.whispersystems.signalservice.internal.push.PushServiceSocket.getMessages(PushServiceSocket.java:278)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.whispersystems.signalservice.api.SignalServiceMessageReceiver.retrieveMessages(SignalServiceMessageReceiver.java:216)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.thoughtcrime.securesms.jobs.PushNotificationReceiveJob.pullAndProcessMessages(PushNotificationReceiveJob.java:59)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.thoughtcrime.securesms.gcm.FcmService.handleReceivedNotification(FcmService.java:81)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.thoughtcrime.securesms.gcm.FcmService.lambda$onMessageReceived$0(FcmService.java:44)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.thoughtcrime.securesms.gcm.-$$Lambda$FcmService$lphrLliKqZl2MzQqEJXjrq2ixhA.run(Unknown Source:2)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.thoughtcrime.securesms.util.WakeLockUtil.runWithLock(WakeLockUtil.java:23)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at org.thoughtcrime.securesms.gcm.FcmService.onMessageReceived(FcmService.java:43)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at com.google.firebase.messaging.FirebaseMessagingService.zzd(Unknown Source:60)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at com.google.firebase.iid.zzc.run(Unknown Source:2)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at com.google.android.gms.common.util.concurrent.zza.run(Unknown Source:6)
2019-07-11 00:31:19.578 GMT+01:00 I FcmService: 	at java.lang.Thread.run(Thread.java:764)

@Elschnuppero
Copy link

Any solution in sight?

@awaitlink
Copy link
Contributor

awaitlink commented Aug 16, 2019

@Elschnuppero Please read comments before posting. The previous comment to yours (by Signal Android developer) literally says:

  1. [...] I think I have something that should help that we're looking to ship in 4.46.x.

@aliceell
Copy link

aliceell commented Aug 16, 2019 via email

@Elschnuppero
Copy link

@Elschnuppero Please read comments before posting. The previous comment to yours (by Signal Android developer) literally says:

  1. [...] I think I have something that should help that we're looking to ship in 4.46.x.

Ups, you're right. Thanks.

@arcivanov
Copy link

Just fyi, people, this is a feature of Android 9 on Pixel 3. I wonder if there is a some sort of lock (not wakelock, obviously) you can acquire or some QoS you can demand not to be subject to this.

image

@awaitlink
Copy link
Contributor

@arcivanov I think it was designed specifically so smart apps which you don't use that constantly work in background can't do anything about it.

I'm running Q beta 6 on Pixel 3 XL with this feature enabled, but haven't yet experienced any delays in Signal notifications. I use the app pretty often; all (Signal as application)-specific battery saving options are turned off.

@arcivanov
Copy link

But that's the point - Android decides which infrequently used app is going to be anesthetized, so that its notifications are delayed. It means your settings are irrelevant, it's some usage pattern faux-AI that picks applications depending on your personal use, i.e. everyone will have a different experience regardless of settings.

@arcivanov
Copy link

@BryanQuigley
Copy link

I still experienced this with Adaptive Battery turned on on the Beta 4.47.0. (But Signal is one of my top apps.). I'll try turning off Adaptive Battery and see if that improves things..

@arcivanov
Copy link

I moved to Android 10 (QP1A.190711.020.C3) and with Signal 4.47.7 messages are now being delivered in RT.

@Fiercesappho
Copy link

Is there a fix to this that doesn't require Android 10?

@Esokrates
Copy link
Author

I have been using Android 10 on my Pixel since the betas and while the situation is a lot better, it still happens sometimes that I get an delay of 15 minutes.

@Fiercesappho
Copy link

That's unacceptable to me. I love Signal but with my line of work, I can't have delays. Suppose I'll need to leave Signal unfortunately...at least until this issue is worked out.

@Esokrates
Copy link
Author

@Fiercesappho Before doing so please upload a debug log after the issue happens.
@greyson-signal Could you give a status update whether your experiments for 4.46.x. landed? Sry for explicitly asking, but since there is no code linked to the issue, it's hard to tell.

@greyson-signal
Copy link
Contributor

@Esokrates Those experiments did go out, yes. As far as I have seen, it has eliminated an entire class of notification delays. Whenever I see delays now, they're the result of FCM delivery delays, which is really just this vast unknown problem space that has no clear solution. But feel free to upload debug logs and I can confirm.

@Esokrates
Copy link
Author

Esokrates commented Oct 9, 2019

@greyson-signal Thanks very much for responding. I had a batch of 3 messages delayed today, the sent timestamp of the third one is "09:56:47 MESZ" which I received at "10:09:47 MESZ".
https://debuglogs.org/e0bbdc93f73dcd5773761d366c4b41b5b8743e22f6b059f720c67edb9de15d49
Would be glad if you have a look at it.

@Fiercesappho
Copy link

I restarted the phone and that caused a load of messages to come in. Here's the debug log: https://debuglogs.org/f1c60ce3a20bc914d0c445a43ff5e51c2b2965eb6d61b9291964cb2f638d2400

@arcivanov
Copy link

Those experiments did go out, yes.
@greyson-signal Does it mean that whatever fixes you tried were added to the published Signal App on GPlay? If not, how do I get a beta/experimental version to help testing?

@stephanvierkant
Copy link

stephanvierkant commented Nov 6, 2019

Same here. OnePlus 5, Android 9. Receiving messages from my wife takes at least about 15 seconds, while my wife (also OnePlus 5) gets them immediately. But most of the time, I don't get any push notifications at all. Signal is really unusable this way.

Tried all settings related to battery saving, notifications, etc.

Not sure if related, but battery and data usage are very high.

Logs: https://debuglogs.org/e74ade1877da1c2961dafa9354a1773c800773eaedc10e0d9c834b0a17f70496

@mkrusen
Copy link

mkrusen commented Nov 26, 2019

Android 10, Pixel 3 XL
Notifications delayed, messages received out of order. Notifications staying like the message is unread after the message is read. Latency sending messages.

https://debuglogs.org/6bf07f9e1a79db71ae7a2143976ca0934db28ca4cbb2712565c918151501094d

@aliceell
Copy link

aliceell commented Nov 27, 2019 via email

@Esokrates
Copy link
Author

@greyson-signal I haven't had problems since the last time, but did you look into the provided logs in the meantime?

@greyson-signal
Copy link
Contributor

Centralizing "late notification" issues at #8692

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

No branches or pull requests