Adds cache lock timeout handling after finishing headers phase.

net/http/http_cache_transaction.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/http/http_cache_transaction.h"
 
 #include "build/build_config.h"  // For OS_POSIX
 
 #if defined(OS_POSIX)
 #include <unistd.h>
@@ skipping 150 matching lines @@
       invalid_range_(false),
       truncated_(false),
       is_sparse_(false),
       range_requested_(false),
       handling_206_(false),
       cache_pending_(false),
       done_reading_(false),
       vary_mismatch_(false),
       couldnt_conditionalize_request_(false),
       bypass_lock_for_test_(false),
+      bypass_lock_after_headers_for_test_(false),
       fail_conditionalization_for_test_(false),
       io_buf_len_(0),
       read_offset_(0),
       effective_load_flags_(0),
       write_len_(0),
       cache_entry_status_(CacheEntryStatus::ENTRY_UNDEFINED),
       validation_cause_(VALIDATION_CAUSE_UNDEFINED),
       total_received_bytes_(0),
       total_sent_bytes_(0),
       websocket_handshake_stream_base_create_helper_(NULL),
@@ skipping 665 matching lines @@
         rv = DoPartialHeadersReceived();
         break;
       case STATE_CACHE_READ_METADATA:
         DCHECK_EQ(OK, rv);
         rv = DoCacheReadMetadata();
         break;
       case STATE_CACHE_READ_METADATA_COMPLETE:
         rv = DoCacheReadMetadataComplete(rv);
         break;
       case STATE_HEADERS_PHASE_CANNOT_PROCEED:
-        rv = DoHeadersPhaseCannotProceed();
+        rv = DoHeadersPhaseCannotProceed(rv);
         break;
       case STATE_FINISH_HEADERS:
         rv = DoFinishHeaders(rv);
         break;
       case STATE_FINISH_HEADERS_COMPLETE:
         rv = DoFinishHeadersComplete(rv);
         break;
       case STATE_NETWORK_READ:
         DCHECK_EQ(OK, rv);
         rv = DoNetworkRead();
@@ skipping 49 matching lines @@
   net_log_.BeginEvent(NetLogEventType::HTTP_CACHE_GET_BACKEND);
   return cache_->GetBackendForTransaction(this);
 }
 
 int HttpCache::Transaction::DoGetBackendComplete(int result) {
   DCHECK(result == OK || result == ERR_FAILED);
   net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_GET_BACKEND,
                                     result);
   cache_pending_ = false;
 
+  // Reset mode_ that might get set in this function. This is done because this
+  // function can be invoked multiple times for a transaction.
+  mode_ = NONE;

[Randy Smith (Not in Mondays), 2017/06/23 17:38:01]

Was there a specific failure that this was addressing, or is this just trying to
make the function more clearly and reliably execute its intent?

[shivanisha, 2017/06/23 19:16:08]

Since we now have another flow that comes to this state and in this flow its
possible that mode_ was set to something and this function assumes that it is
set to NONE (There is no default path setting it to NONE below when
ShouldPassThrough() returns true.)

