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

15 files changed, 178 insertions, 133 deletions

diff --git a/net/socket/client_socket_handle.cc b/net/socket/client_socket_handle.cc
index 5964239..4f61a68 100644
--- a/net/socket/client_socket_handle.cc
+++ b/net/socket/client_socket_handle.cc
@@ -33,6 +33,7 @@ void ClientSocketHandle::ResetInternal(bool cancel) {
   if (socket_.get()) {
     // Because of http://crbug.com/37810 we may not have a pool, but have
     // just a raw socket.
+    socket_->NetLog().EndEvent(NetLog::TYPE_SOCKET_IN_USE, NULL);
     if (pool_)
       // If we've still got a socket, release it back to the ClientSocketPool so
       // it can be deleted or reused.
@@ -92,6 +93,15 @@ void ClientSocketHandle::HandleInitCompletion(int result) {
       NOTREACHED();
       break;
   }
+
+  // Broadcast that the socket has been acquired.
+  // TODO(eroman): This logging is not complete, in particular set_socket() and
+  // release() socket. It ends up working though, since those methods are being
+  // used to layer sockets (and the destination sources are the same).
+  DCHECK(socket_.get());
+  socket_->NetLog().BeginEvent(
+      NetLog::TYPE_SOCKET_IN_USE,
+      new NetLogSourceParameter("source_dependency", requesting_source_));
 }
 
 }  // namespace net
diff --git a/net/socket/client_socket_handle.h b/net/socket/client_socket_handle.h
index f750c7b..4b36e58 100644
--- a/net/socket/client_socket_handle.h
+++ b/net/socket/client_socket_handle.h
@@ -14,6 +14,7 @@
 #include "net/base/completion_callback.h"
 #include "net/base/load_states.h"
 #include "net/base/net_errors.h"
+#include "net/base/net_log.h"
 #include "net/base/request_priority.h"
 #include "net/socket/client_socket.h"
 #include "net/socket/client_socket_pool.h"
@@ -144,6 +145,8 @@ class ClientSocketHandle {
   base::TimeTicks init_time_;
   base::TimeDelta setup_time_;
 
+  NetLog::Source requesting_source_;
+
   DISALLOW_COPY_AND_ASSIGN(ClientSocketHandle);
 };
 
@@ -155,6 +158,8 @@ int ClientSocketHandle::Init(const std::string& group_name,
                              CompletionCallback* callback,
                              const scoped_refptr<PoolType>& pool,
                              const BoundNetLog& net_log) {
+  requesting_source_ = net_log.source();
+
   CHECK(!group_name.empty());
   // Note that this will result in a link error if the SocketParams has not been
   // registered for the PoolType via REGISTER_SOCKET_PARAMS_FOR_POOL (defined in
diff --git a/net/socket/client_socket_pool_base.cc b/net/socket/client_socket_pool_base.cc
index 99011be..ddaa430 100644
--- a/net/socket/client_socket_pool_base.cc
+++ b/net/socket/client_socket_pool_base.cc
@@ -42,42 +42,46 @@ ConnectJob::ConnectJob(const std::string& group_name,
       idle_(true) {
   DCHECK(!group_name.empty());
   DCHECK(delegate);
+  net_log.BeginEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL);
 }
 
 ConnectJob::~ConnectJob() {
-  if (delegate_ && !idle_) {
-    // If the delegate was not NULLed, then NotifyDelegateOfCompletion has
-    // not been called yet.  If we've started then we are cancelling.
-    net_log_.AddEvent(NetLog::TYPE_CANCELLED, NULL);
-    net_log_.EndEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL);
-  }
+  net_log().EndEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL);
 }
 
 int ConnectJob::Connect() {
   if (timeout_duration_ != base::TimeDelta())
     timer_.Start(timeout_duration_, this, &ConnectJob::OnTimeout);
 
-  net_log_.BeginEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB,
-                      new NetLogStringParameter("group_name", group_name_));
   idle_ = false;
 
+  LogConnectStart();
+
   int rv = ConnectInternal();
 
   if (rv != ERR_IO_PENDING) {
+    LogConnectCompletion(rv);
     delegate_ = NULL;
-    net_log_.EndEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL);
   }
 
   return rv;
 }
 
+void ConnectJob::set_socket(ClientSocket* socket) {
+  if (socket) {
+    net_log().AddEvent(NetLog::TYPE_CONNECT_JOB_SET_SOCKET,
+                       new NetLogSourceParameter("source_dependency",
+                                                 socket->NetLog().source()));
+  }
+  socket_.reset(socket);
+}
+
 void ConnectJob::NotifyDelegateOfCompletion(int rv) {
   // The delegate will delete |this|.
   Delegate *delegate = delegate_;
   delegate_ = NULL;
 
-  net_log_.EndEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL);
-
+  LogConnectCompletion(rv);
   delegate->OnConnectJobComplete(rv, this);
 }
 
@@ -86,6 +90,18 @@ void ConnectJob::ResetTimer(base::TimeDelta remaining_time) {
   timer_.Start(remaining_time, this, &ConnectJob::OnTimeout);
 }
 
