Pass the LoadLog through the FlipStream.

BUG=none
TEST=FlipNetworkTransactionTest.LoadLog

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

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

9 files changed, 149 insertions, 24 deletions

diff --git a/net/base/load_log_event_type_list.h b/net/base/load_log_event_type_list.h
index 5b063de..880305e 100644
--- a/net/base/load_log_event_type_list.h
+++ b/net/base/load_log_event_type_list.h
@@ -178,6 +178,25 @@ EVENT_TYPE(FLIP_TRANSACTION_READ_HEADERS)
 EVENT_TYPE(FLIP_TRANSACTION_READ_BODY)
 
 // ------------------------------------------------------------------------
+// FlipStream
+// ------------------------------------------------------------------------
+
+// Measures the time taken to send headers on a stream.
+EVENT_TYPE(FLIP_STREAM_SEND_HEADERS)
+
+// Measures the time taken to send the body (e.g. a POST) on a stream.
+EVENT_TYPE(FLIP_STREAM_SEND_BODY)
+
+// Measures the time taken to read headers on a stream.
+EVENT_TYPE(FLIP_STREAM_READ_HEADERS)
+
+// Measures the time taken to read the body on a stream.
+EVENT_TYPE(FLIP_STREAM_READ_BODY)
+
+// Logs that a stream attached to a pushed stream.
+EVENT_TYPE(FLIP_STREAM_ADOPTED_PUSH_STREAM)
+
+// ------------------------------------------------------------------------
 // HttpStreamParser
 // ------------------------------------------------------------------------
 
diff --git a/net/base/load_log_unittest.h b/net/base/load_log_unittest.h
index f67c8bc..6f0cb45 100644
--- a/net/base/load_log_unittest.h
+++ b/net/base/load_log_unittest.h
@@ -64,6 +64,23 @@ inline ::testing::AssertionResult LogContains(
   return ::testing::AssertionSuccess();
 }
 
+// Expect that the log contains an event, but don't care about where
+// as long as the index where it is found is greater than min_index.
+// Returns the position where the event was found.
+inline size_t ExpectLogContainsSomewhere(const LoadLog* log,
+                                         size_t min_index,
+                                         LoadLog::EventType expected_event,
+                                         LoadLog::EventPhase expected_phase) {
+  size_t i = 0;
+  for (; i < log->events().size(); ++i)
+    if (log->events()[i].type == expected_event &&
+        log->events()[i].phase == expected_phase)
+      break;
+  EXPECT_LT(i, log->events().size());
+  EXPECT_GE(i, min_index);
+  return i;
+}
+
 }  // namespace net
 
 #endif  // NET_BASE_LOAD_LOG_UNITTEST_H_
diff --git a/net/flip/flip_network_transaction.cc b/net/flip/flip_network_transaction.cc
index 4e0c3d2d..7ea5370 100644
--- a/net/flip/flip_network_transaction.cc
+++ b/net/flip/flip_network_transaction.cc
@@ -251,7 +251,7 @@ int FlipNetworkTransaction::DoSendRequest() {
   CHECK(!stream_.get());
   UploadDataStream* upload_data = request_->upload_data ?
       new UploadDataStream(request_->upload_data) : NULL;
-  stream_ = flip_->GetOrCreateStream(*request_, upload_data);
+  stream_ = flip_->GetOrCreateStream(*request_, upload_data, load_log_.get());
   return stream_->SendRequest(upload_data, &response_, &io_callback_);
 }
 
diff --git a/net/flip/flip_network_transaction_unittest.cc b/net/flip/flip_network_transaction_unittest.cc
index a236194..bbb2a7f 100644
--- a/net/flip/flip_network_transaction_unittest.cc
+++ b/net/flip/flip_network_transaction_unittest.cc
@@ -7,6 +7,7 @@
 #include "base/basictypes.h"
 #include "base/ref_counted.h"
 #include "net/base/completion_callback.h"
+#include "net/base/load_log_unittest.h"
 #include "net/base/mock_host_resolver.h"
 #include "net/base/ssl_config_service_defaults.h"
 #include "net/base/test_completion_callback.h"
