I'll disable and investigate

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

commit 446a85514f577f794d4da755e3ac48fb3a5bc2b2
Author: Matt Falkenhagen <falken@chromium.org>
Date: Thu Aug 23 00:46:01 2018

service worker: Disable a nav preload test under NetworkService.

ServiceWorkerNavigationPreloadTest.NetworkFallback is flaky when
NetworkService is on, after r585201. Temporarily disabling
to soothe the CQ while I investigate.

Bug:  876911 ,   873575 
Change-Id: I8b5cdd9ae8ac173a2a6debba05219bad7fa0d606
TBR: kinuko
NOTRY: true
Reviewed-on: https://chromium-review.googlesource.com/1186003
Reviewed-by: Matt Falkenhagen <falken@chromium.org>
Commit-Queue: Matt Falkenhagen <falken@chromium.org>
Cr-Commit-Position: refs/heads/master@{#585343}
[modify] https://crrev.com/446a85514f577f794d4da755e3ac48fb3a5bc2b2/testing/buildbot/filters/mojo.fyi.network_content_browsertests.filter

This is flaky when NetworkService is enabled. I'm investigating.

mmenke: can you help me debug this?

For background, the test does the following:
1) Navigate to a site that has a service worker with navigation preload.
2) A navigation preload request is sent to network.
3) The service worker does nothing in the fetch event, so the request falls back to network. I.e., another request is sent to network.

The expected behavior is this two requests hitting EmbeddedTestServer. But sometimes there are three requests.

It looks like the single net::HttpCache::Transaction made for the fallback request in step 3 hits the network twice. It reaches DoSendRequest() after BeginCacheValidation() and after DoAddToEntryComplete(). The DoAddToEntryComplete() snippet is:

  if (result == ERR_CACHE_LOCK_TIMEOUT) {
    ...
    // The cache is busy, bypass it for this transaction.
    mode_ = NONE;
    TransitionToState(STATE_SEND_REQUEST);
  }

I suspect the nav preload request also accesses the cache, so we end up with a busy cache and this code path gets hit. It's not clear to me why r585201 would trigger this path more. It might have always been theoretically possible and the flaky path just happens to get triggered more.

Here is my debugging log. Sorry it might not be understandable. The suspicious part to me is that the same HttpCache::Transaction (0x3a7f7ea4d000) hits network twice after Start() is called once. Is that an expected possible behavior?