+void ConnectJob::LogConnectStart() {
+  net_log().BeginEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT,
+                       new NetLogStringParameter("group_name", group_name_));
+}
+
+void ConnectJob::LogConnectCompletion(int net_error) {
+  scoped_refptr<NetLog::EventParameters> params;
+  if (net_error != OK)
+    params = new NetLogIntegerParameter("net_error", net_error);
+  net_log().EndEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT, params);
+}
+
 void ConnectJob::OnTimeout() {
   // Make sure the socket is NULL before calling into |delegate|.
   set_socket(NULL);
@@ -236,21 +252,12 @@ int ClientSocketPoolBaseHelper::RequestSocketInternal(
   }
 
   // We couldn't find a socket to reuse, so allocate and connect a new one.
-  BoundNetLog job_net_log = BoundNetLog::Make(
-      request->net_log().net_log(), NetLog::SOURCE_CONNECT_JOB);
-  request->net_log().BeginEvent(
-      NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID,
-      new NetLogIntegerParameter("source_id", job_net_log.source().id));
-
   scoped_ptr<ConnectJob> connect_job(
-      connect_job_factory_->NewConnectJob(group_name, *request, this,
-                                          job_net_log));
+      connect_job_factory_->NewConnectJob(group_name, *request, this));
 
   int rv = connect_job->Connect();
   if (rv == OK) {
-    request->net_log().EndEvent(
-        NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID,
-        new NetLogIntegerParameter("source_id", job_net_log.source().id));
+    LogBoundConnectJobToRequest(connect_job->net_log().source(), request);
     HandOutSocket(connect_job->ReleaseSocket(), false /* not reused */,
                   handle, base::TimeDelta(), &group, request->net_log());
   } else if (rv == ERR_IO_PENDING) {
@@ -260,8 +267,7 @@ int ClientSocketPoolBaseHelper::RequestSocketInternal(
     if (group.IsEmpty() && !group.backup_job && backup_jobs_enabled_) {
       group.backup_job = connect_job_factory_->NewConnectJob(group_name,
                                                              *request,
-                                                             this,
-                                                             job_net_log);
+                                                             this);
       StartBackupSocketTimer(group_name);
     }
 
@@ -270,9 +276,7 @@ int ClientSocketPoolBaseHelper::RequestSocketInternal(
     ConnectJob* job = connect_job.release();
     group.jobs.insert(job);
   } else {
-    request->net_log().EndEvent(
-        NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID,
-        new NetLogIntegerParameter("source_id", job_net_log.source().id));
+    LogBoundConnectJobToRequest(connect_job->net_log().source(), request);
     if (group.IsEmpty())
       group_map_.erase(group_name);
   }
@@ -280,6 +284,14 @@ int ClientSocketPoolBaseHelper::RequestSocketInternal(
   return rv;
 }
 
+// static
+void ClientSocketPoolBaseHelper::LogBoundConnectJobToRequest(
+    const NetLog::Source& connect_job_source, const Request* request) {
+  request->net_log().AddEvent(
+      NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
+      new NetLogSourceParameter("source_dependency", connect_job_source));
+}
+
 void ClientSocketPoolBaseHelper::StartBackupSocketTimer(
     const std::string& group_name) {
   CHECK(ContainsKey(group_map_, group_name));
@@ -312,8 +324,6 @@ void ClientSocketPoolBaseHelper::OnBackupSocketTimerFired(
   if (ReachedMaxSocketsLimit() ||
       !group.HasAvailableSocketSlot(max_sockets_per_group_) ||
       (*group.jobs.begin())->GetLoadState() == LOAD_STATE_RESOLVING_HOST) {
-    group.backup_job->net_log().AddEvent(
-        NetLog::TYPE_SOCKET_BACKUP_TIMER_EXTENDED, NULL);
     StartBackupSocketTimer(group_name);
     return;
   }
@@ -583,13 +593,11 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
     if (!group.pending_requests.empty()) {
       scoped_ptr<const Request> r(RemoveRequestFromQueue(
           group.pending_requests.begin(), &group.pending_requests));
-      r->net_log().EndEvent(
-          NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID,
-          new NetLogIntegerParameter("source_id", job_log.source().id));
-      r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, NULL);
+      LogBoundConnectJobToRequest(job_log.source(), r.get());
       HandOutSocket(
           socket.release(), false /* unused socket */, r->handle(),
           base::TimeDelta(), &group, r->net_log());
+      r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, NULL);
       r->callback()->Run(result);
     } else {
       AddIdleSocket(socket.release(), false /* unused socket */, &group);
@@ -600,10 +608,9 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
     if (!group.pending_requests.empty()) {
       scoped_ptr<const Request> r(RemoveRequestFromQueue(
           group.pending_requests.begin(), &group.pending_requests));
-      r->net_log().EndEvent(
-          NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID,
-          new NetLogIntegerParameter("source_id", job_log.source().id));
-      r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, NULL);
+      LogBoundConnectJobToRequest(job_log.source(), r.get());
+      r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL,
+                            new NetLogIntegerParameter("net_error", result));
       r->callback()->Run(result);
     }
     MaybeOnAvailableSocketSlot(group_name);
@@ -667,7 +674,11 @@ void ClientSocketPoolBaseHelper::ProcessPendingRequest(
   if (rv != ERR_IO_PENDING) {
     scoped_ptr<const Request> r(RemoveRequestFromQueue(
           group->pending_requests.begin(), &group->pending_requests));
-    r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, NULL);
+
+    scoped_refptr<NetLog::EventParameters> params;
+    if (rv != OK)
+      params = new NetLogIntegerParameter("net_error", rv);
+    r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL, params);
     r->callback()->Run(rv);
     if (rv != OK) {
       // |group| may be invalid after the callback, we need to search
@@ -696,9 +707,9 @@ void ClientSocketPoolBaseHelper::HandOutSocket(
             "idle_ms", static_cast<int>(idle_time.InMilliseconds())));
   }
 
