1467755 - Downloads stick to 0% progress on Retry (Android) - disable background tab net optimizations

Status: VERIFIED FIXED

(Core :: Networking: HTTP, defect, P1)

Description

[Oana Horvath [:ohorvath]]

Device:
Sony Xperia Z5 Premium (Android 6.0.1)
Huawei MediaPad M2 (Android 5.1.1)
Nexus 6P (Android 8.1.0)

Build: Nightly 62.0a1 (2018-06-8);

Steps to reproduce:
1. Download a large file from: https://www.thinkbroadband.com/download or https://speed.hetzner.de
2. After a 2-3% progress, cancel it.
3. Long tap the file in about:downloads and tap Retry.
4. Check the progress in the notification bar.

Expected result:
The files id downloaded.

Actual result:
The download restarts but it's stuck to 0%.

Notes:
Doesn't reproduce with a PDF file: https://www.google.com/url?sa=t&rct=j&q=&esrc=s&source=web&cd=12&cad=rja&uact=8&ved=0ahUKEwjW-7uLhMTbAhUDiywKHZd_C1IQFghlMAs&url=http%3A%2F%2Fixoloxi.com%2Fvoynich%2Fpdf%2Fen%2Fvms-quire1-en.pdf&usg=AOvVaw1X0U2PMzDzQWBrvM_we-fD

Regression window performed: 
Last good build: 2018-03-21
First bad build: 2018-03-22

2018-06-08T14:28:08: DEBUG : Using url: https://hg.mozilla.org/mozilla-central/json-pushes?changeset=005891e345a4c1ecba4bb087c8717fe00b798f03&full=1
2018-06-08T14:28:09: DEBUG : Found commit message:
Backed out changeset deb3484ed429 (bug 1444973) for remoteautomation.py failures on Android  a=backout

Comment 1

[Oana Horvath [:ohorvath]]

 
> Notes:
> Doesn't reproduce with a PDF file:
> https://www.google.com/
> url?sa=t&rct=j&q=&esrc=s&source=web&cd=12&cad=rja&uact=8&ved=0ahUKEwjW-
> 7uLhMTbAhUDiywKHZd_C1IQFghlMAs&url=http%3A%2F%2Fixoloxi.
> com%2Fvoynich%2Fpdf%2Fen%2Fvms-quire1-en.pdf&usg=AOvVaw1X0U2PMzDzQWBrvM_we-fD

Sorry, bad URL. The PDF is from a google search page: https://www.screencast.com/t/nTWgAcys20Ym

Comment 2

[Kevin Brosnan [Ex-Mozilla]]

That regression range url does not look correct. With a mozilla-central range it should list several changesets.

Comment 3

[Oana Horvath [:ohorvath]]

Yup, sorry, something went wrong there. Ran mozregression again and found the following:

Last good build: 2018-03-19
First bad build: 2018-03-20

2018-06-11T14:53:46: DEBUG : Using url: https://hg.mozilla.org/integration/mozilla-inbound/json-pushes?changeset=ba39210b7512dd571c557e69e98cd67f6774ab42&full=1
2018-06-11T14:53:47: DEBUG : Found commit message:
Bug 1444975 - Switch to HTTP throttling v2 algorithm. r=valentin

Comment 4

[Bogdan Surd, QA [:bsurd, NI]]

Pushlog: https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=006ec77ea08a30ca336c2e1e85bbbf4b021b3258&tochange=ba39210b7512dd571c557e69e98cd67f6774ab42

Comment 5

[Ryan VanderMeulen [:RyanVM]]

Any idea what could be going on here, Honza?

Comment 6

[Oana Horvath [:ohorvath]]

Note: Same result for the pause & resume action.

Comment 7

[Honza Bambas (:mayhemer)]

Oana, thanks for the report.  Are you able to run Firefox on android with logging on?  There are several ways: 

1. preferences (about:config)
create `logging.nsHttp` and set to number 5
create `logging.config.add_timestamp` (boolean) and set to `true`
create `logging.config.LOG_FILE` and set to a path the process can write to