[87774:87783:0823/161548.547437:ERROR:navigation_url_loader_impl.cc(756)] Interceptor will handle the request, creting throttle
[87774:87783:0823/161548.547636:ERROR:throttling_url_loader.cc(350)] Throttler is calling CreateLoaderAndStart for: http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.547685:ERROR:service_worker_navigation_loader.cc(174)] SWNavigationLoader::StartRequest called for http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.547894:ERROR:service_worker_fetch_dispatcher.cc(727)] MaybeStartNavigationPreload calling CreateLoaderAndStart on network
[87774:87783:0823/161548.548478:ERROR:url_loader_factory.cc(67)] URLLoaderFactory::CreateLoaderAndStart called for: http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.548638:ERROR:url_request_http_job.cc(410)] URLRequestHttpJob::Start: http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.548761:ERROR:url_request_http_job.cc(621)] URLRequestHttpJob::StartTransactionInternal on 0x3a7f7d8bab00 is creating a new transaction: http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.548797:ERROR:http_cache_transaction.cc(204)] new HttpCache::Transaction: 0x3a7f7d25d400
[87774:87783:0823/161548.548825:ERROR:http_cache_transaction.cc(266)] Start at 0x3a7f7d25d400
[87774:87783:0823/161548.548956:ERROR:http_cache_transaction.cc(1426)] int net::HttpCache::Transaction::DoAddToEntryComplete(int) to Send
[87774:87783:0823/161548.548987:ERROR:throttling_network_transaction_factory.cc(30)] (throttling factory) Made new HttpNetworkTransaction: 0x3a7f7e51b600
[87774:87783:0823/161548.549007:ERROR:http_cache_transaction.cc(1680)] (cache) HttpCache::Transaction::DoSendRequest() at 0x3a7f7d25d400 calling Start on: 0x3a7f7eadc540
[87774:87783:0823/161548.549026:ERROR:throttling_network_transaction.cc(149)] ThrottlingNetworkTransaction::Start at 0x3a7f7eadc540 calling Start on 0x3a7f7e51b600
[87774:87783:0823/161548.549042:ERROR:http_network_transaction.cc(144)] HttpNetworkTransaction::Start on 0x3a7f7e51b600 for http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87803:0823/161548.549475:ERROR:embedded_test_server.cc(209)] HandleRequest(0x3a7f7d9060e0): http://localhost/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.549621:ERROR:navigation_url_loader_impl.cc(821)] FallbackCallback called
[87774:87783:0823/161548.549653:ERROR:navigation_url_loader_impl.cc(847)] Entered MakeNonInterceptedRequest for: http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.549753:ERROR:throttling_url_loader.cc(350)] Throttler is calling CreateLoaderAndStart for: http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.550029:ERROR:url_request_http_job.cc(977)] OnStartCompelted for http://127.0.0.1:40169/service_worker/navigation_preloadz.html: 0
[87774:87783:0823/161548.550492:ERROR:url_loader_factory.cc(67)] URLLoaderFactory::CreateLoaderAndStart called for: http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.550606:ERROR:url_request_http_job.cc(410)] URLRequestHttpJob::Start: http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.550695:ERROR:url_request_http_job.cc(621)] URLRequestHttpJob::StartTransactionInternal on 0x3a7f7d8baf80 is creating a new transaction: http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.550727:ERROR:http_cache_transaction.cc(204)] new HttpCache::Transaction: 0x3a7f7ea4d000
[87774:87783:0823/161548.550754:ERROR:http_cache_transaction.cc(266)] Start at 0x3a7f7ea4d000
[87774:87783:0823/161548.551092:ERROR:http_cache_transaction.cc(2556)] int net::HttpCache::Transaction::BeginCacheValidation() to Send
[87774:87783:0823/161548.551127:ERROR:throttling_network_transaction_factory.cc(30)] (throttling factory) Made new HttpNetworkTransaction: 0x3a7f7ea4d600
[87774:87783:0823/161548.551152:ERROR:http_cache_transaction.cc(1680)] (cache) HttpCache::Transaction::DoSendRequest() at 0x3a7f7ea4d000 calling Start on: 0x3a7f7eadc780
[87774:87783:0823/161548.551176:ERROR:throttling_network_transaction.cc(149)] ThrottlingNetworkTransaction::Start at 0x3a7f7eadc780 calling Start on 0x3a7f7ea4d600
[87774:87783:0823/161548.551200:ERROR:http_network_transaction.cc(144)] HttpNetworkTransaction::Start on 0x3a7f7ea4d600 for http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87803:0823/161548.551815:ERROR:embedded_test_server.cc(209)] HandleRequest(0x3a7f7ea94e00): http://localhost/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.552000:ERROR:http_cache_transaction.cc(1426)] int net::HttpCache::Transaction::DoAddToEntryComplete(int) to Send
[87774:87783:0823/161548.552052:ERROR:throttling_network_transaction_factory.cc(30)] (throttling factory) Made new HttpNetworkTransaction: 0x3a7f7ea4d600
[87774:87783:0823/161548.552081:ERROR:http_cache_transaction.cc(1680)] (cache) HttpCache::Transaction::DoSendRequest() at 0x3a7f7ea4d000 calling Start on: 0x3a7f7eadc780
[87774:87783:0823/161548.552103:ERROR:throttling_network_transaction.cc(149)] ThrottlingNetworkTransaction::Start at 0x3a7f7eadc780 calling Start on 0x3a7f7ea4d600
[87774:87783:0823/161548.552127:ERROR:http_network_transaction.cc(144)] HttpNetworkTransaction::Start on 0x3a7f7ea4d600 for http://127.0.0.1:40169/service_worker/navigation_preloadz.html
[87774:87803:0823/161548.552465:ERROR:embedded_test_server.cc(209)] HandleRequest(0x3a7f7ea94ee0): http://localhost/service_worker/navigation_preloadz.html
[87774:87783:0823/161548.552618:ERROR:url_request_http_job.cc(977)] OnStartCompelted for http://127.0.0.1:40169/service_worker/navigation_preloadz.html: 0
../../content/browser/service_worker/service_worker_browsertest.cc:2018: Failure
Value of: request_count == 1 || request_count == 2
  Actual: false
  Expected: true
  3

[+morlovich]:  This seems to be an issue at the cache layer.  Think you could be more useful here than I.  See explanation below.

The cache lock timeout is 20 seconds for non-range requests.  Putting a CHECK in the cache lock timeout case, it's not hit, but I do run into failures.  I suspect you're seeing the lock timeout because you're using breakpoints, and it's actually unrelated to the test failing.

By adding:
  static int count = 0;
  if (request->url.path() == "/service_worker/navigation_preload.html") {
    count ++;
    CHECK_LT(count, 3);
  }

everywhere (with the network service enabled), I've found that when the test fails, only two HttpCache::Transactions are created for navigation_preload.html, but three HttpNetworkTransactions are created for the url.  I'm not sure what could cause this to happen, since these aren't range requests (I assume).

Should out/Default/content_browser_tests --gtest_filter=ServiceWorkerNavigationPreloadTest.NetworkFallback --gtest_repeat=100 --enable-features=NetworkService
be able to reproduce it?

Yes.  My arguments (Just in case I'm missing some difference):

--gtest_filter=ServiceWorkerNavigationPreloadTest.NetworkFallback --enable-features=NetworkService --gtest_repeat=20

Oh, it's content_browsertests, by the way.

Thanks all. I wasn't using breakpoints but added LOG output and used this script to repro it:

#!/bin/bash
x=0
while [ $x == 0 ]
do
  testing/xvfb.py out/Default/content_browsertests --single-process --enable-features=NetworkService --gtest_filter="ServiceWorkerNavigationPreloadTest.NetworkFallback"
  x=$?
  echo $x
done

I could also use --gtest_repeat=100 without --single-process (I'd added that because I was going to try to use rr and gdb but didn't got that far.)

Just to give more information, the culprit CL r585201 did the following. Before the CL, the behavior was:
1) NavigationURLLoaderImpl asks service worker code whether it wants to handle the request.
2) SW code sends the navigation preload request.
3) SW code starts the SW and dispatches the fetch event.
4) SW code tells Navigation it doesn't want to handle the request.
5) Default navigation request behavior occurs: a ThrottlingURLLoader is created for the request, throttles run, and the request goes to network.

