Text message are sent, but randomly never received

AlexandreBonneau commented 4 years ago

[x] I have searched open and closed issues for duplicates
[x] I am submitting a bug report for existing functionality that does not work as intended
[x] I have read https://github.com/signalapp/Signal-Android/wiki/Submitting-useful-bug-reports
[x] This isn't a feature request or a discussion topic

Bug description

For a couple days now, when I send some messages either via the Android signal app, or the desktop one, some message are sent, but never arrive on the receiver's phone. The bug seems totally random, except that once a message isn't received, subsequent messages within a span of approximately an hour are not received either.

Steps to reproduce

Use the android app to send a text message
The first 'check' is shown
The second 'check' is never shown, and on the other end the receiver never receive the message
Do note that when sending a message via Android, the desktop app will correctly picked it up and show it (as sent only, not received)

Device info

Device: Realme x2 pro Android version: 9 Signal version: 4.53.7

Link to debug log

The bug is random, capturing a log is tricky

Jawastew commented 4 years ago

My friends and me are also seeing these issues, we're all on various Android devices.

greyson-signal commented 4 years ago

Message delivery could be delayed for a number of reasons depending on the battery optimizations present on the receiver's phones. You can check out our support page on the matter.

Are these messages received when the receiver opens the app?

AlexandreBonneau commented 4 years ago

Unfortunately, they are never received, even when opening the Signal app, or closing and reopening it. The battery optimizations are disabled on the receiver phone for The Signal app.

santa-klaus commented 4 years ago

I have the same problems since about maximum a week. It affects at least the phones of 3 of my friends who own different brands. Some messages are received hours later, some never.

I am also using 4.53.7.

greyson-signal commented 4 years ago

If messages are never received at all, even when opening that app, please post a debuglog of both the sending and receiving device. This is something I haven't seen before.

Also, as a sanity check, these message are Signal messages, yes? Not SMS messages? SMS messages will have a little unlocked padlock in the corner of the bubble. They will never get a 2nd checkmark.

greyson-signal commented 4 years ago

If messages are never received at all, even when opening that app, please post a debuglog of both the sending and receiving device. This is something I haven't seen before.

Also, as a sanity check, these message are Signal messages, yes? Not SMS messages? SMS messages will have a little unlocked padlock in the corner of the bubble. They will never get a 2nd checkmark.

santa-klaus commented 4 years ago

Yes, in my case they are Signal messages. My partner got my message 5 hours late today, although they opened the app several times in between. It might be hard to get a debug log due to the random nature of the bug, but I can try my best. Would be the moment after the message is sent or after it is received be important?

TomAFrench commented 4 years ago

Hey, I've been getting this issue as well. I've found that resetting the secure session fixes this (edit: for a couple minutes).

santa-klaus commented 4 years ago

I don't know how valuable the logs are, this time the message arrived when I opened the app (~2 minutes after I sent it).

Log from the sending phone: https://debuglogs.org/3f77e112505c4dbd20acbd0573dcc6576f22554339c73d34c85c09c33d9e7ca7

Log from the receiving phone: https://debuglogs.org/e0e450e16af93b3cc7a454401ac3b68264a7dd91ecf81180dae2695c2d1c45fc

I also did a later try after I checked all the settings mentioned on the support page with sending from my desktop app, this one didn't arrive. Here is the log for the receiving unit: https://debuglogs.org/c5ee9ad692ae49f9f5ee5c433c4e676c96917d5b92da9771b8c22d3e1087ba0f (Message was sent 22. Januar 2020 23:04 and hasn't been received yet)

@TomAFrench I am sorry, I don't understand what you mean with secure session. Do you mean the settings for disappearing messages? They are off with one of the people I have problems with.

TomAFrench commented 4 years ago

@santa-klaus In the options menu for each conversation there is an option to "reset session"

santa-klaus commented 4 years ago

@TomAFrench Ah, okay, now I get it! Sorry, I am using a German and a Swedish version...

The first message after resetting the session worked fine. I will have an eye on this and report tomorrow if it stops working again.

santa-klaus commented 4 years ago

Since the desktop app is also affected (in not receiving messages) it seems like this is not only caused by Android energy saving settings.

This morning the session I reset yesterday had stopped working again.

deutrino commented 4 years ago

This is new behavior as of a few days ago, and affects Desktop for me as well. It's not battery settings.

quaqo commented 4 years ago

