[SPDY] Close SPDY sessions on session flow control errors

net/spdy/spdy_session.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/spdy/spdy_session.h"
 
 #include <algorithm>
 #include <map>
 
 #include "base/basictypes.h"
 #include "base/bind.h"
 #include "base/compiler_specific.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "base/metrics/field_trial.h"
 #include "base/metrics/histogram.h"
 #include "base/metrics/sparse_histogram.h"
 #include "base/metrics/stats_counters.h"
 #include "base/stl_util.h"
-#include "base/string_number_conversions.h"
 #include "base/string_util.h"
 #include "base/stringprintf.h"
+#include "base/strings/string_number_conversions.h"
 #include "base/time.h"
 #include "base/utf_string_conversions.h"
 #include "base/values.h"
 #include "crypto/ec_private_key.h"
 #include "crypto/ec_signature_creator.h"
 #include "net/base/connection_type_histograms.h"
 #include "net/base/net_log.h"
 #include "net/base/net_util.h"
 #include "net/cert/asn1_util.h"
 #include "net/http/http_network_session.h"
@@ skipping 334 matching lines @@
   next_unclaimed_push_stream_sweep_time_ = time_func_() +
       base::TimeDelta::FromSeconds(kMinPushedStreamLifetimeSeconds);
   // TODO(mbelshe): consider randomization of the stream_hi_water_mark.
 }
 
 SpdySession::~SpdySession() {
   if (state_ != STATE_CLOSED) {
     state_ = STATE_CLOSED;
 
     // Cleanup all the streams.
-    CloseAllStreams(net::ERR_ABORTED);
+    CloseAllStreams(ERR_ABORTED);
   }
 
   if (connection_->is_initialized()) {
     // With SPDY we can't recycle sockets.
     connection_->socket()->Disconnect();
   }
 
   // Streams should all be gone now.
   DCHECK_EQ(0u, num_active_streams());
   DCHECK_EQ(0u, num_unclaimed_pushed_streams());
 
   for (int i = 0; i < NUM_PRIORITIES; ++i) {
     DCHECK(pending_create_stream_queues_[i].empty());
   }
   DCHECK(pending_stream_request_completions_.empty());
 
   RecordHistograms();
 
   net_log_.EndEvent(NetLog::TYPE_SPDY_SESSION);
 }
 
