Support SpdySession as a new NetLog source type. Start logging some more SPDY control frames.

BUG=43237

Review URL: http://codereview.chromium.org/2102003

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@47342 0039d316-1c4b-4281-b951-d872f2087c98

5 files changed, 93 insertions, 6 deletions

diff --git a/net/base/net_log.h b/net/base/net_log.h
index 9270d78..02f0a4b 100644
--- a/net/base/net_log.h
+++ b/net/base/net_log.h
@@ -59,6 +59,7 @@ class NetLog {
     SOURCE_INIT_PROXY_RESOLVER,
     SOURCE_CONNECT_JOB,
     SOURCE_SOCKET,
+    SOURCE_SPDY_SESSION,
   };
 
   // Identifies the entity that generated this log. The |id| field should
diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index 7a75f26..7ae2a69 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -366,6 +366,34 @@ EVENT_TYPE(SPDY_TRANSACTION_READ_HEADERS)
 EVENT_TYPE(SPDY_TRANSACTION_READ_BODY)
 
 // ------------------------------------------------------------------------
+// SpdySession
+// ------------------------------------------------------------------------
+
+// The start/end of a SpdySession.
+EVENT_TYPE(SPDY_SESSION)
+
+// On sending a SPDY SETTINGS frame.
+// The following parameters are attached:
+//   {
+//     "settings": <The list of setting id:value pairs>
+//   }
+EVENT_TYPE(SPDY_SESSION_SEND_SETTINGS)
+
+// Receipt of a SPDY SETTINGS frame.
+// The following parameters are attached:
+//   {
+//     "settings": <The list of setting id:value pairs>
+//   }
+EVENT_TYPE(SPDY_SESSION_RECV_SETTINGS)
+
+// Receipt of a SPDY GOAWAY frame.
+// The following parameters are attached:
+//   {
+//     "last_accepted_stream_id": <Last stream id accepted by the server, duh>
+//   }
+EVENT_TYPE(SPDY_SESSION_GOAWAY)
+
+// ------------------------------------------------------------------------
 // SpdyStream
 // ------------------------------------------------------------------------
 
@@ -402,6 +430,13 @@ EVENT_TYPE(SPDY_STREAM_READ_BODY)
 // Logs that a stream attached to a pushed stream.
 EVENT_TYPE(SPDY_STREAM_ADOPTED_PUSH_STREAM)
 
+// The receipt of a RST_STREAM
+// The following parameters are attached:
+//   {
+//     "status": <The reason for the RST_STREAM>
+//   }
+EVENT_TYPE(SPDY_STREAM_RST_STREAM)
+
 // ------------------------------------------------------------------------
 // HttpStreamParser
 // ------------------------------------------------------------------------
diff --git a/net/spdy/spdy_session.cc b/net/spdy/spdy_session.cc
index 4208d06..de3042d 100644
--- a/net/spdy/spdy_session.cc
+++ b/net/spdy/spdy_session.cc
@@ -213,6 +213,31 @@ class NetLogSpdySynParameter : public NetLog::EventParameters {
   DISALLOW_COPY_AND_ASSIGN(NetLogSpdySynParameter);
 };
 
+class NetLogSpdySettingsParameter : public NetLog::EventParameters {
+ public:
+  explicit NetLogSpdySettingsParameter(const spdy::SpdySettings& settings)
+      : settings_(settings) {}
+
+  Value* ToValue() const {
+    DictionaryValue* dict = new DictionaryValue();
+    ListValue* settings = new ListValue();
+    for (spdy::SpdySettings::const_iterator it = settings_.begin();
+         it != settings_.end(); ++it) {
+      settings->Append(new StringValue(
+          StringPrintf("[%u:%u]", it->first.id(), it->second)));
+    }
+    dict->Set(L"settings", settings);
+    return dict;
+  }
+
+ private:
+  ~NetLogSpdySettingsParameter() {}
+
+  const spdy::SpdySettings settings_;
+
+  DISALLOW_COPY_AND_ASSIGN(NetLogSpdySettingsParameter);
+};
+
 }  // namespace
 
 // static
