Rework the logging for sockets/connectjobs....

net/socket/client_socket_pool_base.cc

 // Copyright (c) 2010 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/socket/client_socket_pool_base.h"
 
 #include "base/compiler_specific.h"
 #include "base/format_macros.h"
 #include "base/message_loop.h"
 #include "base/stats_counters.h"
@@ skipping 24 matching lines @@
                        base::TimeDelta timeout_duration,
                        Delegate* delegate,
                        const BoundNetLog& net_log)
     : group_name_(group_name),
       timeout_duration_(timeout_duration),
       delegate_(delegate),
       net_log_(net_log),
       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);
 }
 
 void ConnectJob::ResetTimer(base::TimeDelta remaining_time) {
   timer_.Stop();
   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);
 
   net_log_.AddEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_TIMED_OUT, NULL);
 
   NotifyDelegateOfCompletion(ERR_TIMED_OUT);
 }
 
 namespace internal {
@@ skipping 130 matching lines @@
     delete idle_socket.socket;
   }
 
   // See if we already have enough connect jobs or sockets that will be released
   // soon.
   if (group.HasReleasingSockets()) {
     return ERR_IO_PENDING;
   }
 
   // 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) {
     // If we don't have any sockets in this group, set a timer for potentially
     // creating a new one.  If the SYN is lost, this backup socket may complete
     // before the slow socket, improving end user latency.
     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);
     }
 
     connecting_socket_count_++;
 
     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);
   }
 
   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));
   Group& group = group_map_[group_name];
 
   // Only allow one timer pending to create a backup socket.
   if (group.backup_task)
     return;
 
   group.backup_task = method_factory_.NewRunnableMethod(
@@ skipping 12 matching lines @@
   group.backup_task = NULL;
 
   CHECK(group.backup_job);
 
   // If our backup job is waiting on DNS, or if we can't create any sockets
   // right now due to limits, just reset the timer.
   CHECK(group.jobs.size());
   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;
   }
 
   group.backup_job->net_log().AddEvent(NetLog::TYPE_SOCKET_BACKUP_CREATED,
                                        NULL);
   SIMPLE_STATS_COUNTER("socket.backup_created");
   int rv = group.backup_job->Connect();
   connecting_socket_count_++;
   group.jobs.insert(group.backup_job);
@@ skipping 249 matching lines @@
   scoped_ptr<ClientSocket> socket(job->ReleaseSocket());
 
   BoundNetLog job_log = job->net_log();
   RemoveConnectJob(job, &group);
 
   if (result == OK) {
     DCHECK(socket.get());
     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);
       OnAvailableSocketSlot(group_name, &group);
     }
   } else {
     DCHECK(!socket.get());
     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);
   }
 }
 
 void ClientSocketPoolBaseHelper::OnIPAddressChanged() {
   CloseIdleSockets();
 }
 
@@ skipping 43 matching lines @@
   }
 }
 
 void ClientSocketPoolBaseHelper::ProcessPendingRequest(
     const std::string& group_name, Group* group) {
   int rv = RequestSocketInternal(group_name, *group->pending_requests.begin());
 
   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
       // |group_map_| again.
       MaybeOnAvailableSocketSlot(group_name);
     }
   }
 }
 
 void ClientSocketPoolBaseHelper::HandOutSocket(
     ClientSocket* socket,
     bool reused,
     ClientSocketHandle* handle,
     base::TimeDelta idle_time,
     Group* group,
     const BoundNetLog& net_log) {
   DCHECK(socket);
   handle->set_socket(socket);
   handle->set_is_reused(reused);
   handle->set_idle_time(idle_time);
 
   if (reused) {
     net_log.AddEvent(
         NetLog::TYPE_SOCKET_POOL_REUSED_AN_EXISTING_SOCKET,
         new NetLogIntegerParameter(
             "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++;
 }
 
 void ClientSocketPoolBaseHelper::AddIdleSocket(
     ClientSocket* socket, bool used, Group* group) {
   DCHECK(socket);
   IdleSocket idle_socket;
   idle_socket.socket = socket;
@@ skipping 30 matching lines @@
   DCHECK_LE(total, max_sockets_);
   if (total < max_sockets_)
     return false;
   LOG(WARNING) << "ReachedMaxSocketsLimit: " << total << "/" << max_sockets_;
   return true;
 }
 
 }  // namespace internal
 
 }  // namespace net