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

11 files changed, 132 insertions, 56 deletions

diff --git a/net/http/http_basic_stream.cc b/net/http/http_basic_stream.cc
index 433b08e..64352c4 100644
--- a/net/http/http_basic_stream.cc
+++ b/net/http/http_basic_stream.cc
@@ -43,9 +43,9 @@ int HttpBasicStream::SendRequest(const HttpRequestHeaders& headers,
                            HttpUtil::PathForRequest(request_info_->url);
   request_line_ = base::StringPrintf("%s %s HTTP/1.1\r\n",
                                      request_info_->method.c_str(),
-                                     path.c_str()) + headers.ToString();
-
-  return parser_->SendRequest(request_line_, request_body, response, callback);
+                                     path.c_str());
+  return parser_->SendRequest(request_line_, headers, request_body, response,
+                              callback);
 }
 
 HttpBasicStream::~HttpBasicStream() {}
diff --git a/net/http/http_net_log_params.h b/net/http/http_net_log_params.h
index 403b6a7..6a0b47b 100644
--- a/net/http/http_net_log_params.h
+++ b/net/http/http_net_log_params.h
@@ -30,6 +30,10 @@ class NetLogHttpRequestParameter : public NetLog::EventParameters {
     return headers_;
   }
 
+  const std::string& GetLine() const {
+    return line_;
+  }
+
  private:
   virtual ~NetLogHttpRequestParameter();
 
diff --git a/net/http/http_network_transaction.cc b/net/http/http_network_transaction.cc
index bc2d322..7cbbc9bf 100644
--- a/net/http/http_network_transaction.cc
+++ b/net/http/http_network_transaction.cc
@@ -635,12 +635,6 @@ int HttpNetworkTransaction::DoSendRequest() {
     if (session_->network_delegate())
       session_->network_delegate()->OnSendHttpRequest(&request_headers_);
   }
-  if (net_log_.IsLoggingAllEvents()) {
-    net_log_.AddEvent(
-        NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST_HEADERS,
-        make_scoped_refptr(new NetLogHttpRequestParameter(
-            request_->url.spec(), request_->extra_headers)));
-  }
 
   headers_valid_ = false;
   return stream_->SendRequest(request_headers_, request_body, &response_,
diff --git a/net/http/http_network_transaction_unittest.cc b/net/http/http_network_transaction_unittest.cc
index b060d7c..e328031 100644
--- a/net/http/http_network_transaction_unittest.cc
+++ b/net/http/http_network_transaction_unittest.cc
@@ -28,6 +28,7 @@
 #include "net/http/http_auth_handler_mock.h"
 #include "net/http/http_auth_handler_ntlm.h"
 #include "net/http/http_basic_stream.h"
+#include "net/http/http_net_log_params.h"
 #include "net/http/http_network_session.h"
 #include "net/http/http_network_session_peer.h"
 #include "net/http/http_stream.h"
@@ -156,6 +157,7 @@ class HttpNetworkTransactionTest : public PlatformTest {
     TestCompletionCallback callback;
 
     CapturingBoundNetLog log(CapturingNetLog::kUnbounded);
+    EXPECT_TRUE(log.bound().IsLoggingAllEvents());
     int rv = trans->Start(&request, &callback, log.bound());
     EXPECT_EQ(ERR_IO_PENDING, rv);
 
@@ -179,6 +181,14 @@ class HttpNetworkTransactionTest : public PlatformTest {
         NetLog::TYPE_HTTP_TRANSACTION_READ_RESPONSE_HEADERS,
         NetLog::PHASE_NONE);
 
+    CapturingNetLog::Entry entry = log.entries()[pos];
+    NetLogHttpRequestParameter* request_params =
+        static_cast<NetLogHttpRequestParameter*>(entry.extra_parameters.get());
+    EXPECT_EQ("GET / HTTP/1.1\r\n", request_params->GetLine());
+    EXPECT_EQ("Host: www.google.com\r\n"
+              "Connection: keep-alive\r\n\r\n",
+              request_params->GetHeaders().ToString());
+
     return out;
   }
 
diff --git a/net/http/http_proxy_client_socket.cc b/net/http/http_proxy_client_socket.cc
index 186b459..1e6b713 100644
--- a/net/http/http_proxy_client_socket.cc
+++ b/net/http/http_proxy_client_socket.cc
@@ -132,7 +132,8 @@ int HttpProxyClientSocket::DidDrainBodyForAuthRestart(bool keep_alive) {
   drain_buf_ = NULL;
   parser_buf_ = NULL;
   http_stream_parser_.reset();
-  request_headers_.clear();
+  request_line_.clear();
+  request_headers_.Clear();
   response_ = HttpResponseInfo();
   return OK;
 }
@@ -332,28 +333,25 @@ int HttpProxyClientSocket::DoSendRequest() {
 
   // This is constructed lazily (instead of within our Start method), so that
   // we have proxy info available.
-  if (request_headers_.empty()) {
+  if (request_line_.empty()) {
+    DCHECK(request_headers_.IsEmpty());
     HttpRequestHeaders authorization_headers;
     if (auth_->HaveAuth())
       auth_->AddAuthorizationHeader(&authorization_headers);
-    std::string request_line;
-    HttpRequestHeaders request_headers;
     BuildTunnelRequest(request_, authorization_headers, endpoint_,
-                       &request_line, &request_headers);
+                       &request_line_, &request_headers_);
     if (net_log_.IsLoggingAllEvents()) {
       net_log_.AddEvent(
           NetLog::TYPE_HTTP_TRANSACTION_SEND_TUNNEL_HEADERS,
           make_scoped_refptr(new NetLogHttpRequestParameter(
-              request_line, request_headers)));
+              request_line_, request_headers_)));
     }
