Rework the logging for sockets/connectjobs....

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.

Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=48797

[willchan no longer on Chromium, 2010-05-28 23:14:22]

Feel free not to start addressing these comments.  They're half-baked still. 
I'm still digesting everything.  I'm just sending it out now because I don't
think I'll have full comments until next week (and will probably have to re-page
everything back in).

http://codereview.chromium.org/2363003/diff/28001/29003
File chrome/browser/net/passive_log_collector.cc (right):

http://codereview.chromium.org/2363003/diff/28001/29003#newcode48
chrome/browser/net/passive_log_collector.cc:48:
init_proxy_resolver_tracker_.func;    \
Can you just initialize an array of RequestTrackerBase* as a member of the
object?  The memory cost should be minimal.  It avoids this macro stuff and
eliminates the GetTrackerForSourceType() stuff.  It also prevents sync'ing
issues.  When you initialize the array member in the constructor body, you can
add a for loop for (int i = 0; i < NUM_SOURCE_TYPES; ++i) CHECK(trackers_[i]);
to enforce they're non-zero.  You need to make sure that the constructor
initializer list zero initializes the array, which you can do by including it in
the initializer list |trackers_()|.

http://codereview.chromium.org/2363003/diff/28001/29003#newcode98
chrome/browser/net/passive_log_collector.cc:98: default:
Is this ever expected to be NULL?  It's not getting recorded then, right? 
Sounds like a bug and we should LOG(DFATAL).  Let me know if it's valid in some
case.

http://codereview.chromium.org/2363003/diff/28001/29004
File chrome/browser/net/passive_log_collector.h (right):

http://codereview.chromium.org/2363003/diff/28001/29004#newcode63
chrome/browser/net/passive_log_collector.h:63: DependentSourceList
dependent_sources;
I read "DependentSourceList" out to someone else.  I think you have it
backwards.  These should be SourceDependencies or SourceDependencyList or
something.  Either that or I'm reading your comment backward.

http://codereview.chromium.org/2363003/diff/28001/29004#newcode84
chrome/browser/net/passive_log_collector.h:84: virtual ~RequestTrackerBase() {}
Please define this in the .cc file.  This is adding the code bloat for the
inlined destructor of std::deque<uint32>.

http://codereview.chromium.org/2363003/diff/28001/29004#newcode116
chrome/browser/net/passive_log_collector.h:116: protected:
You have protected: twice.

http://codereview.chromium.org/2363003/diff/28001/29004#newcode135
chrome/browser/net/passive_log_collector.h:135: void
IncrementReferenceCountForSource(int offset, uint32 source_id);
Probably should be named Adjust instead of Increment.

http://codereview.chromium.org/2363003/diff/28001/29004#newcode205
chrome/browser/net/passive_log_collector.h:205: protected:
This doesn't need to be protected.  It's only called by the base class, right?

http://codereview.chromium.org/2363003/diff/28001/29011
File net/http/http_cache.h (right):

http://codereview.chromium.org/2363003/diff/28001/29011#newcode18
net/http/http_cache.h:18: #include <string>
out of order

http://codereview.chromium.org/2363003/diff/28001/29022
File net/socket/client_socket_pool_base.h (right):

http://codereview.chromium.org/2363003/diff/28001/29022#newcode102
net/socket/client_socket_pool_base.h:102: virtual void LogConnectStart();
Why is this virtual?

[eroman, 2010-05-29 01:16:23]

http://codereview.chromium.org/2363003/diff/28001/29003
File chrome/browser/net/passive_log_collector.cc (right):

http://codereview.chromium.org/2363003/diff/28001/29003#newcode48
chrome/browser/net/passive_log_collector.cc:48:
init_proxy_resolver_tracker_.func;    \
On 2010/05/28 23:14:23, willchan wrote:
> Can you just initialize an array of RequestTrackerBase* as a member of the
> object?  The memory cost should be minimal.  It avoids this macro stuff and
> eliminates the GetTrackerForSourceType() stuff.  It also prevents sync'ing
> issues.  When you initialize the array member in the constructor body, you can
> add a for loop for (int i = 0; i < NUM_SOURCE_TYPES; ++i) CHECK(trackers_[i]);
> to enforce they're non-zero.  You need to make sure that the constructor
> initializer list zero initializes the array, which you can do by including it
in
> the initializer list |trackers_()|.