Just commented in signalapp/Signal-Desktop#3909 that 1.29.6 on Desktop fixed it for me for the time being. I don't know if it's a combination of using Desktop and Android.

hneij commented 4 years ago

Experiencing this issue as of yesterday as well.

Android 10 Signal on Android 4.53.7

I'm not using Desktop. It started with messages not reaching recipient - one check mark. Then just a spinning circle. It worked for a while today but is back to spinning circle now. Resetting session doesn't help.

As of 30 min ago I can't even send SMS to my Signal contacts with the Signal app. Spinning circle for those as well. Had to switch to standard Messages Android app to send SMS succesfully..

greyson-signal commented 4 years ago

@santa-klaus I saw the following in the receiving log:

2020-01-20 16:46:53.528 CET I FcmService: FCM message... Delay: 3440010

That translates to a delay of ~1hr. Meaning the message was sent and the device was notified, but for whatever reason, their phone decided to not forward that notification to us for 1hr. This is usually due to some sort of battery optimization on the device.

I saw no delays during sending.

Resetting your session will not have any impact on this problem. That's only there in case you get into a bad session state where you're receiving bad encrypted messages.

@hneij Please post a debug log.

greyson-signal commented 4 years ago

In general, if you're receiving late notifications (but messages come in when you open the app), please track the issue here: #8692

I've kept this issue open because @AlexandreBonneau has indicated that some messages are never received, which I would still like to see logs for when the opportunity presents itself.

hneij commented 4 years ago

@greyson-signal I have experienced what others describe, that it takes a long time for messages to be delivered. At the moment I'm back to one checkmark and the message is not received on the other end which is an iPhone.

https://debuglogs.org/6a08390197d89af456fa543fc5da20f012377ef06620ed4d5a3348cf856b0678

greyson-signal commented 4 years ago

@hneij Looks like your sends aren't going through due to some interesting network issues. What network are you on when you experience sending problems? Are you on wifi? If so, do you have any interesting firewall configuration?

2020-01-23 22:00:22.688 CET I BaseJob: [JOB::2d8f5780-277e-4f3a-a027-4f434a244102][PushTextSendJob] Encountered a retryable exception. (Time Since Submission: 349 ms, Lifespan: 86400000 ms, Run Attempt: 1/Unlimited)
2020-01-23 22:00:22.688 CET I BaseJob: org.thoughtcrime.securesms.transport.RetryLaterException: org.whispersystems.signalservice.api.push.exceptions.PushNetworkException: java.net.UnknownHostException: Unable to resolve host "textsecure-service.whispersystems.org": No address associated with hostname
2020-01-23 22:00:22.688 CET I BaseJob:  at org.thoughtcrime.securesms.jobs.PushTextSendJob.deliver(PushTextSendJob.java:183)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.thoughtcrime.securesms.jobs.PushTextSendJob.onPushSend(PushTextSendJob.java:87)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.thoughtcrime.securesms.jobs.PushSendJob.onSend(PushSendJob.java:87)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.thoughtcrime.securesms.jobs.SendJob.onRun(SendJob.java:36)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.thoughtcrime.securesms.jobs.BaseJob.run(BaseJob.java:21)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:82)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:46)
2020-01-23 22:00:22.688 CET I BaseJob: Caused by: org.whispersystems.signalservice.api.push.exceptions.PushNetworkException: java.net.UnknownHostException: Unable to resolve host "textsecure-service.whispersystems.org": No address associated with hostname
2020-01-23 22:00:22.688 CET I BaseJob:  at org.whispersystems.signalservice.internal.push.PushServiceSocket.getServiceConnection(PushServiceSocket.java:1085)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.whispersystems.signalservice.internal.push.PushServiceSocket.makeServiceRequest(PushServiceSocket.java:938)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.whispersystems.signalservice.internal.push.PushServiceSocket.makeServiceRequest(PushServiceSocket.java:932)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.whispersystems.signalservice.internal.push.PushServiceSocket.sendMessage(PushServiceSocket.java:333)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendMessage(SignalServiceMessageSender.java:1068)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.whispersystems.signalservice.api.SignalServiceMessageSender.sendMessage(SignalServiceMessageSender.java:225)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.thoughtcrime.securesms.jobs.PushTextSendJob.deliver(PushTextSendJob.java:176)
2020-01-23 22:00:22.688 CET I BaseJob:  ... 6 more
2020-01-23 22:00:22.688 CET I BaseJob: Caused by: java.net.UnknownHostException: Unable to resolve host "textsecure-service.whispersystems.org": No address associated with hostname
2020-01-23 22:00:22.688 CET I BaseJob:  at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:156)
2020-01-23 22:00:22.688 CET I BaseJob:  at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:103)
2020-01-23 22:00:22.688 CET I BaseJob:  at java.net.InetAddress.getAllByName(InetAddress.java:1152)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.Dns$1.lookup(Dns.java:40)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.connection.RouteSelector.resetNextInetSocketAddress(RouteSelector.java:185)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.connection.RouteSelector.nextProxy(RouteSelector.java:149)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.connection.RouteSelector.next(RouteSelector.java:84)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.connection.StreamAllocation.findConnection(StreamAllocation.java:214)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.connection.StreamAllocation.findHealthyConnection(StreamAllocation.java:135)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.connection.StreamAllocation.newStream(StreamAllocation.java:114)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:42)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:254)
2020-01-23 22:00:22.688 CET I BaseJob:  at okhttp3.RealCall.execute(RealCall.java:92)
2020-01-23 22:00:22.688 CET I BaseJob:  at org.whispersystems.signalservice.internal.push.PushServiceSocket.getServiceConnection(PushServiceSocket.java:1078)
2020-01-23 22:00:22.688 CET I BaseJob:  ... 12 more
2020-01-23 22:00:22.688 CET I BaseJob: Caused by: android.system.GaiException: android_getaddrinfo failed: EAI_NODATA (No address associated with hostname)
2020-01-23 22:00:22.688 CET I BaseJob:  at libcore.io.Linux.android_getaddrinfo(Native Method)
2020-01-23 22:00:22.688 CET I BaseJob:  at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:74)
2020-01-23 22:00:22.688 CET I BaseJob:  at libcore.io.BlockGuardOs.android_getaddrinfo(BlockGuardOs.java:200)
2020-01-23 22:00:22.688 CET I BaseJob:  at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:74)
2020-01-23 22:00:22.688 CET I BaseJob:  at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:135)
2020-01-23 22:00:22.688 CET I BaseJob:  ... 35 more

