1119280 - downloads in nightly 37 completing prematurely

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[Ben Kelly [:bkelly, not reviewing]]

Steps:

1) Open FF 37 nightly
2) Attempt to download a large directory as a zip from google drive (for example the flame base image)
3) See that the download completes at a size smaller than it should be and the resulting zip is invalid.

I tried downloading many times and got different sizes each time.

I then tried with FF release and was able to download the zip just fine.

Comment 1

[Ben Kelly [:bkelly, not reviewing]]

The failure occurred in 37.0a1 (2015-01-08).

Comment 2

[:Paolo Amadini]

If the downloads are always corrupt in Nightly, but always succeed on Release, this looks like something related to the network layer (although the background file saver may be involved as well).

Just to avoid confusion, please note that the size reported in the Downloads Panel may be slightly less than the actual size on disk, and different for each download, see for example bug 1020886. So, that number alone can't be used for telling the download is corrupt, the actual saved file must be checked every time.

Maybe an HTTP log can help in understanding at least whether we're receiving the full data?

Comment 3

[Ben Kelly [:bkelly, not reviewing]]

It was not a slight difference.  The download was 192MB.  Different sizes I got:  160MB, 150MB, 8MB, 16MB, etc.

Comment 4

[Ben Kelly [:bkelly, not reviewing]]

I should mention I also have e10s disabled.

Comment 5

[:Paolo Amadini]

(In reply to Ben Kelly [:bkelly] from comment #3)
> It was not a slight difference.  The download was 192MB.  Different sizes I
> got:  160MB, 150MB, 8MB, 16MB, etc.

Uh, so definitely I'd look into the networking layer first. Sometimes we're not able to tell whether a download terminated abruptly, but in this case if you always get the full data with Release, rather than seeing a failure, there is probably a regression to investigate.

Log comparison for Nightly and Release very welcome :-)

Comment 6

[Dragana Damjanovic [:dragana]]

I do not know this code, maybe I am completely wrong, but I have seen in the log a Spdy error and the httpTransaction ends with reason = 0

Patrick, can you take a quick look. 


2015-01-08 22:19:55.734116 UTC - -2099308800[c86ef0]: nsHttpTransaction::OnSocketStatus [this=621e140 status=804b0006 progress=8354233]
2015-01-08 22:19:55.734122 UTC - -2099308800[c86ef0]: nsHttpTransaction::ProcessData [this=621e140 count=10]
2015-01-08 22:19:55.734126 UTC - -2099308800[c86ef0]: nsHttpTransaction::HandleContent [this=621e140 count=10]
2015-01-08 22:19:55.734130 UTC - -2099308800[c86ef0]: nsHttpTransaction::HandleContent [this=621e140 count=10 read=10 mContentRead=8354196 mContentLength=-1]
2015-01-08 22:19:55.734137 UTC - -2099308800[c86ef0]: SpdyStream31::WriteSegments 7f517840bde0 count=32768 state=4
2015-01-08 22:19:55.734164 UTC - -2099308800[c86ef0]: SpdySession31::WriteSegments session=7f5178044df0 stream=7f517840bde0 0x3 needscleanup=0. cleanup stream based on stream->writeSegments returning code 80470007
2015-01-08 22:19:55.734170 UTC - -2099308800[c86ef0]: SpdySession31::CleanupStream 7f5178044df0 7f517840bde0 0x3 0
2015-01-08 22:19:55.734176 UTC - -2099308800[c86ef0]: Stream had not processed recv FIN, sending RST code 5
2015-01-08 22:19:55.734180 UTC - -2099308800[c86ef0]: SpdySession31::GenerateRst 7f5178044df0 0x3 5
2015-01-08 22:19:55.734185 UTC - -2099308800[c86ef0]: SpdySession31::LogIO 7f5178044df0 stream=0 id=0x0 [Generate Reset]
2015-01-08 22:19:55.734192 UTC - -2099308800[c86ef0]: 00000000: 80 03 00 03 00 00 00 08 00 00 00 03 00 00 00 05
2015-01-08 22:19:55.734196 UTC - -2099308800[c86ef0]: nsSocketOutputStream::Write [this=7f51781b6fb0 count=16]
2015-01-08 22:19:55.734200 UTC - -2099308800[c86ef0]:   calling PR_Write [count=16]
2015-01-08 22:19:55.734311 UTC - -2099308800[c86ef0]:   PR_Write returned [n=16]
2015-01-08 22:19:55.734322 UTC - -2099308800[c86ef0]: JIMB: ReleaseFD_Locked: mFDref = 2
2015-01-08 22:19:55.734326 UTC - -2099308800[c86ef0]: nsSocketTransport::SendStatus [this=7f51781b6e00 status=804b0005]
2015-01-08 22:19:55.734333 UTC - -2099308800[c86ef0]: SpdySession31::FlushOutputQueue 7f5178044df0 sz=16 rv=0 actual=16
2015-01-08 22:19:55.734338 UTC - -2099308800[c86ef0]: DecrementConcurrent 7f5178044df0 id=0x3 concurrent=0
2015-01-08 22:19:55.734343 UTC - -2099308800[c86ef0]: SpdySession31::CloseStream 7f5178044df0 7f517840bde0 0x3 0
2015-01-08 22:19:55.734347 UTC - -2099308800[c86ef0]: Stream had active partial read frame on close
2015-01-08 22:19:55.734351 UTC - -2099308800[c86ef0]: SpdySession31::ChangeDownstreamState() 7f5178044df0 from 2 to 3
2015-01-08 22:19:55.734356 UTC - -2099308800[c86ef0]: nsHttpTransaction::Close [this=621e140 reason=0]

Comment 7

[Patrick McManus [:mcmanus]]

thanks dragana - that's a regression of mine from 1113065

I'll fix it up. The download manager is pushing back with WOULD_BLOCK and that's being treated as an error.

Comment 8

[Patrick McManus [:mcmanus]]

Attachment: fix large spdy/h2 transfer truncation

Comment 9

[Patrick McManus [:mcmanus]]

Your results will be at https://tbpl.mozilla.org/?tree=Try&rev=439497554826

Comment 10

[Patrick McManus [:mcmanus]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/78d4dd5a75cd

Comment 11

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/78d4dd5a75cd

Comment 12

[Patrick McManus [:mcmanus]]

Comment on attachment 8546670 [details] [diff] [review]
fix large spdy/h2 transfer truncation

Approval Request Comment
[Feature/regressing bug #]:1113065
[User impact if declined]: occasional network errors with large transfers from google, facebook, etc..
[Describe test coverage new/current, TBPL]: new xpcshell tests
[Risks and why]: low. regression on 37, fixed on first merge of 38 from inbound.
[String/UUID change made/needed]: none

Comment 14

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8546670 [details] [diff] [review]
fix large spdy/h2 transfer truncation

Aurora+

Comment 15

[Patrick McManus [:mcmanus]]

remote:   https://hg.mozilla.org/releases/mozilla-aurora/rev/b61267bf124e