QUIC - NetLog instrumentation for server push.

BUG=

Review URL: https://codereview.chromium.org/1821743002

Cr-Commit-Position: refs/heads/master@{#382462}

9 files changed, 133 insertions, 18 deletions

diff --git a/net/log/net_log_event_type_list.h b/net/log/net_log_event_type_list.h
index 5817b5b..d3dd30f 100644
--- a/net/log/net_log_event_type_list.h
+++ b/net/log/net_log_event_type_list.h
@@ -1783,6 +1783,15 @@ EVENT_TYPE(QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED)
 //   }
 EVENT_TYPE(QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT)
 
+// A QUIC connection received a PUSH_PROMISE frame.  The following
+// parameters are attached:
+//   {
+//     "headers": <The list of header:value pairs>,
+//     "id": <The stream id>,
+//     "promised_stream_id": <The stream id>,
+//   }
+EVENT_TYPE(QUIC_SESSION_PUSH_PROMISE_RECEIVED)
+
 // Session was closed, either remotely or by the peer.
 //   {
 //     "quic_error": <QuicErrorCode which caused the connection to be closed>,
@@ -1806,6 +1815,23 @@ EVENT_TYPE(QUIC_HTTP_STREAM_SEND_REQUEST_HEADERS)
 //   }
 EVENT_TYPE(QUIC_HTTP_STREAM_READ_RESPONSE_HEADERS)
 
+// A stream request's url matches a received push promise.  The
+// promised stream can be adopted for this request once vary header
+// validation is complete (as part of response header processing).
+//   {
+//     "stream_id":  <The stream id>,
+//     "url":        <The url of the pushed resource>,
+//   }
+EVENT_TYPE(QUIC_HTTP_STREAM_PUSH_PROMISE_RENDEZVOUS)
+
+// Vary validation has succeeded, a http stream is attached to
+// a pushed QUIC stream.
+//   {
+//     "stream_id":  <The stream id>,
+//     "url":        <The url of the pushed resource>,
+//   }
+EVENT_TYPE(QUIC_HTTP_STREAM_ADOPTED_PUSH_STREAM)
+
 // Identifies the NetLog::Source() for the QuicSesssion that handled the stream.
 // The event parameters are:
 //   {
diff --git a/net/quic/quic_chromium_client_session.cc b/net/quic/quic_chromium_client_session.cc
index 85d06ae..fbc1382 100644
--- a/net/quic/quic_chromium_client_session.cc
+++ b/net/quic/quic_chromium_client_session.cc
@@ -18,6 +18,7 @@
 #include "net/base/io_buffer.h"
 #include "net/base/net_errors.h"
 #include "net/base/network_activity_monitor.h"
+#include "net/http/http_log_util.h"
 #include "net/http/transport_security_state.h"
 #include "net/quic/crypto/proof_verifier_chromium.h"
 #include "net/quic/crypto/quic_server_info.h"
@@ -128,6 +129,31 @@ scoped_ptr<base::Value> NetLogQuicClientSessionCallback(
   return std::move(dict);
 }
 
+scoped_ptr<base::ListValue> SpdyHeaderBlockToListValue(
+    const SpdyHeaderBlock& headers,
+    NetLogCaptureMode capture_mode) {
+  scoped_ptr<base::ListValue> headers_list(new base::ListValue());
+  for (const auto& it : headers) {
+    headers_list->AppendString(
+        it.first.as_string() + ": " +
+        ElideHeaderValueForNetLog(capture_mode, it.first.as_string(),
+                                  it.second.as_string()));
+  }
+  return headers_list;
+}
+
+scoped_ptr<base::Value> NetLogQuicPushPromiseReceivedCallback(
+    const SpdyHeaderBlock* headers,
+    SpdyStreamId stream_id,
+    SpdyStreamId promised_stream_id,
+    NetLogCaptureMode capture_mode) {
+  scoped_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+  dict->Set("headers", SpdyHeaderBlockToListValue(*headers, capture_mode));
+  dict->SetInteger("id", stream_id);
+  dict->SetInteger("promised_stream_id", promised_stream_id);
+  return std::move(dict);
+}
+
 }  // namespace
 
 QuicChromiumClientSession::StreamRequest::StreamRequest() : stream_(nullptr) {}
@@ -1124,4 +1150,13 @@ bool QuicChromiumClientSession::HasNonMigratableStreams() const {
   return false;
 }
 