-    request_headers_ = request_line + request_headers.ToString();
   }
 
-
   parser_buf_ = new GrowableIOBuffer();
   http_stream_parser_.reset(
       new HttpStreamParser(transport_.get(), &request_, parser_buf_, net_log_));
-  return http_stream_parser_->SendRequest(request_headers_, NULL,
+  return http_stream_parser_->SendRequest(request_line_, request_headers_, NULL,
                                           &response_, &io_callback_);
 }
 
diff --git a/net/http/http_proxy_client_socket.h b/net/http/http_proxy_client_socket.h
index b42c78b..e11e731 100644
--- a/net/http/http_proxy_client_socket.h
+++ b/net/http/http_proxy_client_socket.h
@@ -156,7 +156,8 @@ class HttpProxyClientSocket : public ClientSocket {
   // If true, then the connection to the proxy is a SPDY connection.
   const bool using_spdy_;
 
-  std::string request_headers_;
+  std::string request_line_;
+  HttpRequestHeaders request_headers_;
 
   const BoundNetLog net_log_;
 
diff --git a/net/http/http_stream_parser.cc b/net/http/http_stream_parser.cc
index d3e4abd..2a3fb15 100644
--- a/net/http/http_stream_parser.cc
+++ b/net/http/http_stream_parser.cc
@@ -9,6 +9,8 @@
 #include "net/base/auth.h"
 #include "net/base/io_buffer.h"
 #include "net/base/ssl_cert_request_info.h"
+#include "net/http/http_net_log_params.h"
+#include "net/http/http_request_headers.h"
 #include "net/http/http_request_info.h"
 #include "net/http/http_response_headers.h"
 #include "net/http/http_util.h"
@@ -43,7 +45,8 @@ HttpStreamParser::HttpStreamParser(ClientSocketHandle* connection,
 
 HttpStreamParser::~HttpStreamParser() {}
 
-int HttpStreamParser::SendRequest(const std::string& headers,
+int HttpStreamParser::SendRequest(const std::string& request_line,
+                                  const HttpRequestHeaders& headers,
                                   UploadDataStream* request_body,
                                   HttpResponseInfo* response,
                                   CompletionCallback* callback) {
@@ -52,8 +55,15 @@ int HttpStreamParser::SendRequest(const std::string& headers,
   DCHECK(callback);
   DCHECK(response);
 
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.AddEvent(
+        NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST_HEADERS,
+        make_scoped_refptr(new NetLogHttpRequestParameter(
+            request_line, headers)));
+  }
   response_ = response;
-  scoped_refptr<StringIOBuffer> headers_io_buf(new StringIOBuffer(headers));
+  std::string request = request_line + headers.ToString();
+  scoped_refptr<StringIOBuffer> headers_io_buf(new StringIOBuffer(request));
   request_headers_ = new DrainableIOBuffer(headers_io_buf,
                                            headers_io_buf->size());
   request_body_.reset(request_body);
diff --git a/net/http/http_stream_parser.h b/net/http/http_stream_parser.h
index a1dda07..bbd551f 100644
--- a/net/http/http_stream_parser.h
+++ b/net/http/http_stream_parser.h
@@ -20,6 +20,7 @@ class ClientSocketHandle;
 class DrainableIOBuffer;
 class GrowableIOBuffer;
 struct HttpRequestInfo;
+class HttpRequestHeaders;
 class HttpResponseInfo;
 class IOBuffer;
 class SSLCertRequestInfo;
@@ -40,7 +41,9 @@ class HttpStreamParser {
 
   // These functions implement the interface described in HttpStream with
   // some additional functionality
-  int SendRequest(const std::string& headers, UploadDataStream* request_body,
+  int SendRequest(const std::string& request_line,
+                  const HttpRequestHeaders& headers,
+                  UploadDataStream* request_body,
                   HttpResponseInfo* response, CompletionCallback* callback);
 
   int ReadResponseHeaders(CompletionCallback* callback);
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_