Add LoadLogging to SOCKS5ClientSocket. Logs the state transitions, and more verbose information on errors.

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

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

2 files changed, 84 insertions, 7 deletions

diff --git a/net/base/load_log_event_type_list.h b/net/base/load_log_event_type_list.h
index 880305e..a0acb6c 100644
--- a/net/base/load_log_event_type_list.h
+++ b/net/base/load_log_event_type_list.h
@@ -216,3 +216,19 @@ EVENT_TYPE(SOCKET_STREAM_SENT)
 
 // A message received on the SocketStream.
 EVENT_TYPE(SOCKET_STREAM_RECEIVED)
+
+// ------------------------------------------------------------------------
+// SOCKS5ClientSocket
+// ------------------------------------------------------------------------
+
+// The time spent sending the "greeting" to the SOCKS server.
+EVENT_TYPE(SOCKS5_GREET_WRITE)
+
+// The time spent waiting for the "greeting" response from the SOCKS server.
+EVENT_TYPE(SOCKS5_GREET_READ)
+
+// The time spent sending the CONNECT request to the SOCKS server.
+EVENT_TYPE(SOCKS5_HANDSHAKE_WRITE)
+
+// The time spent waiting for the response to the CONNECT request.
+EVENT_TYPE(SOCKS5_HANDSHAKE_READ)
diff --git a/net/socket/socks5_client_socket.cc b/net/socket/socks5_client_socket.cc
index 33d8e53..d1af427 100644
--- a/net/socket/socks5_client_socket.cc
+++ b/net/socket/socks5_client_socket.cc
@@ -6,6 +6,8 @@
 
 #include "base/basictypes.h"
 #include "base/compiler_specific.h"
+#include "base/format_macros.h"
+#include "base/string_util.h"
 #include "base/trace_event.h"
 #include "net/base/io_buffer.h"
 #include "net/base/load_log.h"
