Images take a long time to send on a good connection

Nisc3d commented 3 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

Images, Stickers or Link Preview Images sometimes take a long time to send on a good connection (one minute or more). Most of the time it only takes a few seconds.

Steps to reproduce

Send Image, Sticker or Link Preview Image
wait

Actual result: It takes a long time Expected result: It should not take that long

Device info

Device: Asus Zenfone 6 Android version: 11 Signal version: 5.24.14

Link to debug log

https://debuglogs.org/2ce8d7a927cb8761c0dfdf9fc5cbcdbcada03ac0c6bc60ac5e9e9cca647f18af

Sticker that took long: 23:59:39 MESZ Link Preview image that took long: 23:21:33 MESZ

Nisc3d commented 2 years ago

New Debug Log with an image that took too long. This time over a minute for a picture with 22,7kB. This issue is happening on different phones and different wifi connections. On this phone it is happening really often. Link: https://debuglogs.org/13a995b9a344577cc6f848bdab402368d761634546dad8a203dc021749798dad Image ID: 1637697617384

Nisc3d commented 2 years ago

Another one on a Asus Zenfone 8. Image took over a minute to upload. It should only take seconds on this good internet connection. https://debuglogs.org/3e3b87deca7ac5e0a3359dd6a56b58be7a84b229b15c36f53f6b5435a2db7fbf Image ID: 1637842231765

Nisc3d commented 2 years ago

I think this might be something with specific german isps. If someone can confirm that they have the same Problem sometimes with Telekom or 1&1 this would be helpful.

Nisc3d commented 2 years ago

Can someone please look at this issue or give me tips how I can debug it? New Debug log: https://debuglogs.org/c415d32538e1d24747af22566dbdadea4012916b9a308df635b7517fd5e46fb5 Message ID: 1643655545171

cody-signal commented 2 years ago

Hi there, it looks like the part that's taking a long time isn't the upload but the request to get metadata used to perform the upload. Looking at your logs, it seems like some upload jobs are taking 60s just to get that metadata, and then no time at all to send the upload. I don't know why that is happening.

Are you able to reliably reproduce it or is it just random?

Nisc3d commented 2 years ago

On my phone (Asus Zenfone) it happens very rarely. Like once a month. On the Motorola phone from my friend it happens 90% of the time for media uploads. If I can help more with additional debug logs let me know. This issue is one of the more annoying ones and I will help with everything that I can do if you can get it resolved.

cody-signal commented 2 years ago

Do you know what kind of network your friend is using it from? Is they on a VPN or other extra networking kit?

If not on a VPN, could they try one, or try the built in TLS proxy. The part that's taking so long is after we've requested the metadata and waiting for it to come back so it's hard to know what could be faltering.

Nisc3d commented 2 years ago

So, just by coincidence it happened to me again today (I was not using a VPN). https://debuglogs.org/d86cff4ab46410e2daa70f712faa69f136aa191408ccd10f7ec9c5689c8a7499 Message ID: 1643847843414 (I think it was this one. If not it was the one before or 2 before).

I was on Wifi with a good connection (Router in the same room) and good speeds. After this I tried with a VPN and without a VPN again but I couldn't reproduce it. The photo was taken with the in-app Camera and also cropped. My network is pretty normal. But I use a pihole for DNS. My friend doesn't have a pihole and just uses a regularly wifi router. They also said it happens on mobile data which is interesting.

I will test it also again with my friend but it takes some time, because we are not living in the same area.

cody-signal commented 2 years ago

Thanks for the extra info. I added some logging to the 5.31.x beta that just dropped. If you could install and run that, it would be helpful. It added some benchmark data around the part that's been slow for you so I can figure out exactly which of 3-4 things is actually taking so long.

Nisc3d commented 2 years ago

Thank you for your work. We are currently testing it and I will post a debug log when we can get a good result.

Nisc3d commented 2 years ago

Another Update: It just isn't happening right now. We will keep an eye on this and I will post a debug log, when it's happening again.

cody-signal commented 2 years ago

Can you post the debuglog from it happening? Should still have the timing data in it.

Nisc3d commented 2 years ago

Do you mean I can generate a new debug log and it will have the timing data from 11 or 9 days ago? If that's true, here is a log: https://debuglogs.org/android/5.32.0/a061105390cccc3ed7d6c6c4fefb73c03a5ab0309b3d343628976d13313a7535

cody-signal commented 2 years ago

Ah, misread your previous message. It won't have data that old. I read "it just happened right now" when it's the opposite. Sorry, I'll keep an eye for updates to the issue.

Nisc3d commented 2 years ago

Good News: It happened. https://debuglogs.org/android/5.32.4/bd01b00267172aa95c27bd95287be280253227f3edc18a8ae6391eccb578b48c

greyson-signal commented 2 years ago

It looks like a lock was being held on decryption that took a good 15 seconds to get a hold of. Something is up there.

cody-signal commented 2 years ago

Do you know if this is happening in both 1:1 conversation and groups or just groups?

Nisc3d commented 2 years ago

It is happening in both 1:1 conversations and groups.

Nisc3d commented 2 years ago