After the CL, the behavior is:
1) NavigationURLLoaderImpl asks service worker code whether it wants to handle the request.
2) SW code says yes.
3) Navigation creates a ThrottlingURLLoader for the request, throttles run, and the request goes to service worker code.
4) SW code sends the navigation preload request.
5) SW code starts the SW and dispatches the fetch event.
6) SW code tells Navigation it doesn't want to handle the request after all.
7) The original ThrottlingURLLoader is dropped.
8) Default navigation request behavior occurs: a new ThrottlingURLLoader is created for the request, throttles run, and the request goes to network.

Notable we run throttling twice after the CL. I don't see how that would induce the extra network request from HttpCache::Transaction though.

Finally got it to reproduce (didn't seem to want to on Linux), and this is what the debug output is --- probably will need more stuff to make any sense of out it...:


[5388:16956:0823/182148.793:ERROR:http_cache_transaction.cc(3570)] http://127.0.0.1:52145/service_worker/navigation_preload.html transition to send:Backtrace:
        base::debug::StackTrace::StackTrace [0x00007FFE06801855+101] (c:\src\chromium\src\base\debug\stack_trace_win.cc:286)
        base::debug::StackTrace::StackTrace [0x00007FFE0680088F+31] (c:\src\chromium\src\base\debug\stack_trace.cc:199)
        net::HttpCache::Transaction::TransitionToState [0x00007FFE05A8696E+222] (c:\src\chromium\src\net\http\http_cache_transaction.cc:3570)
        net::HttpCache::Transaction::DoAddToEntryComplete [0x00007FFE05A7F389+1689] (c:\src\chromium\src\net\http\http_cache_transaction.cc:1420)
        net::HttpCache::Transaction::DoLoop [0x00007FFE05A72F87+2215] (c:\src\chromium\src\net\http\http_cache_transaction.cc:880)
        net::HttpCache::Transaction::OnIOComplete [0x00007FFE05A70CEB+27] (c:\src\chromium\src\net\http\http_cache_transaction.cc:3565)
        base::internal::FunctorTraits<void (net::HttpCache::Transaction::*)(int),void>::Invoke<void (net::HttpCache::Transaction::*)(int),const base::WeakPtr<net::HttpCache::Transaction> &,int> [0x00007FFE05A8CE97+71] (c:\src\chromium\src\base\bind_internal.h:516)
        base::internal::InvokeHelper<1,void>::MakeItSo<void (net::HttpCache::Transaction::*const &)(int),const base::WeakPtr<net::HttpCache::Transaction> &,int> [0x00007FFE05A8CDB4+100] (c:\src\chromium\src\base\bind_internal.h:639)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::Transaction::*)(int),base::WeakPtr<net::HttpCache::Transaction> >,void (int)>::RunImpl<void (net::HttpCache::Transaction::*const &)(int),const std::tuple<base::WeakPtr<net::HttpCache: [0x00007FFE05A8CD42+98] (c:\src\chromium\src\base\bind_internal.h:689)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::Transaction::*)(int),base::WeakPtr<net::HttpCache::Transaction> >,void (int)>::Run [0x00007FFE05A8CC1F+95] (c:\src\chromium\src\base\bind_internal.h:671)
        base::RepeatingCallback<void (int)>::Run [0x00007FFE0595A5F9+105] (c:\src\chromium\src\base\callback.h:129)
        net::HttpCache::ProcessAddToEntryQueue [0x00007FFE05A48212+370] (c:\src\chromium\src\net\http\http_cache.cc:1066)
        net::HttpCache::OnProcessQueuedTransactions [0x00007FFE05A48079+521] (c:\src\chromium\src\net\http\http_cache.cc:1305)
        base::internal::FunctorTraits<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),void>::Invoke<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),const base::WeakPtr<net::HttpCache> &,net::HttpCache::ActiveEntry *const &> [0x00007FFE05A66478+72] (c:\src\chromium\src\base\bind_internal.h:516)
        base::internal::InvokeHelper<1,void>::MakeItSo<void (net::HttpCache::*const &)(net::HttpCache::ActiveEntry *),const base::WeakPtr<net::HttpCache> &,net::HttpCache::ActiveEntry *const &> [0x00007FFE05A66344+100] (c:\src\chromium\src\base\bind_internal.h:639)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),base::WeakPtr<net::HttpCache>,net::HttpCache::ActiveEntry *>,void ()>::RunImpl<void (net::HttpCache::*const &)(net::HttpCache::ActiveEntry *),const s [0x00007FFE05A662CD+109] (c:\src\chromium\src\base\bind_internal.h:689)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),base::WeakPtr<net::HttpCache>,net::HttpCache::ActiveEntry *>,void ()>::Run [0x00007FFE05A661AC+60] (c:\src\chromium\src\base\bind_internal.h:671)
        base::OnceCallback<void ()>::Run [0x00007FFE0679D851+97] (c:\src\chromium\src\base\callback.h:100)
        base::debug::TaskAnnotator::RunTask [0x00007FFE06805E93+915] (c:\src\chromium\src\base\debug\task_annotator.cc:103)
        base::MessageLoop::RunTask [0x00007FFE068A2FA3+979] (c:\src\chromium\src\base\message_loop\message_loop.cc:436)
        base::MessageLoop::DeferOrRunPendingTask [0x00007FFE068A34F3+83] (c:\src\chromium\src\base\message_loop\message_loop.cc:448)
        base::MessageLoop::DoWork [0x00007FFE068A39E4+484] (c:\src\chromium\src\base\message_loop\message_loop.cc:517)
        base::MessagePumpForIO::DoRunLoop [0x00007FFE068B2125+37] (c:\src\chromium\src\base\message_loop\message_pump_win.cc:494)
        base::MessagePumpWin::Run [0x00007FFE068AF9BC+140] (c:\src\chromium\src\base\message_loop\message_pump_win.cc:54)
        base::MessageLoop::Run [0x00007FFE068A281C+524] (c:\src\chromium\src\base\message_loop\message_loop.cc:388)
        base::RunLoop::Run [0x00007FFE0698056A+506] (c:\src\chromium\src\base\run_loop.cc:105)
        base::Thread::Run [0x00007FFE06AAB5FE+366] (c:\src\chromium\src\base\threading\thread.cc:262)
        base::Thread::ThreadMain [0x00007FFE06AABEF9+1449] (c:\src\chromium\src\base\threading\thread.cc:360)
        base::`anonymous namespace'::ThreadFunc [0x00007FFE06A9D6A3+403] (c:\src\chromium\src\base\threading\platform_thread_win.cc:102)
        BaseThreadInitThunk [0x00007FFE4DD21FE4+20]
        RtlUserThreadStart [0x00007FFE4F2CCB31+33]

[5388:16956:0823/182148.803:ERROR:http_cache_transaction.cc(3570)] http://127.0.0.1:52145/service_worker/navigation_preload.html transition to send:Backtrace:
        base::debug::StackTrace::StackTrace [0x00007FFE06801855+101] (c:\src\chromium\src\base\debug\stack_trace_win.cc:286)
        base::debug::StackTrace::StackTrace [0x00007FFE0680088F+31] (c:\src\chromium\src\base\debug\stack_trace.cc:199)
        net::HttpCache::Transaction::TransitionToState [0x00007FFE05A8696E+222] (c:\src\chromium\src\net\http\http_cache_transaction.cc:3570)
        net::HttpCache::Transaction::BeginCacheValidation [0x00007FFE05A89235+1573] (c:\src\chromium\src\net\http\http_cache_transaction.cc:2545)
        net::HttpCache::Transaction::BeginPartialCacheValidation [0x00007FFE05A884C7+327] (c:\src\chromium\src\net\http\http_cache_transaction.cc:2552)
        net::HttpCache::Transaction::DoCacheDispatchValidation [0x00007FFE05A80703+435] (c:\src\chromium\src\net\http\http_cache_transaction.cc:1561)
        net::HttpCache::Transaction::DoLoop [0x00007FFE05A73269+2953] (c:\src\chromium\src\net\http\http_cache_transaction.cc:901)
        net::HttpCache::Transaction::OnIOComplete [0x00007FFE05A70CEB+27] (c:\src\chromium\src\net\http\http_cache_transaction.cc:3565)
        base::internal::FunctorTraits<void (net::HttpCache::Transaction::*)(int),void>::Invoke<void (net::HttpCache::Transaction::*)(int),const base::WeakPtr<net::HttpCache::Transaction> &,int> [0x00007FFE05A8CE97+71] (c:\src\chromium\src\base\bind_internal.h:516)
        base::internal::InvokeHelper<1,void>::MakeItSo<void (net::HttpCache::Transaction::*const &)(int),const base::WeakPtr<net::HttpCache::Transaction> &,int> [0x00007FFE05A8CDB4+100] (c:\src\chromium\src\base\bind_internal.h:639)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::Transaction::*)(int),base::WeakPtr<net::HttpCache::Transaction> >,void (int)>::RunImpl<void (net::HttpCache::Transaction::*const &)(int),const std::tuple<base::WeakPtr<net::HttpCache: [0x00007FFE05A8CD42+98] (c:\src\chromium\src\base\bind_internal.h:689)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::Transaction::*)(int),base::WeakPtr<net::HttpCache::Transaction> >,void (int)>::Run [0x00007FFE05A8CC1F+95] (c:\src\chromium\src\base\bind_internal.h:671)
        base::RepeatingCallback<void (int)>::Run [0x00007FFE0595A5F9+105] (c:\src\chromium\src\base\callback.h:129)
        net::HttpCache::ProcessAddToEntryQueue [0x00007FFE05A48212+370] (c:\src\chromium\src\net\http\http_cache.cc:1066)
        net::HttpCache::OnProcessQueuedTransactions [0x00007FFE05A48079+521] (c:\src\chromium\src\net\http\http_cache.cc:1305)
        base::internal::FunctorTraits<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),void>::Invoke<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),const base::WeakPtr<net::HttpCache> &,net::HttpCache::ActiveEntry *const &> [0x00007FFE05A66478+72] (c:\src\chromium\src\base\bind_internal.h:516)
        base::internal::InvokeHelper<1,void>::MakeItSo<void (net::HttpCache::*const &)(net::HttpCache::ActiveEntry *),const base::WeakPtr<net::HttpCache> &,net::HttpCache::ActiveEntry *const &> [0x00007FFE05A66344+100] (c:\src\chromium\src\base\bind_internal.h:639)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),base::WeakPtr<net::HttpCache>,net::HttpCache::ActiveEntry *>,void ()>::RunImpl<void (net::HttpCache::*const &)(net::HttpCache::ActiveEntry *),const s [0x00007FFE05A662CD+109] (c:\src\chromium\src\base\bind_internal.h:689)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),base::WeakPtr<net::HttpCache>,net::HttpCache::ActiveEntry *>,void ()>::Run [0x00007FFE05A661AC+60] (c:\src\chromium\src\base\bind_internal.h:671)
        base::OnceCallback<void ()>::Run [0x00007FFE0679D851+97] (c:\src\chromium\src\base\callback.h:100)
        base::debug::TaskAnnotator::RunTask [0x00007FFE06805E93+915] (c:\src\chromium\src\base\debug\task_annotator.cc:103)
        base::MessageLoop::RunTask [0x00007FFE068A2FA3+979] (c:\src\chromium\src\base\message_loop\message_loop.cc:436)
        base::MessageLoop::DeferOrRunPendingTask [0x00007FFE068A34F3+83] (c:\src\chromium\src\base\message_loop\message_loop.cc:448)
        base::MessageLoop::DoWork [0x00007FFE068A39E4+484] (c:\src\chromium\src\base\message_loop\message_loop.cc:517)
        base::MessagePumpForIO::DoRunLoop [0x00007FFE068B2125+37] (c:\src\chromium\src\base\message_loop\message_pump_win.cc:494)
        base::MessagePumpWin::Run [0x00007FFE068AF9BC+140] (c:\src\chromium\src\base\message_loop\message_pump_win.cc:54)
        base::MessageLoop::Run [0x00007FFE068A281C+524] (c:\src\chromium\src\base\message_loop\message_loop.cc:388)
        base::RunLoop::Run [0x00007FFE0698056A+506] (c:\src\chromium\src\base\run_loop.cc:105)
        base::Thread::Run [0x00007FFE06AAB5FE+366] (c:\src\chromium\src\base\threading\thread.cc:262)
        base::Thread::ThreadMain [0x00007FFE06AABEF9+1449] (c:\src\chromium\src\base\threading\thread.cc:360)
        base::`anonymous namespace'::ThreadFunc [0x00007FFE06A9D6A3+403] (c:\src\chromium\src\base\threading\platform_thread_win.cc:102)
        BaseThreadInitThunk [0x00007FFE4DD21FE4+20]
        RtlUserThreadStart [0x00007FFE4F2CCB31+33]

