Include SSL plaintext traffic in addition to the ciphertext when logging raw bytes to a NetLog

R=eroman,mmenke
BUG=82562
TEST=net_unittests SSLClientSocketTest.Read_FullLogging


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

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

6 files changed, 93 insertions, 11 deletions

diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index 7d8817c..8d7b20a 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -405,6 +405,7 @@ EVENT_TYPE(SSL_NSS_ERROR)
 //                           Only present when byte logging is enabled>,
 //   }
 EVENT_TYPE(SOCKET_BYTES_SENT)
+EVENT_TYPE(SSL_SOCKET_BYTES_SENT)
 
 // The specified number of bytes were received on the socket.
 // The following parameters are attached:
@@ -414,6 +415,7 @@ EVENT_TYPE(SOCKET_BYTES_SENT)
 //                           Only present when byte logging is enabled>,
 //   }
 EVENT_TYPE(SOCKET_BYTES_RECEIVED)
+EVENT_TYPE(SSL_SOCKET_BYTES_RECEIVED)
 
 // ------------------------------------------------------------------------
 // ClientSocketPoolBase::ConnectJob
diff --git a/net/socket/ssl_client_socket_mac.cc b/net/socket/ssl_client_socket_mac.cc
index 8a5fed9..2c74eaa 100644
--- a/net/socket/ssl_client_socket_mac.cc
+++ b/net/socket/ssl_client_socket_mac.cc
@@ -1194,8 +1194,11 @@ int SSLClientSocketMac::DoPayloadRead() {
   // transparent renegotiation, so that we can update our state machine above,
   // which otherwise would get out of sync with the SSLContextRef's internal
   // state machine.
-  if (processed > 0)
+  if (processed > 0) {
+    LogByteTransfer(net_log_, NetLog::TYPE_SSL_SOCKET_BYTES_RECEIVED,
+                    processed, user_read_buf_->data());
     return processed;
+  }
 
   switch (status) {
     case errSSLClosedNoNotify:
@@ -1220,8 +1223,11 @@ int SSLClientSocketMac::DoPayloadWrite() {
                              user_write_buf_len_,
                              &processed);
 
-  if (processed > 0)
+  if (processed > 0) {
+    LogByteTransfer(net_log_, NetLog::TYPE_SSL_SOCKET_BYTES_SENT, processed,
+                    user_write_buf_->data());
     return processed;
+  }
 
   return NetErrorFromOSStatus(status);
 }
diff --git a/net/socket/ssl_client_socket_nss.cc b/net/socket/ssl_client_socket_nss.cc
index c372b94..8b88bcd 100644
--- a/net/socket/ssl_client_socket_nss.cc
+++ b/net/socket/ssl_client_socket_nss.cc
@@ -183,7 +183,6 @@ namespace net {
 #define EnterFunction(x)
 #define LeaveFunction(x)
 #define GotoState(s) next_handshake_state_ = s
-#define LogData(s, len)
 #else
 #define EnterFunction(x)\
     VLOG(1) << (void *)this << " " << __FUNCTION__ << " enter " << x\
@@ -196,9 +195,6 @@ namespace net {
       VLOG(1) << (void *)this << " " << __FUNCTION__ << " jump to state " << s;\
       next_handshake_state_ = s;\
     } while (0)
-#define LogData(s, len)\
-    VLOG(1) << (void *)this << " " << __FUNCTION__\
-            << " data [" << std::string(s, len) << "]"
 #endif
 
 namespace {
@@ -1625,7 +1621,8 @@ int SSLClientSocketNSS::DoPayloadRead() {
     return rv;
   }
   if (rv >= 0) {
-    LogData(user_read_buf_->data(), rv);
+    LogByteTransfer(net_log_, NetLog::TYPE_SSL_SOCKET_BYTES_RECEIVED, rv,
+                    user_read_buf_->data());
     LeaveFunction("");
     return rv;
   }
@@ -1646,7 +1643,8 @@ int SSLClientSocketNSS::DoPayloadWrite() {
   DCHECK(user_write_buf_);
   int rv = PR_Write(nss_fd_, user_write_buf_->data(), user_write_buf_len_);
   if (rv >= 0) {
-    LogData(user_write_buf_->data(), rv);
+    LogByteTransfer(net_log_, NetLog::TYPE_SSL_SOCKET_BYTES_SENT, rv,
+                    user_write_buf_->data());
     LeaveFunction("");
     return rv;
   }
diff --git a/net/socket/ssl_client_socket_openssl.cc b/net/socket/ssl_client_socket_openssl.cc
index 156304f..b8ca22d 100644
--- a/net/socket/ssl_client_socket_openssl.cc
+++ b/net/socket/ssl_client_socket_openssl.cc
@@ -1176,8 +1176,11 @@ int SSLClientSocketOpenSSL::DoPayloadRead() {
   if (client_auth_cert_needed_)
     return ERR_SSL_CLIENT_AUTH_CERT_NEEDED;
 
-  if (rv >= 0)
+  if (rv >= 0) {
+    LogByteTransfer(net_log_, NetLog::TYPE_SSL_SOCKET_BYTES_RECEIVED, rv,
+                    user_read_buf_->data());
     return rv;
+  }
 
   int err = SSL_get_error(ssl_, rv);
   return MapOpenSSLError(err, err_tracer);
@@ -1187,8 +1190,11 @@ int SSLClientSocketOpenSSL::DoPayloadWrite() {
   crypto::OpenSSLErrStackTracer err_tracer(FROM_HERE);
   int rv = SSL_write(ssl_, user_write_buf_->data(), user_write_buf_len_);
 
-  if (rv >= 0)
+  if (rv >= 0) {
+    LogByteTransfer(net_log_, NetLog::TYPE_SSL_SOCKET_BYTES_SENT, rv,
+                    user_read_buf_->data());
     return rv;
+  }
 
   int err = SSL_get_error(ssl_, rv);
   return MapOpenSSLError(err, err_tracer);
diff --git a/net/socket/ssl_client_socket_unittest.cc b/net/socket/ssl_client_socket_unittest.cc
index f436512..49c9191 100644
--- a/net/socket/ssl_client_socket_unittest.cc
+++ b/net/socket/ssl_client_socket_unittest.cc
@@ -1,4 +1,4 @@
-// Copyright (c) 2010 The Chromium Authors. All rights reserved.
+// Copyright (c) 2011 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.
 
@@ -511,6 +511,70 @@ TEST_F(SSLClientSocketTest, Read_Interrupted) {
   EXPECT_GT(rv, 0);
 }
 
+TEST_F(SSLClientSocketTest, Read_FullLogging) {
+  net::TestServer test_server(net::TestServer::TYPE_HTTPS, FilePath());
+  ASSERT_TRUE(test_server.Start());
+
+  net::AddressList addr;
+  ASSERT_TRUE(test_server.GetAddressList(&addr));
+
+  TestCompletionCallback callback;
+  net::CapturingNetLog log(net::CapturingNetLog::kUnbounded);
+  log.SetLogLevel(net::NetLog::LOG_ALL);
+  net::StreamSocket* transport = new net::TCPClientSocket(
+      addr, &log, net::NetLog::Source());
+  int rv = transport->Connect(&callback);
+  if (rv == net::ERR_IO_PENDING)
+    rv = callback.WaitForResult();
+  EXPECT_EQ(net::OK, rv);
+
+  scoped_ptr<net::SSLClientSocket> sock(
+      CreateSSLClientSocket(transport, test_server.host_port_pair(),
+                            kDefaultSSLConfig));
+
+  rv = sock->Connect(&callback);
+  if (rv == net::ERR_IO_PENDING)
+    rv = callback.WaitForResult();
+  EXPECT_EQ(net::OK, rv);
+  EXPECT_TRUE(sock->IsConnected());
+
+  const char request_text[] = "GET / HTTP/1.0\r\n\r\n";
+  scoped_refptr<net::IOBuffer> request_buffer(
+      new net::IOBuffer(arraysize(request_text) - 1));
+  memcpy(request_buffer->data(), request_text, arraysize(request_text) - 1);
+
+  rv = sock->Write(request_buffer, arraysize(request_text) - 1, &callback);
+  EXPECT_TRUE(rv >= 0 || rv == net::ERR_IO_PENDING);
+
+  if (rv == net::ERR_IO_PENDING)
+    rv = callback.WaitForResult();
+  EXPECT_EQ(static_cast<int>(arraysize(request_text) - 1), rv);
+
+  net::CapturingNetLog::EntryList entries;
+  log.GetEntries(&entries);
+  size_t last_index = net::ExpectLogContainsSomewhereAfter(
+      entries, 5, net::NetLog::TYPE_SSL_SOCKET_BYTES_SENT,
+      net::NetLog::PHASE_NONE);
+
+  scoped_refptr<net::IOBuffer> buf(new net::IOBuffer(4096));
+  for (;;) {
+    rv = sock->Read(buf, 4096, &callback);
+    EXPECT_TRUE(rv >= 0 || rv == net::ERR_IO_PENDING);
+
+    if (rv == net::ERR_IO_PENDING)
+      rv = callback.WaitForResult();
+
+    EXPECT_GE(rv, 0);
+    if (rv <= 0)
+      break;
+
+    log.GetEntries(&entries);
+    last_index = net::ExpectLogContainsSomewhereAfter(
+        entries, last_index + 1, net::NetLog::TYPE_SSL_SOCKET_BYTES_RECEIVED,
+        net::NetLog::PHASE_NONE);
+  }
+}
+
 // Regression test for http://crbug.com/42538
 TEST_F(SSLClientSocketTest, PrematureApplicationData) {
   net::TestServer test_server(net::TestServer::TYPE_HTTPS, FilePath());
diff --git a/net/socket/ssl_client_socket_win.cc b/net/socket/ssl_client_socket_win.cc
index be8adea..9aea199 100644
--- a/net/socket/ssl_client_socket_win.cc
+++ b/net/socket/ssl_client_socket_win.cc
@@ -740,6 +740,8 @@ int SSLClientSocketWin::Read(IOBuffer* buf, int buf_len,
   // reading more ciphertext from the transport socket.
   if (bytes_decrypted_ != 0) {
     int len = std::min(buf_len, bytes_decrypted_);
+    LogByteTransfer(net_log_, NetLog::TYPE_SSL_SOCKET_BYTES_RECEIVED, len,
+                    decrypted_ptr_);
     memcpy(buf->data(), decrypted_ptr_, len);
     decrypted_ptr_ += len;
     bytes_decrypted_ -= len;
@@ -1359,6 +1361,8 @@ int SSLClientSocketWin::DoPayloadDecrypt() {
   // mistaken for EOF.  Continue decrypting or read more.
   if (len == 0)
     return DoPayloadRead();
+  LogByteTransfer(net_log_, NetLog::TYPE_SSL_SOCKET_BYTES_RECEIVED, len,
+                  user_read_buf_->data());
   return len;
 }
 
@@ -1376,6 +1380,8 @@ int SSLClientSocketWin::DoPayloadEncrypt() {
   payload_send_buffer_.reset(new char[alloc_len]);
   memcpy(&payload_send_buffer_[stream_sizes_.cbHeader],
          user_write_buf_->data(), message_len);
+  LogByteTransfer(net_log_, NetLog::TYPE_SSL_SOCKET_BYTES_SENT, message_len,
+                  user_write_buf_->data());
 
   SecBuffer buffers[4];
   buffers[0].pvBuffer = payload_send_buffer_.get();