Happened again: https://debuglogs.org/android/5.32.7/19f27c4a0e883e87abb1171c5409a9c78b08304241142a1ff6004e0b4b3d0f1a Message: 1645226536194 was slow to upload. Also 1645226320396 was slow to download (not sure if relevant).

Nisc3d commented 2 years ago

Another Log: https://debuglogs.org/android/5.32.10/d268ec249401f3ccb719356dd62468f064576c448b9c80955db0e75ae2bf3e72 The last image took long to send.

greyson-signal commented 2 years ago

For future reference:

https://debuglogs.org/android/5.32.7/19f27c4a0e883e87abb1171c5409a9c78b08304241142a1ff6004e0b4b3d0f1a JOB::0f3848fd-4473-47d8-8f5b-0cee11b8a492 was a ResumableUploadSpecJob that took 60 seconds to run. The AttachmentUploadJob it was blocking (JOB::8ffc6411-9fde-4f8d-9023-a2ba272ea45b) finished soon after.

https://debuglogs.org/android/5.32.10/d268ec249401f3ccb719356dd62468f064576c448b9c80955db0e75ae2bf3e72 JOB::5041a4c7-359d-419e-94c3-56bb3feba5b1 was a ResumableUploadSpecJob that took 60 seconds to run. The AttachmentUploadJob it was blocking (JOB::01d7b82f-c61c-4623-a289-12dfa4fb6217) finished soon after.

Nisc3d commented 2 years ago

Another example: https://debuglogs.org/android/5.32.14/8fa09cf7aa991de63eb2b945a935523fa8a767e2d7a5dbebde28b56b23acd588 Message ID: 1645964625181

I don't know if you have enough already.

cody-signal commented 2 years ago

Thanks, we have another logging change in the next beta release that'll be out soon. I'll let you know here when it drops and then a log after that would be helpful. We're still a little unsure why this is happening and where exactly the issue is, however, we hope the additional logging will show us.

cody-signal commented 2 years ago

@Nisc3d if you could submit a new debuglog using the latest beta, that would have the additional metrics for us to see where time is being spent.

Nisc3d commented 2 years ago

Okay, I will try to capture one.

Nisc3d commented 2 years ago

Here is a log: https://debuglogs.org/android/5.33.2/9d7e8ebaa0248bad1d7a2823c3de05351fe872e56927b6da3c55ed7587cf3f10

cody-signal commented 2 years ago

Thanks for the logs, I finally know where the time is being spent. It looks like it's taking 3 attempts to connect successfully. The first two take 30s each, as that's the timeout, and then finally the 3rd one connects and completes.

Sadly, there's not much we can do to make this faster as it's randomly up to the network conditions on if it'll work or not. The one thing we might do is dial back the timeout to 10s so it'll fail faster (all 3 attempts would take the same as currently the 1st one).

[0.000 callStart]
[0.003 dnsStart]
[0.047 dnsEnd]
[0.047 connectStart]
[30.077 connectFailed]
[30.078 connectStart]
[60.107 connectFailed]
[60.107 connectStart]
[60.159 secureConnectStart]
[60.311 secureConnectEnd]
[60.312 connectEnd]
[60.312 connectionAcquired]
[60.312 requestHeadersStart]
[60.312 requestHeadersEnd]
[60.312 requestBodyStart]
[60.312 requestBodyEnd]
[60.312 responseHeadersStart]
[60.507 responseHeadersEnd]
[60.507 responseBodyStart]
[60.507 responseBodyEnd]
[60.507 connectionReleased]
[60.508 callEnd]

Nisc3d commented 2 years ago

I really appreciate the investigation into this issue. Sadly that confirms my worries, that it is a network issue on an otherwise fast connection. Also this happens on two different ISPs and two different city's in Germany with different routers. The ISPs are Deutsche Telekom and 1&1.

I have two questions: Can you also check and lower your timeout times for downloads a bit? I also have the issue #11059 open which may be related.

And can I use some network tool to troubleshoot this to report it to my ISP when it happens? If yes, can you recommend me one tool that checks the connection like the Signal App does? And the URL where I can point it to.

cody-signal commented 2 years ago

We'll take a look at the download timeouts too. As for troubleshooting, nothing comes to mind right off. I know we've seen some telecoms do weird stuff to our traffic, but that's been cellular related and not wifi. I'll give it a think, and let you know, but I don't know for certain.

If you don't mind, I'd like to close this ticket as we've reached an understanding on the issue, but don't have much else to do wrt to the specific problem.

Nisc3d commented 2 years ago

Yes, we can close the issue. Thanks for helping. If you have something to add in the future feel free to comment here again.

Nisc3d commented 2 years ago

@cody-signal Sorry I have another thing to add, which might be related. The last message (text, not a picture) took long to send. Is this the same problem or another problem? https://debuglogs.org/android/5.33.3/3bbd66cb06d3c5c07a5873fde8eb0c15f4038d5db5ecf6f3ab98ed83cae7c243

Nisc3d commented 2 years ago

Another example: https://debuglogs.org/android/5.34.8/0979c55a1516842d6157623261082c78bfedfe3b2886dbcf543d4e0439c672a3

signalapp / Signal-Android