Enhance net internals/net log output for QUIC.

Fix use after free bug in initial implementation.

Initially landed: 182331
Reverted: 182335


Review URL: https://chromiumcodereview.appspot.com/12253020

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

chrome/browser/resources/net_internals/quic_view.js

@@ -95,6 +95,7 @@ var QuicView = (function() {
     tablePrinter.addHeaderCell('Peer address');
     tablePrinter.addHeaderCell('GUID');
     tablePrinter.addHeaderCell('Active streams');
+    tablePrinter.addHeaderCell('Total streams');
 
     for (var i = 0; i < quicSessions.length; i++) {
       var session = quicSessions[i];
@@ -108,6 +109,7 @@ var QuicView = (function() {
       tablePrinter.addCell(session.peer_address);
       tablePrinter.addCell(session.guid);
       tablePrinter.addCell(session.open_streams);
+      tablePrinter.addCell(session.total_streams);
     }
     return tablePrinter;
   }

chrome/test/data/webui/net_internals/log_view_painter.js

@@ -311,7 +311,7 @@ function painterTestURLRequest() {
       'params': {
         'source_dependency': {
           'id': 149,
-          'type': 11
+          'type': EventSourceType.HTTP_STREAM_JOB
         }
       },
       'phase': EventPhase.PHASE_NONE,
@@ -1077,7 +1077,7 @@ function painterTestHexEncodedBytes() {
       'params': {
         'source_dependency': {
           'id': 634,
-          'type': 4
+          'type': EventSourceType.CONNECT_JOB
         }
       },
       'phase': EventPhase.PHASE_BEGIN,
@@ -1139,7 +1139,7 @@ function painterTestHexEncodedBytes() {
       'params': {
         'source_dependency': {
           'id': 628,
-          'type': 11
+          'type': EventSourceType.HTTP_STREAM_JOB
         }
       },
       'phase': EventPhase.PHASE_BEGIN,

net/base/net_log_event_type_list.h

@@ -1208,6 +1208,38 @@ EVENT_TYPE(SPDY_PROXY_CLIENT_SESSION)
 //     "source_dependency":  <Source identifier for the underlying session>,
 //   }
 
+// ------------------------------------------------------------------------
+// QuicSession
+// ------------------------------------------------------------------------
+
+// The start/end of a QuicSession.
+//   {
+//     "host": <The host-port string>,
+//   }
+EVENT_TYPE(QUIC_SESSION)
+
+// Session is closing because of an error.
+//   {
+//     "net_error": <Net error code for the closure>
+//   }
+EVENT_TYPE(QUIC_SESSION_CLOSE_ON_ERROR)
+
+// ------------------------------------------------------------------------
+// QuicHttpStream
+// ------------------------------------------------------------------------
+
+// The stream is sending the request headers.
+//   {
+//     "headers": <The list of header:value pairs>
+//   }
+EVENT_TYPE(QUIC_HTTP_STREAM_SEND_REQUEST_HEADERS)
+
+// The stream has read the response headers.
+//   {
+//     "headers": <The list of header:value pairs>
+//   }
+EVENT_TYPE(QUIC_HTTP_STREAM_READ_RESPONSE_HEADERS)
+
 // ------------------------------------------------------------------------
 // HttpStreamParser
 // ------------------------------------------------------------------------

net/base/net_log_source_type_list.h

@@ -14,6 +14,7 @@ SOURCE_TYPE(PROXY_SCRIPT_DECIDER)
 SOURCE_TYPE(CONNECT_JOB)
 SOURCE_TYPE(SOCKET)
 SOURCE_TYPE(SPDY_SESSION)
+SOURCE_TYPE(QUIC_SESSION)
 SOURCE_TYPE(HOST_RESOLVER_IMPL_REQUEST)
 SOURCE_TYPE(HOST_RESOLVER_IMPL_JOB)
 SOURCE_TYPE(DISK_CACHE_ENTRY)

net/quic/quic_client_session.cc

@@ -19,17 +19,25 @@ namespace net {
 QuicClientSession::QuicClientSession(QuicConnection* connection,
                                      QuicConnectionHelper* helper,
                                      QuicStreamFactory* stream_factory,
-                                     const string& server_hostname)
+                                     const string& server_hostname,
+                                     NetLog* net_log)
     : QuicSession(connection, false),
       ALLOW_THIS_IN_INITIALIZER_LIST(weak_factory_(this)),
       ALLOW_THIS_IN_INITIALIZER_LIST(crypto_stream_(this, server_hostname)),
       helper_(helper),
       stream_factory_(stream_factory),
       read_buffer_(new IOBufferWithSize(kMaxPacketSize)),
-      read_pending_(false) {
+      read_pending_(false),
+      num_total_streams_(0),
+      net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_QUIC_SESSION)) {
+  // TODO(rch): pass in full host port proxy pair
+  net_log_.BeginEvent(
+      NetLog::TYPE_QUIC_SESSION,
+      NetLog::StringCallback("host", &server_hostname));
 }
 
 QuicClientSession::~QuicClientSession() {
+  net_log_.EndEvent(NetLog::TYPE_QUIC_SESSION);
 }
 
 QuicReliableClientStream* QuicClientSession::CreateOutgoingReliableStream() {
@@ -43,8 +51,9 @@ QuicReliableClientStream* QuicClientSession::CreateOutgoingReliableStream() {
     return NULL;
   }
   QuicReliableClientStream* stream =
-       new QuicReliableClientStream(GetNextStreamId(), this);
+      new QuicReliableClientStream(GetNextStreamId(), this, net_log_);
   ActivateStream(stream);
+  ++num_total_streams_;
   return stream;
 }
 
@@ -115,6 +124,10 @@ void QuicClientSession::CloseSessionOnError(int error) {
     static_cast<QuicReliableClientStream*>(stream)->OnError(error);
     CloseStream(id);
   }
+  net_log_.BeginEvent(
+      NetLog::TYPE_QUIC_SESSION,
+      NetLog::IntegerCallback("net_error", error));
+  // Will delete |this|.
   stream_factory_->OnSessionClose(this);
 }
 
@@ -122,6 +135,7 @@ Value* QuicClientSession::GetInfoAsValue(const HostPortPair& pair) const {
   DictionaryValue* dict = new DictionaryValue();
   dict->SetString("host_port_pair", pair.ToString());
   dict->SetInteger("open_streams", GetNumOpenStreams());
+  dict->SetInteger("total_streams", num_total_streams_);
   dict->SetString("peer_address", peer_address().ToString());
   dict->SetString("guid", base::Uint64ToString(guid()));
   return dict;

net/quic/quic_client_session.h

@@ -31,7 +31,8 @@ class NET_EXPORT_PRIVATE QuicClientSession : public QuicSession {
   QuicClientSession(QuicConnection* connection,
                     QuicConnectionHelper* helper,
                     QuicStreamFactory* stream_factory,
-                    const std::string& server_hostname);
+                    const std::string& server_hostname,
+                    NetLog* net_log);
 
   virtual ~QuicClientSession();
 
@@ -53,6 +54,8 @@ class NET_EXPORT_PRIVATE QuicClientSession : public QuicSession {
 
   base::Value* GetInfoAsValue(const HostPortPair& pair) const;
 
+  const BoundNetLog& net_log() const { return net_log_; }
+
  protected:
   // QuicSession methods:
   virtual ReliableQuicStream* CreateIncomingReliableStream(
@@ -69,6 +72,8 @@ class NET_EXPORT_PRIVATE QuicClientSession : public QuicSession {
   scoped_refptr<IOBufferWithSize> read_buffer_;
   bool read_pending_;
   CompletionCallback callback_;
+  size_t num_total_streams_;
+  BoundNetLog net_log_;
 
   DISALLOW_COPY_AND_ASSIGN(QuicClientSession);
 };

net/quic/quic_client_session_test.cc

@@ -7,6 +7,7 @@
 #include <vector>
 
 #include "base/stl_util.h"
+#include "net/base/capturing_net_log.h"
 #include "net/base/test_completion_callback.h"
 #include "net/quic/crypto/crypto_protocol.h"
 #include "net/quic/test_tools/quic_test_utils.h"
@@ -24,7 +25,7 @@ class QuicClientSessionTest : public ::testing::Test {
   QuicClientSessionTest()
       : guid_(1),
         connection_(new PacketSavingConnection(guid_, IPEndPoint())),
-        session_(connection_, NULL, NULL, kServerHostname) {
+        session_(connection_, NULL, NULL, kServerHostname, NULL) {
   }
 
   QuicGuid guid_;

net/quic/quic_http_stream.cc

@@ -48,6 +48,7 @@ int QuicHttpStream::InitializeStream(const HttpRequestInfo* request_info,
                                      const CompletionCallback& callback) {
   CHECK(stream_);
 
+  stream_net_log_ = stream_net_log;
   request_info_ = request_info;
 
   return OK;
@@ -72,12 +73,32 @@ int QuicHttpStream::SendRequest(const HttpRequestHeaders& request_headers,
     SpdyFramer::WriteHeaderBlock(&builder, 3, &headers);
     scoped_ptr<SpdyFrame> frame(builder.take());
     request_ = std::string(frame->data(), len);
+    // Log the actual request with the URL Request's net log.
+    stream_net_log_.AddEvent(
+        NetLog::TYPE_HTTP_TRANSACTION_SPDY_SEND_REQUEST_HEADERS,
+        base::Bind(&SpdyHeaderBlockNetLogCallback, &headers));
+    // Also log to the QuicSession's net log.
+    stream_->net_log().AddEvent(
+        NetLog::TYPE_QUIC_HTTP_STREAM_SEND_REQUEST_HEADERS,
+        base::Bind(&SpdyHeaderBlockNetLogCallback, &headers));
   } else {
     std::string path = HttpUtil::PathForRequest(request_info_->url);
     std::string first_line = base::StringPrintf("%s %s HTTP/1.1\r\n",
                                                 request_info_->method.c_str(),
                                                 path.c_str());
     request_ = first_line + request_headers.ToString();
+    // Log the actual request with the URL Request's net log.
+    stream_net_log_.AddEvent(
+        NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST_HEADERS,
+        base::Bind(&HttpRequestHeaders::NetLogCallback,
+                   base::Unretained(&request_headers),
+                   &first_line));
+    // Also log to the QuicSession's net log.
+    stream_->net_log().AddEvent(
+        NetLog::TYPE_QUIC_HTTP_STREAM_SEND_REQUEST_HEADERS,
+        base::Bind(&HttpRequestHeaders::NetLogCallback,
+                   base::Unretained(&request_headers),
+                   &first_line));
   }
 
   // Store the request body.
@@ -458,6 +479,12 @@ int QuicHttpStream::ParseResponseHeaders() {
       BufferResponseBody(read_buf_->data(), delta);
     }
 
+    // The URLRequest logs these headers, so only log to the QuicSession's
+    // net log.
+    stream_->net_log().AddEvent(
+        NetLog::TYPE_QUIC_HTTP_STREAM_READ_RESPONSE_HEADERS,
+        base::Bind(&SpdyHeaderBlockNetLogCallback, &headers));
+
     SpdyHeadersToHttpResponse(headers, 3, response_info_);
     // Put the peer's IP address and port into the response.
     IPEndPoint address = stream_->GetPeerAddress();
@@ -487,6 +514,13 @@ int QuicHttpStream::ParseResponseHeaders() {
   response_info_->vary_data.Init(*request_info_, *response_info_->headers);
   response_headers_received_ = true;
 
+  // The URLRequest logs these headers, so only log to the QuicSession's
+  // net log.
+  stream_->net_log().AddEvent(
+      NetLog::TYPE_QUIC_HTTP_STREAM_READ_RESPONSE_HEADERS,
+      base::Bind(&HttpResponseHeaders::NetLogCallback,
+                 response_info_->headers));
+
   // Save the remaining received data.
   int delta = read_buf_->offset() - end_offset;
   if (delta > 0) {

net/quic/quic_http_stream.h

@@ -138,6 +138,8 @@ class NET_EXPORT_PRIVATE QuicHttpStream :
   // Wraps raw_request_body_buf_ to read the remaining data progressively.
   scoped_refptr<DrainableIOBuffer> request_body_buf_;
 
+  BoundNetLog stream_net_log_;
+
   base::WeakPtrFactory<QuicHttpStream> weak_factory_;
 };
 

net/quic/quic_http_stream_test.cc

@@ -174,7 +174,7 @@ class QuicHttpStreamTest : public ::testing::TestWithParam<bool> {
     connection_->SetSendAlgorithm(send_algorithm_);
     connection_->SetReceiveAlgorithm(receive_algorithm_);
     session_.reset(new QuicClientSession(connection_, helper_, NULL,
-                                         "www.google.com"));
+                                         "www.google.com", NULL));
     CryptoHandshakeMessage message;
     message.tag = kSHLO;
     session_->GetCryptoStream()->OnHandshakeMessage(message);

net/quic/quic_reliable_client_stream.cc

@@ -10,8 +10,10 @@
 namespace net {
 
 QuicReliableClientStream::QuicReliableClientStream(QuicStreamId id,
-                                                   QuicSession* session)
+                                                   QuicSession* session,
+                                                   const BoundNetLog& net_log)
     : ReliableQuicStream(id, session),
+      net_log_(net_log),
       delegate_(NULL) {
 }
 

net/quic/quic_reliable_client_stream.h

@@ -56,7 +56,8 @@ class NET_EXPORT_PRIVATE QuicReliableClientStream : public ReliableQuicStream {
   };
 
   QuicReliableClientStream(QuicStreamId id,
-                           QuicSession* session);
+                           QuicSession* session,
+                           const BoundNetLog& net_log);
 
   virtual ~QuicReliableClientStream();
 
@@ -72,7 +73,10 @@ class NET_EXPORT_PRIVATE QuicReliableClientStream : public ReliableQuicStream {
   Delegate* GetDelegate() { return delegate_; }
   void OnError(int error);
 
+  const BoundNetLog& net_log() const { return net_log_; }
+
  private:
+  BoundNetLog net_log_;
   Delegate* delegate_;
 
   DISALLOW_COPY_AND_ASSIGN(QuicReliableClientStream);

net/quic/quic_reliable_client_stream_test.cc

@@ -35,7 +35,7 @@ class QuicReliableClientStreamTest : public ::testing::Test {
  public:
   QuicReliableClientStreamTest()
       : session_(new MockConnection(1, IPEndPoint()), false),
-        stream_(1, &session_) {
+        stream_(1, &session_, BoundNetLog()) {
     stream_.SetDelegate(&delegate_);
   }
 

net/quic/quic_stream_factory.cc

@@ -378,7 +378,7 @@ QuicClientSession* QuicStreamFactory::CreateSession(
 
   QuicConnection* connection = new QuicConnection(guid, addr, helper);
   QuicClientSession* session = new QuicClientSession(connection, helper, this,
-                                                     host);
+                                                     host, net_log.net_log());
   all_sessions_.insert(session);  // owning pointer
   return session;
 }