[5388:16956:0823/182148.810:ERROR:http_cache_transaction.cc(3570)] http://127.0.0.1:52145/service_worker/navigation_preload.html transition to send:Backtrace:
        base::debug::StackTrace::StackTrace [0x00007FFE06801855+101] (c:\src\chromium\src\base\debug\stack_trace_win.cc:286)
        base::debug::StackTrace::StackTrace [0x00007FFE0680088F+31] (c:\src\chromium\src\base\debug\stack_trace.cc:199)
        net::HttpCache::Transaction::TransitionToState [0x00007FFE05A8696E+222] (c:\src\chromium\src\net\http\http_cache_transaction.cc:3570)
        net::HttpCache::Transaction::DoAddToEntryComplete [0x00007FFE05A7F389+1689] (c:\src\chromium\src\net\http\http_cache_transaction.cc:1420)
        net::HttpCache::Transaction::DoLoop [0x00007FFE05A72F87+2215] (c:\src\chromium\src\net\http\http_cache_transaction.cc:880)
        net::HttpCache::Transaction::OnIOComplete [0x00007FFE05A70CEB+27] (c:\src\chromium\src\net\http\http_cache_transaction.cc:3565)
        base::internal::FunctorTraits<void (net::HttpCache::Transaction::*)(int),void>::Invoke<void (net::HttpCache::Transaction::*)(int),const base::WeakPtr<net::HttpCache::Transaction> &,int> [0x00007FFE05A8CE97+71] (c:\src\chromium\src\base\bind_internal.h:516)
        base::internal::InvokeHelper<1,void>::MakeItSo<void (net::HttpCache::Transaction::*const &)(int),const base::WeakPtr<net::HttpCache::Transaction> &,int> [0x00007FFE05A8CDB4+100] (c:\src\chromium\src\base\bind_internal.h:639)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::Transaction::*)(int),base::WeakPtr<net::HttpCache::Transaction> >,void (int)>::RunImpl<void (net::HttpCache::Transaction::*const &)(int),const std::tuple<base::WeakPtr<net::HttpCache: [0x00007FFE05A8CD42+98] (c:\src\chromium\src\base\bind_internal.h:689)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::Transaction::*)(int),base::WeakPtr<net::HttpCache::Transaction> >,void (int)>::Run [0x00007FFE05A8CC1F+95] (c:\src\chromium\src\base\bind_internal.h:671)
        base::RepeatingCallback<void (int)>::Run [0x00007FFE0595A5F9+105] (c:\src\chromium\src\base\callback.h:129)
        net::HttpCache::ProcessAddToEntryQueue [0x00007FFE05A48212+370] (c:\src\chromium\src\net\http\http_cache.cc:1066)
        net::HttpCache::OnProcessQueuedTransactions [0x00007FFE05A48079+521] (c:\src\chromium\src\net\http\http_cache.cc:1305)
        base::internal::FunctorTraits<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),void>::Invoke<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),const base::WeakPtr<net::HttpCache> &,net::HttpCache::ActiveEntry *const &> [0x00007FFE05A66478+72] (c:\src\chromium\src\base\bind_internal.h:516)
        base::internal::InvokeHelper<1,void>::MakeItSo<void (net::HttpCache::*const &)(net::HttpCache::ActiveEntry *),const base::WeakPtr<net::HttpCache> &,net::HttpCache::ActiveEntry *const &> [0x00007FFE05A66344+100] (c:\src\chromium\src\base\bind_internal.h:639)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),base::WeakPtr<net::HttpCache>,net::HttpCache::ActiveEntry *>,void ()>::RunImpl<void (net::HttpCache::*const &)(net::HttpCache::ActiveEntry *),const s [0x00007FFE05A662CD+109] (c:\src\chromium\src\base\bind_internal.h:689)
        base::internal::Invoker<base::internal::BindState<void (net::HttpCache::*)(net::HttpCache::ActiveEntry *),base::WeakPtr<net::HttpCache>,net::HttpCache::ActiveEntry *>,void ()>::Run [0x00007FFE05A661AC+60] (c:\src\chromium\src\base\bind_internal.h:671)
        base::OnceCallback<void ()>::Run [0x00007FFE0679D851+97] (c:\src\chromium\src\base\callback.h:100)
        base::debug::TaskAnnotator::RunTask [0x00007FFE06805E93+915] (c:\src\chromium\src\base\debug\task_annotator.cc:103)
        base::MessageLoop::RunTask [0x00007FFE068A2FA3+979] (c:\src\chromium\src\base\message_loop\message_loop.cc:436)
        base::MessageLoop::DeferOrRunPendingTask [0x00007FFE068A34F3+83] (c:\src\chromium\src\base\message_loop\message_loop.cc:448)
        base::MessageLoop::DoWork [0x00007FFE068A39E4+484] (c:\src\chromium\src\base\message_loop\message_loop.cc:517)
        base::MessagePumpForIO::DoRunLoop [0x00007FFE068B2125+37] (c:\src\chromium\src\base\message_loop\message_pump_win.cc:494)
        base::MessagePumpWin::Run [0x00007FFE068AF9BC+140] (c:\src\chromium\src\base\message_loop\message_pump_win.cc:54)
        base::MessageLoop::Run [0x00007FFE068A281C+524] (c:\src\chromium\src\base\message_loop\message_loop.cc:388)
        base::RunLoop::Run [0x00007FFE0698056A+506] (c:\src\chromium\src\base\run_loop.cc:105)
        base::Thread::Run [0x00007FFE06AAB5FE+366] (c:\src\chromium\src\base\threading\thread.cc:262)
        base::Thread::ThreadMain [0x00007FFE06AABEF9+1449] (c:\src\chromium\src\base\threading\thread.cc:360)
        base::`anonymous namespace'::ThreadFunc [0x00007FFE06A9D6A3+403] (c:\src\chromium\src\base\threading\platform_thread_win.cc:102)
        BaseThreadInitThunk [0x00007FFE4DD21FE4+20]
        RtlUserThreadStart [0x00007FFE4F2CCB31+33]

Ugh, it looks like I just misread my log from last times.

ERR_CACHE_LOCK_TIMEOUT indeed isn't being hit. DoAddToEntryComplete transitions from here instead:

  if (mode_ == WRITE) {
    if (partial_)
      partial_->RestoreHeaders(&custom_request_->extra_headers);
    TransitionToState(STATE_SEND_REQUEST);

It looks like in the failure path there's a "collision" of BeginCacheValidation() and DoAddToEntryComplete() both transitioning to STATE_SEND_REQUEST. In the success path, either BeginCacheValidation() or DoAddToEntryComplete() transition to STATE_SEND_REQUEST, but not both. Almost all of the time, it's DoAddToEntryComplete().

Here is a failing log with state changes printed for one HttpCache::Transaction.

[202386:202400:0824/101453.876480:ERROR:http_cache_transaction.cc(204)] new HttpCache::Transaction: 0x389e70cd4600
[202386:202400:0824/101453.876505:ERROR:http_cache_transaction.cc(266)] Start at 0x389e70cd4600
[202386:202400:0824/101453.876536:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 2 (STATE_GET_BACKEND)
[202386:202400:0824/101453.876563:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 3 (STATE_GET_BACKEND_COMPLETE)
[202386:202400:0824/101453.876595:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 4 (STATE_INIT_ENTRY)
[202386:202400:0824/101453.876623:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 5 (STATE_OPEN_ENTRY)
[202386:202400:0824/101453.876646:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 6 (STATE_OPEN_ENTY_COMPLETE)
[202386:202400:0824/101453.876665:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 11 (STATE_ADD_TO_ENTRY)
[202386:202400:0824/101453.877780:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 12 (STATE_ADD_TO_ENTRY_COMPLETE)
[202386:202400:0824/101453.877810:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 14 (STATE_CACHE_READ_RESPONSE)
[202386:202400:0824/101453.877834:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 15 (STATE_CACHE_READ_RESPONSE_COMPLETE)
[202386:202400:0824/101453.877863:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 18 (STATE_CACHE_DISPATCH_VALIDATION)
[202386:202400:0824/101453.877890:ERROR:http_cache_transaction.cc(2560)] int net::HttpCache::Transaction::BeginCacheValidation() to Send
[202386:202400:0824/101453.877909:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 26 (STATE_SEND_REQUEST)
[202386:202400:0824/101453.877932:ERROR:throttling_network_transaction_factory.cc(30)] (throttling factory) Made new HttpNetworkTransaction: 0x389e70cd4c00
[202386:202400:0824/101453.877952:ERROR:http_cache_transaction.cc(1684)] (cache) HttpCache::Transaction::DoSendRequest() at 0x389e70cd4600 calling Start on: 0x389e70cdac60
[202386:202400:0824/101453.877971:ERROR:throttling_network_transaction.cc(149)] ThrottlingNetworkTransaction::Start at 0x389e70cdac60 calling Start on 0x389e70cd4c00
[202386:202400:0824/101453.877989:ERROR:http_network_transaction.cc(144)] HttpNetworkTransaction::Start on 0x389e70cd4c00 for http://127.0.0.1:40265/service_worker/navigation_preloadz.html
[202365:202414:0824/101453.878220:ERROR:embedded_test_server.cc(426)] made a new HttpConnection: 0x22cbec93070
[202365:202414:0824/101453.878750:ERROR:embedded_test_server.cc(209)] HandleRequest(0x22cbec93070): http://localhost/service_worker/navigation_preloadz.html
[202386:202400:0824/101453.878871:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 43 (STATE_HEADERS_PHASE_CANNOT_PROCEED)
[202386:202400:0824/101453.878937:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 2 (STATE_GET_BACKEND)
[202386:202400:0824/101453.878964:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 3 (STATE_GET_BACKEND_COMPLETE)
[202386:202400:0824/101453.878987:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 4 (STATE_INIT_ENTRY)
[202386:202400:0824/101453.879006:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 5 (STATE_OPEN_ENTRY)
[202386:202400:0824/101453.879039:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 6 (STATE_OPEN_ENTRY_COMPLETE)
[202386:202400:0824/101453.879059:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 9 (STATE_CREATE_ENTRY)
[202386:202400:0824/101453.879085:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 10 (STATE_CREATE_ENTRY_COMPLETE)
[202386:202400:0824/101453.879104:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 11 (STATE_ADD_TO_ENTRY)
[202386:202400:0824/101453.879139:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 12 (STATE_ADD_TO_ENTRY_COMPLETE)
[202386:202400:0824/101453.879161:ERROR:http_cache_transaction.cc(1430)] int net::HttpCache::Transaction::DoAddToEntryComplete(int) to Send
[202386:202400:0824/101453.879180:ERROR:http_cache_transaction.cc(843)] Enter state(0x389e70cd4600): 26 (STATE_SEND_REQEST)

It looks like the key is we somehow jump to STATE_HEADERS_PHASE_CANNOT_PROCEED.

The jump comes from net::HttpCache::RestartHeadersTransaction() calling SetValidatingCannotProceed():

#0 0x7f0948f7f3ec base::debug::StackTrace::StackTrace()
#1 0x7f0948a1ad2d net::HttpCache::RestartHeadersTransaction()
#2 0x7f0948a19fc6 net::HttpCache::ProcessEntryFailure()
#3 0x7f0948a1a70e net::HttpCache::WritersDoneWritingToEntry()
#4 0x7f0948a3287d net::HttpCache::Writers::RemoveTransaction()
#5 0x7f0948a19f80 net::HttpCache::DoneWithEntry()
#6 0x7f0948a1e494 net::HttpCache::Transaction::DoneWithEntry()
#7 0x7f0948a1e061 net::HttpCache::Transaction::~Transaction()
#8 0x7f0948a1e4de net::HttpCache::Transaction::~Transaction()
#9 0x7f0948c3d371 net::URLRequestHttpJob::DestroyTransaction()
#10 0x7f0948c3d236 net::URLRequestHttpJob::Kill()
#11 0x7f0948c33b5d net::URLRequest::DoCancel()
#12 0x7f0948c30731 net::URLRequest::~URLRequest()
#13 0x7f0948c30b1e net::URLRequest::~URLRequest()
#14 0x7f0944608b83 network::URLLoader::~URLLoader()
#15 0x7f0944608d9e network::URLLoader::~URLLoader()
#16 0x7f09445aebc8 network::cors::CORSURLLoaderFactory::DestroyURLLoader()
#17 0x7f09446084ad network::URLLoader::NotifyCompleted()
#18 0x7f09445a5034 mojo::SimpleWatcher::DiscardReadyState()
#19 0x7f0948d74ad3 mojo::SimpleWatcher::OnHandleReady()
#20 0x7f0948d74f61 mojo::SimpleWatcher::Context::Notify()
#21 0x7f0948d73973 mojo::SimpleWatcher::Context::CallNotify()
#22 0x7f093d9147c7 mojo::core::WatcherDispatcher::InvokeWatchCallback()
#23 0x7f093d913f12 mojo::core::Watch::InvokeCallback()
#24 0x7f093d90e9da mojo::core::RequestContext::~RequestContext()
#25 0x7f093d8ff84d mojo::core::NodeChannel::OnChannelMessage()
#26 0x7f093d8eaa0f mojo::core::Channel::OnReadComplete()
#27 0x7f093d9198b2 mojo::core::(anonymous namespace)::ChannelPosix::OnFileCanReadWithoutBlocking()
#28 0x7f0948fa282c base::MessagePumpLibevent::OnLibeventNotification()
#29 0x7f0948fba7ed event_base_loop
#30 0x7f0948fa2aae base::MessagePumpLibevent::Run()
#31 0x7f0948eb7cd1 base::MessageLoop::Run()
#32 0x7f0948eec276 base::RunLoop::Run()
#33 0x7f0948f4757a base::Thread::Run()
#34 0x7f0948f47b37 base::Thread::ThreadMain()
#35 0x7f0948f9511f base::(anonymous namespace)::ThreadFunc()
#36 0x7f093e769494 start_thread
#37 0x7f093e1a7a8f clone

So it thinks that a previous fetch failed (since it still has an open cache entry), and so restarts those concurrent to it since it thinks the data is incomplete and can't be reused...

Why would that result in creating two requests?

I think what the code believes is that while one request failed during fetching the body (did it?), another partly concurrent one is in process of looking at response headers that the earlier fetch wrote out, and if it decides to either use the previous response or send a conditional request (which is what happened here) it would run into a trouble since the body for a cache hit or a 304 isn't actually there, so it just starts the process over (and if it was going to decide to start over anyway, it would just duplicate the cache read).

It may be that the initial prefetch is aborted if it doesn't complete in time, I think?

Yep I've confirmed it's the URLLoader for the initial navigation preload request whose destruction triggers the net::HttpCache::RestartHeadersTransaction() call.

It's expected in this test that the nav preload request gets aborted, since the service worker doesn't use it.

I thought these requests would be isolated because the nav preload request has a Service-Worker-Navigation-Preload header which the normal navigation request doesn't have. Is the HTTP cache keyed only by URL and ignores headers?

It's conceivable a site delivers a different response for the preload request than the normal request. For example, a mail/SNS site might deliver only a JSON payload of your most recent news/mail, and expect the SW to produce the appshell locally from cache.

Anyways, it seems like this behavior was possible even before r585201 (comment 11 describes what that CL did).

Do you all think this a behavior to fix in the HTTP cache implementation, or should the service worker layer try to change its use of requests to avoid this?

The cache is keyed on URL (See the "Vary" header, which specifies which headers changing require revalidation - even then, it's still revalidation, using the old cache entry, despite the header changes).  Any server that returns different responses based on headers must send a "Vary" header for that URL (Or a header to disable caching).

It sounds to me like the cache is behaving as intended, though it's a bit unfortunate that it can cancel and re-issue a request in response to another request being cancelled.

Thanks, that makes sense. I'll edit the browser_test to expect this behavior. We should only see this behavior if the navigation preload request is not actually used, which is wasteful and developers are warned not to do: https://developers.google.com/web/updates/2017/02/navigation-preload#using_the_preloaded_response

However, for some reason I'm not seeing our expected warning in the console these days: https://cs.chromium.org/chromium/src/content/renderer/service_worker/service_worker_context_client.cc?l=649&rcl=f631db2c2d9598a2bfe3233068bf567966536100

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

commit ba675a6061016667486723541f9845607afb760a
Author: Matt Falkenhagen <falken@chromium.org>
Date: Mon Aug 27 22:12:04 2018

service worker: Enable nav preload network fallback test under NetworkService.

The test was flakily failing because the test server was seeing three
requests during the navigation instead of the expected one or two.

Analysis of the bug showed this was an expected possible path of the
browser cache, which happens when there are concurrent requests and one
of them is cancelled. The cache thinks it should not continue and
restarts the ongoing request, which can cause an extra network request.

This test hit the path because it issues a navigation preload request
and immediately cancels it and starts the normal navigation request.

Since developers are advised not to activate navigation preload and then
not use it,[1] we can keep this behavior.

It's unknown though why r585201 caused this flake to appear when it
didn't appear before. It's looks like it should have always been
possible.

[1] https://developers.google.com/web/updates/2017/02/navigation-preload#using_the_preloaded_response

Bug:  876911 
Cq-Include-Trybots: luci.chromium.try:linux_mojo
Change-Id: I42eca116bcfffbb3c622d040343aa62980b83ee5
Reviewed-on: https://chromium-review.googlesource.com/1189514
Commit-Queue: Matt Falkenhagen <falken@chromium.org>
Reviewed-by: Kinuko Yasuda <kinuko@chromium.org>
Cr-Commit-Position: refs/heads/master@{#586442}
[modify] https://crrev.com/ba675a6061016667486723541f9845607afb760a/content/browser/service_worker/service_worker_browsertest.cc
[modify] https://crrev.com/ba675a6061016667486723541f9845607afb760a/testing/buildbot/filters/mojo.fyi.network_content_browsertests.filter