+void QuicChromiumClientSession::HandlePromised(QuicStreamId id,
+                                               QuicStreamId promised_id,
+                                               const SpdyHeaderBlock& headers) {
+  QuicClientSessionBase::HandlePromised(id, promised_id, headers);
+  net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PUSH_PROMISE_RECEIVED,
+                    base::Bind(&NetLogQuicPushPromiseReceivedCallback, &headers,
+                               id, promised_id));
+}
+
 }  // namespace net
diff --git a/net/quic/quic_chromium_client_session.h b/net/quic/quic_chromium_client_session.h
index 5cc31d3..b7ac5bb 100644
--- a/net/quic/quic_chromium_client_session.h
+++ b/net/quic/quic_chromium_client_session.h
@@ -262,6 +262,10 @@ class NET_EXPORT_PRIVATE QuicChromiumClientSession
   // Returns true if session has one ore more streams marked as non-migratable.
   bool HasNonMigratableStreams() const;
 
+  void HandlePromised(QuicStreamId associated_id,
+                      QuicStreamId promised_id,
+                      const SpdyHeaderBlock& headers) override;
+
  protected:
   // QuicSession methods:
   QuicChromiumClientStream* CreateIncomingDynamicStream(
diff --git a/net/quic/quic_chromium_client_stream.cc b/net/quic/quic_chromium_client_stream.cc
index 529f0a7..ef71bf1 100644
--- a/net/quic/quic_chromium_client_stream.cc
+++ b/net/quic/quic_chromium_client_stream.cc
@@ -73,7 +73,7 @@ void QuicChromiumClientStream::OnPromiseHeadersComplete(
   }
   MarkHeadersConsumed(headers_len);
 
-  session_->HandlePromised(promised_id, headers);
+  session_->HandlePromised(id(), promised_id, headers);
 }
 
 void QuicChromiumClientStream::OnDataAvailable() {
diff --git a/net/quic/quic_client_session_base.cc b/net/quic/quic_client_session_base.cc
index 7e45d00..26f42eb 100644
--- a/net/quic/quic_client_session_base.cc
+++ b/net/quic/quic_client_session_base.cc
@@ -77,7 +77,8 @@ void QuicClientSessionBase::OnPromiseHeadersComplete(
   stream->OnPromiseHeadersComplete(promised_stream_id, frame_len);
 }
 
-void QuicClientSessionBase::HandlePromised(QuicStreamId id,
+void QuicClientSessionBase::HandlePromised(QuicStreamId /* associated_id */,
+                                           QuicStreamId id,
                                            const SpdyHeaderBlock& headers) {
   // Due to pathalogical packet re-ordering, it is possible that
   // frames for the promised stream have already arrived, and the
diff --git a/net/quic/quic_client_session_base.h b/net/quic/quic_client_session_base.h
index 3b3a180..7577ecf 100644
--- a/net/quic/quic_client_session_base.h
+++ b/net/quic/quic_client_session_base.h
@@ -63,8 +63,11 @@ class NET_EXPORT_PRIVATE QuicClientSessionBase
 
   // Called by |QuicSpdyClientStream| on receipt of PUSH_PROMISE, does
   // some session level validation and creates the
-  // |QuicClientPromisedInfo| inserting into maps by id and url.
-  void HandlePromised(QuicStreamId id, const SpdyHeaderBlock& headers);
+  // |QuicClientPromisedInfo| inserting into maps by (promised) id and
+  // url.
+  virtual void HandlePromised(QuicStreamId associated_id,
+                              QuicStreamId promised_id,
+                              const SpdyHeaderBlock& headers);
 
   // For cross-origin server push, this should verify the server is
   // authoritative per [RFC2818], Section 3.  Roughly, subjectAltName
diff --git a/net/quic/quic_http_stream.cc b/net/quic/quic_http_stream.cc
index 55f3296..3c77fdc 100644
--- a/net/quic/quic_http_stream.cc
+++ b/net/quic/quic_http_stream.cc
@@ -27,6 +27,20 @@
 
 namespace net {
 
+namespace {
+
+scoped_ptr<base::Value> NetLogQuicPushStreamCallback(
+    QuicStreamId stream_id,
+    const GURL* url,
+    NetLogCaptureMode capture_mode) {
+  scoped_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+  dict->SetInteger("stream_id", stream_id);
+  dict->SetString("url", url->spec());
+  return std::move(dict);
+}
+
+}  // namespace
+
 QuicHttpStream::QuicHttpStream(
     const base::WeakPtr<QuicChromiumClientSession>& session)
     : next_state_(STATE_NONE),
@@ -100,6 +114,14 @@ void QuicHttpStream::OnRendezvousResult(QuicSpdyStream* stream) {
   if (!callback_.is_null()) {
     if (stream) {
       next_state_ = STATE_OPEN;
+      stream_net_log_.AddEvent(
+          NetLog::TYPE_QUIC_HTTP_STREAM_ADOPTED_PUSH_STREAM,
+          base::Bind(&NetLogQuicPushStreamCallback, stream_->id(),
+                     &request_info_->url));
+      session_->net_log().AddEvent(
+          NetLog::TYPE_QUIC_HTTP_STREAM_ADOPTED_PUSH_STREAM,
+          base::Bind(&NetLogQuicPushStreamCallback, stream_->id(),
+                     &request_info_->url));
       DoCallback(OK);
       return;
     }
@@ -131,11 +153,19 @@ int QuicHttpStream::InitializeStream(const HttpRequestInfo* request_info,
   DCHECK(success);
   DCHECK(ssl_info_.cert.get());
 
-  if (session_->push_promise_index()->GetPromised(request_info->url.spec())) {
-    // A PUSH_PROMISE frame for this URL has arrived, next steps of
-    // the rendezvous will happen in |SendRequest()| when the browser
-    // request headers (required for push validation) are available.
+  string url(request_info->url.spec());
+  QuicClientPromisedInfo* promised =
+      session_->push_promise_index()->GetPromised(url);
+  if (promised) {
     found_promise_ = true;
+    stream_net_log_.AddEvent(
+        NetLog::TYPE_QUIC_HTTP_STREAM_PUSH_PROMISE_RENDEZVOUS,
+        base::Bind(&NetLogQuicPushStreamCallback, promised->id(),
+                   &request_info_->url));
+    session_->net_log().AddEvent(
+        NetLog::TYPE_QUIC_HTTP_STREAM_PUSH_PROMISE_RENDEZVOUS,
+        base::Bind(&NetLogQuicPushStreamCallback, promised->id(),
+                   &request_info_->url));
     return OK;
   }
 
@@ -221,10 +251,19 @@ int QuicHttpStream::HandlePromise() {
     case QUIC_SUCCESS:
       next_state_ = STATE_OPEN;
       if (!CancelPromiseIfHasBody()) {
+        stream_net_log_.AddEvent(
+            NetLog::TYPE_QUIC_HTTP_STREAM_ADOPTED_PUSH_STREAM,
+            base::Bind(&NetLogQuicPushStreamCallback, stream_->id(),
+                       &request_info_->url));
+        session_->net_log().AddEvent(
+            NetLog::TYPE_QUIC_HTTP_STREAM_ADOPTED_PUSH_STREAM,
+            base::Bind(&NetLogQuicPushStreamCallback, stream_->id(),
+                       &request_info_->url));
         // Avoid the call to |DoLoop()| below, which would reset
         // next_state_ to STATE_NONE.
         return OK;
       }
+
       break;
     case QUIC_PENDING:
       if (!CancelPromiseIfHasBody()) {
diff --git a/net/tools/quic/quic_client_session_test.cc b/net/tools/quic/quic_client_session_test.cc
index f592da0..f2aa9c0 100644
--- a/net/tools/quic/quic_client_session_test.cc
+++ b/net/tools/quic/quic_client_session_test.cc
@@ -354,7 +354,8 @@ TEST_P(QuicClientSessionTest, PushPromiseHandlePromise) {
 
   session_->CreateOutgoingDynamicStream(kDefaultPriority);
 
-  session_->HandlePromised(promised_stream_id_, push_promise_);
+  session_->HandlePromised(associated_stream_id_, promised_stream_id_,
+                           push_promise_);
 
   EXPECT_NE(session_->GetPromisedById(promised_stream_id_), nullptr);
   EXPECT_NE(session_->GetPromisedByUrl(promise_url_), nullptr);
@@ -372,7 +373,8 @@ TEST_P(QuicClientSessionTest, PushPromiseAlreadyClosed) {
 
   session_->ResetPromised(promised_stream_id_, QUIC_REFUSED_STREAM);
   SpdyHeaderBlock promise_headers;
-  session_->HandlePromised(promised_stream_id_, promise_headers);
+  session_->HandlePromised(associated_stream_id_, promised_stream_id_,
+                           promise_headers);
 
   // Verify that the promise was not created.
   EXPECT_EQ(session_->GetPromisedById(promised_stream_id_), nullptr);
@@ -385,7 +387,8 @@ TEST_P(QuicClientSessionTest, PushPromiseDuplicateUrl) {
 
   session_->CreateOutgoingDynamicStream(kDefaultPriority);
 
-  session_->HandlePromised(promised_stream_id_, push_promise_);
+  session_->HandlePromised(associated_stream_id_, promised_stream_id_,
+                           push_promise_);
 
   EXPECT_NE(session_->GetPromisedById(promised_stream_id_), nullptr);
   EXPECT_NE(session_->GetPromisedByUrl(promise_url_), nullptr);
@@ -394,7 +397,8 @@ TEST_P(QuicClientSessionTest, PushPromiseDuplicateUrl) {
   EXPECT_CALL(*connection_, SendRstStream(promised_stream_id_,
                                           QUIC_DUPLICATE_PROMISE_URL, 0));
 
-  session_->HandlePromised(promised_stream_id_, push_promise_);
+  session_->HandlePromised(associated_stream_id_, promised_stream_id_,
+                           push_promise_);
 
   // Verify that the promise was not created.
   EXPECT_EQ(session_->GetPromisedById(promised_stream_id_), nullptr);
@@ -406,7 +410,7 @@ TEST_P(QuicClientSessionTest, ReceivingPromiseEnhanceYourCalm) {
 
     QuicStreamId id = promised_stream_id_ + i * 2;
 
-    session_->HandlePromised(id, push_promise_);
+    session_->HandlePromised(associated_stream_id_, id, push_promise_);
 
     // Verify that the promise is in the unclaimed streams map.
     string promise_url(SpdyUtils::GetUrlFromHeaderBlock(push_promise_));
@@ -420,7 +424,7 @@ TEST_P(QuicClientSessionTest, ReceivingPromiseEnhanceYourCalm) {
 
   QuicStreamId id = promised_stream_id_ + i * 2;
   EXPECT_CALL(*connection_, SendRstStream(id, QUIC_REFUSED_STREAM, 0));
-  session_->HandlePromised(id, push_promise_);
+  session_->HandlePromised(associated_stream_id_, id, push_promise_);
 
   // Verify that the promise was not created.
   string promise_url(SpdyUtils::GetUrlFromHeaderBlock(push_promise_));
@@ -449,7 +453,8 @@ TEST_P(QuicClientSessionTest, OnInitialHeadersCompleteIsPush) {
   // Initialize crypto before the client session will create a stream.
   CompleteCryptoHandshake();
   session_->GetStream(promised_stream_id_);
-  session_->HandlePromised(promised_stream_id_, push_promise_);
+  session_->HandlePromised(associated_stream_id_, promised_stream_id_,
+                           push_promise_);
   EXPECT_NE(session_->GetPromisedById(promised_stream_id_), nullptr);
   EXPECT_NE(session_->GetPromisedStream(promised_stream_id_), nullptr);
   EXPECT_NE(session_->GetPromisedByUrl(promise_url_), nullptr);
@@ -468,7 +473,8 @@ TEST_P(QuicClientSessionTest, DeletePromised) {
   // Initialize crypto before the client session will create a stream.
   CompleteCryptoHandshake();
   session_->GetStream(promised_stream_id_);
-  session_->HandlePromised(promised_stream_id_, push_promise_);
+  session_->HandlePromised(associated_stream_id_, promised_stream_id_,
+                           push_promise_);
   QuicClientPromisedInfo* promised =
       session_->GetPromisedById(promised_stream_id_);
   EXPECT_NE(promised, nullptr);
@@ -484,7 +490,8 @@ TEST_P(QuicClientSessionTest, ResetPromised) {
   // Initialize crypto before the client session will create a stream.
   CompleteCryptoHandshake();
   session_->GetStream(promised_stream_id_);
-  session_->HandlePromised(promised_stream_id_, push_promise_);
+  session_->HandlePromised(associated_stream_id_, promised_stream_id_,
+                           push_promise_);
   EXPECT_CALL(*connection_, SendRstStream(promised_stream_id_,
                                           QUIC_STREAM_PEER_GOING_AWAY, 0));
   session_->SendRstStream(promised_stream_id_, QUIC_STREAM_PEER_GOING_AWAY, 0);
diff --git a/net/tools/quic/quic_spdy_client_stream.cc b/net/tools/quic/quic_spdy_client_stream.cc
index 615fab4..af9ad0b 100644
--- a/net/tools/quic/quic_spdy_client_stream.cc
+++ b/net/tools/quic/quic_spdy_client_stream.cc
@@ -89,7 +89,7 @@ void QuicSpdyClientStream::OnPromiseHeadersComplete(QuicStreamId promised_id,
   }
   MarkHeadersConsumed(decompressed_headers().length());
 
-  session_->HandlePromised(promised_id, promise_headers);
+  session_->HandlePromised(id(), promised_id, promise_headers);
 }
 
 void QuicSpdyClientStream::OnDataAvailable() {