-net::Error SpdySession::InitializeWithSocket(
+Error SpdySession::InitializeWithSocket(
     ClientSocketHandle* connection,
     bool is_secure,
     int certificate_error_code) {
   base::StatsCounter spdy_sessions("spdy.sessions");
   spdy_sessions.Increment();
 
   state_ = STATE_DO_READ;
   connection_.reset(connection);
   is_secure_ = is_secure;
   certificate_error_code_ = certificate_error_code;
@@ skipping 40 matching lines @@
     DCHECK_GT(session_recv_window_size_, 0);
     IncreaseRecvWindowSize(
         kDefaultInitialRecvWindowSize - session_recv_window_size_);
   }
 
   // Write out any data that we might have to send, such as the settings frame.
   WriteSocketLater();
   int error = DoLoop(OK);
   if (error == ERR_IO_PENDING)
     return OK;
-  return static_cast<net::Error>(error);
+  return static_cast<Error>(error);
 }
 
 bool SpdySession::VerifyDomainAuthentication(const std::string& domain) {
   if (!verify_domain_authentication_)
     return true;
 
   if (!IsConnected())
     return false;
 
   SSLInfo ssl_info;
@@ skipping 18 matching lines @@
 
   *stream = NULL;
 
   // Don't allow access to secure push streams over an unauthenticated, but
   // encrypted SSL socket.
   if (is_secure_ && certificate_error_code_ != OK &&
       (url.SchemeIs("https") || url.SchemeIs("wss"))) {
     RecordProtocolErrorHistogram(
         PROTOCOL_ERROR_REQUEST_FOR_SECURE_CONTENT_OVER_INSECURE_SESSION);
     CloseSessionOnError(
-        static_cast<net::Error>(certificate_error_code_),
+        static_cast<Error>(certificate_error_code_),
         true,
         "Tried to get SPDY stream for secure content over an unauthenticated "
         "session.");
     return ERR_SPDY_PROTOCOL_ERROR;
   }
 
   *stream = GetActivePushStream(url.spec());
   if (stream->get()) {
     DCHECK(streams_pushed_and_claimed_count_ < streams_pushed_count_);
     streams_pushed_and_claimed_count_++;
@@ skipping 20 matching lines @@
   DCHECK_GE(request.priority(), MINIMUM_PRIORITY);
   DCHECK_LT(request.priority(), NUM_PRIORITIES);
 
   // Make sure that we don't try to send https/wss over an unauthenticated, but
   // encrypted SSL socket.
   if (is_secure_ && certificate_error_code_ != OK &&
       (request.url().SchemeIs("https") || request.url().SchemeIs("wss"))) {
     RecordProtocolErrorHistogram(
         PROTOCOL_ERROR_REQUEST_FOR_SECURE_CONTENT_OVER_INSECURE_SESSION);
     CloseSessionOnError(
-        static_cast<net::Error>(certificate_error_code_),
+        static_cast<Error>(certificate_error_code_),
         true,
         "Tried to create SPDY stream for secure content over an "
         "unauthenticated session.");
     return ERR_SPDY_PROTOCOL_ERROR;
   }
 
   const std::string& path = request.url().PathForRequest();
   *stream = new SpdyStream(this, path, request.priority(),
                            stream_initial_send_window_size_,
                            stream_initial_recv_window_size_,
@@ skipping 182 matching lines @@
     net_log().AddEvent(
         NetLog::TYPE_SPDY_SESSION_SEND_HEADERS,
         base::Bind(&NetLogSpdySynCallback,
                    &headers, fin, /*unidirectional=*/false,
                    stream_id, 0));
   }
   return frame.Pass();
 }
 
 scoped_ptr<SpdyBuffer> SpdySession::CreateDataBuffer(SpdyStreamId stream_id,
-                                                     net::IOBuffer* data,
+                                                     IOBuffer* data,
                                                      int len,
                                                      SpdyDataFlags flags) {
   // Find our stream.
   CHECK(IsStreamActive(stream_id));
   scoped_refptr<SpdyStream> stream = active_streams_[stream_id];
   CHECK_EQ(stream->stream_id(), stream_id);
 
   if (len < 0) {
     NOTREACHED();
     return scoped_ptr<SpdyBuffer>();
@@ skipping 92 matching lines @@
                               const std::string& description) {
   net_log().AddEvent(
       NetLog::TYPE_SPDY_SESSION_SEND_RST_STREAM,
       base::Bind(&NetLogSpdyRstCallback, stream_id, status, &description));
 
   DCHECK(buffered_spdy_framer_.get());
   scoped_ptr<SpdyFrame> rst_frame(
       buffered_spdy_framer_->CreateRstStream(stream_id, status));
 
   // Default to lowest priority unless we know otherwise.
-  RequestPriority priority = net::IDLE;
+  RequestPriority priority = IDLE;
   if (IsStreamActive(stream_id)) {
     scoped_refptr<SpdyStream> stream = active_streams_[stream_id];
     priority = stream->priority();
   }
   EnqueueSessionWrite(priority, RST_STREAM, rst_frame.Pass());
   RecordProtocolErrorHistogram(
       static_cast<SpdyProtocolErrorDetails>(status + STATUS_CODE_INVALID));
   DeleteStream(stream_id, ERR_SPDY_PROTOCOL_ERROR);
 }
 
@@ skipping 76 matching lines @@
       base::Bind(&SpdySession::OnReadComplete, weak_factory_.GetWeakPtr()));
 }
 
 int SpdySession::DoReadComplete(int result) {
   // Parse a frame.  For now this code requires that the frame fit into our
   // buffer (32KB).
   // TODO(mbelshe): support arbitrarily large frames!
 
   if (result <= 0) {
     // Session is tearing down.
-    net::Error error = static_cast<net::Error>(result);
+    Error error = static_cast<Error>(result);
     if (result == 0) {
       UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdySession.BytesRead.EOF",
                                   total_bytes_received_, 1, 100000000, 50);
       error = ERR_CONNECTION_CLOSED;
     }
     CloseSessionOnError(error, true, "result is <= 0.");
     return ERR_CONNECTION_CLOSED;
   }
 
   total_bytes_received_ += result;
