The issue occurs when Chrome sends out a conditional range request (an if-range header with Last-Modified validator), and the server responds with 200 OK and full response.

I have attached the net log of a repro.
For example, the image sunset-birds-flying-sky-70577.jpeg was shown broken in the page, This request (ID 17385) is fetched with request headers
 if-range: Mon, 13 Aug 2018 2:25:44 GMT
 range: bytes=2048-12869

The server responds with
 HTTP/1.1 200
 status: 200

Note there are no HTTP_TRANSACTION_READ_BODY events for this request, which indicates Chrome is not reading the response from the network.

There are other images (for example, pexels-photo-627678.jpeg) where Chrome sets if-range header, and the server responds with 206 range response, and the image is shown fine.

Deleted: chrome-net-export-log.json 12.3 MB

chrome-net-export-log.json 12.3 MB View Download

Some more debug info after converting TRACE_EVENT0() to LOG(WARNING) in net/http/http_cache_transaction.cc.
Note that the line numbers may not exactly align, since I had some more debugs there. But it should be pretty close.
pexels-photo-273136.jpeg is the failing image here.


[89179:89402:0924/132344.011243:WARNING:http_cache_transaction.cc(1645)] HttpCacheTransaction::DoSendRequest
[89179:89402:0924/132344.023811:WARNING:http_cache_transaction.cc(1679)] HttpCacheTransaction::DoSendRequestComplete
[89179:89402:0924/132344.023876:WARNING:http_cache_transaction.cc(1718)] HttpCacheTransaction::DoSuccessfulSendRequest
[89179:89402:0924/132344.023997:WARNING:http_cache_transaction.cc(2989)] Failed to revalidate partial entry
[89179:89402:0924/132344.024035:WARNING:http_cache_transaction.cc(2991)] Transaction::ValidatePartialResponse 
[89179:89402:0924/132344.024073:WARNING:http_cache_transaction.cc(3210)] Transaction::DoomPartialEntryhttps://images.pexels.com/photos/273136/pexels-photo-273136.jpeg?auto=compress&cs=tinysrgb&h=350
[89179:89402:0924/132344.024341:WARNING:http_cache_transaction.cc(1919)] HttpCacheTransaction::DoOverwriteCachedResponse
[89179:89402:0924/132344.024421:WARNING:http_cache_transaction.cc(1954)] HttpCacheTransaction::DoCacheWriteResponse
[89179:89402:0924/132344.024469:WARNING:http_cache_transaction.cc(1982)] HttpCacheTransaction::DoCacheWriteResponseComplete
[89179:89402:0924/132344.024517:WARNING:http_cache_transaction.cc(1988)] HttpCacheTransaction::DoTruncateCachedData
[89179:89402:0924/132344.024563:WARNING:http_cache_transaction.cc(1999)] HttpCacheTransaction::DoInitEntry
[89179:89402:0924/132344.024606:WARNING:http_cache_transaction.cc(2012)] HttpCacheTransaction::DoTruncateCachedMetadata
[89179:89402:0924/132344.024644:WARNING:http_cache_transaction.cc(2023)] HttpCacheTransaction::DoTruncateCachedMetadataComplete
[89179:89402:0924/132344.024920:WARNING:data_use_measurement.cc(185)] NetworkDelegate OnCompleted called GetTotalReceivedBytes()=93 was_cached()=1  https://images.pexels.com/photos/273136/pexels-photo-273136.jpeg?auto=compress&cs=tinysrgb&h=350
[89179:89402:0924/132344.026247:WARNING:http_cache_transaction.cc(215)] HttpCacheTransaction::~Transaction

HttpCacheTransaction::DoNetworkRead is never logged for a failing case, and this suggests that Chrome is not reading the response after 200 for if-range request.

cc morlovich@ if he could help.

