Version: Chromium's a7e95b0468908825cdafa072ed1b8f99f3859a93
OS: All

What steps will reproduce the problem?
(1) Open chrome with --enable-features=StaleWhileRevalidate2
(2) Clear any HTTP cache state you may have
(3) Navigate to http://www.ggusd.us/ (This web site have the nice property of having a lot of sub-resources having Cache-Control:max-age=60,stale-while-revalidate=86400) (Wpr archive attached below)
(4) Wait about a minute
(5) Re-navigate to http://www.ggusd.us/ in the same tab using Omnibox (DO NOT USE ctrl-r or F5) 

What is the expected output?
All the resources having Cache-Control:max-age=60,stale-while-revalidate=86400 should be re-validated asynchronously.

What do you see instead?
Up to 48 resources out of 58 having this Cache-Control: are getting synchronously re-validated.



**************************************** Debuging session DUMP for further details

I'm attaching below my debuging work that led me to identify the issue.
 - debug.py.wpr: A WPR archive to use to repro the bug (in any case the website changes in the meantime)
 - debug.py: A linux only python script that repro the bug grammatically using WPR (record by default a new archive, but using the one attached below is trivial)
 - swr_debuging.diff: A patch to apply to the chromium src/ and compile. It does some printf debuging, but also had a fake Async-Revalidation: True request header to the async requests to identify them in logs.

To repro: 
(0) git -C <chromium's src> apply swr_debuging.diff & compile
(1) Edit debug.py (there is SRC and a big comment about a line to comment/uncomment to repro the bug or not)
(2) python debug.py 2>&1 | tee debug.log
It will generate:
debug.log hold the chrome log and the information (headers and stuff) of all the requests.
debug.py.wpr.log the log of wpr running, to list the requests that WPR has actually served.
(3) cat debug.py.wpr.log | grep async-revalidation | wc -l (it counts the number of async requests WPR have served)
Shows 58 when uncommenting the line in debug.py (No bug because navigating again in a new tab (even in an new chrome instance)).
Shows 10 when commenting the line in debug.py (Reproducing the bug because navigating again in the same renderer)



My debuging has show that requests are getting re-validated synchronously because they are handed to the HttpCache::Transaction already as conditional GET requests and so branch in the following code: https://code.google.com/p/chromium/codesearch#chromium/src/net/http/http_cache_transaction.cc&l=900&cl=GROK&gsn=UPDATE&rcl=1464607459

That changes the code path in: HttpCache::Transaction::DoCacheDispatchValidation() calling HttpCache::Transaction::BeginExternallyConditionalizedRequest() that is missing async requests handling instead of HttpCache::Transaction::BeginPartialCacheValidation() that is the only code path handling async requests.

Indeed in debug.log when navigating to the URL again in the same renderer, you will have the requests information for http://www.ggusd.us/pics/header.jpg (that is one of the resource getting sync revalidation instead of the expected async revalidation)

{
 [...................... some stuf ................]
  "from_service_worker": false, 
  "failed": false, 
  "request_headers": { // actual request headers sent
    "Accept-Language": "en-US,en;q=0.8", 
    "Accept-Encoding": "gzip, deflate, sdch", 
    "Host": "www.ggusd.us", 
    "Accept": "image/webp,image/*,*/*;q=0.8", 
    "User-Agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2753.0 Safari/537.36", 
    "Connection": "keep-alive", 
    "Cookie": "__utmc=237669398; ENUnique=0.7852758791423842; CUID=b86714dd89b9460899d86aca46395a0b; JSESSIONID=3EFF9F1B3AC29600662DC9E3EB230BD1", 
    "Referer": "http://www.ggusd.us/", 
    "If-Modified-Since": "Thu, 18 Feb 2016 17:12:17 GMT", 
    "If-None-Match": "\"16f1f-52c0e77f6a610\"", 
    "Resource-Freshness": "max-age=60,stale-while-revalidate=86400,age=70" // Request header proving that the async revalidation should have been done (doc: https://github.com/KenjiBaheux/resource-freshness/blob/master/specification.txt).
  }, 
 [...................... some stuf ................]
  "status": 304, // NOTE: WPR may not be handling 304 correctly yet and returning 200 instead (https://github.com/chromium/web-page-replay/issues/76)
  "response_headers": { // response headers of the revalidation
    "content-length": "0", 
    "via": "1.1 varnish", 
    "x-cache": "HIT", 
    "age": "0", 
    "x-timer": "S1464631447.724806,VS0,VE161", 
    "Server": "WebPageReplay", 
    "connection": "keep-alive", 
    "etag": "\"16f1f-52c0e77f6a610\"", 
    "x-cache-hits": "1", 
    "x-served-by": "cache-ams4129-AMS", 
    "cache-control": "public, max-age=60, stale-while-revalidate=86400, stale-if-error=86400", 
    "Date": "Mon, 30 May 2016 18:04:07 GMT"
  }, 
 [...................... some stuf ................]
  "url": "http://www.ggusd.us/pics/header.jpg", 
  "headers": { // requests headers handed to HttpCache::Transaction
    "If-None-Match": "\"16f1f-52c0e77f6a610\"", // See here that the request is already conditional
    "If-Modified-Since": "Thu, 18 Feb 2016 17:12:17 GMT", 
    "Referer": "http://www.ggusd.us/", 
    "Resource-Freshness": "max-age=60,stale-while-revalidate=86400,age=70", 
    "User-Agent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2753.0 Safari/537.36"
  }, 
 [...................... some stuf ................]
}

 

Deleted: swr_debuging.diff 5.6 KB

swr_debuging.diff 5.6 KB Download

Deleted: debug.py.wpr 1.3 MB

debug.py.wpr 1.3 MB Download

Deleted: debug.py 2.2 KB

debug.py 2.2 KB View Download