Change the way request headers are logged to the NetLog to ensure

that the complete request is logged, not just the extra_headers.
Before I broke things, HttpNetworkTransaction was attempting to 
do the logging, but after some refactors it no longer has access
to the final request.  SpdySession already logs correctly in the 
SPDY case, and I modified HttpBasicStream to log in the HTTP case.

Added unit tests is both HttpNetworkTransactionTest and 
SpdyNetworkTransactionTest.

BUG=48962
TEST=net_unittests --gtest_filter=HttpNetworkTransactionTest.SimpleGET\*

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

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

3 files changed, 90 insertions, 34 deletions

diff --git a/net/spdy/spdy_network_transaction_unittest.cc b/net/spdy/spdy_network_transaction_unittest.cc
index d72a2a7..1aaf657 100644
--- a/net/spdy/spdy_network_transaction_unittest.cc
+++ b/net/spdy/spdy_network_transaction_unittest.cc
@@ -324,6 +324,17 @@ class SpdyNetworkTransactionTest
     return google_get_request_;
   }
 
+  const HttpRequestInfo& CreateGetRequestWithUserAgent() {
+    if (!google_get_request_initialized_) {
+      google_get_request_.method = "GET";
+      google_get_request_.url = GURL(kDefaultURL);
+      google_get_request_.load_flags = 0;
+      google_get_request_.extra_headers.SetHeader("User-Agent", "Chrome");
+      google_get_request_initialized_ = true;
+    }
+    return google_get_request_;
+  }
+
   const HttpRequestInfo& CreatePostRequest() {
     if (!google_post_request_initialized_) {
       google_post_request_.method = "POST";
@@ -3300,7 +3311,11 @@ TEST_P(SpdyNetworkTransactionTest, DecompressFailureOnSynReply) {
 
 // Test that the NetLog contains good data for a simple GET request.
 TEST_P(SpdyNetworkTransactionTest, NetLog) {
-  scoped_ptr<spdy::SpdyFrame> req(ConstructSpdyGet(NULL, 0, false, 1, LOWEST));
+  static const char* const kExtraHeaders[] = {
+    "user-agent",   "Chrome",
+  };
+  scoped_ptr<spdy::SpdyFrame> req(ConstructSpdyGet(kExtraHeaders, 1, false, 1,
+                                                   LOWEST));
   MockWrite writes[] = { CreateMockWrite(*req) };
 
   scoped_ptr<spdy::SpdyFrame> resp(ConstructSpdyGetSynReply(NULL, 0, 1));
@@ -3316,7 +3331,7 @@ TEST_P(SpdyNetworkTransactionTest, NetLog) {
   scoped_refptr<DelayedSocketData> data(
       new DelayedSocketData(1, reads, arraysize(reads),
                             writes, arraysize(writes)));
-  NormalSpdyTransactionHelper helper(CreateGetRequest(),
+  NormalSpdyTransactionHelper helper(CreateGetRequestWithUserAgent(),
                                      log.bound(), GetParam());
   helper.RunToCompletion(data.get());
   TransactionHelperResult out = helper.output();
@@ -3348,6 +3363,32 @@ TEST_P(SpdyNetworkTransactionTest, NetLog) {
   pos = net::ExpectLogContainsSomewhere(log.entries(), pos + 1,
       net::NetLog::TYPE_HTTP_TRANSACTION_READ_BODY,
       net::NetLog::PHASE_END);
+
+  // Check that we logged all the headers correctly
+  pos = net::ExpectLogContainsSomewhere(
+      log.entries(), 0,
+      net::NetLog::TYPE_SPDY_SESSION_SYN_STREAM,
+      net::NetLog::PHASE_NONE);
+  CapturingNetLog::Entry entry = log.entries()[pos];
+  NetLogSpdySynParameter* request_params =
+      static_cast<NetLogSpdySynParameter*>(entry.extra_parameters.get());
+  spdy::SpdyHeaderBlock* headers =
+      request_params->GetHeaders().get();
+
+  spdy::SpdyHeaderBlock expected;
+  expected["host"] = "www.google.com";
+  expected["url"] = "/";
+  expected["scheme"] = "http";
+  expected["version"] = "HTTP/1.1";
+  expected["method"] = "GET";
+  expected["user-agent"] = "Chrome";
+  EXPECT_EQ(expected.size(), headers->size());
+  spdy::SpdyHeaderBlock::const_iterator end = expected.end();
+  for (spdy::SpdyHeaderBlock::const_iterator it = expected.begin();
+      it != end;
+      ++it) {
+    EXPECT_EQ(it->second, (*headers)[it->first]);
+  }
 }
 
 // Since we buffer the IO from the stream to the renderer, this test verifies
diff --git a/net/spdy/spdy_session.cc b/net/spdy/spdy_session.cc
index 7035bb8..472e3ae 100644
--- a/net/spdy/spdy_session.cc
+++ b/net/spdy/spdy_session.cc
@@ -28,6 +28,30 @@
 
 namespace net {
 
+NetLogSpdySynParameter::NetLogSpdySynParameter(
+    const linked_ptr<spdy::SpdyHeaderBlock>& headers,
+    spdy::SpdyControlFlags flags,
+    spdy::SpdyStreamId id)
+    : headers_(headers), flags_(flags), id_(id) {
+}
+
+NetLogSpdySynParameter::~NetLogSpdySynParameter() {
+}
+
+Value* NetLogSpdySynParameter::ToValue() const {
+  DictionaryValue* dict = new DictionaryValue();
+  ListValue* headers_list = new ListValue();
+  for (spdy::SpdyHeaderBlock::const_iterator it = headers_->begin();
+      it != headers_->end(); ++it) {
+    headers_list->Append(new StringValue(base::StringPrintf(
+        "%s: %s", it->first.c_str(), it->second.c_str())));
+  }
+  dict->SetInteger("flags", flags_);
+  dict->Set("headers", headers_list);
+  dict->SetInteger("id", id_);
+  return dict;
+}
+
 namespace {
 
 const int kReadBufferSize = 8 * 1024;
@@ -58,43 +82,12 @@ class NetLogSpdySessionParameter : public NetLog::EventParameters {
   DISALLOW_COPY_AND_ASSIGN(NetLogSpdySessionParameter);
 };
 
-class NetLogSpdySynParameter : public NetLog::EventParameters {
- public:
-  NetLogSpdySynParameter(const linked_ptr<spdy::SpdyHeaderBlock>& headers,
-                         spdy::SpdyControlFlags flags,
-                         spdy::SpdyStreamId id)
-      : headers_(headers), flags_(flags), id_(id) {}
-
-  Value* ToValue() const {
-    DictionaryValue* dict = new DictionaryValue();
-    ListValue* headers_list = new ListValue();
-    for (spdy::SpdyHeaderBlock::const_iterator it = headers_->begin();
-         it != headers_->end(); ++it) {
-      headers_list->Append(new StringValue(base::StringPrintf(
-          "%s: %s", it->first.c_str(), it->second.c_str())));
-    }
-    dict->SetInteger("flags", flags_);
-    dict->Set("headers", headers_list);
-    dict->SetInteger("id", id_);
-    return dict;
-  }
-
- private:
-  ~NetLogSpdySynParameter() {}
-
-  const linked_ptr<spdy::SpdyHeaderBlock> headers_;
-  const spdy::SpdyControlFlags flags_;
-  const spdy::SpdyStreamId id_;
-
-  DISALLOW_COPY_AND_ASSIGN(NetLogSpdySynParameter);
-};
-
 class NetLogSpdySettingsParameter : public NetLog::EventParameters {
  public:
   explicit NetLogSpdySettingsParameter(const spdy::SpdySettings& settings)
       : settings_(settings) {}
 
-  Value* ToValue() const {
+  virtual Value* ToValue() const {
     DictionaryValue* dict = new DictionaryValue();
     ListValue* settings = new ListValue();
     for (spdy::SpdySettings::const_iterator it = settings_.begin();
diff --git a/net/spdy/spdy_session.h b/net/spdy/spdy_session.h
index 7d12d50..24c8e42 100644
--- a/net/spdy/spdy_session.h
+++ b/net/spdy/spdy_session.h
@@ -411,6 +411,28 @@ class SpdySession : public base::RefCounted<SpdySession>,
   static size_t max_concurrent_stream_limit_;
 };
 
+class NetLogSpdySynParameter : public NetLog::EventParameters {
+ public:
+  NetLogSpdySynParameter(const linked_ptr<spdy::SpdyHeaderBlock>& headers,
+                         spdy::SpdyControlFlags flags,
+                         spdy::SpdyStreamId id);
+
+  virtual Value* ToValue() const;
+
+  const linked_ptr<spdy::SpdyHeaderBlock>& GetHeaders() const {
+    return headers_;
+  }
+
+ private:
+  virtual ~NetLogSpdySynParameter();
+
+  const linked_ptr<spdy::SpdyHeaderBlock> headers_;
+  const spdy::SpdyControlFlags flags_;
+  const spdy::SpdyStreamId id_;
+
+  DISALLOW_COPY_AND_ASSIGN(NetLogSpdySynParameter);
+};
+
 }  // namespace net
 
 #endif  // NET_SPDY_SPDY_SESSION_H_