Add logging for headers sent and received in BidirectionalStreamQuicImpl

net/quic/bidirectional_stream_quic_impl_unittest.cc

 // Copyright 2016 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/quic/bidirectional_stream_quic_impl.h"
 
 #include <stdint.h>
 #include <vector>
 
 #include "base/callback_helpers.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/message_loop/message_loop.h"
 #include "base/run_loop.h"
 #include "base/strings/string_number_conversions.h"
 #include "net/base/net_errors.h"
 #include "net/http/bidirectional_stream_request_info.h"
 #include "net/http/transport_security_state.h"
+#include "net/log/test_net_log.h"
+#include "net/log/test_net_log_util.h"
 #include "net/quic/crypto/crypto_protocol.h"
 #include "net/quic/crypto/quic_decrypter.h"
 #include "net/quic/crypto/quic_encrypter.h"
 #include "net/quic/crypto/quic_server_info.h"
 #include "net/quic/quic_chromium_client_session.h"
 #include "net/quic/quic_chromium_client_stream.h"
 #include "net/quic/quic_chromium_connection_helper.h"
 #include "net/quic/quic_chromium_packet_reader.h"
 #include "net/quic/quic_chromium_packet_writer.h"
 #include "net/quic/quic_connection.h"
@@ skipping 237 matching lines @@
   struct PacketToWrite {
     PacketToWrite(IoMode mode, QuicEncryptedPacket* packet)
         : mode(mode), packet(packet) {}
     PacketToWrite(IoMode mode, int rv) : mode(mode), packet(nullptr), rv(rv) {}
     IoMode mode;
     QuicEncryptedPacket* packet;
     int rv;
   };
 
   BidirectionalStreamQuicImplTest()
-      : net_log_(BoundNetLog()),
-        crypto_config_(CryptoTestUtils::ProofVerifierForTesting()),
+      : crypto_config_(CryptoTestUtils::ProofVerifierForTesting()),
         read_buffer_(new IOBufferWithSize(4096)),
         connection_id_(2),
         stream_id_(kClientDataStreamId1),
         maker_(GetParam(), connection_id_, &clock_, kDefaultServerHostName),
         random_generator_(0) {
     IPAddressNumber ip;
     CHECK(ParseIPLiteralToNumber("192.0.2.33", &ip));
     peer_addr_ = IPEndPoint(ip, 443);
     self_addr_ = IPEndPoint(ip, 8435);
     clock_.AdvanceTime(QuicTime::Delta::FromMilliseconds(20));
@@ skipping 28 matching lines @@
         mock_writes_[i] = MockWrite(writes_[i].mode, writes_[i].rv, i);
       } else {
         mock_writes_[i] = MockWrite(writes_[i].mode, writes_[i].packet->data(),
                                     writes_[i].packet->length());
       }
     };
 
     socket_data_.reset(new StaticSocketDataProvider(
         nullptr, 0, mock_writes_.get(), writes_.size()));
 
-    MockUDPClientSocket* socket =
-        new MockUDPClientSocket(socket_data_.get(), net_log_.net_log());
+    MockUDPClientSocket* socket = new MockUDPClientSocket(

[mmenke, 2016/03/23 20:32:21]

Not realted to this CL, but this should be a scoped_ptr, and should use
std::move to pass it to QuicChromiumClientSession's constructor.

[xunjieli, 2016/03/23 22:19:23]

You are right. I copied from quic_http_stream_test.cc, which needs to be changed
as well. Will do that as a  follow-up.

+        socket_data_.get(), net_log().bound().net_log());
     socket->Connect(peer_addr_);
     runner_ = new TestTaskRunner(&clock_);
     helper_.reset(new QuicChromiumConnectionHelper(runner_.get(), &clock_,
                                                    &random_generator_));
     connection_ = new QuicConnection(
         connection_id_, peer_addr_, helper_.get(),
         new QuicChromiumPacketWriter(socket), true /* owns_writer */,
         Perspective::IS_CLIENT, SupportedVersions(GetParam()));
 
     session_.reset(new QuicChromiumClientSession(
         connection_, scoped_ptr<DatagramClientSocket>(socket),
         /*stream_factory=*/nullptr, &crypto_client_stream_factory_, &clock_,
         &transport_security_state_, make_scoped_ptr((QuicServerInfo*)nullptr),
         QuicServerId(kDefaultServerHostName, kDefaultServerPort,
                      PRIVACY_MODE_DISABLED),
         kQuicYieldAfterPacketsRead,
         QuicTime::Delta::FromMilliseconds(kQuicYieldAfterDurationMilliseconds),
         /*cert_verify_flags=*/0, DefaultQuicConfig(), &crypto_config_,
         "CONNECTION_UNKNOWN", base::TimeTicks::Now(), &push_promise_index_,
         base::ThreadTaskRunnerHandle::Get().get(),
-        /*socket_performance_watcher=*/nullptr, nullptr));
+        /*socket_performance_watcher=*/nullptr, net_log().bound().net_log()));
     session_->Initialize();
     session_->GetCryptoStream()->CryptoConnect();
     EXPECT_TRUE(session_->IsCryptoHandshakeConfirmed());
   }
 
   void SetRequest(const std::string& method,
                   const std::string& path,
                   RequestPriority priority) {
     request_headers_ = maker_.GetRequestHeaders(method, "http", path);
   }