Done. I hardcoded the values for NetLog::SourceType to make this work well.

Note that I left the FOR_EACH_TRACKER macro(), and I didn't use the initializer
since I wasn't able to get VS to stop warning.

http://codereview.chromium.org/2363003/diff/28001/29003#newcode98
chrome/browser/net/passive_log_collector.cc:98: default:
On 2010/05/28 23:14:23, willchan wrote:
> Is this ever expected to be NULL?  It's not getting recorded then, right? 
> Sounds like a bug and we should LOG(DFATAL).  Let me know if it's valid in
some
> case.

No longer applicable.

http://codereview.chromium.org/2363003/diff/28001/29004
File chrome/browser/net/passive_log_collector.h (right):

http://codereview.chromium.org/2363003/diff/28001/29004#newcode63
chrome/browser/net/passive_log_collector.h:63: DependentSourceList
dependent_sources;
On 2010/05/28 23:14:23, willchan wrote:
> I read "DependentSourceList" out to someone else.  I think you have it
> backwards.  These should be SourceDependencies or SourceDependencyList or
> something.  Either that or I'm reading your comment backward.

Done.

http://codereview.chromium.org/2363003/diff/28001/29004#newcode84
chrome/browser/net/passive_log_collector.h:84: virtual ~RequestTrackerBase() {}
On 2010/05/28 23:14:23, willchan wrote:
> Please define this in the .cc file.  This is adding the code bloat for the
> inlined destructor of std::deque<uint32>.

Done.

http://codereview.chromium.org/2363003/diff/28001/29004#newcode116
chrome/browser/net/passive_log_collector.h:116: protected:
On 2010/05/28 23:14:23, willchan wrote:
> You have protected: twice.

Done.

http://codereview.chromium.org/2363003/diff/28001/29004#newcode135
chrome/browser/net/passive_log_collector.h:135: void
IncrementReferenceCountForSource(int offset, uint32 source_id);
On 2010/05/28 23:14:23, willchan wrote:
> Probably should be named Adjust instead of Increment.

Done.