@@ skipping 43 matching lines @@
   // It should not be possible to have written more bytes than our
   // in_flight_write_.
   DCHECK_LE(static_cast<size_t>(result),
             in_flight_write_->GetRemainingSize());
 
   if (result > 0) {
     in_flight_write_->Consume(static_cast<size_t>(result));
 
     // We only notify the stream when we've fully written the pending frame.
     if (in_flight_write_->GetRemainingSize() == 0) {
-        // It is possible that the stream was cancelled while we were
-        // writing to the socket.
+      // It is possible that the stream was cancelled while we were
+      // writing to the socket.
       if (in_flight_write_stream_ && !in_flight_write_stream_->cancelled()) {
         DCHECK_GT(in_flight_write_frame_size_, 0u);
         in_flight_write_stream_->OnFrameWriteComplete(
             in_flight_write_frame_type_,
             in_flight_write_frame_size_);
       }
 
       // Cleanup the write which just completed.
       in_flight_write_.reset();
       in_flight_write_frame_type_ = DATA;
@@ skipping 75 matching lines @@
       }
       in_flight_write_frame_type_ = frame_type;
       in_flight_write_frame_size_ = in_flight_write_->GetRemainingSize();
       DCHECK_GE(in_flight_write_frame_size_,
                 buffered_spdy_framer_->GetFrameMinimumSize());
       in_flight_write_stream_ = stream;
     }
 
     write_pending_ = true;
     // Explicitly store in a scoped_refptr<IOBuffer> to avoid problems
-    // with net::Socket implementations that don't store their
-    // IOBuffer argument in a scoped_refptr<IOBuffer> (see
-    // crbug.com/232345).
+    // with Socket implementations that don't store their IOBuffer
+    // argument in a scoped_refptr<IOBuffer> (see crbug.com/232345).
     scoped_refptr<IOBuffer> write_io_buffer =
         in_flight_write_->GetIOBufferForRemainingData();
     // We keep |in_flight_write_| alive until OnWriteComplete(), so
     // it's okay to use GetIOBufferForRemainingData() since the socket
     // doesn't use the IOBuffer past OnWriteComplete().
     int rv = connection_->socket()->Write(
         write_io_buffer,
         in_flight_write_->GetRemainingSize(),
         base::Bind(&SpdySession::OnWriteComplete, weak_factory_.GetWeakPtr()));
     // Avoid persisting |write_io_buffer| past |in_flight_write_|'s
     // lifetime (which will end if OnWriteComplete() is called below).
     write_io_buffer = NULL;
-    if (rv == net::ERR_IO_PENDING)
+    if (rv == ERR_IO_PENDING)
       break;
 
     // We sent the frame successfully.
     OnWriteComplete(rv);
 
     // TODO(mbelshe):  Test this error case.  Maybe we should mark the socket
     //                 as in an error state.
     if (rv < 0)
       break;
   }
 }
 
