Rework the logging for sockets/connectjobs.

In particular, make it work better when using backup jobs / late binding (the display was very confused before because of how these asynchronous events would nest).

Also changed the paradigm for how PassiveLogCollector preserves these async associations -- this fixes how it replays the events to net-internals. (Before we would collapse the event streams into the SOURCE_URL_REQUEST which lost some hiearchy.. now I keep the separate streams).

Some of the particular changes to the event streams:

* ConnectJobs now create their own source stream internally.
* Sockets are now bounded by +SOCKET_ALIVE / -SOCKET_ALIVE events (removed the one-off SOCKET_DONE event).
* The socket log streams contains +SOCKET_IN_USE / -SOCKET_IN_USE event blocks to show which URLRequest was controlling it at various points in time (this makes it much easier to understand which read/writes belonged to a particular network transaction when a socket gets re-used).
* ConnectJobs are bounded by +SOCKET_POOL_CONNECT_JOB / - SOCKET_POOL_CONNECT_JOB events.
* ConnectJobs log the net error they failed with.
* Removed the SOCKET_BACKUP_TIMER_EXTENDED event.
Review URL: http://codereview.chromium.org/2363003

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

4 files changed, 79 insertions, 27 deletions

diff --git a/net/base/net_log.cc b/net/base/net_log.cc
index 02b6bbd..ace4a53 100644
--- a/net/base/net_log.cc
+++ b/net/base/net_log.cc
@@ -97,4 +97,15 @@ Value* NetLogStringParameter::ToValue() const {
   return dict;
 }
 
+Value* NetLogSourceParameter::ToValue() const {
+  DictionaryValue* dict = new DictionaryValue();
+
+  DictionaryValue* source_dict = new DictionaryValue();
+  source_dict->SetInteger(L"type", static_cast<int>(value_.type));
+  source_dict->SetInteger(L"id", static_cast<int>(value_.id));
+
+  dict->Set(ASCIIToWide(name_), source_dict);
+  return dict;
+}
+
 }  // namespace net
diff --git a/net/base/net_log.h b/net/base/net_log.h
index 619b57b..a9d24f8 100644
--- a/net/base/net_log.h
+++ b/net/base/net_log.h
@@ -53,7 +53,7 @@ class NetLog {
 
   // The "source" identifies the entity that generated the log message.
   enum SourceType {
-#define SOURCE_TYPE(label) SOURCE_ ## label,
+#define SOURCE_TYPE(label, value) SOURCE_ ## label = value,
 #include "net/base/net_log_source_type_list.h"
 #undef SOURCE_TYPE
   };
@@ -206,6 +206,25 @@ class NetLogIntegerParameter : public NetLog::EventParameters {
   const int value_;
 };
 
+// NetLogSourceParameter is a subclass of EventParameters that encapsulates a
+// single NetLog::Source parameter.
+class NetLogSourceParameter : public NetLog::EventParameters {
+ public:
+  // |name| must be a string literal.
+  NetLogSourceParameter(const char* name, const NetLog::Source& value)
+      : name_(name), value_(value) {}
+
+  const NetLog::Source& value() const {
+    return value_;
+  }
+
+  virtual Value* ToValue() const;
+
+ private:
+  const char* name_;
+  const NetLog::Source value_;
+};
+
 }  // namespace net
 
 #endif  // NET_BASE_NET_LOG_H_
diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index 531a019..709a130 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -13,12 +13,7 @@
 // log context around it.)
 EVENT_TYPE(CANCELLED)
 
-// TODO(eroman): remove the remaining consumers of this.
-EVENT_TYPE(TODO_STRING)
-
 // Marks the creation/destruction of a request (URLRequest or SocketStream).
-// In the begin phase of this event, the message will contain a string which
-// is the URL.
 EVENT_TYPE(REQUEST_ALIVE)
 
 // ------------------------------------------------------------------------
@@ -154,8 +149,18 @@ EVENT_TYPE(TCP_CONNECT)
 //   }
 EVENT_TYPE(TCP_CONNECT_ATTEMPT)
 
-// Marks the destruction of a TCP socket.
-EVENT_TYPE(TCP_SOCKET_DONE)
+// Marks the begin/end of a socket (TCP/SOCKS/SSL).
+EVENT_TYPE(SOCKET_ALIVE)
+
+// This event is logged to the socket stream whenever the socket is
+// acquired/released via a ClientSocketHandle.
+//
+// The BEGIN phase contains the following parameters:
+//
+//   {
+//     "source_dependency": <Source identifier for the controlling entity>
+//   }
+EVENT_TYPE(SOCKET_IN_USE)
 
 // The start/end of a SOCKS connect().
 EVENT_TYPE(SOCKS_CONNECT)