-  net_log.AddEvent(NetLog::TYPE_SOCKET_POOL_SOCKET_ID,
-                   new NetLogIntegerParameter(
-                       "source_id", socket->NetLog().source().id));
+  net_log.AddEvent(NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET,
+                   new NetLogSourceParameter(
+                       "source_dependency", socket->NetLog().source()));
 
   handed_out_socket_count_++;
   group->active_socket_count++;
diff --git a/net/socket/client_socket_pool_base.h b/net/socket/client_socket_pool_base.h
index db408a2..470c120 100644
--- a/net/socket/client_socket_pool_base.h
+++ b/net/socket/client_socket_pool_base.h
@@ -91,7 +91,7 @@ class ConnectJob {
   virtual LoadState GetLoadState() const = 0;
 
  protected:
-  void set_socket(ClientSocket* socket) { socket_.reset(socket); }
+  void set_socket(ClientSocket* socket);
   ClientSocket* socket() { return socket_.get(); }
   void NotifyDelegateOfCompletion(int rv);
   void ResetTimer(base::TimeDelta remainingTime);
@@ -99,6 +99,9 @@ class ConnectJob {
  private:
   virtual int ConnectInternal() = 0;
 
+  void LogConnectStart();
+  void LogConnectCompletion(int net_error);
+
   // Alerts the delegate that the ConnectJob has timed out.
   void OnTimeout();
 
@@ -158,8 +161,7 @@ class ClientSocketPoolBaseHelper
     virtual ConnectJob* NewConnectJob(
         const std::string& group_name,
         const Request& request,
-        ConnectJob::Delegate* delegate,
-        const BoundNetLog& net_log) const = 0;
+        ConnectJob::Delegate* delegate) const = 0;
 
     virtual base::TimeDelta ConnectionTimeout() const = 0;
 
@@ -231,7 +233,7 @@ class ClientSocketPoolBaseHelper
     return connect_job_factory_->ConnectionTimeout();
   }
 
-  void enable_backup_jobs() { backup_jobs_enabled_ = true; };
+  void enable_backup_jobs() { backup_jobs_enabled_ = true; }
 
  private:
   friend class base::RefCounted<ClientSocketPoolBaseHelper>;
@@ -387,6 +389,9 @@ class ClientSocketPoolBaseHelper
   int RequestSocketInternal(const std::string& group_name,
                             const Request* request);
 
+  static void LogBoundConnectJobToRequest(
+      const NetLog::Source& connect_job_source, const Request* request);
+
   // Set a timer to create a backup socket if it takes too long to create one.
   void StartBackupSocketTimer(const std::string& group_name);
 
@@ -486,8 +491,7 @@ class ClientSocketPoolBase {
     virtual ConnectJob* NewConnectJob(
         const std::string& group_name,
         const Request& request,
-        ConnectJob::Delegate* delegate,
-        const BoundNetLog& net_log) const = 0;
+        ConnectJob::Delegate* delegate) const = 0;
 
     virtual base::TimeDelta ConnectionTimeout() const = 0;
 
@@ -580,7 +584,7 @@ class ClientSocketPoolBase {
     return histograms_;
   }
 
-  void enable_backup_jobs() { helper_->enable_backup_jobs(); };
+  void enable_backup_jobs() { helper_->enable_backup_jobs(); }
 
  private:
   // This adaptor class exists to bridge the
@@ -602,11 +606,10 @@ class ClientSocketPoolBase {
     virtual ConnectJob* NewConnectJob(
         const std::string& group_name,
         const internal::ClientSocketPoolBaseHelper::Request& request,
-        ConnectJob::Delegate* delegate,
-        const BoundNetLog& net_log) const {
+        ConnectJob::Delegate* delegate) const {
       const Request* casted_request = static_cast<const Request*>(&request);
       return connect_job_factory_->NewConnectJob(
-          group_name, *casted_request, delegate, net_log);
+          group_name, *casted_request, delegate);
     }
 
     virtual base::TimeDelta ConnectionTimeout() const {
diff --git a/net/socket/client_socket_pool_base_unittest.cc b/net/socket/client_socket_pool_base_unittest.cc
index b33da2e..bf0f96e 100644
--- a/net/socket/client_socket_pool_base_unittest.cc
+++ b/net/socket/client_socket_pool_base_unittest.cc
@@ -46,8 +46,8 @@ class MockClientSocket : public ClientSocket {
       IOBuffer* /* buf */, int /* len */, CompletionCallback* /* callback */) {
     return ERR_UNEXPECTED;
   }
-  virtual bool SetReceiveBufferSize(int32 size) { return true; };
-  virtual bool SetSendBufferSize(int32 size) { return true; };
+  virtual bool SetReceiveBufferSize(int32 size) { return true; }
+  virtual bool SetSendBufferSize(int32 size) { return true; }
 
   // ClientSocket methods:
 
@@ -122,8 +122,9 @@ class TestConnectJob : public ConnectJob {
                  base::TimeDelta timeout_duration,
                  ConnectJob::Delegate* delegate,
                  MockClientSocketFactory* client_socket_factory,
-                 const BoundNetLog& net_log)
-      : ConnectJob(group_name, timeout_duration, delegate, net_log),
+                 NetLog* net_log)
+      : ConnectJob(group_name, timeout_duration, delegate,
+                   BoundNetLog::Make(net_log, NetLog::SOURCE_CONNECT_JOB)),
         job_type_(job_type),
         client_socket_factory_(client_socket_factory),
         method_factory_(ALLOW_THIS_IN_INITIALIZER_LIST(this)),