2. command line options (since Firefox 61 only!)
run ./firefox -MOZ_LOG_FILE=/path -MOZ_LOG=nsHttp:5,timestamp

3. environment variables
export MOZ_LOG_FILE=/path
export MOZ_LOG=nsHttp:5,timestamp
./firefox


Then reproduce and submit the log.  Please provide the URL that failed so I can look for it.

Thanks!

Comment 8

[Oana Horvath [:ohorvath]]

Attachment: thinkbroadband - log.txt

The test files are downloaded from: 
https://www.thinkbroadband.com/download
and
http://speed.hetzner.de/
I'll attach a logcat for each.

Comment 9

[Oana Horvath [:ohorvath]]

Attachment: speed hetzner de - log.txt

Comment 10

[Oana Horvath [:ohorvath]]

Attachment: thinkbroadband - log.txt

Comment 11

[Honza Bambas (:mayhemer)]

Thanks!  The download is indefinitely throttled (actually stopped) - not an expected behavior.  Looks like you found a really big bug!

Oana, to get a bit more information I will ask you for a *complete log* - from the start of the Firefox session - option 2 or 3 only from comment 7, redirecting it to a file preferred.  Thank you.


Going to investigate, this is now on Beta and really should be fixed before it goes to release.  Note that this likely affects desktop as well, but at this moment I can't confirm it.

Note for drivers: it's no big deal to uplift a pref flip to go back to throttling version 1 on beta (backout the regression bug), if the timing is bad for this bug.


-------------

Notes for me: 
speed hetzner de - log

    2018-06-13 14:19:54.491808 UTC - [7202:Socket Thread]: V/nsHttp nsHttpConnection::Activate [this=0xa68d1080 trans=0xa3eeec00 caps=1]
    2018-06-13 14:19:54.491833 UTC - [7202:Socket Thread]: V/nsHttp nsHttpConnection::SetUrgentStartPreferred [this=0xa68d1080 urgent=0]
    2018-06-13 14:19:54.491895 UTC - [7202:Socket Thread]: V/nsHttp nsHttpConnection::SetupSSL 0xa68d1080 caps=0x1 .......[tlsflags0x00000000]speed.hetzner.de:80
    2018-06-13 14:19:54.491923 UTC - [7202:Socket Thread]: V/nsHttp nsHttpConnection::StartShortLivedTCPKeepalives[0xa68d1080] idle time[10s].
06-13 17:19:54.492 7202-7591/? I/Gecko: 2018-06-13 14:19:54.491997 UTC - [7202:Socket Thread]: V/nsHttp nsHttpConnectionMgr::AddActiveTransaction    t=0xa3eeec00 tabid=0(1) thr=1
    2018-06-13 14:19:54.492029 UTC - [7202:Socket Thread]: V/nsHttp Active transactions +[0,1,0,0]
    2018-06-13 14:19:54.492058 UTC - [7202:Socket Thread]: V/nsHttp nsHttpConnectionMgr::TouchThrottlingTimeWindow
    2018-06-13 14:19:54.492084 UTC - [7202:Socket Thread]: V/nsHttp nsHttpConnectionMgr::EnsureThrottleTickerIfNeeded
    2018-06-13 14:19:54.492158 UTC - [7202:Socket Thread]: V/nsHttp nsHttpConnectionMgr::IsThrottleTickerNeeded
    2018-06-13 14:19:54.492190 UTC - [7202:Socket Thread]: V/nsHttp   nothing to throttle


    2018-06-13 14:19:54.605877 UTC - [7202:Socket Thread]: V/nsHttp nsHttpConnectionMgr::ShouldThrottle trans=0xa3eeec00
    2018-06-13 14:19:54.605893 UTC - [7202:Socket Thread]: V/nsHttp   active tab loads, trans is tab-less, throttled=1

*** Figure out why mActiveTabTransactionsExist is true (possibly falsely!) and why we don't ensure the timer via some other code path.