@@ -228,6 +233,23 @@ EVENT_TYPE(SOCKET_BYTES_RECEIVED)
 // The start/end of a ConnectJob.
 EVENT_TYPE(SOCKET_POOL_CONNECT_JOB)
 
+// The start/end of the ConnectJob::Connect().
+//
+// The BEGIN phase has these parameters:
+//
+//   {
+//     "group_name": <The group name for the socket request.>
+//   }
+EVENT_TYPE(SOCKET_POOL_CONNECT_JOB_CONNECT)
+
+// This event is logged whenever the ConnectJob gets a new socket
+// association. The event parameters point to that socket:
+//
+//   {
+//     "source_dependency": <The source identifier for the new socket.>
+//   }
+EVENT_TYPE(CONNECT_JOB_SET_SOCKET)
+
 // Whether the connect job timed out.
 EVENT_TYPE(SOCKET_POOL_CONNECT_JOB_TIMED_OUT)
 
@@ -262,25 +284,23 @@ EVENT_TYPE(TCP_CLIENT_SOCKET_POOL_REQUESTED_SOCKET)
 // A backup socket is created due to slow connect
 EVENT_TYPE(SOCKET_BACKUP_CREATED)
 
-// A backup socket is created due to slow connect
-EVENT_TYPE(SOCKET_BACKUP_TIMER_EXTENDED)
-
-// Identifies the NetLog::Source() for a ConnectJob.  The begin event
-// is sent to the request that triggered the ConnectJob, the end event
-// is sent to the request that received the connected socket.  Because of
-// late binding, they may not be the same. Therefore the ID for the
-// ConnectJob NetLog is sent in both events. The event parameters are:
+// This event is sent when a connect job is eventually bound to a request
+// (because of late binding and socket backup jobs, we don't assign the job to
+// a request until it has completed).
+//
+// The event parameters are:
 //   {
-//      "source_id": <ID of the connect job that was bound to this source>
+//      "source_dependency": <Source identifer for the connect job we are
+//                            bound to>
 //   }
-EVENT_TYPE(SOCKET_POOL_CONNECT_JOB_ID)
+EVENT_TYPE(SOCKET_POOL_BOUND_TO_CONNECT_JOB)
 
 // Identifies the NetLog::Source() for the Socket assigned to the pending
 // request. The event parameters are:
 //   {
-//      "source_id": <ID of the socket that was bound to this source>
+//      "source_dependency": <Source identifier for the socket we acquired>
 //   }
-EVENT_TYPE(SOCKET_POOL_SOCKET_ID)
+EVENT_TYPE(SOCKET_POOL_BOUND_TO_SOCKET)
 
 // ------------------------------------------------------------------------
 // URLRequest
diff --git a/net/base/net_log_source_type_list.h b/net/base/net_log_source_type_list.h
index 9d29826..6664c2d 100644
--- a/net/base/net_log_source_type_list.h
+++ b/net/base/net_log_source_type_list.h
@@ -5,11 +5,13 @@
 // NOTE: No header guards are used, since this file is intended to be expanded
 // directly within a block where the SOURCE_TYPE macro is defined.
 
-SOURCE_TYPE(NONE)
-SOURCE_TYPE(URL_REQUEST)
-SOURCE_TYPE(SOCKET_STREAM)
-SOURCE_TYPE(INIT_PROXY_RESOLVER)
-SOURCE_TYPE(CONNECT_JOB)
-SOURCE_TYPE(SOCKET)
-SOURCE_TYPE(SPDY_SESSION)
+SOURCE_TYPE(NONE, -1)
 
+SOURCE_TYPE(URL_REQUEST, 0)
+SOURCE_TYPE(SOCKET_STREAM, 1)
+SOURCE_TYPE(INIT_PROXY_RESOLVER, 2)
+SOURCE_TYPE(CONNECT_JOB, 3)
+SOURCE_TYPE(SOCKET, 4)
+SOURCE_TYPE(SPDY_SESSION, 5)
+
+SOURCE_TYPE(COUNT, 6) // Always keep this as the last entry.