jerkey commented 4 years ago

I was experiencing this (I posted in issue 3909) and after updating Signal Desktop to 1.29.6 it stopped happening. I am pretty sure the problem was only happening while my laptop was open (and Signal Desktop was running)

santa-klaus commented 4 years ago

@greyson-signal thank you for looking into this. We turned off all battery optimization settings as said in the support page you linked, without any improvement. The messages do not always arrive when the app is opened. I also have some message which never were received.

Screenshot_20200124-122535 Do you have a suggestion how to capture a log for this? Should this be from the sender or recipient?

Furthermore, the issue started on Tuesday evening simultaneously with 4 or 5 of my contacts, which doesn't sound like individual energy saving settings to me :/

deutrino commented 4 years ago

Meanwhile I've had this happen with only one of my many contacts, and messages were completely eaten. So far it hasn't happened again when I upgraded both Android and Desktop to the latest version and reset the session with the affected contact. If I can get to a point where I can reproduce it I will try to capture a log.

D4nte commented 4 years ago

This bug just occurred for me for the first time. Logs here https://debuglogs.org/6e91b186c8d4e3dec21f1506600e95e1ba84fd96a07bed6ca5cbee7b162f6345

santa-klaus commented 4 years ago

I updated my signal-desktop to 1.30.0 and now it seems to work.

kilx commented 4 years ago

Had same issue. Linux desktop and Android app.

Signal messages sent from desktop arrived in my App (I could see them in the App), but were never sent on to other parties. However messages sent from others to me appeared both in my App as well as desktop client.

Issue resolved itself after updating the desktop client (1.29.4 -> 1.30.0) today.

In the apt history log file I see signal-desktop was updated before that on 2020-01-15 (1.29.3 -> 1.29.4). Was 1.29.4 buggy? Though it is weird that the messages were not forwarded by the App even though they arrived there, but the bug was in the desktop client.

D4nte commented 4 years ago

https://github.com/signalapp/Signal-Desktop/releases

Yes it looks like 1.29.4 brought in regressions as 1.29.5 and 1.29.6 try to fix such regression (according to the short changelog).

greyson-signal commented 4 years ago

There's a lot going on here, as is often the case when users are experiencing an issue with many possible causes. Seems like a swath of you were experiencing a desktop bug that was fixed. Another set are likely seeing FCM message delays, which you should track here: #8692

signalapp / Signal-Android