Log sent and received bytes in net::BidirectionalStream

net/http/bidirectional_stream_unittest.cc

Index: net/http/bidirectional_stream_unittest.cc
diff --git a/net/http/bidirectional_stream_unittest.cc b/net/http/bidirectional_stream_unittest.cc
index 4d6445f4631884304f0193459ef2cdb5cc7bc17a..2449d01ab77201707fb18ea6bdd84dc84fc04c00 100644
--- a/net/http/bidirectional_stream_unittest.cc
+++ b/net/http/bidirectional_stream_unittest.cc
@@ -18,6 +18,8 @@
 #include "net/http/http_response_headers.h"
 #include "net/http/http_server_properties.h"
 #include "net/log/net_log.h"
+#include "net/log/test_net_log.h"
+#include "net/log/test_net_log_util.h"
 #include "net/socket/socket_test_util.h"
 #include "net/spdy/spdy_session.h"
 #include "net/spdy/spdy_test_util_common.h"
@@ -302,6 +304,7 @@ class BidirectionalStreamTest : public testing::TestWithParam<bool> {
         ssl_data_(SSLSocketDataProvider(ASYNC, OK)) {
     ssl_data_.SetNextProto(kProtoHTTP2);
     ssl_data_.cert = ImportCertFromFile(GetTestCertsDirectory(), "ok_cert.pem");
+    net_log_.SetCaptureMode(NetLogCaptureMode::IncludeSocketBytes());
   }
 
  protected:
@@ -323,10 +326,13 @@ class BidirectionalStreamTest : public testing::TestWithParam<bool> {
     sequenced_data_.reset(
         new SequencedSocketData(reads, reads_count, writes, writes_count));
     session_deps_.socket_factory->AddSocketDataProvider(sequenced_data_.get());
+    session_deps_.net_log = net_log_.bound().net_log();
     http_session_ = SpdySessionDependencies::SpdyCreateSession(&session_deps_);
-    session_ = CreateSecureSpdySession(http_session_.get(), key, BoundNetLog());
+    session_ =
+        CreateSecureSpdySession(http_session_.get(), key, net_log_.bound());
   }
 
+  BoundTestNetLog net_log_;
   SpdyTestUtil spdy_util_;
   SpdySessionDependencies session_deps_;
   scoped_ptr<SequencedSocketData> sequenced_data_;
@@ -444,6 +450,106 @@ TEST_F(BidirectionalStreamTest, TestReadDataAfterClose) {
             delegate->GetTotalReceivedBytes());
 }
 
