1527293 - Loading a large script transferred with Content-Range from cache returns empty file

Status: RESOLVED FIXED

(Core :: Networking, defect, P1)

Description

[Martin Kühl]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:60.0) Gecko/20100101 Firefox/60.0

Steps to reproduce:

I have a webserver that includes Content-Range headers in all of its responses. https://github.com/mkhl/issue-firefox-cache-content-range mimics its behaviour for reproduction purposes.
To reproduce:

• Load the web page it serves (localhost:8080)
• Reload the page

Actual results:

On reloading, the requests for both JavaScript files receive 304 responses from the server, but for the larger file (vendor.js) Firefox loads 0 Bytes instead of the actual file, resulting in ReferenceErrors during execution of the second script (bundle.js).

Expected results:

Firefox should load the full contents of both scripts from its cache and execute the second script (bundle.js) without errors.

Comment 1

[Martin Kühl]

Reproduced with clean profiles in both Firefox 65.0 and 66.0b from the aurora channel.

Comment 2

[Martin Kühl]

The error only seems to occur when the server includes Content-Range headers and when the file is sufficiently large.
The header is added in serve.js:6.
The file contains a large inline source map in public/vendor.js:83042, removing that line eliminates the problem.

Comment 3

[Martin Kühl]

The file vendor.js a bundle of open source libraries, including moment.js and angular js. I have not tried making other modifications to it besides removing the inline source map, since I found that that change was sufficient to disable the problematic behaviour.

Comment 4

[Damira Akh]

Thank you for reporting this issue,
I am unable to test this issue since I don't have access to the web server.

I am moving this issue to Core: Networking
Please correct to the right component if this is not the case. Thank you.

Comment 5

[Michal Novotny [:michal]]

I cannot reproduce it. In my log I can see that after receiving 304 from the server we read the content from the cache. Please provide a log (https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging). Also please note that server IMO shouldn't send Content-Range headers in 200 response. It can be sent only in 206 or 416 response.

Comment 6

[Martin Kühl]

Attachment: HTTP debug log

Attached HTTP debug log.
The log contains both requests, I believe the first starts around 16:14:22 and the second around 16:14:26.

Comment 7

[Michal Novotny [:michal]]

The problem is that the entry would be too big, so the data isn't cached on the first load:

2019-02-20 16:14:23.131905 UTC - [Parent 71462: Main Thread]: D/cache2 CacheEntry::OpenOutputStream [this=0x125938940]
2019-02-20 16:14:23.131910 UTC - [Parent 71462: Main Thread]: D/cache2 entry would exceed size limit
2019-02-20 16:14:23.131915 UTC - [Parent 71462: Main Thread]: D/nsHttp entry would exceed max allowed size, not writing it [channel=0x12858f000]

For some reason the entry isn't doomed, so later the entry's state changes to READY:

2019-02-20 16:14:23.433086 UTC - [Parent 71462: Main Thread]: D/cache2 CacheEntryHandle::Dismiss 0x12281f3e0
2019-02-20 16:14:23.433123 UTC - [Parent 71462: Main Thread]: D/cache2 CacheEntry::OnHandleClosed [this=0x125938940, state=READY, handle=0x12281f3e0]

On the second load we have an empty entry which we try to re-validate:

2019-02-20 16:14:26.489944 UTC - [Parent 71462: Main Thread]: D/nsHttp nsHTTPChannel::OnCacheEntryCheck exit [this=0x1114c6000 doValidation=1 result=2]
2019-02-20 16:14:26.489954 UTC - [Parent 71462: Main Thread]: D/cache2 OnCacheEntryCheck: rv=0x00000000, result=2
2019-02-20 16:14:26.489977 UTC - [Parent 71462: Main Thread]: D/cache2 CacheEntryHandle::Dismiss 0x1228b7200
2019-02-20 16:14:26.490016 UTC - [Parent 71462: Main Thread]: D/cache2 CacheEntry::OnHandleClosed [this=0x125938940, state=READY, handle=0x1228b7200]
2019-02-20 16:14:26.490054 UTC - [Parent 71462: Main Thread]: D/cache2 CacheEntryHandle::~CacheEntryHandle 0x1228b7200
2019-02-20 16:14:26.490104 UTC - [Parent 71462: Main Thread]: D/cache2 CacheEntry::InvokeAvailableCallback [this=0x125938940, state=REVALIDATING, cb=0x1114c6590, r/o=0, n/w=0]

Revalidation succeeds, but obviously we fail to read the data:

2019-02-20 16:14:26.518794 UTC - [Parent 71462: Main Thread]: D/nsHttp nsHttpChannel::ReadFromCache [this=0x1114c6000] Using cached copy of: http://localhost:8080/vendor.js
2019-02-20 16:14:26.518801 UTC - [Parent 71462: Main Thread]: D/cache2 CacheFileInputStream::AsyncWait() [this=0x12a699660, callback=0x1536237e8, flags=0, requestedCount=0, eventTarget=0x108c63100]
2019-02-20 16:14:26.518805 UTC - [Parent 71462: Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=0x12a699660, releaseOnly=0]
2019-02-20 16:14:26.518810 UTC - [Parent 71462: Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=0x153a90240, idx=0, caller=0, listener=0x12a699670]
2019-02-20 16:14:26.518814 UTC - [Parent 71462: Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - GetChunkLocked failed. [this=0x12a699660, idx=0, rv=0x80040111]

Looks like all we need to do is to doom the entry at https://searchfox.org/mozilla-central/rev/93905b660fc99a5d52b683690dd26471daca08c8/netwerk/protocol/http/nsHttpChannel.cpp#5538

The bug is reproducible only when server's response doesn't contain Content-Length header, because if it's present then we don't use the empty cache entry on the second load due to size mismatch https://searchfox.org/mozilla-central/rev/93905b660fc99a5d52b683690dd26471daca08c8/netwerk/protocol/http/nsHttpChannel.cpp#4191

Comment 8

[Martin Kühl]

The problem is that the entry would be too big, so the data isn't cached on the first load:

I just checked and without the Content-Range header, the file does get cached (and read from cache correctly), despite its size.

Comment 9

[Michal Novotny [:michal]]

(In reply to Martin Kühl from comment #8)

The problem is that the entry would be too big, so the data isn't cached on the first load:

I just checked and without the Content-Range header, the file does get cached (and read from cache correctly), despite its size.

Do you know how to force chunked transfer encoding in your test? When I run the test the response has Content-Length header, when you run it chunked transfer encoding is used.

Comment 10

[Martin Kühl]

Do you know how to force chunked transfer encoding in your test?

I have pushed a commit that I believe should do just that.

Comment 11

[Michal Novotny [:michal]]

It still does contain Content-length:

HTTP/1.1 200 OK
X-Powered-By: Express
Content-Range: bytes 0-9174357/9174358
Transfer-Encoding: chunked
Accept-Ranges: bytes
Cache-Control: public, max-age=0
Last-Modified: Wed, 20 Feb 2019 12:00:41 GMT
ETag: W/"8bfd56-1690ac7856a"
Content-Type: application/javascript; charset=UTF-8
Content-Length: 9174358
Vary: Accept-Encoding
Date: Thu, 21 Feb 2019 14:08:52 GMT
Connection: keep-alive

I created a simple test using apache and I can reproduce only the problem described in comment #7, but I have to limit max entry size in preferences to avoid caching the file. Otherwise the file is cached regardless Content-Range is present or not. What's your cache size (Maximum storage size in about:cache)?

Comment 12

[Martin Kühl]

It still does contain Content-length:

Sorry about that.

What's your cache size (Maximum storage size in about:cache)?

• memory: 32768 KiB
• disk: 1048576 KiB
• appcache: 512000 KiB

Comment 13

[Michal Novotny [:michal]]

(In reply to Martin Kühl from comment #12)

It still does contain Content-length:

Sorry about that.

No problem. I'm just surprised that the same test behaves differently on my computer. Maybe I have different version of nodejs libraries.

What's your cache size (Maximum storage size in about:cache)?

• memory: 32768 KiB
• disk: 1048576 KiB
• appcache: 512000 KiB

That's very strange. 1048576 is maximum cache size used by smart size algorithm. Maximum entry size by default is 50MB or 1/8 of cache size if it's smaller (128MB in this case). And predicted entry size is taken from Content-Range or Content-Length header (https://searchfox.org/mozilla-central/rev/b36e97fc776635655e84f2048ff59f38fa8a4626/netwerk/protocol/http/nsHttpResponseHead.cpp#958). This means we should cache the entry with as well as without Content-Range header in this case.

Comment 14

[Michal Novotny [:michal]]

Attachment: Bug 1527293 - Loading a large script transferred with Content-Range from cache returns empty file, r=mayhemer

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c33c24d21420
Loading a large script transferred with Content-Range from cache returns empty file, r=mayhemer

Comment 16

[Andrei Ciure[:aciure]]

https://hg.mozilla.org/mozilla-central/rev/c33c24d21420