@@ -255,15 +256,14 @@ class TestConnectJobFactory
   virtual ConnectJob* NewConnectJob(
       const std::string& group_name,
       const TestClientSocketPoolBase::Request& request,
-      ConnectJob::Delegate* delegate,
-      const BoundNetLog& net_log) const {
+      ConnectJob::Delegate* delegate) const {
     return new TestConnectJob(job_type_,
                               group_name,
                               request,
                               timeout_duration_,
                               delegate,
                               client_socket_factory_,
-                              net_log);
+                              NULL);
   }
 
   virtual base::TimeDelta ConnectionTimeout() const {
@@ -484,14 +484,14 @@ TEST_F(ClientSocketPoolBaseTest, ConnectJob_NoTimeoutOnSynchronousCompletion) {
                          base::TimeDelta::FromMicroseconds(1),
                          &delegate,
                          &client_socket_factory_,
-                         BoundNetLog()));
+                         NULL));
   EXPECT_EQ(OK, job->Connect());
 }
 
 TEST_F(ClientSocketPoolBaseTest, ConnectJob_TimedOut) {
   TestConnectJobDelegate delegate;
   ClientSocketHandle ignored;
-  CapturingBoundNetLog log(CapturingNetLog::kUnbounded);
+  CapturingNetLog log(CapturingNetLog::kUnbounded);
 
   TestClientSocketPoolBase::Request request(
       &ignored, NULL, kDefaultPriority, NULL, BoundNetLog());
@@ -503,19 +503,26 @@ TEST_F(ClientSocketPoolBaseTest, ConnectJob_TimedOut) {
                          base::TimeDelta::FromMicroseconds(1),
                          &delegate,
                          &client_socket_factory_,
-                         log.bound());
+                         &log);
   ASSERT_EQ(ERR_IO_PENDING, job->Connect());
   PlatformThread::Sleep(1);
   EXPECT_EQ(ERR_TIMED_OUT, delegate.WaitForResult());
 
