Closed Bug 1467755 Opened 2 years ago Closed 2 years ago

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

Categories

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

ARM
Android
defect

Tracking

()

VERIFIED FIXED
mozilla62
Tracking Status
firefox-esr52 --- unaffected
firefox-esr60 --- unaffected
firefox60 --- unaffected
firefox61 blocking verified
firefox62 + verified

People

(Reporter: oana.horvath, Assigned: mayhemer)

References

(Depends on 1 open bug)

Details

(Keywords: regression, Whiteboard: [necko-triaged])

Attachments

(3 files, 1 obsolete file)

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
Summary: Cancel & retry of downloads doesn't work → Downloads stick to 0% progress on Retry
tracking-fennec: --- → ?
Keywords: regression
 
> 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
That regression range url does not look correct. With a mozilla-central range it should list several changesets.
Flags: needinfo?(oana.horvath)
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
Flags: needinfo?(oana.horvath)
Any idea what could be going on here, Honza?
Blocks: 1444975
Flags: needinfo?(honzab.moz)
Note: Same result for the pause & resume action.
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!
Component: Download Manager → Networking: HTTP
Flags: needinfo?(honzab.moz) → needinfo?(oana.horvath)
Priority: -- → P2
Product: Firefox for Android → Core
Summary: Downloads stick to 0% progress on Retry → Downloads stick to 0% progress on Retry (Android)
Whiteboard: [necko-triaged]
Attached file thinkbroadband - log.txt (obsolete) —
The test files are downloaded from: 
https://www.thinkbroadband.com/download
and
http://speed.hetzner.de/
I'll attach a logcat for each.
Flags: needinfo?(oana.horvath)
Attachment #8985157 - Attachment is obsolete: true
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 ?
Assignee: nobody → honzab.moz
Status: NEW → ASSIGNED
Flags: needinfo?(oana.horvath)
Priority: P2 → P1
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.
Depends on: 1382274
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.
Flags: needinfo?(oana.horvath)
(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.
Summary: Downloads stick to 0% progress on Retry (Android) → Downloads stick to 0% progress on Retry (Android) - disable background tab net optimizations
I will push to try later (can't update the tree from some reason), beta patch soon, cloning the repo takes time.
Attachment #8986208 - Flags: review?(valentin.gosu)
Attachment #8986208 - Flags: review?(valentin.gosu) → review+
Keywords: checkin-needed
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
Attachment #8986208 - Flags: approval-mozilla-beta?
Pushed by archaeopteryx@coole-files.de:
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
Keywords: checkin-needed
(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!
https://hg.mozilla.org/mozilla-central/rev/86754e309cfe
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
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.
Attachment #8986208 - Flags: approval-mozilla-beta? → approval-mozilla-release+
Do we have a bug to fix this for Android instead of leaving this disabled indefinitely?
Flags: needinfo?(honzab.moz)
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
Status: RESOLVED → VERIFIED
tracking-fennec: ? → ---
(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
Flags: needinfo?(honzab.moz)
You need to log in before you can comment on or make changes to this bug.