+
   if (!ShouldPassThrough()) {
     cache_key_ = cache_->GenerateCacheKey(request_);
 
     // Requested cache access mode.
     if (effective_load_flags_ & LOAD_ONLY_FROM_CACHE) {
       if (effective_load_flags_ & LOAD_BYPASS_CACHE) {
         // The client has asked for nonsense.
         TransitionToState(STATE_FINISH_HEADERS);
         return ERR_CACHE_MISS;
       }
@@ skipping 188 matching lines @@
 
 int HttpCache::Transaction::DoAddToEntry() {
   TRACE_EVENT0("io", "HttpCacheTransaction::DoAddToEntry");
   DCHECK(new_entry_);
   cache_pending_ = true;
   TransitionToState(STATE_ADD_TO_ENTRY_COMPLETE);
   net_log_.BeginEvent(NetLogEventType::HTTP_CACHE_ADD_TO_ENTRY);
   DCHECK(entry_lock_waiting_since_.is_null());
   entry_lock_waiting_since_ = TimeTicks::Now();
   int rv = cache_->AddTransactionToEntry(new_entry_, this);
-  if (rv == ERR_IO_PENDING) {
-    if (bypass_lock_for_test_) {
-      base::ThreadTaskRunnerHandle::Get()->PostTask(
-          FROM_HERE,
-          base::Bind(&HttpCache::Transaction::OnAddToEntryTimeout,
-                     weak_factory_.GetWeakPtr(), entry_lock_waiting_since_));
-    } else {
-      int timeout_milliseconds = 20 * 1000;
-      if (partial_ && new_entry_->writer &&
-          new_entry_->writer->range_requested_) {
-        // Quickly timeout and bypass the cache if we're a range request and
-        // we're blocked by the reader/writer lock. Doing so eliminates a long
-        // running issue, http://crbug.com/31014, where two of the same media
-        // resources could not be played back simultaneously due to one locking
-        // the cache entry until the entire video was downloaded.
-        //
-        // Bypassing the cache is not ideal, as we are now ignoring the cache
-        // entirely for all range requests to a resource beyond the first. This
-        // is however a much more succinct solution than the alternatives, which
-        // would require somewhat significant changes to the http caching logic.
-        //
-        // Allow some timeout slack for the entry addition to complete in case
-        // the writer lock is imminently released; we want to avoid skipping
-        // the cache if at all possible. See http://crbug.com/408765
-        timeout_milliseconds = 25;
-      }
-      base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
-          FROM_HERE,
-          base::Bind(&HttpCache::Transaction::OnAddToEntryTimeout,
-                     weak_factory_.GetWeakPtr(), entry_lock_waiting_since_),
-          TimeDelta::FromMilliseconds(timeout_milliseconds));
-    }
-  }
+  if (rv == ERR_IO_PENDING)
+    AddTimeoutHandler(new_entry_);
   return rv;
 }
 
+void HttpCache::Transaction::AddTimeoutHandler(ActiveEntry* entry) {
+  if (bypass_lock_for_test_ || bypass_lock_after_headers_for_test_) {

[Randy Smith (Not in Mondays), 2017/06/23 17:38:01]

How is the effect of these two booleans different?  If it isn't different, why
can't they be combined?

[shivanisha, 2017/06/23 19:16:08]

bypass_lock_for_test_ calls the timeout handler when the transaction is in
add_to_entry_queue and bypass_lock_after_headers_for_test_ calls the timeout
handler when the transaction is in done_headers_queue. A test that needs to test
the latter should not use the time out handler when the transaction is in
add_to_entry_queue.

+    base::ThreadTaskRunnerHandle::Get()->PostTask(
+        FROM_HERE,
+        base::Bind(&HttpCache::Transaction::OnCacheLockTimeout,
+                   weak_factory_.GetWeakPtr(), entry_lock_waiting_since_));
+  } else {
+    int timeout_milliseconds = 20 * 1000;
+    if (partial_ && entry->writer && entry->writer->range_requested_) {
+      // Quickly timeout and bypass the cache if we're a range request and
+      // we're blocked by the reader/writer lock. Doing so eliminates a long
+      // running issue, http://crbug.com/31014, where two of the same media
+      // resources could not be played back simultaneously due to one locking
+      // the cache entry until the entire video was downloaded.
+      //
+      // Bypassing the cache is not ideal, as we are now ignoring the cache
+      // entirely for all range requests to a resource beyond the first. This
+      // is however a much more succinct solution than the alternatives, which
+      // would require somewhat significant changes to the http caching logic.
+      //
+      // Allow some timeout slack for the entry addition to complete in case
+      // the writer lock is imminently released; we want to avoid skipping
+      // the cache if at all possible. See http://crbug.com/408765
+      timeout_milliseconds = 25;
+    }
+    base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
+        FROM_HERE,
+        base::Bind(&HttpCache::Transaction::OnCacheLockTimeout,
+                   weak_factory_.GetWeakPtr(), entry_lock_waiting_since_),
+        TimeDelta::FromMilliseconds(timeout_milliseconds));
+  }
+}
+
 int HttpCache::Transaction::DoAddToEntryComplete(int result) {
   TRACE_EVENT0("io", "HttpCacheTransaction::DoAddToEntryComplete");
   net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_ADD_TO_ENTRY,
                                     result);
   const TimeDelta entry_lock_wait =
       TimeTicks::Now() - entry_lock_waiting_since_;
   UMA_HISTOGRAM_TIMES("HttpCache.EntryLockWait", entry_lock_wait);
 
   entry_lock_waiting_since_ = TimeTicks();
   DCHECK(new_entry_);
@@ skipping 630 matching lines @@
     // We are about to return the headers for a byte-range request to the user,
     // so let's fix them.
     partial_->FixResponseHeaders(response_.headers.get(), true);
     TransitionToState(STATE_FINISH_HEADERS);
   } else {
     TransitionToState(STATE_FINISH_HEADERS);
   }
   return OK;
 }
 