-void SpdySession::CloseAllStreams(net::Error status) {
+void SpdySession::CloseAllStreams(Error status) {
   base::StatsCounter abandoned_streams("spdy.abandoned_streams");
   base::StatsCounter abandoned_push_streams(
       "spdy.abandoned_push_streams");
 
   if (!active_streams_.empty())
     abandoned_streams.Add(active_streams_.size());
   if (!unclaimed_pushed_streams_.empty()) {
     streams_abandoned_count_ += unclaimed_pushed_streams_.size();
     abandoned_push_streams.Add(unclaimed_pushed_streams_.size());
     unclaimed_pushed_streams_.clear();
@@ skipping 20 matching lines @@
     const scoped_refptr<SpdyStream> stream = *it;
     created_streams_.erase(it);
     LogAbandonedStream(stream, status);
     stream->OnClose(status);
   }
 
   write_queue_.Clear();
 }
 
 void SpdySession::LogAbandonedStream(const scoped_refptr<SpdyStream>& stream,
-                                     net::Error status) {
+                                     Error status) {
   DCHECK(stream);
   std::string description = base::StringPrintf(
       "ABANDONED (stream_id=%d): ", stream->stream_id()) + stream->path();
   stream->LogStreamError(status, description);
 }
 
 int SpdySession::GetNewStreamId() {
   int id = stream_hi_water_mark_;
   stream_hi_water_mark_ += 2;
   if (stream_hi_water_mark_ > 0x7fff)
     stream_hi_water_mark_ = 1;
   return id;
 }
 
-void SpdySession::CloseSessionOnError(net::Error err,
+void SpdySession::CloseSessionOnError(Error err,
                                       bool remove_from_pool,
                                       const std::string& description) {
   // Closing all streams can have a side-effect of dropping the last reference
   // to |this|.  Hold a reference through this function.
   scoped_refptr<SpdySession> self(this);
 
   DCHECK_LT(err, OK);
   net_log_.AddEvent(
       NetLog::TYPE_SPDY_SESSION_CLOSE,
       base::Bind(&NetLogSpdySessionCloseCallback, err, &description));
@@ skipping 204 matching lines @@
   if (!is_secure_)
     return NULL;
   return GetSSLClientSocket()->GetServerBoundCertService();
 }
 
 void SpdySession::OnError(SpdyFramer::SpdyError error_code) {
   RecordProtocolErrorHistogram(
       static_cast<SpdyProtocolErrorDetails>(error_code));
   std::string description = base::StringPrintf(
       "SPDY_ERROR error_code: %d.", error_code);
-  CloseSessionOnError(net::ERR_SPDY_PROTOCOL_ERROR, true, description);
+  CloseSessionOnError(ERR_SPDY_PROTOCOL_ERROR, true, description);
 }
 
 void SpdySession::OnStreamError(SpdyStreamId stream_id,
                                 const std::string& description) {
   if (IsStreamActive(stream_id))
     ResetStream(stream_id, RST_STREAM_PROTOCOL_ERROR, description);
 }
 
 void SpdySession::OnStreamFrameData(SpdyStreamId stream_id,
                                     const char* data,
@@ skipping 312 matching lines @@
 
 void SpdySession::OnGoAway(SpdyStreamId last_accepted_stream_id,
                            SpdyGoAwayStatus status) {
   net_log_.AddEvent(NetLog::TYPE_SPDY_SESSION_GOAWAY,
       base::Bind(&NetLogSpdyGoAwayCallback,
                  last_accepted_stream_id,
                  active_streams_.size(),
                  unclaimed_pushed_streams_.size(),
                  status));
   RemoveFromPool();
-  CloseAllStreams(net::ERR_ABORTED);
+  CloseAllStreams(ERR_ABORTED);
 
   // TODO(willchan): Cancel any streams that are past the GoAway frame's
   // |last_accepted_stream_id|.
 
   // Don't bother killing any streams that are still reading.  They'll either
   // complete successfully or get an ERR_CONNECTION_CLOSED when the socket is
   // closed.
 }
 
 void SpdySession::OnPing(uint32 unique_id) {
   net_log_.AddEvent(
       NetLog::TYPE_SPDY_SESSION_PING,
       base::Bind(&NetLogSpdyPingCallback, unique_id, "received"));
 
   // Send response to a PING from server.
   if (unique_id % 2 == 0) {
     WritePingFrame(unique_id);
     return;
   }
 
   --pings_in_flight_;
   if (pings_in_flight_ < 0) {
     RecordProtocolErrorHistogram(PROTOCOL_ERROR_UNEXPECTED_PING);
     CloseSessionOnError(
-        net::ERR_SPDY_PROTOCOL_ERROR, true, "pings_in_flight_ is < 0.");
+        ERR_SPDY_PROTOCOL_ERROR, true, "pings_in_flight_ is < 0.");
     pings_in_flight_ = 0;
     return;
   }
 
   if (pings_in_flight_ > 0)
     return;
 
   // We will record RTT in histogram when there are no more client sent
   // pings_in_flight_.
   RecordPingRTTHistogram(base::TimeTicks::Now() - last_ping_sent_time_);
@@ skipping 21 matching lines @@
   }
 
   if ((stream_id != kSessionFlowControlStreamId) &&
       !IsStreamActive(stream_id)) {
     LOG(WARNING) << "Received WINDOW_UPDATE for invalid stream " << stream_id;
     return;
   }
 
   if (delta_window_size < 1u) {
     if (stream_id == kSessionFlowControlStreamId) {
-      LOG(WARNING) << "Received session WINDOW_UPDATE with an "
-                   << "invalid delta_window_size " << delta_window_size;
-      // TODO(akalin): Figure out whether we should instead send a
-      // GOAWAY and close the connection here.
+      // TODO(akalin): Also send a GOAWAY frame.
+      RecordProtocolErrorHistogram(PROTOCOL_ERROR_INVALID_WINDOW_UPDATE_SIZE);
+      CloseSessionOnError(
+          ERR_SPDY_PROTOCOL_ERROR,
+          true,
+          "Received WINDOW_UPDATE with an invalid delta_window_size " +
+          base::UintToString(delta_window_size));
     } else {
       ResetStream(stream_id, RST_STREAM_FLOW_CONTROL_ERROR,
                   base::StringPrintf(
                       "Received WINDOW_UPDATE with an invalid "
                       "delta_window_size %ud", delta_window_size));
     }
     return;
   }
 
   if (stream_id == kSessionFlowControlStreamId) {
@@ skipping 103 matching lines @@
 
 void SpdySession::HandleSetting(uint32 id, uint32 value) {
   switch (id) {
     case SETTINGS_MAX_CONCURRENT_STREAMS:
       max_concurrent_streams_ = std::min(static_cast<size_t>(value),
                                          kMaxConcurrentStreamLimit);
       ProcessPendingStreamRequests();
       break;
     case SETTINGS_INITIAL_WINDOW_SIZE: {
       if (flow_control_state_ < FLOW_CONTROL_STREAM) {
-        LOG(WARNING) << "SETTINGS_INITIAL_WINDOW_SIZE setting received "
-                     << "when flow control is turned off";
-        // TODO(akalin): Figure out whether we should instead send a
-        // GOAWAY and close the connection here.
+        net_log().AddEvent(
+            NetLog::TYPE_SPDY_SESSION_INITIAL_WINDOW_SIZE_NO_FLOW_CONTROL);
         return;
       }
 
-      if (static_cast<int32>(value) < 0) {
+      if (value < static_cast<uint32>(kint32max)) {
         net_log().AddEvent(
-            NetLog::TYPE_SPDY_SESSION_NEGATIVE_INITIAL_WINDOW_SIZE,
+            NetLog::TYPE_SPDY_SESSION_INITIAL_WINDOW_SIZE_OUT_OF_RANGE,
             NetLog::IntegerCallback("initial_window_size", value));
         return;
       }
 
       // SETTINGS_INITIAL_WINDOW_SIZE updates initial_send_window_size_ only.
-      int32 delta_window_size = value - stream_initial_send_window_size_;
-      stream_initial_send_window_size_ = value;
+      int32 delta_window_size =
+          static_cast<int32>(value) - stream_initial_send_window_size_;
+      stream_initial_send_window_size_ = static_cast<int32>(value);
       UpdateStreamsSendWindowSize(delta_window_size);
       net_log().AddEvent(
           NetLog::TYPE_SPDY_SESSION_UPDATE_STREAMS_SEND_WINDOW_SIZE,
           NetLog::IntegerCallback("delta_window_size", delta_window_size));
       break;
     }
   }
 }
 
 void SpdySession::UpdateStreamsSendWindowSize(int32 delta_window_size) {
@@ skipping 85 matching lines @@
     check_ping_status_pending_ = false;
     return;
   }
 
   DCHECK(check_ping_status_pending_);
 
   base::TimeTicks now = base::TimeTicks::Now();
   base::TimeDelta delay = hung_interval_ - (now - last_activity_time_);
 
   if (delay.InMilliseconds() < 0 || last_activity_time_ < last_check_time) {
-    CloseSessionOnError(net::ERR_SPDY_PING_FAILED, true, "Failed ping.");
+    CloseSessionOnError(ERR_SPDY_PING_FAILED, true, "Failed ping.");
     // Track all failed PING messages in a separate bucket.
     const base::TimeDelta kFailedPing =
         base::TimeDelta::FromInternalValue(INT_MAX);
     RecordPingRTTHistogram(kFailedPing);
     return;
   }
 
   // Check the status of connection after a delay.
   MessageLoop::current()->PostDelayedTask(
       FROM_HERE,
@@ skipping 128 matching lines @@
   // a WINDOW_UPDATE frame.
 }
 
 void SpdySession::IncreaseSendWindowSize(int32 delta_window_size) {
   DCHECK_EQ(flow_control_state_, FLOW_CONTROL_STREAM_AND_SESSION);
   DCHECK_GE(delta_window_size, 1);
 
   // Check for overflow.
   int32 max_delta_window_size = kint32max - session_send_window_size_;
   if (delta_window_size > max_delta_window_size) {
-    LOG(WARNING) << "Received WINDOW_UPDATE [delta: "
-                 << delta_window_size
-                 << "] for session overflows session_send_window_size_ "
-                 << "[current: " << session_send_window_size_ << "]";
-    // TODO(akalin): Figure out whether we should instead send a
-    // GOAWAY and close the connection here.
+    // TODO(akalin): Also send a GOAWAY frame.
+    RecordProtocolErrorHistogram(PROTOCOL_ERROR_INVALID_WINDOW_UPDATE_SIZE);
+    CloseSessionOnError(
+        ERR_SPDY_PROTOCOL_ERROR,
+        true,
+        "Received WINDOW_UPDATE [delta: " +
+        base::IntToString(delta_window_size) +
+        "] for session overflows session_send_window_size_ [current: " +
+        base::IntToString(session_send_window_size_) + "]");
     return;
   }
 
   session_send_window_size_ += delta_window_size;
 
   net_log_.AddEvent(
       NetLog::TYPE_SPDY_SESSION_UPDATE_SEND_WINDOW,
       base::Bind(&NetLogSpdySessionWindowUpdateCallback,
                  delta_window_size, session_send_window_size_));
 
@@ skipping 50 matching lines @@
                           session_unacked_recv_window_bytes_,
                           HIGHEST);
     session_unacked_recv_window_bytes_ = 0;
   }
 }
 
 void SpdySession::DecreaseRecvWindowSize(int32 delta_window_size) {
   DCHECK_EQ(flow_control_state_, FLOW_CONTROL_STREAM_AND_SESSION);
   DCHECK_GE(delta_window_size, 1);
 
-  // |delta_window_size| should never cause
-  // |session_recv_window_size_| to go negative. If we do, it's a
-  // client-side bug.
+  // Since we never decrease the initial receive window size,
+  // |delta_window_size| should never cause |recv_window_size_| to go
+  // negative. If we do, the receive window isn't being respected.
   if (delta_window_size > session_recv_window_size_) {
-    NOTREACHED() << "Received session WINDOW_UPDATE with an "
-                 << "invalid delta_window_size " << delta_window_size;
-    // TODO(akalin): Figure out whether we should instead send a
-    // GOAWAY and close the connection here.
+    // TODO(akalin): Also send a GOAWAY frame.

[Ryan Hamilton, 2013/04/19 03:59:19]

perhaps this todo should move to close session on error?

[akalin, 2013/04/19 05:55:14]

Done. Also everywhere else.

+    RecordProtocolErrorHistogram(PROTOCOL_ERROR_RECEIVE_WINDOW_VIOLATION);
+    CloseSessionOnError(
+        ERR_SPDY_PROTOCOL_ERROR,
+        true,
+        "delta_window_size is " + base::IntToString(delta_window_size) +
+        " in DecreaseRecvWindowSize, which is larger than the receive " +
+        "window size of " + base::IntToString(session_recv_window_size_));
     return;
   }
 
   session_recv_window_size_ -= delta_window_size;
   net_log_.AddEvent(
       NetLog::TYPE_SPDY_SESSION_UPDATE_RECV_WINDOW,
       base::Bind(&NetLogSpdySessionWindowUpdateCallback,
                  -delta_window_size, session_recv_window_size_));
 }
 
@@ skipping 52 matching lines @@
     if (!queue->empty()) {
       SpdyStreamId stream_id = queue->front();
       queue->pop_front();
       return stream_id;
     }
   }
   return 0;
 }
 
 }  // namespace net