Send PING to check the status of the SPDY connection.

net/spdy/spdy_session.cc

Index: net/spdy/spdy_session.cc
===================================================================
--- net/spdy/spdy_session.cc	(revision 105385)
+++ net/spdy/spdy_session.cc	(working copy)
@@ -172,6 +172,23 @@
   DISALLOW_COPY_AND_ASSIGN(NetLogSpdyRstParameter);
 };
 
+class NetLogSpdyPingParameter : public NetLog::EventParameters {
+ public:
+  explicit NetLogSpdyPingParameter(uint32 unique_id) : unique_id_(unique_id) {}
+
+  virtual Value* ToValue() const {
+    DictionaryValue* dict = new DictionaryValue();
+    dict->SetInteger("unique_id", unique_id_);
+    return dict;
+  }
+
+ private:
+  ~NetLogSpdyPingParameter() {}
+  const uint32 unique_id_;
+
+  DISALLOW_COPY_AND_ASSIGN(NetLogSpdyPingParameter);
+};
+
 class NetLogSpdyGoAwayParameter : public NetLog::EventParameters {
  public:
   NetLogSpdyGoAwayParameter(spdy::SpdyStreamId last_stream_id,
@@ -213,6 +230,18 @@
 // static
 size_t SpdySession::max_concurrent_stream_limit_ = 256;
 
+// static
+bool SpdySession::enable_ping_based_connection_checking_ = true;
+
+// static
+int SpdySession::connection_at_risk_of_loss_ms_ = 10000;
+
+// static
+int SpdySession::trailing_ping_delay_time_ms_ = 1000;
+
+// static
+int SpdySession::hung_interval_ms_ = 10000;
+
 SpdySession::SpdySession(const HostPortProxyPair& host_port_proxy_pair,
                          SpdySessionPool* spdy_session_pool,
                          SpdySettingsStorage* spdy_settings,
@@ -246,6 +275,12 @@
       sent_settings_(false),
       received_settings_(false),
       stalled_streams_(0),
+      pings_in_flight_(0),
+      next_ping_id_(1),
+      received_data_time_(base::TimeTicks::Now()),
+      trailing_ping_pending_(false),
+      check_ping_status_pending_(false),
+      last_sent_was_ping_(false),
       initial_send_window_size_(spdy::kSpdyStreamInitialWindowSize),
       initial_recv_window_size_(spdy::kSpdyStreamInitialWindowSize),
       net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SPDY_SESSION)),
@@ -474,6 +509,8 @@
   const scoped_refptr<SpdyStream>& stream = active_streams_[stream_id];
   CHECK_EQ(stream->stream_id(), stream_id);
 
+  SendPrefacePingIfNoneInFlight();
+
   scoped_ptr<spdy::SpdySynStreamControlFrame> syn_frame(
       spdy_framer_.CreateSynStream(
           stream_id, 0,
@@ -491,6 +528,7 @@
         make_scoped_refptr(
             new NetLogSpdySynParameter(headers, flags, stream_id, 0)));
   }
+  last_sent_was_ping_ = false;
 
   return ERR_IO_PENDING;
 }
@@ -505,6 +543,8 @@
   if (!stream)
     return ERR_INVALID_SPDY_STREAM;
 
+  SendPrefacePingIfNoneInFlight();
+
   if (len > kMaxSpdyFrameChunkSize) {
     len = kMaxSpdyFrameChunkSize;
     flags = static_cast<spdy::SpdyDataFlags>(flags & ~spdy::DATA_FLAG_FIN);
@@ -544,6 +584,7 @@
   scoped_ptr<spdy::SpdyDataFrame> frame(
       spdy_framer_.CreateDataFrame(stream_id, data->data(), len, flags));
   QueueFrame(frame.get(), stream->priority(), stream);
+  last_sent_was_ping_ = false;
   return ERR_IO_PENDING;
 }
 
@@ -571,7 +612,7 @@
     priority = stream->priority();
   }
   QueueFrame(rst_frame.get(), priority, NULL);
-
+  last_sent_was_ping_ = false;

[willchan no longer on Chromium, 2011/10/15 08:08:03]

I feel like it'd be safer if you set this in QueueFrame().

[jar (doing other things), 2011/10/15 09:00:52]

The problem(?) is that we send pings via QueueFrame() as well.  Hence we'd have
to have QueueFrame() filter on the type of frame, and only do the increment some
of the time.  Worse yet, QueueFrame() function is used to send both respond
pings as well as client initiated pings.  We only want to set this boolean to
false if we don't send a client initiated ping. 

