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 105268)
+++ net/spdy/spdy_session.cc	(working copy)
@@ -4,6 +4,7 @@
 
 #include "net/spdy/spdy_session.h"
 
+#include "base/auto_reset.h"
 #include "base/basictypes.h"
 #include "base/logging.h"
 #include "base/memory/linked_ptr.h"
@@ -172,6 +173,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,
@@ -246,6 +264,9 @@
       sent_settings_(false),
       received_settings_(false),
       stalled_streams_(0),
+      pings_in_flight_(0),
+      unique_id_counter_(1),
+      follower_ping_pending_(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 +495,10 @@
   const scoped_refptr<SpdyStream>& stream = active_streams_[stream_id];
   CHECK_EQ(stream->stream_id(), stream_id);
 
+  int result = SendPing(stream_id);
+  if (result != ERR_IO_PENDING)
+    return result;
+
   scoped_ptr<spdy::SpdySynStreamControlFrame> syn_frame(
       spdy_framer_.CreateSynStream(
           stream_id, 0,
@@ -612,6 +637,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 +1256,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 +1347,13 @@
   // closed.
 }
 
+void SpdySession::OnPing(const spdy::SpdyPingControlFrame& frame) {
+  --pings_in_flight_;

[willchan no longer on Chromium, 2011/10/13 15:47:17]

If you aren't doing any PING validation of the unique_id, what happens if the
server is broken and sends us a PING immediately? Will this underflow?

[ramant (doing other things), 2011/10/13 21:41:14]

Decrements pings_in_flight_ only if client had sent (we send odd unique_ids).

Added DCHECK for pings_in_flight_ to be > 0 (made sure it doesn't go below a
negative number).

Would like to talk to you and Jim about the above. thanks.

+  net_log_.AddEvent(
+      NetLog::TYPE_SPDY_SESSION_PING,
+      make_scoped_refptr(new NetLogSpdyPingParameter(frame.unique_id())));
+}
+
 void SpdySession::OnSettings(const spdy::SpdySettingsControlFrame& frame) {
   spdy::SpdySettings settings;
   if (spdy_framer_.ParseSettings(&frame, &settings)) {
@@ -1455,6 +1492,105 @@
   }
 }
 
+int SpdySession::SendPing(spdy::SpdyStreamId stream_id) {
+  const base::TimeDelta kInterval = base::TimeDelta::FromMilliseconds(10000);
+
+  base::TimeTicks now = base::TimeTicks::Now();
+  // If there are no PINGs in flight and we haven't heard from server, then
+  // send a pre-PING.
+  if ((pings_in_flight_ == 0) && ((now - received_data_time_) > kInterval)) {
+    int result = SendPrePing(stream_id);
+    if (result != ERR_IO_PENDING)
+      return result;
+  }
+
+  // Send a post-PING after a delay to make sure request has been received by
+  // the server.
+  const int kRequestTimeMs = 5000;
+  if (!follower_ping_pending_) {

[willchan no longer on Chromium, 2011/10/13 15:47:17]

What's the difference between a follower_ping and a post-PING?

[ramant (doing other things), 2011/10/13 21:41:14]

Used the word post_ping everywhere (sorry for using follower_ping).

Done.

+    follower_ping_pending_ = true;
+    MessageLoop::current()->PostDelayedTask(
+        FROM_HERE,
+        method_factory_.NewRunnableMethod(
+            &SpdySession::SendPostPing, stream_id),
+        kRequestTimeMs);
+
+    // Post a task to check the status of the connection.
+    const int kCheckStatusTimeMs = 10000;
+    MessageLoop::current()->PostDelayedTask(
+        FROM_HERE,
+        method_factory_.NewRunnableMethod(
+            &SpdySession::CheckStatus, stream_id, now),
+        kCheckStatusTimeMs);
+  }
+  return ERR_IO_PENDING;
+}
+
+int SpdySession::SendPrePing(spdy::SpdyStreamId stream_id) {
+  // Delay the writing of the PING frame so that it goes along with other
+  // frames.

[willchan no longer on Chromium, 2011/10/13 15:47:17]

What does this comment mean? What is supposed to happen with this code?

[ramant (doing other things), 2011/10/13 21:41:14]

My intention is not to send PING frame as a separate packet (wanted it to bo
sent along with other data). Would like to talk to you if I got the above logic
right or not. thanks.

+  AutoReset<bool> reset(&delayed_write_pending_, true);
+  return WritePingFrame(stream_id);
+}
+
+int SpdySession::SendPostPing(spdy::SpdyStreamId stream_id) {
+  DCHECK(follower_ping_pending_);
+  follower_ping_pending_ = false;
+  return WritePingFrame(stream_id);
+}
+
+int SpdySession::WritePingFrame(spdy::SpdyStreamId stream_id) {
+  // Find our stream.
+  if (!IsStreamActive(stream_id))

[willchan no longer on Chromium, 2011/10/13 15:47:17]

Why is WritePingFrame() looking up the stream?

[ramant (doing other things), 2011/10/13 21:41:14]

Deleted the use of stream_id from all PING related code.

Done.

+    return ERR_INVALID_SPDY_STREAM;
+  const scoped_refptr<SpdyStream>& stream = active_streams_[stream_id];
+  CHECK_EQ(stream->stream_id(), stream_id);
+
+  scoped_ptr<spdy::SpdyPingControlFrame> ping_frame(
+      spdy_framer_.CreatePingFrame(unique_id_counter_));
+  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(unique_id_counter_)));
+  }
+
+  ++pings_in_flight_;
+  unique_id_counter_ += 2;
+  return ERR_IO_PENDING;
+}
+
+void SpdySession::CheckStatus(spdy::SpdyStreamId stream_id,
+                              base::TimeTicks last_check_time) {
+  // Find our stream.
+  if (!IsStreamActive(stream_id))
+    return;
+  const scoped_refptr<SpdyStream>& stream = active_streams_[stream_id];
+  CHECK_EQ(stream->stream_id(), stream_id);
+
+  // Check if we got a response back for all PINGs we had sent.
+  if (pings_in_flight_ == 0)
+    return;
+
+  // Check if we haven't received any data in |kHungInterval|.
+  const base::TimeDelta kHungInterval = base::TimeDelta::FromSeconds(10);
+  if (received_data_time_ < last_check_time) {
+    DCHECK(base::TimeTicks::Now() - received_data_time_ > kHungInterval);
+    DeleteStream(stream_id, ERR_SPDY_PING_FAILED);
+    return;
+  }
+
+  // Check the status of connection after a delay.
+  base::TimeTicks now = base::TimeTicks::Now();
+  base::TimeDelta delay = now - received_data_time_ + kHungInterval;

[willchan no longer on Chromium, 2011/10/13 15:47:17]

Is this math right? Shouldn't it be kHungInterval - (now - received_data_time_)?

[ramant (doing other things), 2011/10/13 21:41:14]

Done.

+  MessageLoop::current()->PostDelayedTask(
+      FROM_HERE,
+      method_factory_.NewRunnableMethod(
+          &SpdySession::CheckStatus, stream_id, now),
+      delay.InMilliseconds());
+}
+
 void SpdySession::RecordHistograms() {
   UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdyStreamsPerSession",
                               streams_initiated_count_,