@@ skipping 93 matching lines @@
   }
 
   scoped_ptr<QuicEncryptedPacket> ConstructAckPacket(
       QuicPacketNumber packet_number,
       QuicPacketNumber largest_received,
       QuicPacketNumber least_unacked) {
     return maker_.MakeAckPacket(packet_number, largest_received, least_unacked,
                                 !kIncludeCongestionFeedback);
   }
 
-  const BoundNetLog& net_log() const { return net_log_; }
+  const BoundTestNetLog& net_log() const { return net_log_; }

[mmenke, 2016/03/23 20:32:21]

This should be a TestNetLog

BoundTestNetLog is for when you have a class that takes a BoundNetLog created by
a higher layer.  When you have a class that takes a full NetLog, use TestNetLog.

[mmenke, 2016/03/23 22:11:59]

Oops...intended to delete this comment - looks like this is done elsewhere, and
the delegate->Start calls all take a BoundNetLog.  Could just create one
ourselves from the TestNetLog, but...This works.

[xunjieli, 2016/03/23 22:19:23]

Acknowledged.

 
   QuicChromiumClientSession* session() const { return session_.get(); }
 
  private:
-  BoundNetLog net_log_;
+  BoundTestNetLog net_log_;
   scoped_refptr<TestTaskRunner> runner_;
   scoped_ptr<MockWrite[]> mock_writes_;
   MockClock clock_;
   QuicConnection* connection_;
   scoped_ptr<QuicChromiumConnectionHelper> helper_;
   TransportSecurityState transport_security_state_;
   scoped_ptr<QuicChromiumClientSession> session_;
   QuicCryptoClientConfig crypto_config_;
   HttpRequestHeaders headers_;
   HttpResponseInfo response_;
@@ skipping 26 matching lines @@
 
   BidirectionalStreamRequestInfo request;
   request.method = "GET";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = true;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<TestDelegateBase> delegate(
       new TestDelegateBase(read_buffer.get(), kReadBufferSize));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Server acks the request.
   ProcessPacket(ConstructAckPacket(1, 0, 0));
 
   // Server sends the response headers.
   SpdyHeaderBlock response_headers = ConstructResponseHeaders("200");
 
   size_t spdy_response_headers_frame_length;
   QuicStreamOffset offset = 0;
@@ skipping 34 matching lines @@
 
   EXPECT_EQ(2, delegate->on_data_read_count());
   EXPECT_EQ(0, delegate->on_data_sent_count());
   EXPECT_EQ(kProtoQUIC1SPDY3, delegate->GetProtocol());
   EXPECT_EQ(static_cast<int64_t>(spdy_request_headers_frame_length),
             delegate->GetTotalSentBytes());
   EXPECT_EQ(
       static_cast<int64_t>(spdy_response_headers_frame_length +
                            strlen(kResponseBody) + spdy_trailers_frame_length),
       delegate->GetTotalReceivedBytes());