Bottom line: If we put this logic into QueueFrame() then we'd have to teach
QueueFrame to not only parse out Pings, but also to parse out odd vs even
(server initiated vs client initiated) pings. Raman and I thought we'd then be
putting too much Ping specific awareness into that general function.

[willchan no longer on Chromium, 2011/10/15 20:17:40]

Yes, this is one of those typical tradeoffs. Do you impose more burden on new
callers who all have to remember to set this bool? Or do you do it at a single
chokepoint but potentially cross abstraction/layering boundaries.

My sense is that the internal details within the .cc file don't constitute an
important layering boundary, so it's better to make it easier for implementers
of new frame types, since the failure to set this bool is very easy for a
reviewer to miss. But your concern is noted. Probably a good middle ground is to
keep QueueFrame() as is, create a QueueFrameInternal() with a bool indicating
whether or not it's a ping frame, and make the PING code call
QueueFrameInternal() with ping set to true.

[jar (doing other things), 2011/10/15 23:25:11]

I'm fine with the factoring you suggested if it makes you feel more comfortable.
 The only two re/setting of this flag that are IMO critical are:
a) Set to true when we send a ping.
b) Set to false when we send a session frame (content or request header, or any
"user" data).

We don't (I think) need a "follower ping" after we send some meta data (such as
configuration info, or a reply to a ping etc.)  As a result, it is not
significant to update the flag in such cases.  There is no big loss (I think) if
we later find out the connection is black holed, and meta-data never reached the
server.  As it is, we're getting very near to hacking this protocol to
universally ack all frames... and this seems like a bad level to work toward
such.

As a result, I'm mostly (only?) concerned with setting the flag in those two
cases, and we probably should (in our leisure time) nail this policy and the
related abstractions (kindred to what you suggest).  For other transmission, we
don't need to set the status.

Again, I'm fine with the factoring you suggested.  Given the current code, it
will achieve the re/setting more clearly to a reader (and harder to mess up as a
programmer), with the same semantics.

As a result, it really should only be those two classes of frames that we key on
to modify this state... but it seemed too hard in our rushed time to get it
perfect... and we opted for more pings than "needed" in such cases.

On 2011/10/15 20:17:40, willchan wrote:

[willchan no longer on Chromium, 2011/10/15 23:52:28]

OK

On 2011/10/15 23:25:11, jar wrote:

   DeleteStream(stream_id, ERR_SPDY_PROTOCOL_ERROR);
 }
 
@@ -612,6 +653,8 @@
 
   bytes_received_ += bytes_read;
 
+  received_data_time_ = base::TimeTicks::Now();
+
   // The SpdyFramer will use callbacks onto |this| as it parses frames.
   // When errors occur, those callbacks can lead to teardown of all references
   // to |this|, so maintain a reference to self during this call for safe
@@ -1229,6 +1272,9 @@
     case spdy::GOAWAY:
       OnGoAway(*reinterpret_cast<const spdy::SpdyGoAwayControlFrame*>(frame));
       break;
+    case spdy::PING:
+      OnPing(*reinterpret_cast<const spdy::SpdyPingControlFrame*>(frame));
+      break;
     case spdy::SETTINGS:
       OnSettings(
           *reinterpret_cast<const spdy::SpdySettingsControlFrame*>(frame));
@@ -1317,6 +1363,32 @@
   // closed.
 }
 
+void SpdySession::OnPing(const spdy::SpdyPingControlFrame& frame) {
+  net_log_.AddEvent(
+      NetLog::TYPE_SPDY_SESSION_PING,
+      make_scoped_refptr(new NetLogSpdyPingParameter(frame.unique_id())));
+
+  // Send reponse to a PING from Server.

[willchan no longer on Chromium, 2011/10/15 08:08:03]

s/reponse/response/, s/Server/server/g

[ramant (doing other things), 2011/10/15 23:33:11]

Done.

+  if (frame.unique_id() % 2 == 0) {
+    WritePingFrame(frame.unique_id());
+    return;
+  }
+
+  --pings_in_flight_;
+  if (pings_in_flight_ < 0) {
+    CloseSessionOnError(net::ERR_SPDY_PROTOCOL_ERROR, true);
+    return;
+  }
+
+  if (pings_in_flight_ > 0)
+    return;
+
+  if (last_sent_was_ping_)
+    return;
+
+  PlanToSendTrailingPing();
+}
+
 void SpdySession::OnSettings(const spdy::SpdySettingsControlFrame& frame) {
   spdy::SpdySettings settings;
   if (spdy_framer_.ParseSettings(&frame, &settings)) {
@@ -1374,6 +1446,7 @@
   scoped_ptr<spdy::SpdyWindowUpdateControlFrame> window_update_frame(
       spdy_framer_.CreateWindowUpdate(stream_id, delta_window_size));
   QueueFrame(window_update_frame.get(), stream->priority(), stream);
+  last_sent_was_ping_ = false;
 }
 
 // Given a cwnd that we would have sent to the server, modify it based on the
@@ -1438,6 +1511,7 @@
       spdy_framer_.CreateSettings(settings));
   sent_settings_ = true;
   QueueFrame(settings_frame.get(), 0, NULL);