(You suggested this to me once before, but I couldn't remember the magic name :)

http://codereview.chromium.org/2363003/diff/28001/29004#newcode205
chrome/browser/net/passive_log_collector.h:205: protected:
On 2010/05/28 23:14:23, willchan wrote:
> This doesn't need to be protected.  It's only called by the base class, right?

Correct. I am matching the style with the other trackers, so If I make a change
it should be to all.

http://codereview.chromium.org/2363003/diff/28001/29011
File net/http/http_cache.h (right):

http://codereview.chromium.org/2363003/diff/28001/29011#newcode18
net/http/http_cache.h:18: #include <string>
On 2010/05/28 23:14:23, willchan wrote:
> out of order

Done.

http://codereview.chromium.org/2363003/diff/28001/29022
File net/socket/client_socket_pool_base.h (right):

http://codereview.chromium.org/2363003/diff/28001/29022#newcode102
net/socket/client_socket_pool_base.h:102: virtual void LogConnectStart();
On 2010/05/28 23:14:23, willchan wrote:
> Why is this virtual?

Removed.

(In an earlier draft, I had different subclasses printing a different set of
parameters, now I only print connection_group from all).

[willchan no longer on Chromium, 2010-06-01 19:39:47]

I think I've got the PassiveLogCollector stuff all in my head now.  I'm starting
to think lots of the "Request" stuff should be renamed to "Source" (SourceInfo,
SourceTracker, etc).  I'm also wondering if the trackers that are actually
requests should maintain auxiliary data structures that map a RequestInfo to a
URL, rather than embedding this into RequestInfo.  Food for thought.  I'm not
expecting you to tackle my suggestions in this changelist, although I'd like to
hear your response to them.

I still need to review all the other code that changed, and also the test
changes.  But this is probably enough for me to unblock you for now.

http://codereview.chromium.org/2363003/diff/69001/70004
File chrome/browser/net/passive_log_collector.cc (right):

http://codereview.chromium.org/2363003/diff/69001/70004#newcode40
chrome/browser/net/passive_log_collector.cc:40: #define FOR_EACH_TRACKER(func) \
I'm not sure if it's worth keeping this macro.  It's only 2 lines of code at
each call site.

http://codereview.chromium.org/2363003/diff/69001/70004#newcode180
chrome/browser/net/passive_log_collector.cc:180: void
PassiveLogCollector::RequestTrackerBase::DeleteRequestInfo(
What happens when a request that is in |deletion_queue_| is manually deleted? 
Is there a test for this somewhere?

http://codereview.chromium.org/2363003/diff/69001/70004#newcode234
chrome/browser/net/passive_log_collector.cc:234: if (it == requests_.end())
If this condition valid?  It's not immediately obvious to me when it would be. 
If it's valid, can you add comments here?  Otherwise, can you add an assertion?

http://codereview.chromium.org/2363003/diff/69001/70004#newcode243
chrome/browser/net/passive_log_collector.cc:243: if (info.reference_count == 1
&& offset == 1) {
This seems confusing to me.  I sorta think that for long-lived sources that
aren't necessarily tied to a single request, we should always keep them around,
until they close down, and then move them to the graveyard.  Once they're closed
down, then it should be impossible for anyone to acquire new references to them.
 I'm thinking of sockets and spdy sessions here.  They're long-lived, and until
they get completely closed, I think we should keep them.

I read through the socket and init proxy resolver and spdy session trackers. 
They all seem to do this, so I don't see what situation can cause us to hit this
condition.  Do you have a test for this situation?

http://codereview.chromium.org/2363003/diff/69001/70004#newcode309
chrome/browser/net/passive_log_collector.cc:309: AddEntryToRequestInfo(entry,
out_info);
Does every request tracker do this now?  Can we move this into OnAddEntry()?

http://codereview.chromium.org/2363003/diff/69001/70005
File chrome/browser/net/passive_log_collector.h (right):

http://codereview.chromium.org/2363003/diff/69001/70005#newcode19
chrome/browser/net/passive_log_collector.h:19: class PassiveLogCollector :
public ChromeNetLog::Observer {
This PassiveLogCollector is complicated enough now that it really needs
class/file comments describing the overall architecture.

http://codereview.chromium.org/2363003/diff/69001/70005#newcode46
chrome/browser/net/passive_log_collector.h:46: struct RequestInfo {
Does this need to get renamed?  These are not always associated with a request. 
Perhaps Source would be a better name?  I dunno.  Not something that necessarily
needs to be done in this change.  It's just something that I found confusing
when reading through this.

http://codereview.chromium.org/2363003/diff/69001/70005#newcode117
chrome/browser/net/passive_log_collector.h:117: void
AddReferenceToDependentSource(const net::NetLog::Source& source,
s/DependentSource/SourceDependency/ for consistency.

http://codereview.chromium.org/2363003/diff/69001/70005#newcode128
chrome/browser/net/passive_log_collector.h:128: void DeleteRequestInfo(uint32
source_id);
Please comment these functions.  I think it's useful to note that
DeleteRequestInfo will release references from the RequestInfo on other
dependencies.

[willchan no longer on Chromium, 2010-06-01 20:08:22]

Read through the rest of the files too now.  Mod the tests.

http://codereview.chromium.org/2363003/diff/69001/70010
File net/base/net_log_event_type_list.h (right):

http://codereview.chromium.org/2363003/diff/69001/70010#newcode296
net/base/net_log_event_type_list.h:296: //      "dependent_source": <Source
identifer for the connect job we bound to>
Rename to "source_dependency"?

http://codereview.chromium.org/2363003/diff/69001/70015
File net/http/http_network_layer.h (right):

http://codereview.chromium.org/2363003/diff/69001/70015#newcode91
net/http/http_network_layer.h:91: NetLog* net_log_;
Does it have to be here?  Can't we just get it from the session?  I think it's
probably the same for most of these other member variables.  I thought they just
existed for lazily creating the session.

http://codereview.chromium.org/2363003/diff/69001/70023
File net/socket/client_socket_pool_base.cc (left):

http://codereview.chromium.org/2363003/diff/69001/70023#oldcode316
net/socket/client_socket_pool_base.cc:316:
NetLog::TYPE_SOCKET_BACKUP_TIMER_EXTENDED, NULL);
Is this completely gone now?

http://codereview.chromium.org/2363003/diff/69001/70023
File net/socket/client_socket_pool_base.cc (right):

http://codereview.chromium.org/2363003/diff/69001/70023#newcode72
net/socket/client_socket_pool_base.cc:72:
net_log().AddEvent(NetLog::TYPE_CONNECT_JOB_SET_SOCKET,
I think this is relying on some unspecified semantics.  set_socket() probably
should not be called multiple times per ConnectJob.  We should document this in
the comments for set_socket().

[eroman, 2010-06-01 21:06:25]

Responses to first batch of comments.

http://codereview.chromium.org/2363003/diff/69001/70004
File chrome/browser/net/passive_log_collector.cc (right):

http://codereview.chromium.org/2363003/diff/69001/70004#newcode40
chrome/browser/net/passive_log_collector.cc:40: #define FOR_EACH_TRACKER(func) \
On 2010/06/01 19:39:47, willchan wrote:
> I'm not sure if it's worth keeping this macro.  It's only 2 lines of code at
> each call site.

Done.

http://codereview.chromium.org/2363003/diff/69001/70004#newcode180
chrome/browser/net/passive_log_collector.cc:180: void
PassiveLogCollector::RequestTrackerBase::DeleteRequestInfo(
On 2010/06/01 19:39:47, willchan wrote:
> What happens when a request that is in |deletion_queue_| is manually deleted? 
> Is there a test for this somewhere?

That shouldn't be a possible code-path (we remove from deletion queue before
calling this function).

I have added a DCHECK to make sure that doesn't happen.

http://codereview.chromium.org/2363003/diff/69001/70004#newcode234
chrome/browser/net/passive_log_collector.cc:234: if (it == requests_.end())
On 2010/06/01 19:39:47, willchan wrote:
> If this condition valid?  It's not immediately obvious to me when it would be.

> If it's valid, can you add comments here?  Otherwise, can you add an
assertion?

It is possible to reach this because of RequestTrackerBase::Clear().
Clear() drops all the data, regardless of its reference count.

In this case, it is possible that the sources we nuked were referenced by some
other tracker, and it will later try to deref it.

I have added a comment explaining why that check is necessary, and a TODO for a
test that exercises it.

http://codereview.chromium.org/2363003/diff/69001/70004#newcode243
chrome/browser/net/passive_log_collector.cc:243: if (info.reference_count == 1
&& offset == 1) {
On 2010/06/01 19:39:47, willchan wrote:
> This seems confusing to me.  I sorta think that for long-lived sources that
> aren't necessarily tied to a single request, we should always keep them
around,
> until they close down, and then move them to the graveyard.  Once they're
closed
> down, then it should be impossible for anyone to acquire new references to
them.
>  I'm thinking of sockets and spdy sessions here.  They're long-lived, and
until
> they get completely closed, I think we should keep them.
> 
> I read through the socket and init proxy resolver and spdy session trackers. 
> They all seem to do this, so I don't see what situation can cause us to hit
this
> condition.  Do you have a test for this situation?

This is the case with ConnectJobs.

The way the code in ClientSocketPoolBaseHelper is organized, we first
RemoveConnectJob() (which deletes the job), and then figure out which request to
give the socket to.

Rather than try to rework that code, I think it is most appropriate to allow for
this case. (I don't want PassiveLogCollector's particular implementation to
complicate how log entries can be emitted).

http://codereview.chromium.org/2363003/diff/69001/70004#newcode309
chrome/browser/net/passive_log_collector.cc:309: AddEntryToRequestInfo(entry,
out_info);
On 2010/06/01 19:39:47, willchan wrote:
> Does every request tracker do this now?  Can we move this into OnAddEntry()?

Not every codepath ends up calling AddEntryToRequestInfo(). For example
SocketTracker does not save the bytes sent/received (however I have a TODO for
aggregating these).

http://codereview.chromium.org/2363003/diff/69001/70005
File chrome/browser/net/passive_log_collector.h (right):

http://codereview.chromium.org/2363003/diff/69001/70005#newcode19
chrome/browser/net/passive_log_collector.h:19: class PassiveLogCollector :
public ChromeNetLog::Observer {
On 2010/06/01 19:39:47, willchan wrote:
> This PassiveLogCollector is complicated enough now that it really needs
> class/file comments describing the overall architecture.

Done.

http://codereview.chromium.org/2363003/diff/69001/70005#newcode46
chrome/browser/net/passive_log_collector.h:46: struct RequestInfo {
On 2010/06/01 19:39:47, willchan wrote:
> Does this need to get renamed?  These are not always associated with a
request. 
> Perhaps Source would be a better name?  I dunno.  Not something that
necessarily
> needs to be done in this change.  It's just something that I found confusing
> when reading through this.

Yes, these should be renamed "Request".
I have added a TODO, will do it in another pass.

http://codereview.chromium.org/2363003/diff/69001/70005#newcode117
chrome/browser/net/passive_log_collector.h:117: void
AddReferenceToDependentSource(const net::NetLog::Source& source,
On 2010/06/01 19:39:47, willchan wrote:
> s/DependentSource/SourceDependency/ for consistency.

Done.

http://codereview.chromium.org/2363003/diff/69001/70005#newcode128
chrome/browser/net/passive_log_collector.h:128: void DeleteRequestInfo(uint32
source_id);
On 2010/06/01 19:39:47, willchan wrote:
> Please comment these functions.  I think it's useful to note that
> DeleteRequestInfo will release references from the RequestInfo on other
> dependencies.

Done.

[eroman, 2010-06-01 21:08:52]

http://codereview.chromium.org/2363003/diff/69001/70005
File chrome/browser/net/passive_log_collector.h (right):

http://codereview.chromium.org/2363003/diff/69001/70005#newcode46
chrome/browser/net/passive_log_collector.h:46: struct RequestInfo {
On 2010/06/01 21:06:25, eroman wrote:
> On 2010/06/01 19:39:47, willchan wrote:
> > Does this need to get renamed?  These are not always associated with a
> request. 
> > Perhaps Source would be a better name?  I dunno.  Not something that
> necessarily
> > needs to be done in this change.  It's just something that I found confusing
> > when reading through this.
> 
> Yes, these should be renamed "Request".

Er, I meant "Source" :)

> I have added a TODO, will do it in another pass.

[eroman, 2010-06-01 22:56:17]

Last batch of comments addressed:

http://codereview.chromium.org/2363003/diff/69001/70010
File net/base/net_log_event_type_list.h (right):

http://codereview.chromium.org/2363003/diff/69001/70010#newcode296
net/base/net_log_event_type_list.h:296: //      "dependent_source": <Source
identifer for the connect job we bound to>
On 2010/06/01 20:08:22, willchan wrote:
> Rename to "source_dependency"?

Done.

http://codereview.chromium.org/2363003/diff/69001/70015
File net/http/http_network_layer.h (right):

http://codereview.chromium.org/2363003/diff/69001/70015#newcode91
net/http/http_network_layer.h:91: NetLog* net_log_;
On 2010/06/01 20:08:22, willchan wrote:
> Does it have to be here?  Can't we just get it from the session?  I think it's
> probably the same for most of these other member variables.  I thought they
just
> existed for lazily creating the session.

There are two ways of creating a NetworkLayer:

(1) From a set of parameters (and the HttpNetworkSession will be lazily
initialized on first access).
(2) From an existing HttpNetworkSession.

In case (1), all of the parameters that go into creating the HttpNetworkSession
get buffered by the HttpNetworkLayer until they are used to create the
HttpNetworkSession, at which point they are cleared.

I think what you are hinting at, is:
http://code.google.com/p/chromium/issues/detail?id=19323

http://codereview.chromium.org/2363003/diff/69001/70023
File net/socket/client_socket_pool_base.cc (left):

http://codereview.chromium.org/2363003/diff/69001/70023#oldcode316
net/socket/client_socket_pool_base.cc:316:
NetLog::TYPE_SOCKET_BACKUP_TIMER_EXTENDED, NULL);
On 2010/06/01 20:08:22, willchan wrote:
> Is this completely gone now?

Yes.
(I removed it from the .h now too).

The problem with these events is they weren't well thought out, and were getting
logged in a bizarre fashion (would show up in the URLRequest or the first
connect job or something). The other problem is they would spam for long
requests (emitted every XX ms), and eventually the source would hit truncation
from all these "extensions". I don't think it really adds value having that,
since you can infer how many times it was extended based on the time deltas.

I think the better way to do logging here would be to annotate the connect jobs
that were created as backups. Then you could tell if a backup job ended up
actually being used, or if all the in progress stuff is backups.

http://codereview.chromium.org/2363003/diff/69001/70023
File net/socket/client_socket_pool_base.cc (right):

http://codereview.chromium.org/2363003/diff/69001/70023#newcode72
net/socket/client_socket_pool_base.cc:72:
net_log().AddEvent(NetLog::TYPE_CONNECT_JOB_SET_SOCKET,
On 2010/06/01 20:08:22, willchan wrote:
> I think this is relying on some unspecified semantics.  set_socket() probably
> should not be called multiple times per ConnectJob.  We should document this
in
> the comments for set_socket().

It can get called with NULL when an error happens.

I will think about other ways to do this..

[willchan no longer on Chromium, 2010-06-01 23:31:18]

I need to re-read parts of the code again, but here are some responses to your
comments.

http://codereview.chromium.org/2363003/diff/69001/70004
File chrome/browser/net/passive_log_collector.cc (right):

http://codereview.chromium.org/2363003/diff/69001/70004#newcode180
chrome/browser/net/passive_log_collector.cc:180: void
PassiveLogCollector::RequestTrackerBase::DeleteRequestInfo(
On 2010/06/01 21:06:25, eroman wrote:
> On 2010/06/01 19:39:47, willchan wrote:
> > What happens when a request that is in |deletion_queue_| is manually
deleted? 
> > Is there a test for this somewhere?
> 
> That shouldn't be a possible code-path (we remove from deletion queue before
> calling this function).
> 
> I have added a DCHECK to make sure that doesn't happen.

Where's the code path that removes from a deletion queue before calling this
function?  I'm actually not quite sure how the javascript manually deletes a
request, so I wasn't able to trace the flow.  I see two places though that call
DeleteRequestInfo():
RequestTrackerBase::OnAddEntry()
and
RequestTrackerBase::AddToDeletionQueue().  I didn't see where the deletion queue
gets modified before these calls.

http://codereview.chromium.org/2363003/diff/69001/70004#newcode234
chrome/browser/net/passive_log_collector.cc:234: if (it == requests_.end())
On 2010/06/01 21:06:25, eroman wrote:
> On 2010/06/01 19:39:47, willchan wrote:
> > If this condition valid?  It's not immediately obvious to me when it would
be.
> 
> > If it's valid, can you add comments here?  Otherwise, can you add an
> assertion?
> 
> It is possible to reach this because of RequestTrackerBase::Clear().
> Clear() drops all the data, regardless of its reference count.
> 
> In this case, it is possible that the sources we nuked were referenced by some
> other tracker, and it will later try to deref it.
> 
> I have added a comment explaining why that check is necessary, and a TODO for
a
> test that exercises it.

Ah, this makes sense.  Thanks for the explanation.

http://codereview.chromium.org/2363003/diff/69001/70004#newcode243
chrome/browser/net/passive_log_collector.cc:243: if (info.reference_count == 1
&& offset == 1) {
On 2010/06/01 21:06:25, eroman wrote:
> On 2010/06/01 19:39:47, willchan wrote:
> > This seems confusing to me.  I sorta think that for long-lived sources that
> > aren't necessarily tied to a single request, we should always keep them
> around,
> > until they close down, and then move them to the graveyard.  Once they're
> closed
> > down, then it should be impossible for anyone to acquire new references to
> them.
> >  I'm thinking of sockets and spdy sessions here.  They're long-lived, and
> until
> > they get completely closed, I think we should keep them.
> > 
> > I read through the socket and init proxy resolver and spdy session trackers.

> > They all seem to do this, so I don't see what situation can cause us to hit
> this
> > condition.  Do you have a test for this situation?
> 
> This is the case with ConnectJobs.
> 
> The way the code in ClientSocketPoolBaseHelper is organized, we first
> RemoveConnectJob() (which deletes the job), and then figure out which request
to
> give the socket to.
> 
> Rather than try to rework that code, I think it is most appropriate to allow
for
> this case. (I don't want PassiveLogCollector's particular implementation to
> complicate how log entries can be emitted).

Practically speaking, you're probably correct.  Something still feels unclean to
me, because since we're reaching into the graveyard for this, it technically
could drop off the end of the graveyard before we use it.  This might actually
happen if we have more jobs than requests (backup jobs or canceled requests), so
the sockets sit in the idle socket pool for awhile before getting used.  In the
meanwhile, the SourceInfo for the jobs might get deleted from the graveyard,
before the socket actually gets used.  That seems unfortunate.  I wonder if
there's a way to change the API to indicate the the connect job's SourceInfo
should stay alive until it gets used.  Perhaps we need an extra begin/end event
pair, where the end event only happens when the socket/error is given to a
ClientSocketHandle, or the idle socket is closed.

http://codereview.chromium.org/2363003/diff/69001/70004#newcode309
chrome/browser/net/passive_log_collector.cc:309: AddEntryToRequestInfo(entry,
out_info);
On 2010/06/01 21:06:25, eroman wrote:
> On 2010/06/01 19:39:47, willchan wrote:
> > Does every request tracker do this now?  Can we move this into OnAddEntry()?
> 
> Not every codepath ends up calling AddEntryToRequestInfo(). For example
> SocketTracker does not save the bytes sent/received (however I have a TODO for
> aggregating these).

Am I misreading it?  PassiveLogCollector::SocketTracker::DoAddEntry() seems to
call AddEntryToRequestInfo().

http://codereview.chromium.org/2363003/diff/69001/70015
File net/http/http_network_layer.h (right):

http://codereview.chromium.org/2363003/diff/69001/70015#newcode91
net/http/http_network_layer.h:91: NetLog* net_log_;
On 2010/06/01 22:56:18, eroman wrote:
> On 2010/06/01 20:08:22, willchan wrote:
> > Does it have to be here?  Can't we just get it from the session?  I think
it's
> > probably the same for most of these other member variables.  I thought they
> just
> > existed for lazily creating the session.
> 
> There are two ways of creating a NetworkLayer:
> 
> (1) From a set of parameters (and the HttpNetworkSession will be lazily
> initialized on first access).
> (2) From an existing HttpNetworkSession.
> 
> In case (1), all of the parameters that go into creating the
HttpNetworkSession
> get buffered by the HttpNetworkLayer until they are used to create the
> HttpNetworkSession, at which point they are cleared.
> 
> I think what you are hinting at, is:
> http://code.google.com/p/chromium/issues/detail?id=19323

Oh, I forgot about that bug.  Actually, what I was thinking was that you were
not just using it lazily.  I see that you are now.  It wasn't obvious from the
header.  As you can see from the comment above, it is implied from lines 79-80
that only the host resolver and proxy service are used lazily in this matter.

http://codereview.chromium.org/2363003/diff/69001/70023
File net/socket/client_socket_pool_base.cc (left):

http://codereview.chromium.org/2363003/diff/69001/70023#oldcode316
net/socket/client_socket_pool_base.cc:316:
NetLog::TYPE_SOCKET_BACKUP_TIMER_EXTENDED, NULL);
On 2010/06/01 22:56:18, eroman wrote:
> On 2010/06/01 20:08:22, willchan wrote:
> > Is this completely gone now?
> 
> Yes.
> (I removed it from the .h now too).
> 
> The problem with these events is they weren't well thought out, and were
getting
> logged in a bizarre fashion (would show up in the URLRequest or the first
> connect job or something). The other problem is they would spam for long
> requests (emitted every XX ms), and eventually the source would hit truncation
> from all these "extensions". I don't think it really adds value having that,
> since you can infer how many times it was extended based on the time deltas.
> 
> I think the better way to do logging here would be to annotate the connect
jobs
> that were created as backups. Then you could tell if a backup job ended up
> actually being used, or if all the in progress stuff is backups.

You should add this to the changelist description.  I'm going to cc mbelshe
about this in case he has any comments.  I'm fine with your suggestion of simply
tagging which ConnectJobs were backups.

http://codereview.chromium.org/2363003/diff/69001/70023
File net/socket/client_socket_pool_base.cc (right):

http://codereview.chromium.org/2363003/diff/69001/70023#newcode72
net/socket/client_socket_pool_base.cc:72:
net_log().AddEvent(NetLog::TYPE_CONNECT_JOB_SET_SOCKET,
On 2010/06/01 22:56:18, eroman wrote:
> On 2010/06/01 20:08:22, willchan wrote:
> > I think this is relying on some unspecified semantics.  set_socket()
probably
> > should not be called multiple times per ConnectJob.  We should document this
> in
> > the comments for set_socket().
> 
> It can get called with NULL when an error happens.

Sorry yes, what I meant was that it shouldn't be called multiple times with a
non-NULL parameter.

> 
> I will think about other ways to do this..

[willchan no longer on Chromium, 2010-06-02 22:40:44]

LGTM

http://codereview.chromium.org/2363003/diff/123002/106008
File chrome/browser/net/passive_log_collector_unittest.cc (right):

http://codereview.chromium.org/2363003/diff/123002/106008#newcode75
chrome/browser/net/passive_log_collector_unittest.cc:75: const
PassiveLogCollector::RequestTrackerBase* tracker) {
My style pref is to use a const reference instead of a pointer, to show that it
can't be NULL.

http://codereview.chromium.org/2363003/diff/123002/106013
File net/base/net_log_event_type_list.h (right):

http://codereview.chromium.org/2363003/diff/123002/106013#newcode293
net/base/net_log_event_type_list.h:293: //      "source_dependency": <Source
identifer for the connect job we bound to>
s/identifer/identifier/
"we bound to" sounds weird.  maybe "we are bound to"?

http://codereview.chromium.org/2363003/diff/123002/106033
File net/socket/tcp_client_socket_libevent.cc (right):

http://codereview.chromium.org/2363003/diff/123002/106033#newcode113
net/socket/tcp_client_socket_libevent.cc:113:
net_log_.BeginEvent(NetLog::TYPE_SOCKET_ALIVE, NULL);
I wonder if we'd actually be better off monitoring between when the socket is
connected and disconnected.  I don't have any concrete data here.  Just
wondering.

[eroman, 2010-06-02 22:52:56]

http://codereview.chromium.org/2363003/diff/123002/106008
File chrome/browser/net/passive_log_collector_unittest.cc (right):

http://codereview.chromium.org/2363003/diff/123002/106008#newcode75
chrome/browser/net/passive_log_collector_unittest.cc:75: const
PassiveLogCollector::RequestTrackerBase* tracker) {
On 2010/06/02 22:40:45, willchan wrote:
> My style pref is to use a const reference instead of a pointer, to show that
it
> can't be NULL.

Done.

(I was preferring pointer since it was a base class, but reference works too).

http://codereview.chromium.org/2363003/diff/123002/106013
File net/base/net_log_event_type_list.h (right):

http://codereview.chromium.org/2363003/diff/123002/106013#newcode293
net/base/net_log_event_type_list.h:293: //      "source_dependency": <Source
identifer for the connect job we bound to>
On 2010/06/02 22:40:45, willchan wrote:
> s/identifer/identifier/
> "we bound to" sounds weird.  maybe "we are bound to"?

Done.

http://codereview.chromium.org/2363003/diff/123002/106033
File net/socket/tcp_client_socket_libevent.cc (right):

http://codereview.chromium.org/2363003/diff/123002/106033#newcode113
net/socket/tcp_client_socket_libevent.cc:113:
net_log_.BeginEvent(NetLog::TYPE_SOCKET_ALIVE, NULL);
On 2010/06/02 22:40:45, willchan wrote:
> I wonder if we'd actually be better off monitoring between when the socket is
> connected and disconnected.  I don't have any concrete data here.  Just
> wondering.

My preference is both.

We already track the socket object's lifetime, as well as the  calls to
Connect().

The only omission right now is we don't track the calls to Disconnect(). (I
actually intend to add that soon, which is why I separated Disconnect() and
DoDisconnect() in an earlier change :).