+  // Check that NetLog was filled as expected.
+  TestNetLogEntry::List entries;
+  net_log().GetEntries(&entries);
+  size_t pos = ExpectLogContainsSomewhere(
+      entries, /*min_offset=*/0,
+      NetLog::TYPE_QUIC_CHROMIUM_CLIENT_STREAM_SEND_REQUEST_HEADERS,
+      NetLog::PHASE_NONE);
+  pos = ExpectLogContainsSomewhere(
+      entries, /*min_offset=*/pos,
+      NetLog::TYPE_QUIC_CHROMIUM_CLIENT_STREAM_SEND_REQUEST_HEADERS,
+      NetLog::PHASE_NONE);
+  ExpectLogContainsSomewhere(
+      entries, /*min_offset=*/pos,
+      NetLog::TYPE_QUIC_CHROMIUM_CLIENT_STREAM_SEND_REQUEST_HEADERS,
+      NetLog::PHASE_NONE);
 }
 
 TEST_P(BidirectionalStreamQuicImplTest, PostRequest) {
   SetRequest("POST", "/", DEFAULT_PRIORITY);
   size_t spdy_request_headers_frame_length;
   AddWrite(ConstructRequestHeadersPacket(1, !kFin, DEFAULT_PRIORITY,
                                          &spdy_request_headers_frame_length));
   AddWrite(ConstructDataPacket(2, kIncludeVersion, kFin, 0, kUploadData));
   AddWrite(ConstructAckPacket(3, 3, 1));
 
   Initialize();
 
   BidirectionalStreamRequestInfo request;
   request.method = "POST";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = false;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<TestDelegateBase> delegate(
       new TestDelegateBase(read_buffer.get(), kReadBufferSize));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Send a DATA frame.
   scoped_refptr<StringIOBuffer> buf(new StringIOBuffer(kUploadData));
 
   delegate->SendData(buf.get(), buf->size(), true);
   delegate->WaitUntilNextCallback();  // OnDataSent
 
   // Server acks the request.
   ProcessPacket(ConstructAckPacket(1, 0, 0));
@@ skipping 56 matching lines @@
 
   BidirectionalStreamRequestInfo request;
   request.method = "POST";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = false;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<TestDelegateBase> delegate(
       new TestDelegateBase(read_buffer.get(), kReadBufferSize));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Server acks the request.
   ProcessPacket(ConstructAckPacket(1, 0, 0));
 
   // Server sends the response headers.
   SpdyHeaderBlock response_headers = ConstructResponseHeaders("200");
   size_t spdy_response_headers_frame_length;
   ProcessPacket(ConstructResponseHeadersPacket(
       2, !kFin, response_headers, &spdy_response_headers_frame_length, 0));
@@ skipping 56 matching lines @@
 
   BidirectionalStreamRequestInfo request;
   request.method = "GET";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = true;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<TestDelegateBase> delegate(
       new TestDelegateBase(read_buffer.get(), kReadBufferSize));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Server sends a Rst.
   ProcessPacket(ConstructRstStreamPacket(1));
 
   delegate->WaitUntilNextCallback();  // OnFailed
   TestCompletionCallback cb;
   EXPECT_EQ(ERR_QUIC_PROTOCOL_ERROR, delegate->ReadData(cb.callback()));
 
   base::MessageLoop::current()->RunUntilIdle();
@@ skipping 18 matching lines @@
 
   BidirectionalStreamRequestInfo request;
   request.method = "GET";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = true;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<TestDelegateBase> delegate(
       new TestDelegateBase(read_buffer.get(), kReadBufferSize));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Server acks the request.
   ProcessPacket(ConstructAckPacket(1, 0, 0));
 
   // Server sends the response headers.
   SpdyHeaderBlock response_headers = ConstructResponseHeaders("200");
 
   size_t spdy_response_headers_frame_length;
   QuicStreamOffset offset = 0;
@@ skipping 36 matching lines @@
 
   BidirectionalStreamRequestInfo request;
   request.method = "POST";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = false;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<TestDelegateBase> delegate(
       new TestDelegateBase(read_buffer.get(), kReadBufferSize));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Server acks the request.
   ProcessPacket(ConstructAckPacket(1, 0, 0));
 
   // Server sends the response headers.
   SpdyHeaderBlock response_headers = ConstructResponseHeaders("200");
   size_t spdy_response_headers_frame_length;
   ProcessPacket(ConstructResponseHeadersPacket(
       2, !kFin, response_headers, &spdy_response_headers_frame_length, 0));
@@ skipping 29 matching lines @@
 
   BidirectionalStreamRequestInfo request;
   request.method = "GET";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = true;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<TestDelegateBase> delegate(
       new TestDelegateBase(read_buffer.get(), kReadBufferSize));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Server acks the request.
   ProcessPacket(ConstructAckPacket(1, 0, 0));
 
   // Server sends the response headers.
   SpdyHeaderBlock response_headers = ConstructResponseHeaders("200");
 
   size_t spdy_response_headers_frame_length;
   QuicStreamOffset offset = 0;
@@ skipping 33 matching lines @@
 
   BidirectionalStreamRequestInfo request;
   request.method = "POST";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = false;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<TestDelegateBase> delegate(
       new TestDelegateBase(read_buffer.get(), kReadBufferSize));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Server acks the request.
   ProcessPacket(ConstructAckPacket(1, 0, 0));
 
   // Server sends the response headers.
   SpdyHeaderBlock response_headers = ConstructResponseHeaders("200");
   size_t spdy_response_headers_frame_length;
   ProcessPacket(ConstructResponseHeadersPacket(
       2, !kFin, response_headers, &spdy_response_headers_frame_length, 0));
@@ skipping 29 matching lines @@
   BidirectionalStreamRequestInfo request;
   request.method = "POST";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = false;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<DeleteStreamDelegate> delegate(new DeleteStreamDelegate(
       read_buffer.get(), kReadBufferSize,
       DeleteStreamDelegate::ON_HEADERS_RECEIVED, true));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Server acks the request.
   ProcessPacket(ConstructAckPacket(1, 0, 0));
 
   // Server sends the response headers.
   SpdyHeaderBlock response_headers = ConstructResponseHeaders("200");
 
   size_t spdy_response_headers_frame_length;
   ProcessPacket(ConstructResponseHeadersPacket(
@@ skipping 22 matching lines @@
   BidirectionalStreamRequestInfo request;
   request.method = "POST";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = false;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<DeleteStreamDelegate> delegate(
       new DeleteStreamDelegate(read_buffer.get(), kReadBufferSize,
                                DeleteStreamDelegate::ON_DATA_READ, true));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Server acks the request.
   ProcessPacket(ConstructAckPacket(1, 0, 0));
 
   // Server sends the response headers.
   SpdyHeaderBlock response_headers = ConstructResponseHeaders("200");
 
   size_t spdy_response_headers_frame_length;
   ProcessPacket(ConstructResponseHeadersPacket(
@@ skipping 31 matching lines @@
   BidirectionalStreamRequestInfo request;
   request.method = "GET";
   request.url = GURL("http://www.google.com/");
   request.end_stream_on_headers = true;
   request.priority = DEFAULT_PRIORITY;
 
   scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
   scoped_ptr<DeleteStreamDelegate> delegate(new DeleteStreamDelegate(
       read_buffer.get(), kReadBufferSize,
       DeleteStreamDelegate::ON_TRAILERS_RECEIVED, true));
-  delegate->Start(&request, net_log(), session()->GetWeakPtr());
+  delegate->Start(&request, net_log().bound(), session()->GetWeakPtr());
   delegate->WaitUntilNextCallback();  // OnHeadersSent
 
   // Server acks the request.
   ProcessPacket(ConstructAckPacket(1, 0, 0));
 
   // Server sends the response headers.
   SpdyHeaderBlock response_headers = ConstructResponseHeaders("200");
 
   QuicStreamOffset offset = 0;
   size_t spdy_response_headers_frame_length;
@@ skipping 30 matching lines @@
 
   base::MessageLoop::current()->RunUntilIdle();
 
   EXPECT_EQ(1, delegate->on_data_read_count());
   EXPECT_EQ(0, delegate->on_data_sent_count());
 }
 
 }  // namespace test
 
 }  // namespace net