+  last_sent_was_ping_ = false;
 }
 
 void SpdySession::HandleSettings(const spdy::SpdySettings& settings) {
@@ -1455,6 +1529,101 @@
   }
 }
 
+void SpdySession::SendPrefacePingIfNoneInFlight() {
+  if (pings_in_flight_ || trailing_ping_pending_ ||
+      !enable_ping_based_connection_checking_)
+    return;
+
+  const base::TimeDelta kConnectionAtRiskOfLoss =
+      base::TimeDelta::FromMilliseconds(connection_at_risk_of_loss_ms_);
+
+  base::TimeTicks now = base::TimeTicks::Now();
+  // If we haven't heard from server, then send a preface-PING.
+  if ((now - received_data_time_) > kConnectionAtRiskOfLoss)
+    SendPrefacePing();
+
+  PlanToSendTrailingPing();
+}
+
+void SpdySession::SendPrefacePing() {
+  WritePingFrame(next_ping_id_);
+}
+
+void SpdySession::PlanToSendTrailingPing() {
+  if (trailing_ping_pending_)
+    return;
+
+  trailing_ping_pending_ = true;
+  MessageLoop::current()->PostDelayedTask(
+      FROM_HERE,
+      method_factory_.NewRunnableMethod(&SpdySession::SendTrailingPing),
+      trailing_ping_delay_time_ms_);
+}
+
+void SpdySession::SendTrailingPing() {
+  DCHECK(trailing_ping_pending_);
+  trailing_ping_pending_ = false;
+  WritePingFrame(next_ping_id_);
+}
+
+void SpdySession::WritePingFrame(uint32 unique_id) {
+  scoped_ptr<spdy::SpdyPingControlFrame> ping_frame(
+      spdy_framer_.CreatePingFrame(next_ping_id_));
+  QueueFrame(ping_frame.get(), SPDY_PRIORITY_HIGHEST, NULL);
+
+  if (net_log().IsLoggingAllEvents()) {
+    net_log().AddEvent(
+        NetLog::TYPE_SPDY_SESSION_PING,
+        make_scoped_refptr(new NetLogSpdyPingParameter(next_ping_id_)));
+  }
+  if (unique_id % 2 != 0) {
+    next_ping_id_ += 2;
+    ++pings_in_flight_;
+    last_sent_was_ping_ = true;
+    PlanToCheckPingStatus();
+  }
+}
+
+void SpdySession::PlanToCheckPingStatus() {
+  if (check_ping_status_pending_)
+    return;
+
+  check_ping_status_pending_ = true;
+  MessageLoop::current()->PostDelayedTask(
+      FROM_HERE,
+      method_factory_.NewRunnableMethod(
+          &SpdySession::CheckPingStatus, base::TimeTicks::Now()),
+      hung_interval_ms_);
+}
+
+void SpdySession::CheckPingStatus(base::TimeTicks last_check_time) {
+  // Check if we got a response back for all PINGs we had sent.
+  if (pings_in_flight_ == 0) {
+    check_ping_status_pending_ = false;
+    return;
+  }
+
+  DCHECK(check_ping_status_pending_);
+
+  const base::TimeDelta kHungInterval =
+      base::TimeDelta::FromMilliseconds(hung_interval_ms_);
+
+  base::TimeTicks now = base::TimeTicks::Now();
+  base::TimeDelta delay = kHungInterval - (now - received_data_time_);
+
+  if (delay.InMilliseconds() < 0 || received_data_time_ < last_check_time) {
+    DCHECK(now - received_data_time_ > kHungInterval);
+    CloseSessionOnError(net::ERR_SPDY_PING_FAILED, true);
+    return;
+  }
+
+  // Check the status of connection after a delay.
+  MessageLoop::current()->PostDelayedTask(
+      FROM_HERE,
+      method_factory_.NewRunnableMethod(&SpdySession::CheckPingStatus, now),
+      delay.InMilliseconds());
+}
+
 void SpdySession::RecordHistograms() {
   UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdyStreamsPerSession",
                               streams_initiated_count_,