+TEST_F(BidirectionalStreamTest, TestContainFullBytes) {
+  BufferedSpdyFramer framer(spdy_util_.spdy_version());
+
+  scoped_ptr<SpdySerializedFrame> req(spdy_util_.ConstructSpdyPost(
+      "https://www.example.org", 1, kBodyDataSize * 3, LOWEST, nullptr, 0));
+  scoped_ptr<SpdySerializedFrame> data_frame(
+      framer.CreateDataFrame(1, kBodyData, kBodyDataSize, DATA_FLAG_FIN));
+  MockWrite writes[] = {
+      CreateMockWrite(*req, 0), CreateMockWrite(*data_frame, 3),
+  };
+
+  scoped_ptr<SpdySerializedFrame> resp(
+      spdy_util_.ConstructSpdyGetSynReply(nullptr, 0, 1));
+  scoped_ptr<SpdySerializedFrame> response_body_frame1(
+      spdy_util_.ConstructSpdyBodyFrame(1, false));
+  scoped_ptr<SpdySerializedFrame> response_body_frame2(
+      spdy_util_.ConstructSpdyBodyFrame(1, true));
+
+  MockRead reads[] = {
+      CreateMockRead(*resp, 1),
+      MockRead(ASYNC, ERR_IO_PENDING, 2),  // Force a pause.
+      CreateMockRead(*response_body_frame1, 4),
+      MockRead(ASYNC, ERR_IO_PENDING, 5),  // Force a pause.
+      CreateMockRead(*response_body_frame2, 6),
+      MockRead(ASYNC, 0, 7),
+  };
+
+  HostPortPair host_port_pair("www.example.org", 443);
+  SpdySessionKey key(host_port_pair, ProxyServer::Direct(),
+                     PRIVACY_MODE_DISABLED);
+  InitSession(reads, arraysize(reads), writes, arraysize(writes), key);
+
+  scoped_ptr<BidirectionalStreamRequestInfo> request_info(
+      new BidirectionalStreamRequestInfo);
+  request_info->method = "POST";
+  request_info->url = GURL("https://www.example.org/");
+  request_info->priority = LOWEST;
+  request_info->extra_headers.SetHeader(net::HttpRequestHeaders::kContentLength,
+                                        base::SizeTToString(kBodyDataSize * 3));
+
+  scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
+  MockTimer* timer = new MockTimer();
+  scoped_ptr<TestDelegateBase> delegate(new TestDelegateBase(
+      read_buffer.get(), kReadBufferSize, make_scoped_ptr(timer)));
+  delegate->set_do_not_start_read(true);
+  delegate->Start(std::move(request_info), http_session_.get());
+  // Send the request and receive response headers.
+  sequenced_data_->RunUntilPaused();
+  EXPECT_FALSE(timer->IsRunning());
+
+  scoped_refptr<StringIOBuffer> buf(
+      new StringIOBuffer(std::string(kBodyData, kBodyDataSize)));
+  // Send a DATA frame.
+  delegate->SendData(buf.get(), buf->size(), true);
+  // ReadData and it should return asynchronously because no data is buffered.

[mmenke, 2016/04/14 15:38:20]

The grammar on this sentence needs to be fixed - I'm not sure what it's trying
to say.

[xunjieli, 2016/04/14 18:57:06]

Done.

+  int rv = delegate->ReadData();
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  sequenced_data_->Resume();
+  sequenced_data_->RunUntilPaused();

[mmenke, 2016/04/14 15:38:20]

Think the reason for this pause should probably be explained - seemed
unnecessary to me at first.

[xunjieli, 2016/04/14 18:57:06]

Done.

+  timer->Fire();
+  base::RunLoop().RunUntilIdle();

[mmenke, 2016/04/14 15:38:20]

Can we just run until the delegate's OnReadComplete method is called instead, or
whatever it's called?  Prefer to avoid depending on test fixture magic unless we
need to.

[xunjieli, 2016/04/14 18:57:06]

Can we handle it in a separate CL? All tests in this file are like this
currently. 

[mmenke, 2016/04/14 19:04:13]

Sure, makes sense.

+  EXPECT_EQ(1, delegate->on_data_read_count());
+
+  sequenced_data_->Resume();

[mmenke, 2016/04/14 15:38:20]

Is this pause actually needed?

[xunjieli, 2016/04/14 18:57:05]

Yes, we need this to be between first and second DATA frame, so we can fire the
timer. Without this pause, the read might contain two frames, and we have no way
to test that synchronous reads will log bytes.

This tests both asynchronous read and synchronous read.

+  base::RunLoop().RunUntilIdle();

[mmenke, 2016/04/14 15:38:20]

Why don't you need to manually fire the timer again here?

[xunjieli, 2016/04/14 18:57:06]

The timer is stopped in BidirectionalStreamSpdyImpl::OnClose() which is invoked
when all data is received and the write side is closed.

I added a comment.

+  // Read completes synchronously.
+  rv = delegate->ReadData();
+  EXPECT_EQ(kUploadDataSize, rv);
+
+  EXPECT_EQ("200", delegate->response_headers().find(":status")->second);
+  EXPECT_EQ(1, delegate->on_data_read_count());
+  EXPECT_EQ(1, delegate->on_data_sent_count());
+  EXPECT_EQ(kProtoHTTP2, delegate->GetProtocol());
+  EXPECT_EQ(CountWriteBytes(writes, arraysize(writes)),
+            delegate->GetTotalSentBytes());
+  EXPECT_EQ(CountReadBytes(reads, arraysize(reads)),
+            delegate->GetTotalReceivedBytes());
+
+  TestNetLogEntry::List entries;
+  net_log_.GetEntries(&entries);
+  // Sent bytes. Sending data is always asynchronous.
+  size_t index = ExpectLogContainsSomewhere(
+      entries, 0, NetLog::TYPE_BIDIRECTIONAL_STREAM_BYTES_SENT,
+      NetLog::PHASE_NONE);
+  TestNetLogEntry entry = entries[index];
+  EXPECT_EQ(NetLog::SOURCE_BIDIRECTIONAL_STREAM, entry.source.type);
+  // Received bytes for asynchronous read.
+  index = ExpectLogContainsSomewhere(
+      entries, index, NetLog::TYPE_BIDIRECTIONAL_STREAM_BYTES_RECEIVED,
+      NetLog::PHASE_NONE);
+  entry = entries[index];
+  EXPECT_EQ(NetLog::SOURCE_BIDIRECTIONAL_STREAM, entry.source.type);
+  // Received bytes for synchronous read.
+  index = ExpectLogContainsSomewhere(
+      entries, index, NetLog::TYPE_BIDIRECTIONAL_STREAM_BYTES_RECEIVED,
+      NetLog::PHASE_NONE);
+  entry = entries[index];
+  EXPECT_EQ(NetLog::SOURCE_BIDIRECTIONAL_STREAM, entry.source.type);
+}
+
 TEST_F(BidirectionalStreamTest, TestInterleaveReadDataAndSendData) {
   BufferedSpdyFramer framer(spdy_util_.spdy_version());