06-13 17:19:54.605 7202-7591/? I/Gecko: 2018-06-13 14:19:54.605911 UTC - [7202:Socket Thread]: V/nsHttp   stop=1, in-window=1, delayed-bck-timer=0
06-13 17:19:54.605 7202-7591/? I/Gecko: 2018-06-13 14:19:54.605928 UTC - [7202:Socket Thread]: V/nsHttp nsHttpTransaction::WriteSegments 0xa3eeec00 response throttled

call ensure from https://searchfox.org/mozilla-central/rev/40577076a6e7a14d143725d0288353c250ea2b16/netwerk/protocol/http/nsHttpTransaction.cpp#944 ?

Comment 12

[Honza Bambas (:mayhemer)]

I believe the problem here is that fennec doesn't correctly deliver the active-tab change notification.  The impl from bug 1366822 is likely desktop only...  This actually depends on bug 1382274 that would also fix this bug.

Still, I think in case the active-tab change notification fails from whatever reason, we should not fail this way.  I will think of a quick fix as part of this bug.

Comment 13

[Oana Horvath [:ohorvath]]

Hey Honza,
For option 2 starting FF with the extra command line options created an empty log file on the device. And I'm not familiar or have the knowledge to test with option no 3.

Comment 14

[Honza Bambas (:mayhemer)]

(In reply to Oana Horvath from comment #13)
> Hey Honza,
> For option 2 starting FF with the extra command line options created an
> empty log file on the device. And I'm not familiar or have the knowledge to
> test with option no 3.

Don't worry about it.  I believe I know what the cause and a fix here is.

Comment 15

[Honza Bambas (:mayhemer)]

Attachment: v1, disabled the affected features by a pref flip on android

I will push to try later (can't update the tree from some reason), beta patch soon, cloning the repo takes time.

Comment 16

[Honza Bambas (:mayhemer)]

Comment on attachment 8986208 [details] [diff] [review]
v1, disabled the affected features by a pref flip on android

No idea if this will apply cleanly, but with some fuzz it should (I still don't have my beta tree!)


Approval Request Comment
[Feature/Bug causing the regression]: bug 1444975
[User impact if declined]: inability to download and probably more network related issues we have not yet even discovered
[Is this code covered by automated tests?]: no
[Has the fix been verified in Nightly?]: no
[Needs manual test from QE? If yes, steps to reproduce]: it's applicable and probably a good idea, see comment 0 for details
[List of other uplifts needed for the feature/fix]: none
[Is the change risky?]: no
[Why is the change risky/not risky?]: we just disable a minor optimization feature that already has a very small effect on android
[String changes made/needed]: none

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/86754e309cfe
Disable background tabs network de-prioritization and response throttling on Android, we don't know the active tab id, r=valentin

Comment 18

[Honza Bambas (:mayhemer)]

(In reply to Honza Bambas (:mayhemer) from comment #16)
> Comment on attachment 8986208 [details] [diff] [review]
> v1, disabled the affected features by a pref flip on android
> 
> No idea if this will apply cleanly, 

It does apply cleanly on Beta!

Comment 19

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/86754e309cfe

Comment 20

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 8986208 [details] [diff] [review]
v1, disabled the affected features by a pref flip on android

Approved for Fennec 61 RC. Definitely want QA to verify this.

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-release/rev/ea048f620099

Comment 22

[Kevin Brosnan [Ex-Mozilla]]

Do we have a bug to fix this for Android instead of leaving this disabled indefinitely?

Comment 23

[Andrei Bodea[:andrei]]

Verified as fixed in RC build 61.0 and Nightly 62.0a1 with the following devices:

Devices:
Nexus 5 (Android 6.0.1)
Google Pixel C Android 8.0.0
OnePlus 3 Android 6.0.1
Sony Xperia Z5 Premium (Android 6.0.1)
Sony Xperia Z2 (Android 6.0.1)

Thanks,
Andrei

Comment 24

[Honza Bambas (:mayhemer)]

(In reply to Kevin Brosnan [:kbrosnan] from comment #22)
> Do we have a bug to fix this for Android instead of leaving this disabled
> indefinitely?

1382274