Closed Bug 1527293 Opened 1 year ago Closed 1 year ago

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

Categories

(Core :: Networking, defect, P1)

60 Branch
defect

Tracking

()

RESOLVED FIXED
mozilla67
Tracking Status
firefox67 --- fixed

People

(Reporter: martin.kuehl, Assigned: michal)

Details

(Whiteboard: [necko-triaged])

Attachments

(2 files)

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.

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

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.

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.

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.

Component: Untriaged → Networking
Product: Firefox → Core

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.

Flags: needinfo?(martin.kuehl)
Attached file 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.

Flags: needinfo?(martin.kuehl)

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

Assignee: nobody → michal.novotny
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Priority: -- → P1
Whiteboard: [necko-triaged]

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.

(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.

Flags: needinfo?(martin.kuehl)

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

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

Flags: needinfo?(martin.kuehl)

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)?

Flags: needinfo?(martin.kuehl)

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
Flags: needinfo?(martin.kuehl)

(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.

Pushed by mnovotny@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/c33c24d21420
Loading a large script transferred with Content-Range from cache returns empty file, r=mayhemer
Status: ASSIGNED → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla67
You need to log in before you can comment on or make changes to this bug.