@@ -14,6 +16,25 @@
 
 namespace net {
 
+namespace {
+
+// Returns a string description of |socks_error|, or NULL.
+const char* MapSOCKSReplyToErrorString(char socks_error) {
+  switch(socks_error) {
+    case 1: return "(1) General SOCKS server failure";
+    case 2: return "(2) Connection not allowed by ruleset";
+    case 3: return "(3) Network unreachable";
+    case 4: return "(4) Host unreachable";
+    case 5: return "(5) Connection refused";
+    case 6: return "(6) TTL expired";
+    case 7: return "(7) Command not supported";
+    case 8: return "(8) Address type not supported";
+    default: return NULL;
+  }
+}
+
+}  // namespace
+
 const unsigned int SOCKS5ClientSocket::kGreetReadHeaderSize = 2;
 const unsigned int SOCKS5ClientSocket::kWriteHeaderSize = 10;
 const unsigned int SOCKS5ClientSocket::kReadHeaderSize = 5;
@@ -120,7 +141,6 @@ void SOCKS5ClientSocket::DoCallback(int result) {
   // clear user_callback_ up front.
   CompletionCallback* c = user_callback_;
   user_callback_ = NULL;
-  DLOG(INFO) << "Finished setting up SOCKSv5 handshake";
   c->Run(result);
 }
 
@@ -143,31 +163,39 @@ int SOCKS5ClientSocket::DoLoop(int last_io_result) {
     switch (state) {
       case STATE_GREET_WRITE:
         DCHECK_EQ(OK, rv);
+        LoadLog::BeginEvent(load_log_, LoadLog::TYPE_SOCKS5_GREET_WRITE);
         rv = DoGreetWrite();
         break;
       case STATE_GREET_WRITE_COMPLETE:
         rv = DoGreetWriteComplete(rv);
+        LoadLog::EndEvent(load_log_, LoadLog::TYPE_SOCKS5_GREET_WRITE);
         break;
       case STATE_GREET_READ:
         DCHECK_EQ(OK, rv);
+        LoadLog::BeginEvent(load_log_, LoadLog::TYPE_SOCKS5_GREET_READ);
         rv = DoGreetRead();
         break;
       case STATE_GREET_READ_COMPLETE:
         rv = DoGreetReadComplete(rv);
+        LoadLog::EndEvent(load_log_, LoadLog::TYPE_SOCKS5_GREET_READ);
         break;
       case STATE_HANDSHAKE_WRITE:
         DCHECK_EQ(OK, rv);
+        LoadLog::BeginEvent(load_log_, LoadLog::TYPE_SOCKS5_HANDSHAKE_WRITE);
         rv = DoHandshakeWrite();
         break;
       case STATE_HANDSHAKE_WRITE_COMPLETE:
         rv = DoHandshakeWriteComplete(rv);
+        LoadLog::EndEvent(load_log_, LoadLog::TYPE_SOCKS5_HANDSHAKE_WRITE);
         break;
       case STATE_HANDSHAKE_READ:
         DCHECK_EQ(OK, rv);
+        LoadLog::BeginEvent(load_log_, LoadLog::TYPE_SOCKS5_HANDSHAKE_READ);
         rv = DoHandshakeRead();
         break;
       case STATE_HANDSHAKE_READ_COMPLETE:
         rv = DoHandshakeReadComplete(rv);
+        LoadLog::EndEvent(load_log_, LoadLog::TYPE_SOCKS5_HANDSHAKE_READ);
         break;
       default:
         NOTREACHED() << "bad state";
@@ -184,8 +212,12 @@ const char kSOCKS5GreetReadData[] = { 0x05, 0x00 };
 int SOCKS5ClientSocket::DoGreetWrite() {
   // Since we only have 1 byte to send the hostname length in, if the
   // URL has a hostname longer than 255 characters we can't send it.
-  if (0xFF < host_request_info_.hostname().size())
+  if (0xFF < host_request_info_.hostname().size()) {
+    LoadLog::AddStringLiteral(load_log_,
+        "Failed sending request because hostname is "
+        "longer than 255 characters");
     return ERR_INVALID_URL;
+  }
 
   if (buffer_.empty()) {
     buffer_ = std::string(kSOCKS5GreetWriteData,
@@ -238,8 +270,18 @@ int SOCKS5ClientSocket::DoGreetReadComplete(int result) {
   }
 
   // Got the greet data.
-  if (buffer_[0] != kSOCKS5Version || buffer_[1] != 0x00)
+  if (buffer_[0] != kSOCKS5Version) {
+    LoadLog::AddStringLiteral(load_log_, "Unexpected SOCKS version");
+    LoadLog::AddString(load_log_, StringPrintf(
+        "buffer_[0] = 0x%x", static_cast<int>(buffer_[0])));
+    return ERR_INVALID_RESPONSE;
+  }
+  if (buffer_[1] != 0x00) {
+    LoadLog::AddStringLiteral(load_log_, "Unexpected authentication method");
+    LoadLog::AddString(load_log_, StringPrintf(
+        "buffer_[1] = 0x%x", static_cast<int>(buffer_[1])));
     return ERR_INVALID_RESPONSE;  // Unknown error
+  }
 
   buffer_.clear();
   next_state_ = STATE_HANDSHAKE_WRITE;
@@ -334,11 +376,26 @@ int SOCKS5ClientSocket::DoHandshakeReadComplete(int result) {
   // When the first few bytes are read, check how many more are required
   // and accordingly increase them
   if (bytes_received_ == kReadHeaderSize) {
-    // TODO(arindam): add error codes to net/error_list.h
-    if (buffer_[0] != kSOCKS5Version || buffer_[2] != kNullByte)
+    if (buffer_[0] != kSOCKS5Version || buffer_[2] != kNullByte) {
+      LoadLog::AddStringLiteral(load_log_, "Unexpected SOCKS version.");
+      LoadLog::AddString(load_log_, StringPrintf(
+          "buffer_[0] = 0x%x; buffer_[2] = 0x%x",
+          static_cast<int>(buffer_[0]),
+          static_cast<int>(buffer_[2])));
       return ERR_INVALID_RESPONSE;
-    if (buffer_[1] != 0x00)
+    }
+    if (buffer_[1] != 0x00) {
+      LoadLog::AddStringLiteral(load_log_,
+                                "SOCKS server returned a failure code:");
+      const char* error_string = MapSOCKSReplyToErrorString(buffer_[1]);
+      if (error_string) {
+        LoadLog::AddStringLiteral(load_log_, error_string);
+      } else {
+        LoadLog::AddString(load_log_, StringPrintf(
+            "buffer_[1] = 0x%x", static_cast<int>(buffer_[1])));
+      }
       return ERR_FAILED;
+    }
 
     // We check the type of IP/Domain the server returns and accordingly
     // increase the size of the response. For domains, we need to read the
@@ -353,8 +410,12 @@ int SOCKS5ClientSocket::DoHandshakeReadComplete(int result) {
       read_header_size += sizeof(struct in_addr) - 1;
     else if (address_type == kEndPointResolvedIPv6)
       read_header_size += sizeof(struct in6_addr) - 1;
-    else
+    else {
+      LoadLog::AddStringLiteral(load_log_, "Unknown address type in response");
+      LoadLog::AddString(load_log_, StringPrintf(
+          "buffer_[3] = 0x%x", static_cast<int>(buffer_[3])));
       return ERR_INVALID_RESPONSE;
+    }
 
     read_header_size += 2;  // for the port.
     next_state_ = STATE_HANDSHAKE_READ;