-  EXPECT_EQ(3u, log.entries().size());
+  EXPECT_EQ(6u, log.entries().size());
   EXPECT_TRUE(LogContainsBeginEvent(
       log.entries(), 0, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
+  EXPECT_TRUE(LogContainsBeginEvent(
+      log.entries(), 1, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT));
+  EXPECT_TRUE(LogContainsEvent(
+      log.entries(), 2, NetLog::TYPE_CONNECT_JOB_SET_SOCKET,
+      NetLog::PHASE_NONE));
   EXPECT_TRUE(LogContainsEvent(
-      log.entries(), 1, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_TIMED_OUT,
+      log.entries(), 3, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_TIMED_OUT,
       NetLog::PHASE_NONE));
   EXPECT_TRUE(LogContainsEndEvent(
-      log.entries(), 2, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
+      log.entries(), 4, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT));
+  EXPECT_TRUE(LogContainsEndEvent(
+      log.entries(), 5, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
 }
 
 TEST_F(ClientSocketPoolBaseTest, BasicSynchronous) {
@@ -531,22 +538,17 @@ TEST_F(ClientSocketPoolBaseTest, BasicSynchronous) {
   EXPECT_TRUE(handle.socket());
   handle.Reset();
 
-  EXPECT_EQ(7u, log.entries().size());
+  EXPECT_EQ(4u, log.entries().size());
   EXPECT_TRUE(LogContainsBeginEvent(
       log.entries(), 0, NetLog::TYPE_SOCKET_POOL));
-  EXPECT_TRUE(LogContainsBeginEvent(
-      log.entries(), 1, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID));
-  EXPECT_TRUE(LogContainsBeginEvent(
-      log.entries(), 2, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
-  EXPECT_TRUE(LogContainsEndEvent(
-      log.entries(), 3, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
-  EXPECT_TRUE(LogContainsEndEvent(
-      log.entries(), 4, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_ID));
   EXPECT_TRUE(LogContainsEvent(
-      log.entries(), 5, NetLog::TYPE_SOCKET_POOL_SOCKET_ID,
+      log.entries(), 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
+      NetLog::PHASE_NONE));
+  EXPECT_TRUE(LogContainsEvent(
+      log.entries(), 2, NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET,
       NetLog::PHASE_NONE));
   EXPECT_TRUE(LogContainsEndEvent(
-      log.entries(), 6, NetLog::TYPE_SOCKET_POOL));
+      log.entries(), 3, NetLog::TYPE_SOCKET_POOL));
 }
 
 TEST_F(ClientSocketPoolBaseTest, InitConnectionFailure) {
@@ -560,14 +562,14 @@ TEST_F(ClientSocketPoolBaseTest, InitConnectionFailure) {
             InitHandle(req.handle(), "a", kDefaultPriority, &req, pool_,
                        log.bound()));
 
-  EXPECT_EQ(6u, log.entries().size());
+  EXPECT_EQ(3u, log.entries().size());
   EXPECT_TRUE(LogContainsBeginEvent(
       log.entries(), 0, NetLog::TYPE_SOCKET_POOL));
-  EXPECT_TRUE(LogContainsBeginEvent(
-      log.entries(), 2, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
+  EXPECT_TRUE(LogContainsEvent(
+      log.entries(), 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
+      NetLog::PHASE_NONE));
   EXPECT_TRUE(LogContainsEndEvent(
-      log.entries(), 3, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
-  EXPECT_TRUE(LogContainsEndEvent(log.entries(), 5, NetLog::TYPE_SOCKET_POOL));
+      log.entries(), 2, NetLog::TYPE_SOCKET_POOL));
 }
 
 TEST_F(ClientSocketPoolBaseTest, TotalLimit) {
@@ -1205,15 +1207,17 @@ TEST_F(ClientSocketPoolBaseTest, BasicAsynchronous) {
   EXPECT_TRUE(req.handle()->socket());
   req.handle()->Reset();
 
-  EXPECT_EQ(7u, log.entries().size());
+  EXPECT_EQ(4u, log.entries().size());
   EXPECT_TRUE(LogContainsBeginEvent(
       log.entries(), 0, NetLog::TYPE_SOCKET_POOL));
-  EXPECT_TRUE(LogContainsBeginEvent(
-      log.entries(), 2, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
-  EXPECT_TRUE(LogContainsEndEvent(
-      log.entries(), 3, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
+  EXPECT_TRUE(LogContainsEvent(
+      log.entries(), 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
+      NetLog::PHASE_NONE));
+  EXPECT_TRUE(LogContainsEvent(
+      log.entries(), 2, NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET,
+      NetLog::PHASE_NONE));
   EXPECT_TRUE(LogContainsEndEvent(
-      log.entries(), 5, NetLog::TYPE_SOCKET_POOL));
+      log.entries(), 3, NetLog::TYPE_SOCKET_POOL));
 }
 
 TEST_F(ClientSocketPoolBaseTest,
@@ -1229,15 +1233,14 @@ TEST_F(ClientSocketPoolBaseTest,
   EXPECT_EQ(LOAD_STATE_CONNECTING, pool_->GetLoadState("a", req.handle()));
   EXPECT_EQ(ERR_CONNECTION_FAILED, req.WaitForResult());
 
-  EXPECT_EQ(6u, log.entries().size());
+  EXPECT_EQ(3u, log.entries().size());
   EXPECT_TRUE(LogContainsBeginEvent(
       log.entries(), 0, NetLog::TYPE_SOCKET_POOL));
-  EXPECT_TRUE(LogContainsBeginEvent(
-      log.entries(), 2, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
-  EXPECT_TRUE(LogContainsEndEvent(
-      log.entries(), 3, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
+  EXPECT_TRUE(LogContainsEvent(
+      log.entries(), 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
+      NetLog::PHASE_NONE));
   EXPECT_TRUE(LogContainsEndEvent(
-      log.entries(), 5, NetLog::TYPE_SOCKET_POOL));
+      log.entries(), 2, NetLog::TYPE_SOCKET_POOL));
 }
 
 TEST_F(ClientSocketPoolBaseTest, TwoRequestsCancelOne) {
diff --git a/net/socket/socks_client_socket_pool.cc b/net/socket/socks_client_socket_pool.cc
index 452ce25..4c446ab 100644
--- a/net/socket/socks_client_socket_pool.cc
+++ b/net/socket/socks_client_socket_pool.cc
@@ -26,13 +26,15 @@ SOCKSConnectJob::SOCKSConnectJob(
     const scoped_refptr<TCPClientSocketPool>& tcp_pool,
     const scoped_refptr<HostResolver>& host_resolver,
     Delegate* delegate,
-    const BoundNetLog& net_log)
-    : ConnectJob(group_name, timeout_duration, delegate, net_log),
+    NetLog* net_log)
+    : ConnectJob(group_name, timeout_duration, delegate,
+                 BoundNetLog::Make(net_log, NetLog::SOURCE_CONNECT_JOB)),
       socks_params_(socks_params),
       tcp_pool_(tcp_pool),
       resolver_(host_resolver),
       ALLOW_THIS_IN_INITIALIZER_LIST(
-          callback_(this, &SOCKSConnectJob::OnIOComplete)) {}
+          callback_(this, &SOCKSConnectJob::OnIOComplete)) {
+}
 
 SOCKSConnectJob::~SOCKSConnectJob() {
   // We don't worry about cancelling the tcp socket since the destructor in
@@ -144,10 +146,9 @@ int SOCKSConnectJob::DoSOCKSConnectComplete(int result) {
 ConnectJob* SOCKSClientSocketPool::SOCKSConnectJobFactory::NewConnectJob(
     const std::string& group_name,
     const PoolBase::Request& request,
-    ConnectJob::Delegate* delegate,
-    const BoundNetLog& net_log) const {
+    ConnectJob::Delegate* delegate) const {
   return new SOCKSConnectJob(group_name, request.params(), ConnectionTimeout(),
-                             tcp_pool_, host_resolver_, delegate, net_log);
+                             tcp_pool_, host_resolver_, delegate, net_log_);
 }
 
 base::TimeDelta
@@ -162,11 +163,12 @@ SOCKSClientSocketPool::SOCKSClientSocketPool(
     const scoped_refptr<ClientSocketPoolHistograms>& histograms,
     const scoped_refptr<HostResolver>& host_resolver,
     const scoped_refptr<TCPClientSocketPool>& tcp_pool,
-    NetworkChangeNotifier* network_change_notifier)
+    NetworkChangeNotifier* network_change_notifier,
+    NetLog* net_log)
     : base_(max_sockets, max_sockets_per_group, histograms,
             base::TimeDelta::FromSeconds(kUnusedIdleSocketTimeout),
             base::TimeDelta::FromSeconds(kUsedIdleSocketTimeout),
-            new SOCKSConnectJobFactory(tcp_pool, host_resolver),
+            new SOCKSConnectJobFactory(tcp_pool, host_resolver, net_log),
             network_change_notifier) {}
 
 SOCKSClientSocketPool::~SOCKSClientSocketPool() {}
diff --git a/net/socket/socks_client_socket_pool.h b/net/socket/socks_client_socket_pool.h
index ea162245..bd975ba 100644
--- a/net/socket/socks_client_socket_pool.h
+++ b/net/socket/socks_client_socket_pool.h
@@ -41,7 +41,7 @@ class SOCKSSocketParams {
 
   const TCPSocketParams& tcp_params() const { return tcp_params_; }
   const HostResolver::RequestInfo& destination() const { return destination_; }
-  bool is_socks_v5() const { return socks_v5_; };
+  bool is_socks_v5() const { return socks_v5_; }
 
  private:
   // The tcp connection must point toward the proxy server.
@@ -61,7 +61,7 @@ class SOCKSConnectJob : public ConnectJob {
                   const scoped_refptr<TCPClientSocketPool>& tcp_pool,
                   const scoped_refptr<HostResolver> &host_resolver,
                   Delegate* delegate,
-                  const BoundNetLog& net_log);
+                  NetLog* net_log);
   virtual ~SOCKSConnectJob();
 
   // ConnectJob methods.
@@ -111,7 +111,8 @@ class SOCKSClientSocketPool : public ClientSocketPool {
       const scoped_refptr<ClientSocketPoolHistograms>& histograms,
       const scoped_refptr<HostResolver>& host_resolver,
       const scoped_refptr<TCPClientSocketPool>& tcp_pool,
-      NetworkChangeNotifier* network_change_notifier);
+      NetworkChangeNotifier* network_change_notifier,
+      NetLog* net_log);
 
   // ClientSocketPool methods:
   virtual int RequestSocket(const std::string& group_name,
@@ -155,9 +156,11 @@ class SOCKSClientSocketPool : public ClientSocketPool {
   class SOCKSConnectJobFactory : public PoolBase::ConnectJobFactory {
    public:
     SOCKSConnectJobFactory(const scoped_refptr<TCPClientSocketPool>& tcp_pool,
-                           HostResolver* host_resolver)
+                           HostResolver* host_resolver,
+                           NetLog* net_log)
         : tcp_pool_(tcp_pool),
-          host_resolver_(host_resolver) {}
+          host_resolver_(host_resolver),
+          net_log_(net_log) {}
 
     virtual ~SOCKSConnectJobFactory() {}
 
@@ -165,14 +168,14 @@ class SOCKSClientSocketPool : public ClientSocketPool {
     virtual ConnectJob* NewConnectJob(
         const std::string& group_name,
         const PoolBase::Request& request,
-        ConnectJob::Delegate* delegate,
-        const BoundNetLog& net_log) const;
+        ConnectJob::Delegate* delegate) const;
 
     virtual base::TimeDelta ConnectionTimeout() const;
 
    private:
     const scoped_refptr<TCPClientSocketPool> tcp_pool_;
     const scoped_refptr<HostResolver> host_resolver_;
+    NetLog* net_log_;
 
     DISALLOW_COPY_AND_ASSIGN(SOCKSConnectJobFactory);
   };
diff --git a/net/socket/socks_client_socket_pool_unittest.cc b/net/socket/socks_client_socket_pool_unittest.cc
index 27cb027..33bc146 100644
--- a/net/socket/socks_client_socket_pool_unittest.cc
+++ b/net/socket/socks_client_socket_pool_unittest.cc
@@ -87,7 +87,7 @@ class MockTCPClientSocketPool : public TCPClientSocketPool {
       ClientSocketFactory* socket_factory,
       NetworkChangeNotifier* network_change_notifier)
       : TCPClientSocketPool(max_sockets, max_sockets_per_group, histograms,
-                            NULL, NULL, network_change_notifier),
+                            NULL, NULL, network_change_notifier, NULL),
         client_socket_factory_(socket_factory),
         release_count_(0),
         cancel_count_(0) {}
@@ -180,7 +180,7 @@ class SOCKSClientSocketPoolTest : public ClientSocketPoolTest {
         socks_histograms_(new ClientSocketPoolHistograms("SOCKSUnitTest")),
         pool_(new SOCKSClientSocketPool(
             kMaxSockets, kMaxSocketsPerGroup, socks_histograms_, NULL,
-            tcp_socket_pool_, &socks_notifier_)) {
+            tcp_socket_pool_, &socks_notifier_, NULL)) {
   }
 
   int StartRequest(const std::string& group_name, RequestPriority priority) {
diff --git a/net/socket/ssl_client_socket_unittest.cc b/net/socket/ssl_client_socket_unittest.cc
index 415cb83..7eec8fa 100644
--- a/net/socket/ssl_client_socket_unittest.cc
+++ b/net/socket/ssl_client_socket_unittest.cc
@@ -84,7 +84,7 @@ TEST_F(SSLClientSocketTest, Connect) {
 
   rv = sock->Connect(&callback);
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      log.entries(), 4, net::NetLog::TYPE_SSL_CONNECT));
+      log.entries(), 5, net::NetLog::TYPE_SSL_CONNECT));
   if (rv != net::OK) {
     ASSERT_EQ(net::ERR_IO_PENDING, rv);
     EXPECT_FALSE(sock->IsConnected());
@@ -128,7 +128,7 @@ TEST_F(SSLClientSocketTest, ConnectExpired) {
 
   rv = sock->Connect(&callback);
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      log.entries(), 4, net::NetLog::TYPE_SSL_CONNECT));
+      log.entries(), 5, net::NetLog::TYPE_SSL_CONNECT));
   if (rv != net::OK) {
     ASSERT_EQ(net::ERR_IO_PENDING, rv);
     EXPECT_FALSE(sock->IsConnected());
@@ -174,7 +174,7 @@ TEST_F(SSLClientSocketTest, ConnectMismatched) {
   rv = sock->Connect(&callback);
 
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      log.entries(), 4, net::NetLog::TYPE_SSL_CONNECT));
+      log.entries(), 5, net::NetLog::TYPE_SSL_CONNECT));
   if (rv != net::ERR_CERT_COMMON_NAME_INVALID) {
     ASSERT_EQ(net::ERR_IO_PENDING, rv);
     EXPECT_FALSE(sock->IsConnected());
diff --git a/net/socket/tcp_client_socket_libevent.cc b/net/socket/tcp_client_socket_libevent.cc
index 93f2333..81c3ccd 100644
--- a/net/socket/tcp_client_socket_libevent.cc
+++ b/net/socket/tcp_client_socket_libevent.cc
@@ -110,11 +110,12 @@ TCPClientSocketLibevent::TCPClientSocketLibevent(const AddressList& addresses,
       next_connect_state_(CONNECT_STATE_NONE),
       connect_os_error_(0),
       net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SOCKET)) {
+  net_log_.BeginEvent(NetLog::TYPE_SOCKET_ALIVE, NULL);
 }
 
 TCPClientSocketLibevent::~TCPClientSocketLibevent() {
   Disconnect();
-  net_log_.AddEvent(NetLog::TYPE_TCP_SOCKET_DONE, NULL);
+  net_log_.EndEvent(NetLog::TYPE_SOCKET_ALIVE, NULL);
 }
 
 int TCPClientSocketLibevent::Connect(CompletionCallback* callback) {
diff --git a/net/socket/tcp_client_socket_pool.cc b/net/socket/tcp_client_socket_pool.cc
index 833b36e..0f2c079 100644
--- a/net/socket/tcp_client_socket_pool.cc
+++ b/net/socket/tcp_client_socket_pool.cc
@@ -29,7 +29,7 @@ namespace net {
 // timeout. Even worse, the per-connect timeout threshold varies greatly
 // between systems (anywhere from 20 seconds to 190 seconds).
 // See comment #12 at http://crbug.com/23364 for specifics.
-static const int kTCPConnectJobTimeoutInSeconds = 240; // 4 minutes.
+static const int kTCPConnectJobTimeoutInSeconds = 240;  // 4 minutes.
 
 TCPConnectJob::TCPConnectJob(
     const std::string& group_name,
@@ -38,8 +38,9 @@ TCPConnectJob::TCPConnectJob(
     ClientSocketFactory* client_socket_factory,
     HostResolver* host_resolver,
     Delegate* delegate,
-    const BoundNetLog& net_log)
-    : ConnectJob(group_name, timeout_duration, delegate, net_log),
+    NetLog* net_log)
+    : ConnectJob(group_name, timeout_duration, delegate,
+                 BoundNetLog::Make(net_log, NetLog::SOURCE_CONNECT_JOB)),
       params_(params),
       client_socket_factory_(client_socket_factory),
       ALLOW_THIS_IN_INITIALIZER_LIST(
@@ -160,11 +161,10 @@ int TCPConnectJob::DoTCPConnectComplete(int result) {
 ConnectJob* TCPClientSocketPool::TCPConnectJobFactory::NewConnectJob(
     const std::string& group_name,
     const PoolBase::Request& request,
-    ConnectJob::Delegate* delegate,
-    const BoundNetLog& net_log) const {
+    ConnectJob::Delegate* delegate) const {
   return new TCPConnectJob(group_name, request.params(), ConnectionTimeout(),
                            client_socket_factory_, host_resolver_, delegate,
-                           net_log);
+                           net_log_);
 }
 
 base::TimeDelta
@@ -178,11 +178,13 @@ TCPClientSocketPool::TCPClientSocketPool(
     const scoped_refptr<ClientSocketPoolHistograms>& histograms,
     HostResolver* host_resolver,
     ClientSocketFactory* client_socket_factory,
-    NetworkChangeNotifier* network_change_notifier)
+    NetworkChangeNotifier* network_change_notifier,
+    NetLog* net_log)
     : base_(max_sockets, max_sockets_per_group, histograms,
             base::TimeDelta::FromSeconds(kUnusedIdleSocketTimeout),
             base::TimeDelta::FromSeconds(kUsedIdleSocketTimeout),
-            new TCPConnectJobFactory(client_socket_factory, host_resolver),
+            new TCPConnectJobFactory(client_socket_factory,
+                                     host_resolver, net_log),
             network_change_notifier) {
   base_.enable_backup_jobs();
 }
diff --git a/net/socket/tcp_client_socket_pool.h b/net/socket/tcp_client_socket_pool.h
index 355bd2a..ea2ef70 100644
--- a/net/socket/tcp_client_socket_pool.h
+++ b/net/socket/tcp_client_socket_pool.h
@@ -64,7 +64,7 @@ class TCPConnectJob : public ConnectJob {
                 ClientSocketFactory* client_socket_factory,
                 HostResolver* host_resolver,
                 Delegate* delegate,
-                const BoundNetLog& net_log);
+                NetLog* net_log);
   virtual ~TCPConnectJob();
 
   // ConnectJob methods.
@@ -118,7 +118,8 @@ class TCPClientSocketPool : public ClientSocketPool {
       const scoped_refptr<ClientSocketPoolHistograms>& histograms,
       HostResolver* host_resolver,
       ClientSocketFactory* client_socket_factory,
-      NetworkChangeNotifier* network_change_notifier);
+      NetworkChangeNotifier* network_change_notifier,
+      NetLog* net_log);
 
   // ClientSocketPool methods:
 
@@ -164,9 +165,11 @@ class TCPClientSocketPool : public ClientSocketPool {
       : public PoolBase::ConnectJobFactory {
    public:
     TCPConnectJobFactory(ClientSocketFactory* client_socket_factory,
-                         HostResolver* host_resolver)
+                         HostResolver* host_resolver,
+                         NetLog* net_log)
         : client_socket_factory_(client_socket_factory),
-          host_resolver_(host_resolver) {}
+          host_resolver_(host_resolver),
+          net_log_(net_log) {}
 
     virtual ~TCPConnectJobFactory() {}
 
@@ -175,14 +178,14 @@ class TCPClientSocketPool : public ClientSocketPool {
     virtual ConnectJob* NewConnectJob(
         const std::string& group_name,
         const PoolBase::Request& request,
-        ConnectJob::Delegate* delegate,
-        const BoundNetLog& net_log) const;
+        ConnectJob::Delegate* delegate) const;
 
     virtual base::TimeDelta ConnectionTimeout() const;
 
    private:
     ClientSocketFactory* const client_socket_factory_;
     const scoped_refptr<HostResolver> host_resolver_;
+    NetLog* net_log_;
 
     DISALLOW_COPY_AND_ASSIGN(TCPConnectJobFactory);
   };
diff --git a/net/socket/tcp_client_socket_pool_unittest.cc b/net/socket/tcp_client_socket_pool_unittest.cc
index e0dc09f..25e7fdd 100644
--- a/net/socket/tcp_client_socket_pool_unittest.cc
+++ b/net/socket/tcp_client_socket_pool_unittest.cc
@@ -272,7 +272,8 @@ class TCPClientSocketPoolTest : public ClientSocketPoolTest {
                                       histograms_,
                                       host_resolver_,
                                       &client_socket_factory_,
-                                      &notifier_)) {
+                                      &notifier_,
+                                      NULL)) {
   }
 
   int StartRequest(const std::string& group_name, RequestPriority priority) {
@@ -746,6 +747,7 @@ TEST_F(TCPClientSocketPoolTest, BackupSocketConnect) {
                                     histograms_,
                                     host_resolver_,
                                     &client_socket_factory_,
+                                    NULL,
                                     NULL);
   }
 }
diff --git a/net/socket/tcp_client_socket_unittest.cc b/net/socket/tcp_client_socket_unittest.cc
index 0c16010..a2b584a 100644
--- a/net/socket/tcp_client_socket_unittest.cc
+++ b/net/socket/tcp_client_socket_unittest.cc
@@ -102,12 +102,11 @@ TEST_F(TCPClientSocketTest, Connect) {
 
   int rv = sock_->Connect(&callback);
   EXPECT_TRUE(net::LogContainsBeginEvent(
-      net_log_.entries(), 0, net::NetLog::TYPE_TCP_CONNECT));
+      net_log_.entries(), 0, net::NetLog::TYPE_SOCKET_ALIVE));
+  EXPECT_TRUE(net::LogContainsBeginEvent(
+      net_log_.entries(), 1, net::NetLog::TYPE_TCP_CONNECT));
   if (rv != OK) {
     ASSERT_EQ(rv, ERR_IO_PENDING);
-    EXPECT_FALSE(net::LogContainsEndEvent(
-        net_log_.entries(), -1, net::NetLog::TYPE_TCP_CONNECT));
-
     rv = callback.WaitForResult();
     EXPECT_EQ(rv, OK);
   }
diff --git a/net/socket/tcp_client_socket_win.cc b/net/socket/tcp_client_socket_win.cc
index c663992..b25d07f 100644
--- a/net/socket/tcp_client_socket_win.cc
+++ b/net/socket/tcp_client_socket_win.cc
@@ -267,12 +267,13 @@ TCPClientSocketWin::TCPClientSocketWin(const AddressList& addresses,
       next_connect_state_(CONNECT_STATE_NONE),
       connect_os_error_(0),
       net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SOCKET)) {
+  net_log_.BeginEvent(NetLog::TYPE_SOCKET_ALIVE, NULL);
   EnsureWinsockInit();
 }
 
 TCPClientSocketWin::~TCPClientSocketWin() {
   Disconnect();
-  net_log_.AddEvent(NetLog::TYPE_TCP_SOCKET_DONE, NULL);
+  net_log_.EndEvent(NetLog::TYPE_SOCKET_ALIVE, NULL);
 }
 
 int TCPClientSocketWin::Connect(CompletionCallback* callback) {