@@ -260,7 +261,8 @@ class FlipNetworkTransactionTest : public PlatformTest {
   };
 
   TransactionHelperResult TransactionHelper(const HttpRequestInfo& request,
-                                            DelayedSocketData* data) {
+                                            DelayedSocketData* data,
+                                            LoadLog* log) {
     TransactionHelperResult out;
 
     // We disable SSL for this test.
@@ -274,7 +276,7 @@ class FlipNetworkTransactionTest : public PlatformTest {
 
     TestCompletionCallback callback;
 
-    int rv = trans->Start(&request, &callback, NULL);
+    int rv = trans->Start(&request, &callback, log);
     EXPECT_EQ(ERR_IO_PENDING, rv);
 
     out.rv = callback.WaitForResult();
@@ -333,7 +335,7 @@ TEST_F(FlipNetworkTransactionTest, Get) {
   request.load_flags = 0;
   scoped_refptr<DelayedSocketData> data(
       new DelayedSocketData(reads, 1, writes));
-  TransactionHelperResult out = TransactionHelper(request, data.get());
+  TransactionHelperResult out = TransactionHelper(request, data.get(), NULL);
   EXPECT_EQ(OK, out.rv);
   EXPECT_EQ("HTTP/1.1 200 OK", out.status_line);
   EXPECT_EQ("hello!", out.response_data);
@@ -368,7 +370,7 @@ TEST_F(FlipNetworkTransactionTest, Post) {
 
   scoped_refptr<DelayedSocketData> data(
       new DelayedSocketData(reads, 2, writes));
-  TransactionHelperResult out = TransactionHelper(request, data.get());
+  TransactionHelperResult out = TransactionHelper(request, data.get(), NULL);
   EXPECT_EQ(OK, out.rv);
   EXPECT_EQ("HTTP/1.1 200 OK", out.status_line);
   EXPECT_EQ("hello!", out.response_data);
@@ -415,7 +417,7 @@ static const unsigned char kEmptyPostSyn[] = {
   scoped_refptr<DelayedSocketData> data(
     new DelayedSocketData(reads, 1, writes));
 
-  TransactionHelperResult out = TransactionHelper(request, data);
+  TransactionHelperResult out = TransactionHelper(request, data, NULL);
   EXPECT_EQ(OK, out.rv);
   EXPECT_EQ("HTTP/1.1 200 OK", out.status_line);
   EXPECT_EQ("hello!", out.response_data);
@@ -435,7 +437,7 @@ TEST_F(FlipNetworkTransactionTest, ResponseWithoutSynReply) {
   request.load_flags = 0;
   scoped_refptr<DelayedSocketData> data(
       new DelayedSocketData(reads, 1, NULL));
-  TransactionHelperResult out = TransactionHelper(request, data.get());
+  TransactionHelperResult out = TransactionHelper(request, data.get(), NULL);
   EXPECT_EQ(ERR_SYN_REPLY_NOT_RECEIVED, out.rv);
 }
 
@@ -586,7 +588,7 @@ TEST_F(FlipNetworkTransactionTest, SynReplyHeaders) {
     request.load_flags = 0;
     scoped_refptr<DelayedSocketData> data(
         new DelayedSocketData(reads, 1, writes));
-    TransactionHelperResult out = TransactionHelper(request, data.get());
+    TransactionHelperResult out = TransactionHelper(request, data.get(), NULL);
     EXPECT_EQ(OK, out.rv);
     EXPECT_EQ("HTTP/1.1 200 OK", out.status_line);
     EXPECT_EQ("hello!", out.response_data);
@@ -661,7 +663,7 @@ TEST_F(FlipNetworkTransactionTest, InvalidSynReply) {
     request.load_flags = 0;
     scoped_refptr<DelayedSocketData> data(
         new DelayedSocketData(reads, 1, writes));
-    TransactionHelperResult out = TransactionHelper(request, data.get());
+    TransactionHelperResult out = TransactionHelper(request, data.get(), NULL);
     EXPECT_EQ(ERR_INVALID_RESPONSE, out.rv);
   }
 }
@@ -848,7 +850,7 @@ TEST_F(FlipNetworkTransactionTest, WriteError) {
   request.load_flags = 0;
   scoped_refptr<DelayedSocketData> data(
       new DelayedSocketData(reads, 2, writes));
-  TransactionHelperResult out = TransactionHelper(request, data.get());
+  TransactionHelperResult out = TransactionHelper(request, data.get(), NULL);
   EXPECT_EQ(ERR_FAILED, out.rv);
   data->Reset();
 }
@@ -874,7 +876,7 @@ TEST_F(FlipNetworkTransactionTest, PartialWrite) {
   request.load_flags = 0;
   scoped_refptr<DelayedSocketData> data(
       new DelayedSocketData(reads, kChunks, writes.get()));
-  TransactionHelperResult out = TransactionHelper(request, data.get());
+  TransactionHelperResult out = TransactionHelper(request, data.get(), NULL);
   EXPECT_EQ(OK, out.rv);
   EXPECT_EQ("HTTP/1.1 200 OK", out.status_line);
   EXPECT_EQ("hello!", out.response_data);
@@ -911,9 +913,73 @@ TEST_F(FlipNetworkTransactionTest, DISABLED_ConnectFailure) {
     request.load_flags = 0;
     scoped_refptr<DelayedSocketData> data(
         new DelayedSocketData(connects[index], reads, 1, writes));
-    TransactionHelperResult out = TransactionHelper(request, data.get());
+    TransactionHelperResult out = TransactionHelper(request, data.get(), NULL);
     EXPECT_EQ(connects[index].result, out.rv);
   }
 }
 
+// Test that the LoadLog contains good data for a simple GET request.
+TEST_F(FlipNetworkTransactionTest, LoadLog) {
+  MockWrite writes[] = {
+    MockWrite(true, reinterpret_cast<const char*>(kGetSyn),
+              arraysize(kGetSyn)),
+    MockWrite(true, 0, 0)  // EOF
+  };
+
+  MockRead reads[] = {
+    MockRead(true, reinterpret_cast<const char*>(kGetSynReply),
+             arraysize(kGetSynReply)),
+    MockRead(true, reinterpret_cast<const char*>(kGetBodyFrame),
+             arraysize(kGetBodyFrame)),
+    MockRead(true, 0, 0)  // EOF
+  };
+
+  scoped_refptr<net::LoadLog> log(new net::LoadLog(net::LoadLog::kUnbounded));
+
+  HttpRequestInfo request;
+  request.method = "GET";
+  request.url = GURL("http://www.google.com/");
+  request.load_flags = 0;
+  scoped_refptr<DelayedSocketData> data(
+      new DelayedSocketData(reads, 1, writes));
+  TransactionHelperResult out = TransactionHelper(request, data.get(),
+                                                  log);
+  EXPECT_EQ(OK, out.rv);
+  EXPECT_EQ("HTTP/1.1 200 OK", out.status_line);
+  EXPECT_EQ("hello!", out.response_data);
+
+  // Check that the LoadLog was filled reasonably.
+  // This test is intentionally non-specific about the exact ordering of
+  // the log; instead we just check to make sure that certain events exist.
+  EXPECT_LT(0u, log->events().size());
+  int pos = 0;
+  // We know the first event at position 0.
+  net::ExpectLogContains(log, 0,
+      net::LoadLog::TYPE_FLIP_TRANSACTION_INIT_CONNECTION,
+      net::LoadLog::PHASE_BEGIN);
+  // For the rest of the events, allow additional events in the middle,
+  // but expect these to be logged in order.
+  pos = net::ExpectLogContainsSomewhere(log, 0,
+      net::LoadLog::TYPE_FLIP_TRANSACTION_INIT_CONNECTION,
+      net::LoadLog::PHASE_END);
+  pos = net::ExpectLogContainsSomewhere(log, pos + 1,
+      net::LoadLog::TYPE_FLIP_TRANSACTION_SEND_REQUEST,
+      net::LoadLog::PHASE_BEGIN);
+  pos = net::ExpectLogContainsSomewhere(log, pos + 1,
+      net::LoadLog::TYPE_FLIP_TRANSACTION_SEND_REQUEST,
+      net::LoadLog::PHASE_END);
+  pos = net::ExpectLogContainsSomewhere(log, pos + 1,
+      net::LoadLog::TYPE_FLIP_TRANSACTION_READ_HEADERS,
+      net::LoadLog::PHASE_BEGIN);
+  pos = net::ExpectLogContainsSomewhere(log, pos + 1,
+      net::LoadLog::TYPE_FLIP_TRANSACTION_READ_HEADERS,
+      net::LoadLog::PHASE_END);
+  pos = net::ExpectLogContainsSomewhere(log, pos + 1,
+      net::LoadLog::TYPE_FLIP_TRANSACTION_READ_BODY,
+      net::LoadLog::PHASE_BEGIN);
+  pos = net::ExpectLogContainsSomewhere(log, pos + 1,
+      net::LoadLog::TYPE_FLIP_TRANSACTION_READ_BODY,
+      net::LoadLog::PHASE_END);
+}
+
 }  // namespace net
diff --git a/net/flip/flip_session.cc b/net/flip/flip_session.cc
index 4045552..bf98152 100644
--- a/net/flip/flip_session.cc
+++ b/net/flip/flip_session.cc
@@ -241,7 +241,8 @@ net::Error FlipSession::Connect(const std::string& group_name,
 
 scoped_refptr<FlipStream> FlipSession::GetOrCreateStream(
     const HttpRequestInfo& request,
-    const UploadDataStream* upload_data) {
+    const UploadDataStream* upload_data,
+    LoadLog* log) {
   const GURL& url = request.url;
   const std::string& path = url.PathForRequest();
 
@@ -261,7 +262,8 @@ scoped_refptr<FlipStream> FlipSession::GetOrCreateStream(
     DCHECK(!it->second);
     // Server will assign a stream id when the push stream arrives.  Use 0 for
     // now.
-    FlipStream* stream = new FlipStream(this, 0, true);
+    LoadLog::AddEvent(log, LoadLog::TYPE_FLIP_STREAM_ADOPTED_PUSH_STREAM);
+    FlipStream* stream = new FlipStream(this, 0, true, log);
     stream->set_path(path);
     it->second = stream;
     return it->second;
@@ -270,7 +272,7 @@ scoped_refptr<FlipStream> FlipSession::GetOrCreateStream(
   const flip::FlipStreamId stream_id = GetNewStreamId();
 
   // If we still don't have a stream, activate one now.
-  stream = new FlipStream(this, stream_id, false);
+  stream = new FlipStream(this, stream_id, false, log);
   stream->set_priority(request.priority);
   stream->set_path(path);
   ActivateStream(stream);
@@ -809,7 +811,8 @@ void FlipSession::OnSyn(const flip::FlipSynStreamControlFrame* frame,
     CHECK(stream->stream_id() == 0);
     stream->set_stream_id(stream_id);
   } else {
-    stream = new FlipStream(this, stream_id, true);
+    // TODO(mbelshe): can we figure out how to use a LoadLog here?
+    stream = new FlipStream(this, stream_id, true, NULL);
   }
 
   // Activate a stream and parse the headers.
diff --git a/net/flip/flip_session.h b/net/flip/flip_session.h
index d0d9142..6fa4b0f 100644
--- a/net/flip/flip_session.h
+++ b/net/flip/flip_session.h
@@ -56,8 +56,8 @@ class FlipSession : public base::RefCounted<FlipSession>,
   // might also not have initiated the stream yet, but indicated it will via
   // X-Associated-Content.
   // Returns the new or existing stream.  Never returns NULL.
-  scoped_refptr<FlipStream> GetOrCreateStream(
-      const HttpRequestInfo& request, const UploadDataStream* upload_data);
+  scoped_refptr<FlipStream> GetOrCreateStream(const HttpRequestInfo& request,
+      const UploadDataStream* upload_data, LoadLog* log);
 
   // Write a data frame to the stream.
   // Used to create and queue a data frame for the given stream.
diff --git a/net/flip/flip_stream.cc b/net/flip/flip_stream.cc
index 7288480..9f76b95 100755
--- a/net/flip/flip_stream.cc
+++ b/net/flip/flip_stream.cc
@@ -11,9 +11,8 @@
 
 namespace net {
 
-FlipStream::FlipStream(FlipSession* session,
-                       flip::FlipStreamId stream_id,
-                       bool pushed)
+FlipStream::FlipStream(FlipSession* session, flip::FlipStreamId stream_id,
+                       bool pushed, LoadLog* log)
     : stream_id_(stream_id),
       priority_(0),
       pushed_(pushed),
@@ -28,7 +27,8 @@ FlipStream::FlipStream(FlipSession* session,
       user_callback_(NULL),
       user_buffer_(NULL),
       user_buffer_len_(0),
-      cancelled_(false) {}
+      cancelled_(false),
+      load_log_(log) {}
 
 FlipStream::~FlipStream() {
   DLOG(INFO) << "Deleting FlipStream for stream " << stream_id_;
@@ -251,23 +251,35 @@ int FlipStream::DoLoop(int result) {
       // State machine 1: Send headers and wait for response headers.
       case STATE_SEND_HEADERS:
         CHECK(result == OK);
+        LoadLog::BeginEvent(load_log_,
+                            LoadLog::TYPE_FLIP_STREAM_SEND_HEADERS);
         result = DoSendHeaders();
         break;
       case STATE_SEND_HEADERS_COMPLETE:
+        LoadLog::EndEvent(load_log_,
+                          LoadLog::TYPE_FLIP_STREAM_SEND_HEADERS);
         result = DoSendHeadersComplete(result);
         break;
       case STATE_SEND_BODY:
         CHECK(result == OK);
+        LoadLog::BeginEvent(load_log_,
+                            LoadLog::TYPE_FLIP_STREAM_SEND_BODY);
         result = DoSendBody();
         break;
       case STATE_SEND_BODY_COMPLETE:
+        LoadLog::EndEvent(load_log_,
+                          LoadLog::TYPE_FLIP_STREAM_SEND_BODY);
         result = DoSendBodyComplete(result);
         break;
       case STATE_READ_HEADERS:
         CHECK(result == OK);
+        LoadLog::BeginEvent(load_log_,
+                            LoadLog::TYPE_FLIP_STREAM_READ_HEADERS);
         result = DoReadHeaders();
         break;
       case STATE_READ_HEADERS_COMPLETE:
+        LoadLog::EndEvent(load_log_,
+                          LoadLog::TYPE_FLIP_STREAM_READ_HEADERS);
         result = DoReadHeadersComplete(result);
         break;
 
@@ -276,9 +288,13 @@ int FlipStream::DoLoop(int result) {
       // the OnDataReceived()/OnClose()/ReadResponseHeaders()/etc.  Only reason
       // to do this is for consistency with the Http code.
       case STATE_READ_BODY:
+        LoadLog::BeginEvent(load_log_,
+                            LoadLog::TYPE_FLIP_STREAM_READ_BODY);
         result = DoReadBody();
         break;
       case STATE_READ_BODY_COMPLETE:
+        LoadLog::EndEvent(load_log_,
+                          LoadLog::TYPE_FLIP_STREAM_READ_BODY);
         result = DoReadBodyComplete(result);
         break;
       case STATE_DONE:
diff --git a/net/flip/flip_stream.h b/net/flip/flip_stream.h
index 3ebdc2e..4c4cc33 100755
--- a/net/flip/flip_stream.h
+++ b/net/flip/flip_stream.h
@@ -15,6 +15,7 @@
 #include "net/base/bandwidth_metrics.h"
 #include "net/base/completion_callback.h"
 #include "net/base/io_buffer.h"
+#include "net/base/load_log.h"
 #include "net/flip/flip_framer.h"
 #include "net/flip/flip_protocol.h"
 
@@ -36,7 +37,8 @@ class UploadDataStream;
 class FlipStream : public base::RefCounted<FlipStream> {
  public:
   // FlipStream constructor
-  FlipStream(FlipSession* session, flip::FlipStreamId stream_id, bool pushed);
+  FlipStream(FlipSession* session, flip::FlipStreamId stream_id, bool pushed,
+             LoadLog* log);
 
   // Ideally I'd use two abstract classes as interfaces for these two sections,
   // but since we're ref counted, I can't make both abstract classes inherit
@@ -184,6 +186,8 @@ class FlipStream : public base::RefCounted<FlipStream> {
 
   bool cancelled_;
 
+  scoped_refptr<LoadLog> load_log_;
+
   DISALLOW_COPY_AND_ASSIGN(FlipStream);
 };
 
diff --git a/net/flip/flip_stream_unittest.cc b/net/flip/flip_stream_unittest.cc
index bb64d63..643aa60 100644
--- a/net/flip/flip_stream_unittest.cc
+++ b/net/flip/flip_stream_unittest.cc
@@ -106,7 +106,7 @@ TEST_F(FlipStreamTest, SendRequest) {
   TestCompletionCallback callback;
   HttpResponseInfo response;
 
-  scoped_refptr<FlipStream> stream(new FlipStream(session, 1, false));
+  scoped_refptr<FlipStream> stream(new FlipStream(session, 1, false, NULL));
   EXPECT_EQ(ERR_IO_PENDING, stream->SendRequest(NULL, &response, &callback));
 
   // Need to manually remove the flip session since normally it gets removed on