Going to need to add a lot more debug output than you had for this... Sadly ValidatePartialResponse is rather hard to follow :(

hi Maksim,

I have the patch with debugs for referring to line numbers.
https://chromium-review.googlesource.com/c/chromium/src/+/1246789/1


Following is the relevant debug output.
In short, failure is set to true in L2919 https://cs.chromium.org/chromium/src/net/http/http_cache_transaction.cc?rcl=ddede7ee04902eaf70c912f9e30d7d4117b30f81&l=2919
And the entry gets doomed in L2977 https://cs.chromium.org/chromium/src/net/http/http_cache_transaction.cc?rcl=ddede7ee04902eaf70c912f9e30d7d4117b30f81&l=2977

[218688:219025:0926/122958.731905:WARNING:http_cache_transaction.cc(2289)] HttpCacheTransaction::DoCacheReadDataComplete
[218688:219025:0926/122958.733219:WARNING:http_cache_transaction.cc(2289)] HttpCacheTransaction::DoCacheReadDataComplete
[218688:219025:0926/122958.733392:WARNING:http_cache_transaction.cc(2266)] HttpCacheTransaction::DoCacheReadData
[218688:219025:0926/122958.733449:WARNING:http_cache_transaction.cc(2289)] HttpCacheTransaction::DoCacheReadDataComplete
[218688:219025:0926/122958.733616:WARNING:data_use_measurement.cc(185)] DataUseMeasurement::OnCompleted 0  https://images.pexels.com/photos/589841/pe
xels-photo-589841.jpeg?auto=compress&cs=tinysrgb&h=350
[218688:219025:0926/122958.733666:WARNING:data_use_measurement.cc(188)] 0 0 cached=1
[218688:219025:0926/122958.734512:WARNING:http_cache_transaction.cc(215)] HttpCacheTransaction::~Transaction
[218688:219025:0926/122958.734969:WARNING:http_cache_transaction.cc(2266)] HttpCacheTransaction::DoCacheReadData
[218688:219025:0926/122958.735014:WARNING:http_cache_transaction.cc(2289)] HttpCacheTransaction::DoCacheReadDataComplete
[218688:219025:0926/122958.735568:WARNING:http_cache_transaction.cc(1645)] HttpCacheTransaction::DoSendRequest
[218688:219025:0926/122958.748668:WARNING:http_cache_transaction.cc(1679)] HttpCacheTransaction::DoSendRequestComplete
[218688:219025:0926/122958.748756:WARNING:http_cache_transaction.cc(1718)] HttpCacheTransaction::DoSuccessfulSendRequest
[218688:219025:0926/122958.748808:WARNING:http_cache_transaction.cc(2939)] failure 1
[218688:219025:0926/122958.748849:WARNING:http_cache_transaction.cc(2961)] reading_=1 is_sparse_=1 partial_response=0
[218688:219025:0926/122958.748894:WARNING:http_cache_transaction.cc(2988)] failure 1
[218688:219025:0926/122958.748933:WARNING:http_cache_transaction.cc(3007)] Failed to revalidate partial entry
[218688:219025:0926/122958.748974:WARNING:http_cache_transaction.cc(3009)] Transaction::ValidatePartialResponse 
[218688:219025:0926/122958.749016:WARNING:http_cache_transaction.cc(3228)] Transaction::DoomPartialEntryhttps://images.pexels.com/photos/60628/flower-garden-blue-sky-hokkaido-japan-60628.jpeg?auto=compress&cs=tinysrgb&h=350
[218688:219025:0926/122958.749288:WARNING:http_cache_transaction.cc(1919)] HttpCacheTransaction::DoOverwriteCachedResponse
[218688:219025:0926/122958.749355:WARNING:http_cache_transaction.cc(1954)] HttpCacheTransaction::DoCacheWriteResponse
[218688:219025:0926/122958.749400:WARNING:http_cache_transaction.cc(1976)] DoCacheWriteResponse 200 (nil) 0
[218688:219025:0926/122958.749448:WARNING:http_cache_transaction.cc(1991)] HttpCacheTransaction::DoCacheWriteResponseComplete
[218688:219025:0926/122958.749490:WARNING:http_cache_transaction.cc(1997)] HttpCacheTransaction::DoTruncateCachedData
[218688:219025:0926/122958.749533:WARNING:http_cache_transaction.cc(2008)] HttpCacheTransaction::DoInitEntry
[218688:219025:0926/122958.749577:WARNING:http_cache_transaction.cc(2021)] HttpCacheTransaction::DoTruncateCachedMetadata
[218688:219025:0926/122958.749620:WARNING:http_cache_transaction.cc(2032)] HttpCacheTransaction::DoTruncateCachedMetadataComplete
[218688:219025:0926/122958.749935:WARNING:data_use_measurement.cc(185)] DataUseMeasurement::OnCompleted 47  https://images.pexels.com/photos/60628/flower-garden-blue-sky-hokkaido-japan-60628.jpeg?auto=compress&cs=tinysrgb&h=350

Well, I can make the site work with:

@@ -2507,14 +2511,16 @@ int HttpCache::Transaction::BeginCacheValidation() {
     // load in histograms.
     UpdateCacheEntryStatus(CacheEntryStatus::ENTRY_OTHER);
     skip_validation = !partial_->initial_validation();
+    LOG(ERROR) << this << " " << cache_key_ << " trucated forced skip_validation to:" << skip_validation;
   }
 
   if (partial_ && (is_sparse_ || truncated_) &&
-      (!partial_->IsCurrentRangeCached() || invalid_range_)) {
+      (!partial_->IsCurrentRangeCached() || invalid_range_ || !reading_)) {
     // Force revalidation for sparse or truncated entries. Note that we don't
     // want to ignore the regular validation logic just because a byte range was
     // part of the request.
     skip_validation = false;
+    LOG(ERROR) << this << " " << cache_key_ << " forced validation for partial!";
   }
 
   if (skip_validation) {


... but that also breaks 17 tests.

Is the fix in #c7 correct, and only the tests need to be fixed ?

It's suboptimal, as it can cause a lot of bytes to be refetched if the server is behaving like the one here (sending a 206 when a 304 would be possible).

BTW, do you have a sense of how broad the problem is? Is it limited this specific site, or something broader for cloudflare? 

This problem is frequently seen in a number of sites with lots of large images. In some sites with only a few or small images it is seen, though not frequently.

CL is in review here.
https://crrev.com/c/chromium/src/+/1291595

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/70039f1108b2dbf054200737179f34449fc4879e

commit 70039f1108b2dbf054200737179f34449fc4879e
Author: Maks Orlovich <morlovich@chromium.org>
Date: Wed Nov 07 18:52:57 2018

HttpCache: be more conservative when trying to reconstruct a full resource from partial one.

(With partial resource being a 206, not a truncated one).

Previously we would happily use a first chunk from cache, then fail in panic when validation
of the second chunk failed; this was especially bad for servers whose validation fails to
match for resources for which headers suggest it should.

After this change, in this case, we force a validation of the first chunk, and if it fails
re-fetch the entire resource. This is far from ideal, but we have limitations when it comes
to converting a pre-existing 206 entry to a 200 one that make using somewhat-better-in-this-case
If-Range really painful (and there is no multi-range support, that would be useful for these
sorts of reconstructions, either).

(Heavily affects the lazyload experiment)

Bug:  888742 
Change-Id: I7f3f3b40dc1e2a98dd093ac09c98fe43eee5f3bd
Reviewed-on: https://chromium-review.googlesource.com/c/1291595
Reviewed-by: David Benjamin <davidben@chromium.org>
Commit-Queue: Maks Orlovich <morlovich@chromium.org>
Cr-Commit-Position: refs/heads/master@{#606092}
[modify] https://crrev.com/70039f1108b2dbf054200737179f34449fc4879e/net/http/http_cache_transaction.cc
[modify] https://crrev.com/70039f1108b2dbf054200737179f34449fc4879e/net/http/http_cache_unittest.cc
[modify] https://crrev.com/70039f1108b2dbf054200737179f34449fc4879e/net/http/partial_data.cc
[modify] https://crrev.com/70039f1108b2dbf054200737179f34449fc4879e/net/http/partial_data.h