@@ -220,7 +245,7 @@ bool SpdySession::use_ssl_ = true;
 
 SpdySession::SpdySession(const HostPortPair& host_port_pair,
                          HttpNetworkSession* session,
-                         const BoundNetLog& net_log)
+                         NetLog* net_log)
     : ALLOW_THIS_IN_INITIALIZER_LIST(
           connect_callback_(this, &SpdySession::OnTCPConnect)),
       ALLOW_THIS_IN_INITIALIZER_LIST(
@@ -245,7 +270,11 @@ SpdySession::SpdySession(const HostPortPair& host_port_pair,
       streams_pushed_and_claimed_count_(0),
       streams_abandoned_count_(0),
       in_session_pool_(true),
-      net_log_(net_log) {
+      net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SPDY_SESSION)) {
+  net_log_.BeginEvent(
+      NetLog::TYPE_SPDY_SESSION,
+      new NetLogStringParameter("host_port", host_port_pair_.ToString()));
+
   // TODO(mbelshe): consider randomization of the stream_hi_water_mark.
 
   spdy_framer_.set_visitor(this);
@@ -277,6 +306,8 @@ SpdySession::~SpdySession() {
   UMA_HISTOGRAM_CUSTOM_COUNTS("Net.SpdyStreamsAbandonedPerSession",
       streams_abandoned_count_,
       0, 300, 50);
+
+  net_log_.EndEvent(NetLog::TYPE_SPDY_SESSION, NULL);
 }
 
 void SpdySession::InitializeWithSSLSocket(ClientSocketHandle* connection) {
@@ -520,7 +551,6 @@ void SpdySession::OnTCPConnect(int result) {
         socket, "" /* request_->url.HostNoBrackets() */ , ssl_config_);
     connection_->set_socket(socket);
     is_secure_ = true;
-    // TODO(willchan): Plumb NetLog into SPDY code.
     int status = connection_->socket()->Connect(&ssl_connect_callback_);
     if (status != ERR_IO_PENDING)
       OnSSLConnect(status);
@@ -1150,6 +1180,12 @@ void SpdySession::OnFin(const spdy::SpdyRstStreamControlFrame& frame) {
   scoped_refptr<SpdyStream> stream = active_streams_[stream_id];
   CHECK_EQ(stream->stream_id(), stream_id);
   CHECK(!stream->cancelled());
+
+  const BoundNetLog& log = stream->net_log();
+  log.AddEvent(
+      NetLog::TYPE_SPDY_STREAM_RST_STREAM,
+      new NetLogIntegerParameter("status", frame.status()));
+
   if (frame.status() == 0) {
     stream->OnDataReceived(NULL, 0);
   } else {
@@ -1165,6 +1201,13 @@ void SpdySession::OnFin(const spdy::SpdyRstStreamControlFrame& frame) {
 void SpdySession::OnGoAway(const spdy::SpdyGoAwayControlFrame& frame) {
   LOG(INFO) << "Spdy GOAWAY for session[" << this << "] for " <<
       host_port_pair().ToString();
+
+  net_log_.AddEvent(
+      NetLog::TYPE_SPDY_SESSION_GOAWAY,
+      new NetLogIntegerParameter(
+          "last_accepted_stream_id",
+          frame.last_accepted_stream_id()));
+
   RemoveFromPool();
 
   // TODO(willchan): Cancel any streams that are past the GoAway frame's
@@ -1181,6 +1224,10 @@ void SpdySession::OnSettings(const spdy::SpdySettingsControlFrame& frame) {
     SpdySettingsStorage* settings_storage = session_->mutable_spdy_settings();
     settings_storage->Set(host_port_pair_, settings);
   }
+
+  net_log_.AddEvent(
+      NetLog::TYPE_SPDY_SESSION_RECV_SETTINGS,
+      new NetLogSpdySettingsParameter(settings));
 }
 
 void SpdySession::SendSettings() {
@@ -1189,6 +1236,10 @@ void SpdySession::SendSettings() {
   if (settings.empty())
     return;
 
+  net_log_.AddEvent(
+      NetLog::TYPE_SPDY_SESSION_SEND_SETTINGS,
+      new NetLogSpdySettingsParameter(settings));
+
   // Create the SETTINGS frame and send it.
   scoped_ptr<spdy::SpdySettingsControlFrame> settings_frame(
       spdy_framer_.CreateSettings(settings));
diff --git a/net/spdy/spdy_session.h b/net/spdy/spdy_session.h
index 8ef2da0..8ef8759 100644
--- a/net/spdy/spdy_session.h
+++ b/net/spdy/spdy_session.h
@@ -46,7 +46,7 @@ class SpdySession : public base::RefCounted<SpdySession>,
   // |session| is the HttpNetworkSession.  |net_log| is the NetLog that we log
   // network events to.
   SpdySession(const HostPortPair& host_port_pair, HttpNetworkSession* session,
-              const BoundNetLog& net_log);
+              NetLog* net_log);
 
   const HostPortPair& host_port_pair() const { return host_port_pair_; }
 
diff --git a/net/spdy/spdy_session_pool.cc b/net/spdy/spdy_session_pool.cc
index af397c7..cd505a8 100644
--- a/net/spdy/spdy_session_pool.cc
+++ b/net/spdy/spdy_session_pool.cc
@@ -35,7 +35,7 @@ scoped_refptr<SpdySession> SpdySessionPool::Get(
 
   DCHECK(list);
   if (!spdy_session)
-    spdy_session = new SpdySession(host_port_pair, session, net_log);
+    spdy_session = new SpdySession(host_port_pair, session, net_log.net_log());
 
   DCHECK(spdy_session);
   list->push_back(spdy_session);
@@ -53,7 +53,7 @@ scoped_refptr<SpdySession> SpdySessionPool::GetSpdySessionFromSSLSocket(
     list = AddSessionList(host_port_pair);
   DCHECK(list->empty());
   scoped_refptr<SpdySession> spdy_session(
-      new SpdySession(host_port_pair, session, net_log));
+      new SpdySession(host_port_pair, session, net_log.net_log()));
   spdy_session->InitializeWithSSLSocket(connection);
   list->push_back(spdy_session);
   return spdy_session;