FTP: add net-internals logging.

net/ftp/ftp_network_transaction.cc

 // Copyright (c) 2012 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.
 
 #include "net/ftp/ftp_network_transaction.h"
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/compiler_specific.h"
 #include "base/metrics/histogram.h"
 #include "base/string_number_conversions.h"
 #include "base/string_split.h"
 #include "base/string_util.h"
 #include "base/utf_string_conversions.h"
+#include "base/values.h"
 #include "net/base/address_list.h"
 #include "net/base/connection_type_histograms.h"
 #include "net/base/escape.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_log.h"
 #include "net/base/net_util.h"
 #include "net/ftp/ftp_network_session.h"
 #include "net/ftp/ftp_request_info.h"
 #include "net/ftp/ftp_util.h"
 #include "net/socket/client_socket_factory.h"
@@ skipping 180 matching lines @@
     FtpNetworkSession* session,
     ClientSocketFactory* socket_factory)
     : command_sent_(COMMAND_NONE),
       ALLOW_THIS_IN_INITIALIZER_LIST(
           io_callback_(base::Bind(&FtpNetworkTransaction::OnIOComplete,
                                   base::Unretained(this)))),
       session_(session),
       request_(NULL),
       resolver_(session->host_resolver()),
       read_ctrl_buf_(new IOBuffer(kCtrlBufLen)),
-      ctrl_response_buffer_(new FtpCtrlResponseBuffer()),
+      ctrl_response_buffer_(NULL),
       read_data_buf_len_(0),
       last_error_(OK),
       system_type_(SYSTEM_TYPE_UNKNOWN),
       // Use image (binary) transfer by default. It should always work,
       // whereas the ascii transfer may damage binary data.
       data_type_(DATA_TYPE_IMAGE),
       resource_type_(RESOURCE_TYPE_UNKNOWN),
       use_epsv_(true),
       data_connection_port_(0),
       socket_factory_(socket_factory),