-int HttpCache::Transaction::DoHeadersPhaseCannotProceed() {
+int HttpCache::Transaction::DoHeadersPhaseCannotProceed(int result) {
   // If its the Start state machine and it cannot proceed due to a cache
   // failure, restart this transaction.
   DCHECK(!reading_);
 
   // Reset before invoking SetRequest() which can reset the request info sent to
   // network transaction.
   if (network_trans_)
     network_trans_.reset();
 
   SetRequest(net_log_);
 
   entry_ = nullptr;
 
+  // Bypass the cache for timeout scenario.
+  if (result == ERR_CACHE_LOCK_TIMEOUT)
+    effective_load_flags_ |= LOAD_DISABLE_CACHE;
+
   TransitionToState(STATE_GET_BACKEND);
   return OK;
 }
 
 int HttpCache::Transaction::DoFinishHeaders(int result) {
   if (!cache_.get() || !entry_ || result != OK) {
     TransitionToState(STATE_NONE);
     return result;
   }
 
   TransitionToState(STATE_FINISH_HEADERS_COMPLETE);
 
   // If it was an auth failure or 416, this transaction should continue to be
   // headers_transaction till consumer takes an action, so no need to do
   // anything now.
   if (auth_response_.headers.get() ||
       (new_response_ && new_response_->headers &&
        new_response_->headers->response_code() == 416))
     return OK;
 
   // If the transaction needs to wait because another transaction is still
   // writing the response body, it will return ERR_IO_PENDING now and the
   // io_callback_ will be invoked when the wait is done.
-  return cache_->DoneWithResponseHeaders(entry_, this, partial_ != nullptr);
+  int rv = cache_->DoneWithResponseHeaders(entry_, this, partial_ != nullptr);
+  if (rv == ERR_IO_PENDING)
+    AddTimeoutHandler(entry_);
+  return rv;
 }
 
 int HttpCache::Transaction::DoFinishHeadersComplete(int rv) {
-  if (rv == ERR_CACHE_RACE) {
+  if (rv == ERR_CACHE_RACE || rv == ERR_CACHE_LOCK_TIMEOUT) {
     TransitionToState(STATE_HEADERS_PHASE_CANNOT_PROCEED);
-    return OK;
+    return rv;
   }
 
   TransitionToState(STATE_NONE);
   return rv;
 }
 
 int HttpCache::Transaction::DoCacheReadMetadata() {
   TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheReadMetadata");
   DCHECK(entry_);
   DCHECK(!response_.metadata.get());
@@ skipping 924 matching lines @@
     is_sparse_ = false;
     partial_.reset();
     TransitionToState(STATE_GET_BACKEND);
     return OK;
   }
 
   TransitionToState(STATE_NONE);
   return ERR_CACHE_READ_FAILURE;
 }
 
-void HttpCache::Transaction::OnAddToEntryTimeout(base::TimeTicks start_time) {
+void HttpCache::Transaction::OnCacheLockTimeout(base::TimeTicks start_time) {
   if (entry_lock_waiting_since_ != start_time)

[Randy Smith (Not in Mondays), 2017/06/23 17:38:02]

AddToEntry->AddToEntryComplete sets and then resets entry_lock_waiting_since_,
allowing this conditional to be a good test to make sure the delayed task has
fired during the async operation we're trying to time out.  Doesn't the same
structure need to be in place across DoFinishHeaders/DoFinishHeadersComplete?

[shivanisha, 2017/06/23 19:16:08]

Good idea, done

     return;
 
-  DCHECK_EQ(next_state_, STATE_ADD_TO_ENTRY_COMPLETE);
+  DCHECK(next_state_ == STATE_ADD_TO_ENTRY_COMPLETE ||
+         next_state_ == STATE_FINISH_HEADERS_COMPLETE);
 
   if (!cache_)
     return;
 
-  cache_->RemovePendingTransaction(this);
+  if (next_state_ == STATE_ADD_TO_ENTRY_COMPLETE)
+    cache_->RemovePendingTransaction(this);
+  else
+    cache_->DoneWithEntry(entry_, this, false, partial_ != nullptr);
   OnIOComplete(ERR_CACHE_LOCK_TIMEOUT);
 }
 
 void HttpCache::Transaction::DoomPartialEntry(bool delete_object) {
   DVLOG(2) << "DoomPartialEntry";
   int rv = cache_->DoomEntry(cache_key_, NULL);
   DCHECK_EQ(OK, rv);
   cache_->DoneWithEntry(entry_, this, false /* process_cancel */,
                         partial_ != nullptr);
   entry_ = NULL;
@@ skipping 309 matching lines @@
 }
 
 void HttpCache::Transaction::TransitionToState(State state) {
   // Ensure that the state is only set once per Do* state.
   DCHECK(in_do_loop_);
   DCHECK_EQ(STATE_UNSET, next_state_) << "Next state is " << state;
   next_state_ = state;
 }
 
 }  // namespace net