@@ skipping 16 matching lines @@
     const CompletionCallback& callback) {
   return ERR_NOT_IMPLEMENTED;
 }
 
 int FtpNetworkTransaction::Start(const FtpRequestInfo* request_info,
                                  const CompletionCallback& callback,
                                  const BoundNetLog& net_log) {
   net_log_ = net_log;
   request_ = request_info;
 
+  ctrl_response_buffer_.reset(new FtpCtrlResponseBuffer(net_log_));
+
   if (request_->url.has_username()) {
     string16 username;
     string16 password;
     GetIdentityFromURL(request_->url, &username, &password);
     credentials_.Set(username, password);
   } else {
     credentials_.Set(ASCIIToUTF16("anonymous"),
                      ASCIIToUTF16("chrome@example.com"));
   }
 
@@ skipping 64 matching lines @@
 
 uint64 FtpNetworkTransaction::GetUploadProgress() const {
   return 0;
 }
 
 void FtpNetworkTransaction::ResetStateForRestart() {
   command_sent_ = COMMAND_NONE;
   user_callback_.Reset();
   response_ = FtpResponseInfo();
   read_ctrl_buf_ = new IOBuffer(kCtrlBufLen);
-  ctrl_response_buffer_.reset(new FtpCtrlResponseBuffer());
+  ctrl_response_buffer_.reset();
   read_data_buf_ = NULL;
   read_data_buf_len_ = 0;
   if (write_buf_)
     write_buf_->SetOffset(0);
   last_error_ = OK;
   data_connection_port_ = 0;
   ctrl_socket_.reset();
   data_socket_.reset();
   next_state_ = STATE_NONE;
 }
@@ skipping 80 matching lines @@
         // Multiple responses for other commands are invalid.
         return Stop(ERR_INVALID_RESPONSE);
     }
   }
 
   return rv;
 }
 
 // Used to prepare and send FTP command.
 int FtpNetworkTransaction::SendFtpCommand(const std::string& command,
+                                          const std::string& command_for_log,
                                           Command cmd) {
   // If we send a new command when we still have unprocessed responses
   // for previous commands, the response receiving code will have no way to know
   // which responses are for which command.
   DCHECK(!ctrl_response_buffer_->ResponseAvailable());
 
   DCHECK(!write_command_buf_);
   DCHECK(!write_buf_);
 
   if (!IsValidFTPCommandString(command)) {
     // Callers should validate the command themselves and return a more specific
     // error code.
     NOTREACHED();
     return Stop(ERR_UNEXPECTED);
   }
 
   command_sent_ = cmd;
 
   write_command_buf_ = new IOBufferWithSize(command.length() + 2);
   write_buf_ = new DrainableIOBuffer(write_command_buf_,
                                      write_command_buf_->size());
   memcpy(write_command_buf_->data(), command.data(), command.length());
   memcpy(write_command_buf_->data() + command.length(), kCRLF, 2);
 
+  net_log_.AddEvent(NetLog::TYPE_FTP_COMMAND_SENT,
+                    NetLog::StringCallback("command", &command_for_log));
+
   next_state_ = STATE_CTRL_WRITE;
   return OK;
 }
 
 std::string FtpNetworkTransaction::GetRequestPathForFtpCommand(
     bool is_directory) const {
   std::string path(current_remote_directory_);
   if (request_->url.has_path()) {
     std::string gurl_path(request_->url.path());
 
@@ skipping 167 matching lines @@
 int FtpNetworkTransaction::DoCtrlResolveHostComplete(int result) {
   if (result == OK)
     next_state_ = STATE_CTRL_CONNECT;
   return result;
 }
 
 int FtpNetworkTransaction::DoCtrlConnect() {
   next_state_ = STATE_CTRL_CONNECT_COMPLETE;
   ctrl_socket_.reset(socket_factory_->CreateTransportClientSocket(
         addresses_, net_log_.net_log(), net_log_.source()));
+  net_log_.AddEvent(
+      NetLog::TYPE_FTP_CONTROL_CONNECTION,
+      ctrl_socket_->NetLog().source().ToEventParametersCallback());
   return ctrl_socket_->Connect(io_callback_);
 }
 
 int FtpNetworkTransaction::DoCtrlConnectComplete(int result) {
   if (result == OK) {
     // Put the peer's IP address and port into the response.
     IPEndPoint ip_endpoint;
     result = ctrl_socket_->GetPeerAddress(&ip_endpoint);
     if (result == OK) {
       response_.socket_address = HostPortPair::FromIPEndPoint(ip_endpoint);
@@ skipping 61 matching lines @@
 // FTP Commands and responses
 
 // USER Command.
 int FtpNetworkTransaction::DoCtrlWriteUSER() {
   std::string command = "USER " + UTF16ToUTF8(credentials_.username());
 
   if (!IsValidFTPCommandString(command))
     return Stop(ERR_MALFORMED_IDENTITY);
 
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_USER);
+  return SendFtpCommand(command, "USER ***", COMMAND_USER);
 }
 
 int FtpNetworkTransaction::ProcessResponseUSER(
     const FtpCtrlResponse& response) {
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_OK:
       next_state_ = STATE_CTRL_WRITE_SYST;
       break;
     case ERROR_CLASS_INFO_NEEDED:
       next_state_ = STATE_CTRL_WRITE_PASS;
@@ skipping 10 matching lines @@
 }
 
 // PASS command.
 int FtpNetworkTransaction::DoCtrlWritePASS() {
   std::string command = "PASS " + UTF16ToUTF8(credentials_.password());
 
   if (!IsValidFTPCommandString(command))
     return Stop(ERR_MALFORMED_IDENTITY);
 
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_PASS);
+  return SendFtpCommand(command, "PASS ***", COMMAND_PASS);
 }
 
 int FtpNetworkTransaction::ProcessResponsePASS(
     const FtpCtrlResponse& response) {
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_OK:
       next_state_ = STATE_CTRL_WRITE_SYST;
       break;
     case ERROR_CLASS_INFO_NEEDED:
       return Stop(GetNetErrorCodeForFtpResponseCode(response.status_code));
     case ERROR_CLASS_TRANSIENT_ERROR:
     case ERROR_CLASS_PERMANENT_ERROR:
       response_.needs_auth = true;
       return Stop(GetNetErrorCodeForFtpResponseCode(response.status_code));
     default:
       NOTREACHED();
       return Stop(ERR_UNEXPECTED);
   }
   return OK;
 }
 
 // SYST command.
 int FtpNetworkTransaction::DoCtrlWriteSYST() {
   std::string command = "SYST";
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_SYST);
+  return SendFtpCommand(command, command, COMMAND_SYST);
 }
 
 int FtpNetworkTransaction::ProcessResponseSYST(
     const FtpCtrlResponse& response) {
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_INITIATED:
       return Stop(ERR_INVALID_RESPONSE);
     case ERROR_CLASS_OK: {
       // All important info should be on the first line.
       std::string line = response.lines[0];
@@ skipping 32 matching lines @@
       NOTREACHED();
       return Stop(ERR_UNEXPECTED);
   }
   return OK;
 }
 
 // PWD command.
 int FtpNetworkTransaction::DoCtrlWritePWD() {
   std::string command = "PWD";
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_PWD);
+  return SendFtpCommand(command, command, COMMAND_PWD);
 }
 
 int FtpNetworkTransaction::ProcessResponsePWD(const FtpCtrlResponse& response) {
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_INITIATED:
       return Stop(ERR_INVALID_RESPONSE);
     case ERROR_CLASS_OK: {
       // The info we look for should be on the first line.
       std::string line = response.lines[0];
       if (line.empty())
@@ skipping 32 matching lines @@
   std::string command = "TYPE ";
   if (data_type_ == DATA_TYPE_ASCII) {
     command += "A";
   } else if (data_type_ == DATA_TYPE_IMAGE) {
     command += "I";
   } else {
     NOTREACHED();
     return Stop(ERR_UNEXPECTED);
   }
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_TYPE);
+  return SendFtpCommand(command, command, COMMAND_TYPE);
 }
 
 int FtpNetworkTransaction::ProcessResponseTYPE(
     const FtpCtrlResponse& response) {
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_INITIATED:
       return Stop(ERR_INVALID_RESPONSE);
     case ERROR_CLASS_OK:
       next_state_ = use_epsv_ ? STATE_CTRL_WRITE_EPSV : STATE_CTRL_WRITE_PASV;
       break;
     case ERROR_CLASS_INFO_NEEDED:
       return Stop(ERR_INVALID_RESPONSE);
     case ERROR_CLASS_TRANSIENT_ERROR:
       return Stop(GetNetErrorCodeForFtpResponseCode(response.status_code));
     case ERROR_CLASS_PERMANENT_ERROR:
       return Stop(GetNetErrorCodeForFtpResponseCode(response.status_code));
     default:
       NOTREACHED();
       return Stop(ERR_UNEXPECTED);
   }
   return OK;
 }
 
 // EPSV command
 int FtpNetworkTransaction::DoCtrlWriteEPSV() {
   const std::string command = "EPSV";
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_EPSV);
+  return SendFtpCommand(command, command, COMMAND_EPSV);
 }
 
 int FtpNetworkTransaction::ProcessResponseEPSV(
     const FtpCtrlResponse& response) {
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_INITIATED:
       return Stop(ERR_INVALID_RESPONSE);
     case ERROR_CLASS_OK:
       if (!ExtractPortFromEPSVResponse( response, &data_connection_port_))
         return Stop(ERR_INVALID_RESPONSE);
@@ skipping 13 matching lines @@
       NOTREACHED();
       return Stop(ERR_UNEXPECTED);
   }
   return OK;
 }
 
 // PASV command
 int FtpNetworkTransaction::DoCtrlWritePASV() {
   std::string command = "PASV";
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_PASV);
+  return SendFtpCommand(command, command, COMMAND_PASV);
 }
 
 int FtpNetworkTransaction::ProcessResponsePASV(
     const FtpCtrlResponse& response) {
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_INITIATED:
       return Stop(ERR_INVALID_RESPONSE);
     case ERROR_CLASS_OK:
       if (!ExtractPortFromPASVResponse(response, &data_connection_port_))
         return Stop(ERR_INVALID_RESPONSE);
@@ skipping 12 matching lines @@
       NOTREACHED();
       return Stop(ERR_UNEXPECTED);
   }
   return OK;
 }
 
 // RETR command
 int FtpNetworkTransaction::DoCtrlWriteRETR() {
   std::string command = "RETR " + GetRequestPathForFtpCommand(false);
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_RETR);
+  return SendFtpCommand(command, command, COMMAND_RETR);
 }
 
 int FtpNetworkTransaction::ProcessResponseRETR(
     const FtpCtrlResponse& response) {
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_INITIATED:
       // We want the client to start reading the response at this point.
       // It got here either through Start or RestartWithAuth. We want that
       // method to complete. Not setting next state here will make DoLoop exit
       // and in turn make Start/RestartWithAuth complete.
@@ skipping 30 matching lines @@
   // an infinite loop (RETR can later send CWD, and CWD can later send RETR).
   DCHECK_NE(RESOURCE_TYPE_UNKNOWN, resource_type_);
 
   return OK;
 }
 
 // SIZE command
 int FtpNetworkTransaction::DoCtrlWriteSIZE() {
   std::string command = "SIZE " + GetRequestPathForFtpCommand(false);
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_SIZE);
+  return SendFtpCommand(command, command, COMMAND_SIZE);
 }
 
 int FtpNetworkTransaction::ProcessResponseSIZE(
     const FtpCtrlResponse& response) {
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_INITIATED:
       break;
     case ERROR_CLASS_OK:
       if (response.lines.size() != 1)
         return Stop(ERR_INVALID_RESPONSE);
@@ skipping 29 matching lines @@
   else
     next_state_ = STATE_CTRL_WRITE_CWD;
 
   return OK;
 }
 
 // CWD command
 int FtpNetworkTransaction::DoCtrlWriteCWD() {
   std::string command = "CWD " + GetRequestPathForFtpCommand(true);
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_CWD);
+  return SendFtpCommand(command, command, COMMAND_CWD);
 }
 
 int FtpNetworkTransaction::ProcessResponseCWD(const FtpCtrlResponse& response) {
   // We should never issue CWD if we know the target resource is a file.
   DCHECK_NE(RESOURCE_TYPE_FILE, resource_type_);
 
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_INITIATED:
       return Stop(ERR_INVALID_RESPONSE);
     case ERROR_CLASS_OK:
@@ skipping 35 matching lines @@
   resource_type_ = RESOURCE_TYPE_FILE;
   next_state_ = STATE_CTRL_WRITE_RETR;
 
   return OK;
 }
 
 // LIST command
 int FtpNetworkTransaction::DoCtrlWriteLIST() {
   std::string command(system_type_ == SYSTEM_TYPE_VMS ? "LIST *.*;0" : "LIST");
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_LIST);
+  return SendFtpCommand(command, command, COMMAND_LIST);
 }
 
 int FtpNetworkTransaction::ProcessResponseLIST(
     const FtpCtrlResponse& response) {
   switch (GetErrorClass(response.status_code)) {
     case ERROR_CLASS_INITIATED:
       // We want the client to start reading the response at this point.
       // It got here either through Start or RestartWithAuth. We want that
       // method to complete. Not setting next state here will make DoLoop exit
       // and in turn make Start/RestartWithAuth complete.
@@ skipping 13 matching lines @@
       NOTREACHED();
       return Stop(ERR_UNEXPECTED);
   }
   return OK;
 }
 
 // QUIT command
 int FtpNetworkTransaction::DoCtrlWriteQUIT() {
   std::string command = "QUIT";
   next_state_ = STATE_CTRL_READ;
-  return SendFtpCommand(command, COMMAND_QUIT);
+  return SendFtpCommand(command, command, COMMAND_QUIT);
 }
 
 int FtpNetworkTransaction::ProcessResponseQUIT(
     const FtpCtrlResponse& response) {
   ctrl_socket_->Disconnect();
   return last_error_;
 }
 
 // Data Connection
 
 int FtpNetworkTransaction::DoDataConnect() {
   next_state_ = STATE_DATA_CONNECT_COMPLETE;
   IPEndPoint ip_endpoint;
   AddressList data_address;
   // Connect to the same host as the control socket to prevent PASV port
   // scanning attacks.
   int rv = ctrl_socket_->GetPeerAddress(&ip_endpoint);
   if (rv != OK)
     return Stop(rv);
   data_address = AddressList::CreateFromIPAddress(
       ip_endpoint.address(), data_connection_port_);
   data_socket_.reset(socket_factory_->CreateTransportClientSocket(
         data_address, net_log_.net_log(), net_log_.source()));
+  net_log_.AddEvent(
+      NetLog::TYPE_FTP_DATA_CONNECTION,
+      data_socket_->NetLog().source().ToEventParametersCallback());
   return data_socket_->Connect(io_callback_);
 }
 
 int FtpNetworkTransaction::DoDataConnectComplete(int result) {
   if (result != OK && use_epsv_) {
     // It's possible we hit a broken server, sadly. They can break in different
     // ways. Some time out, some reset a connection. Fall back to PASV.
     // TODO(phajdan.jr): remember it for future transactions with this server.
     // TODO(phajdan.jr): write a test for this code path.
     use_epsv_ = false;
@@ skipping 123 matching lines @@
   if (!had_error_type[type]) {
     had_error_type[type] = true;
     UMA_HISTOGRAM_ENUMERATION("Net.FtpDataConnectionErrorHappened",
         type, NUM_OF_NET_ERROR_TYPES);
   }
   UMA_HISTOGRAM_ENUMERATION("Net.FtpDataConnectionErrorCount",
       type, NUM_OF_NET_ERROR_TYPES);
 }
 
 }  // namespace net