NetLogEventParameter to Callback refactoring 1,

NetLogEventParameter to Callback refactoring 1,
Get rid of all uses of NetLogEventParameters in net/base,
with the exception of net_log itself, of course.

R=eroman@chromium.org
BUG=126243
Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=141666

[mmenke, 2012-06-11 22:24:36]

I want to get all these changes in before the branch point, just so we have less
extra junk around in M21, though the performance impact of the extra junk is
neglible (At least there's no noticeable difference in how long net_unittests
take on the bots, before and after the original CL as far as I could tell).

That gives us about 2 weeks.  Shouldn't be hard to do, just a lot of somewhat
dull refactoring.

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
File net/base/x509_certificate_net_log_param.h (left):

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
net/base/x509_certificate_net_log_param.h:21: // certificate, thus should only
be used when logging at NetLog::LOG_ALL.
Since we weren't actually doing this, I went ahead and removed the comment.

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
File net/base/x509_certificate_net_log_param.h (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
net/base/x509_certificate_net_log_param.h:17: // These parameters are memory
intensive, due to PEM-encoding each certificate.
I kept this file because of the frequency of X509Certificate's  use in files
that don't include any other net/ files.  I'm happy to move the code into
x509_certificate.cc, if you disagree.

[mmenke, 2012-06-11 22:25:57]

Oh, I tried to make set 2 vs set 4 easier to review on host_resolver_impl.cc by
just adjusting the indent of the original code in set 2, but it only worked for
the first function, which at least is the most complicated one.

[eroman, 2012-06-11 23:42:25]

http://codereview.chromium.org/10539094/diff/5032/net/base/address_list.h
File net/base/address_list.h (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/address_list.h#new...
net/base/address_list.h:22: class Value;
I believe net_log.h already declares this.

http://codereview.chromium.org/10539094/diff/5032/net/base/address_list.h#new...
net/base/address_list.h:59: base::Value* NetLogCallback(NetLog::LogLevel
log_level) const;
Given the usecases of this, might consider making it like:

Callback CreateNetlogParamsCallback();

To avoid all the callers doing the Bind stuff.

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_posix.cc
File net/base/file_stream_posix.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_posix....
net/base/file_stream_posix.cc:60: std::string error_name =
GetFileErrorSourceName(source);
Not a big deal either way since this is an error logging, but how about passing
in &source to NetLogFileStreamErrorCallback instead. And then having that guy do
the stringizing.

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_posix....
net/base/file_stream_posix.cc:82: NetLog::StringCallback("file_name",
&file_name));
Can you take address to to path.AsUTF8Unsafe() directly as a temporary? (Or does
the compiler barf?)

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_win.cc
File net/base/file_stream_win.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_win.cc...
net/base/file_stream_win.cc:49: std::string error_name =
GetFileErrorSourceName(source);
Same comment as for posix.

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_win.cc...
net/base/file_stream_win.cc:68: std::string file_name = path.AsUTF8Unsafe();
same comment as for posix.

http://codereview.chromium.org/10539094/diff/5032/net/base/host_resolver_impl.cc
File net/base/host_resolver_impl.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/host_resolver_impl...
net/base/host_resolver_impl.cc:264: return config->ToValue();
I didn't look in detail, but the original also set a num_hosts parameter.

http://codereview.chromium.org/10539094/diff/5032/net/base/host_resolver_impl...
net/base/host_resolver_impl.cc:673: NetLog::ParametersCallback callback;
optional nit: I suggest calling this "netlog_callback" or "params_callback"
simply because when reading "callback" I think the callback for the lookup
completion.

http://codereview.chromium.org/10539094/diff/5032/net/base/multi_threaded_cer...
File net/base/multi_threaded_cert_verifier.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/multi_threaded_cer...
net/base/multi_threaded_cert_verifier.cc:155: scoped_refptr<X509Certificate>
certificate() const { return cert_; }
Is this change necessary? Seems fine and I'm not suggesting you change it, but
wondering if it was actually necessary for correctness.

My understanding is it wouldn't matter if the extra reference was held from the
perspective of NetLog callback.

http://codereview.chromium.org/10539094/diff/5032/net/base/net_log.cc
File net/base/net_log.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/net_log.cc#newcode61
net/base/net_log.cc:61: if (!value)
Is it necessary to allow this? Seems like passing a NULL value could probably be
defined as an error instead.

http://codereview.chromium.org/10539094/diff/5032/net/base/net_log.h
File net/base/net_log.h (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/net_log.h#newcode299
net/base/net_log.h:299: // Creates a ParametersCallback that encapsulates a
single integer.  Takes
Update comment: "single integer" --> string

http://codereview.chromium.org/10539094/diff/5032/net/base/net_log.h#newcode300
net/base/net_log.h:300: // |value| as a pointer to avoid copying, and emphasize
it must be valid for
Should we describe anything about the encoding of |value|?

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
File net/base/x509_certificate_net_log_param.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
net/base/x509_certificate_net_log_param.cc:16: scoped_refptr<const
X509Certificate> certificate,
nit: per previous comment, might want to just pass a raw pointer to avoid
spamming refcounts.

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
net/base/x509_certificate_net_log_param.cc:18: if
(!NetLog::IsLoggingBytes(log_level))
Are you sure about this? I thought we were always logging these. Especially with
the new callback system, I think we should always log when netinternals is open.

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
File net/base/x509_certificate_net_log_param.h (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
net/base/x509_certificate_net_log_param.h:17: // These parameters are memory
intensive, due to PEM-encoding each certificate.
On 2012/06/11 22:24:36, Matt Menke wrote:
> I kept this file because of the frequency of X509Certificate's  use in files
> that don't include any other net/ files.  I'm happy to move the code into
> x509_certificate.cc, if you disagree.

I'm happy keeping things in place during refactor.
If we want to shuffle things around or change filenames, can do as a follow-up
step.

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
net/base/x509_certificate_net_log_param.h:18: base::Value*
NetLogX509CertificateNetLogCallback(
nit: The naming include NetLog twice, seems redundant.

http://codereview.chromium.org/10539094/diff/5032/net/socket/ssl_client_socke...
File net/socket/ssl_client_socket_openssl.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/socket/ssl_client_socke...
net/socket/ssl_client_socket_openssl.cc:825:
base::Bind(&NetLogX509CertificateNetLogCallback, server_cert_));
nit: indentation seems off

[mmenke, 2012-06-12 00:42:19]

Just to double-check...Temporaries are destroyed *after* the entire expression
has executed?  I Googled this, and it seems to be the case, but just want to
make doubly-sure, since we could crash, otherwise.

http://codereview.chromium.org/10539094/diff/5032/net/base/address_list.h
File net/base/address_list.h (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/address_list.h#new...
net/base/address_list.h:22: class Value;
On 2012/06/11 23:42:25, eroman wrote:
> I believe net_log.h already declares this.

Done.

http://codereview.chromium.org/10539094/diff/5032/net/base/address_list.h#new...
net/base/address_list.h:59: base::Value* NetLogCallback(NetLog::LogLevel
log_level) const;
On 2012/06/11 23:42:25, eroman wrote:
> Given the usecases of this, might consider making it like:
> 
> Callback CreateNetlogParamsCallback();
> 
> To avoid all the callers doing the Bind stuff.

Done, though used "CreateNetLogCallback" instead.  Decided early that
NetLogParamsCallback was too long to append everywhere, so used NetLogCallback
instead.

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_posix.cc
File net/base/file_stream_posix.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_posix....
net/base/file_stream_posix.cc:60: std::string error_name =
GetFileErrorSourceName(source);
On 2012/06/11 23:42:25, eroman wrote:
> Not a big deal either way since this is an error logging, but how about
passing
> in &source to NetLogFileStreamErrorCallback instead. And then having that guy
do
> the stringizing.

Done.

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_posix....
net/base/file_stream_posix.cc:82: NetLog::StringCallback("file_name",
&file_name));
On 2012/06/11 23:42:25, eroman wrote:
> Can you take address to to path.AsUTF8Unsafe() directly as a temporary? (Or
does
> the compiler barf?)


The compiler doesn't barf.

I had assumed temporaries were discarded when the function they were passed to
returned.  Looks like I was wrong, and they're discarded only after evaluation
of the entire expression.  Shockingly, it's never an issue I've had to care
about before.

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_win.cc
File net/base/file_stream_win.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_win.cc...
net/base/file_stream_win.cc:49: std::string error_name =
GetFileErrorSourceName(source);
On 2012/06/11 23:42:25, eroman wrote:
> Same comment as for posix.

Done.

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_win.cc...
net/base/file_stream_win.cc:68: std::string file_name = path.AsUTF8Unsafe();
On 2012/06/11 23:42:25, eroman wrote:
> same comment as for posix.

Done.

http://codereview.chromium.org/10539094/diff/5032/net/base/host_resolver_impl.cc
File net/base/host_resolver_impl.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/host_resolver_impl...
net/base/host_resolver_impl.cc:264: return config->ToValue();
On 2012/06/11 23:42:25, eroman wrote:
> I didn't look in detail, but the original also set a num_hosts parameter.

In the original, we made a copy of the config, except for the hosts part (Since
it can be big).  We go the count from the original, and passed it along.  In
this, since we're using the original one, we don't need to overwrite the
num_hosts, which is also written by ToValue.

http://codereview.chromium.org/10539094/diff/5032/net/base/host_resolver_impl...
net/base/host_resolver_impl.cc:673: NetLog::ParametersCallback callback;
On 2012/06/11 23:42:25, eroman wrote:
> optional nit: I suggest calling this "netlog_callback" or "params_callback"
> simply because when reading "callback" I think the callback for the lookup
> completion.

Done.

http://codereview.chromium.org/10539094/diff/5032/net/base/multi_threaded_cer...
File net/base/multi_threaded_cert_verifier.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/multi_threaded_cer...
net/base/multi_threaded_cert_verifier.cc:155: scoped_refptr<X509Certificate>
certificate() const { return cert_; }
On 2012/06/11 23:42:25, eroman wrote:
> Is this change necessary? Seems fine and I'm not suggesting you change it, but
> wondering if it was actually necessary for correctness.
> 
> My understanding is it wouldn't matter if the extra reference was held from
the
> perspective of NetLog callback.

It's not...But if it someone was being bad and keeping around a pointer to a ref
counted object before adding the first reference to it, and I stored it in a
refcounted temporary, bad things would happen.  Making this explicit makes life
less scary with a smart IDE that shows the return type of functions on mouse
over.

That having been said, since I've removed the code to add a ref, per your
suggestion, I've reverted this, since it's no longer an issue.

http://codereview.chromium.org/10539094/diff/5032/net/base/net_log.cc
File net/base/net_log.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/net_log.cc#newcode61
net/base/net_log.cc:61: if (!value)
On 2012/06/11 23:42:25, eroman wrote:
> Is it necessary to allow this? Seems like passing a NULL value could probably
be
> defined as an error instead.

You're right, done.  Also, noticed other related bugs - SingleIntegerCallback
should also not have the check, but Add/EndEventWithNetError should (Think I was
planning on a specific callback for errors, then changed my mind, though the
test above was still wrong).

http://codereview.chromium.org/10539094/diff/5032/net/base/net_log.h
File net/base/net_log.h (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/net_log.h#newcode299
net/base/net_log.h:299: // Creates a ParametersCallback that encapsulates a
single integer.  Takes
On 2012/06/11 23:42:25, eroman wrote:
> Update comment: "single integer" --> string

Done.

http://codereview.chromium.org/10539094/diff/5032/net/base/net_log.h#newcode300
net/base/net_log.h:300: // |value| as a pointer to avoid copying, and emphasize
it must be valid for
On 2012/06/11 23:42:25, eroman wrote:
> Should we describe anything about the encoding of |value|?

Done, though we actually violate it at times (Since we just stick in some header
lines that may not actually be in UTF 8).

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
File net/base/x509_certificate_net_log_param.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
net/base/x509_certificate_net_log_param.cc:16: scoped_refptr<const
X509Certificate> certificate,
On 2012/06/11 23:42:25, eroman wrote:
> nit: per previous comment, might want to just pass a raw pointer to avoid
> spamming refcounts.

Done.

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
net/base/x509_certificate_net_log_param.cc:18: if
(!NetLog::IsLoggingBytes(log_level))
On 2012/06/11 23:42:25, eroman wrote:
> Are you sure about this? I thought we were always logging these. Especially
with
> the new callback system, I think we should always log when netinternals is
open.

I actually removed it locally after noticing the comment about it lied, but
forgot to re-upload.

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
File net/base/x509_certificate_net_log_param.h (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/x509_certificate_n...
net/base/x509_certificate_net_log_param.h:18: base::Value*
NetLogX509CertificateNetLogCallback(
On 2012/06/11 23:42:25, eroman wrote:
> nit: The naming include NetLog twice, seems redundant.

You sure?  I was thinking about adding it a 3rd time.  Fixed.

http://codereview.chromium.org/10539094/diff/5032/net/socket/ssl_client_socke...
File net/socket/ssl_client_socket_openssl.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/socket/ssl_client_socke...
net/socket/ssl_client_socket_openssl.cc:825:
base::Bind(&NetLogX509CertificateNetLogCallback, server_cert_));
On 2012/06/11 23:42:25, eroman wrote:
> nit: indentation seems off

Fixed.

[mmenke, 2012-06-12 00:50:58]

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_posix.cc
File net/base/file_stream_posix.cc (right):

http://codereview.chromium.org/10539094/diff/5032/net/base/file_stream_posix....
net/base/file_stream_posix.cc:82: NetLog::StringCallback("file_name",
&file_name));
On 2012/06/12 00:42:19, Matt Menke wrote:
> On 2012/06/11 23:42:25, eroman wrote:
> > Can you take address to to path.AsUTF8Unsafe() directly as a temporary? (Or
> does
> > the compiler barf?)
> 
> 
> The compiler doesn't barf.
> 
> I had assumed temporaries were discarded when the function they were passed to
> returned.  Looks like I was wrong, and they're discarded only after evaluation
> of the entire expression.  Shockingly, it's never an issue I've had to care
> about before.

Correction...MSVC doesn't barf, and the string appears to be valid long enough,
but clang *does* barf.  Undone.

[mmenke, 2012-06-12 01:04:30]

Try servers are in open revolt, but CL 8 (And the indentical CL 7) should be
fine.

[mmenke, 2012-06-12 01:04:41]

On 2012/06/12 01:04:30, Matt Menke wrote:
> Try servers are in open revolt, but CL 8 (And the indentical CL 7) should be
> fine.

*identical, rather.

[eroman, 2012-06-12 05:09:16]

lgtm

[eroman, 2012-06-12 05:17:26]

http://codereview.chromium.org/10539094/diff/10071/net/base/x509_certificate_...
File net/base/x509_certificate_net_log_param.h (right):

http://codereview.chromium.org/10539094/diff/10071/net/base/x509_certificate_...
net/base/x509_certificate_net_log_param.h:9: #include
"base/memory/ref_counted.h"
nit: don't need this anymore

http://codereview.chromium.org/10539094/diff/10071/net/base/x509_certificate_...
net/base/x509_certificate_net_log_param.h:17: // These parameters are memory
intensive, due to PEM-encoding each certificate.
nit: maybe just delete this comment alltogether (not sure it adds value anymore)

http://codereview.chromium.org/10539094/diff/10071/net/socket/tcp_client_sock...
File net/socket/tcp_client_socket_win.cc (right):

http://codereview.chromium.org/10539094/diff/10071/net/socket/tcp_client_sock...
net/socket/tcp_client_socket_win.cc:10: #include "base/bind.h"
nit: is this still used?

http://codereview.chromium.org/10539094/diff/10071/net/udp/udp_data_transfer_...
File net/udp/udp_data_transfer_param.h (right):

http://codereview.chromium.org/10539094/diff/10071/net/udp/udp_data_transfer_...
net/udp/udp_data_transfer_param.h:44: #endif  //
NET_UDP_UDP_DATA_TRANSFER_PARAM_H_
Were any changes planned to this file as part of this CL?
Fixing just this line is certainly fine by me, just want to check.

http://codereview.chromium.org/10539094/diff/10071/net/udp/udp_socket_win.cc
File net/udp/udp_socket_win.cc (right):

http://codereview.chromium.org/10539094/diff/10071/net/udp/udp_socket_win.cc#...
net/udp/udp_socket_win.cc:9: #include "base/bind.h"
Is this used?

[mmenke, 2012-06-12 14:52:36]

http://codereview.chromium.org/10539094/diff/10071/net/base/x509_certificate_...
File net/base/x509_certificate_net_log_param.h (right):

http://codereview.chromium.org/10539094/diff/10071/net/base/x509_certificate_...
net/base/x509_certificate_net_log_param.h:9: #include
"base/memory/ref_counted.h"
On 2012/06/12 05:17:26, eroman wrote:
> nit: don't need this anymore

Done.

http://codereview.chromium.org/10539094/diff/10071/net/base/x509_certificate_...
net/base/x509_certificate_net_log_param.h:17: // These parameters are memory
intensive, due to PEM-encoding each certificate.
On 2012/06/12 05:17:26, eroman wrote:
> nit: maybe just delete this comment alltogether (not sure it adds value
anymore)

Done.

http://codereview.chromium.org/10539094/diff/10071/net/socket/tcp_client_sock...
File net/socket/tcp_client_socket_win.cc (right):

http://codereview.chromium.org/10539094/diff/10071/net/socket/tcp_client_sock...
net/socket/tcp_client_socket_win.cc:10: #include "base/bind.h"
On 2012/06/12 05:17:26, eroman wrote:
> nit: is this still used?

Nope.  Removed.

http://codereview.chromium.org/10539094/diff/10071/net/udp/udp_data_transfer_...
File net/udp/udp_data_transfer_param.h (right):

http://codereview.chromium.org/10539094/diff/10071/net/udp/udp_data_transfer_...
net/udp/udp_data_transfer_param.h:44: #endif  //
NET_UDP_UDP_DATA_TRANSFER_PARAM_H_
On 2012/06/12 05:17:26, eroman wrote:
> Were any changes planned to this file as part of this CL?
> Fixing just this line is certainly fine by me, just want to check.

Nope.  Noticed it when looking for uses of address list params.  Included it in
this CL rather than in a future CL just to make sure I wouldn't forget about it.

http://codereview.chromium.org/10539094/diff/10071/net/udp/udp_socket_win.cc
File net/udp/udp_socket_win.cc (right):

http://codereview.chromium.org/10539094/diff/10071/net/udp/udp_socket_win.cc#...
net/udp/udp_socket_win.cc:9: #include "base/bind.h"
On 2012/06/12 05:17:26, eroman wrote:
> Is this used?

Nope.  Removed.

[commit-bot: I haz the power, 2012-06-12 14:59:29]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/mmenke@chromium.org/10539094/14066

[commit-bot: I haz the power, 2012-06-12 16:21:47]

Change committed as 141666

[Ryan Sleevi, 2012-06-12 17:14:38]

A concern below

I'm not sure if it's likely to be hit, based on the ordering of tasks and the
state machine, but I think it's a subtle violation of the threading guarantees
that may need to be addressed.

Also added a comment to your TODO to provide clarity to what eroman and I had
chatted about in person.

https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
File net/socket/ssl_client_socket_nss.cc (right):

https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
net/socket/ssl_client_socket_nss.cc:389: //                is needed.
This was needed because existing consumers of NetLog were only filtering for
IOThread events.

The intent of the change to SSLClientSocketNSS::Core was meant to keep the same
(public) interface, hence all events continuing to be logged on the IOThread. In
particular, the chrome/browser/net/load_timing_observer only looked at IO thread
events.

https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
net/socket/ssl_client_socket_nss.cc:2534:
base::Unretained(nss_handshake_state_.server_cert.get()));
I believe this is wrong.

nss_handshake_state_ should only be accessed on the NSS thread, but you're
binding it to a callback that executes on the I/O thread.

If you were using a retained (refcounted) copy it would be safe, but as it
presently stands, it's possible for this event to be posted, and then
subsequently an SSL record read that fails the handshake and potentially
invalidates this on the Core thread.

note: It's also not "safe" to bind the cert to the |network_handshake_state_|,
since that structure may be getting written on the I/O thread when this is read
on the NSS thread.

[eroman, 2012-06-12 17:30:11]

https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
File net/socket/ssl_client_socket_nss.cc (right):

https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
net/socket/ssl_client_socket_nss.cc:2534:
base::Unretained(nss_handshake_state_.server_cert.get()));
On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> I believe this is wrong.
> 
> nss_handshake_state_ should only be accessed on the NSS thread, but you're
> binding it to a callback that executes on the I/O thread.
> 
> If you were using a retained (refcounted) copy it would be safe, but as it
> presently stands, it's possible for this event to be posted, and then
> subsequently an SSL record read that fails the handshake and potentially
> invalidates this on the Core thread.
> 
> note: It's also not "safe" to bind the cert to the |network_handshake_state_|,
> since that structure may be getting written on the I/O thread when this is
read
> on the NSS thread.

Thanks Ryan! I hadn't read this carefully, you are right there are some
threading issues.

I'm not sure that I much care for the posting between threads. I think the right
fix would be to make the observer able to consume these off the IO thread.

[mmenke, 2012-06-12 17:37:24]

https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
File net/socket/ssl_client_socket_nss.cc (right):

https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
net/socket/ssl_client_socket_nss.cc:389: //                is needed.
On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> This was needed because existing consumers of NetLog were only filtering for
> IOThread events.
> 
> The intent of the change to SSLClientSocketNSS::Core was meant to keep the
same
> (public) interface, hence all events continuing to be logged on the IOThread.
In
> particular, the chrome/browser/net/load_timing_observer only looked at IO
thread
> events.

Thanks for the explanation.

https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
net/socket/ssl_client_socket_nss.cc:2534:
base::Unretained(nss_handshake_state_.server_cert.get()));
On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> I believe this is wrong.
> 
> nss_handshake_state_ should only be accessed on the NSS thread, but you're
> binding it to a callback that executes on the I/O thread.
> 
> If you were using a retained (refcounted) copy it would be safe, but as it
> presently stands, it's possible for this event to be posted, and then
> subsequently an SSL record read that fails the handshake and potentially
> invalidates this on the Core thread.
> 
> note: It's also not "safe" to bind the cert to the |network_handshake_state_|,
> since that structure may be getting written on the I/O thread when this is
read
> on the NSS thread.

Thanks for catching this, a clear bug.

Options:

1)  Keep a reference.  This depends on the certs not being mutable from the
point we post the event onwards.

2)  Go back to walking through it on the current thread, at least for calls from
this file.

3)  Log events on this thread.  Have LoadTimingObserver have special handling
for events it cares about that occur on other threads (Looks like all it cares
about on this thread is the SSL_CONNECTION event).

If we have a strong guarantee of non-mutability, 1) would be fine, and is the
easiest to do.

I'm not a huge fan of 2) or 3), but think 2)'s preferable, just in terms of
keeping life simple.

[Ryan Sleevi, 2012-06-12 17:39:14]

On 2012/06/12 17:30:11, eroman wrote:
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> File net/socket/ssl_client_socket_nss.cc (right):
> 
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> net/socket/ssl_client_socket_nss.cc:2534:
> base::Unretained(nss_handshake_state_.server_cert.get()));
> On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> > I believe this is wrong.
> > 
> > nss_handshake_state_ should only be accessed on the NSS thread, but you're
> > binding it to a callback that executes on the I/O thread.
> > 
> > If you were using a retained (refcounted) copy it would be safe, but as it
> > presently stands, it's possible for this event to be posted, and then
> > subsequently an SSL record read that fails the handshake and potentially
> > invalidates this on the Core thread.
> > 
> > note: It's also not "safe" to bind the cert to the
|network_handshake_state_|,
> > since that structure may be getting written on the I/O thread when this is
> read
> > on the NSS thread.
> 
> Thanks Ryan! I hadn't read this carefully, you are right there are some
> threading issues.
> 
> I'm not sure that I much care for the posting between threads. I think the
right
> fix would be to make the observer able to consume these off the IO thread.

Agreed, it would be nice.

Collectively this fit into the "LoadTimingObserver shouldn't be using the
NetLog" discussion that has been had. Since the CrOS folks see the
separate-thread as an M20 Stable blocker, I wanted to keep the changes minimal
and consistent.

However, the Core is effectively a worker-thread like scenario, in that it may
outlive its SSLClientSocketNSS (which was sort of the point of the Core). As
such, from the point of view of the NSS thread, the NetLog may disappear at any
time. So simply calling NetLog functions directly from the Core thread is
equally racy, and if not being done via message posting, will need to use some
other trick that may be equally messy (passing ownership via some form of
refcounting, adding destruction observers and internal state marshalling to the
BoundNetLog, etc).

This same problem comes up with the desire to log events in the CertVerifiers,
which happen on worker threads, so I'd be very interested in a 'good' solution
for NetLog 4.0...

[Ryan Sleevi, 2012-06-12 17:40:28]

On 2012/06/12 17:37:24, Matt Menke wrote:
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> File net/socket/ssl_client_socket_nss.cc (right):
> 
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> net/socket/ssl_client_socket_nss.cc:389: //                is needed.
> On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> > This was needed because existing consumers of NetLog were only filtering for
> > IOThread events.
> > 
> > The intent of the change to SSLClientSocketNSS::Core was meant to keep the
> same
> > (public) interface, hence all events continuing to be logged on the
IOThread.
> In
> > particular, the chrome/browser/net/load_timing_observer only looked at IO
> thread
> > events.
> 
> Thanks for the explanation.
> 
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> net/socket/ssl_client_socket_nss.cc:2534:
> base::Unretained(nss_handshake_state_.server_cert.get()));
> On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> > I believe this is wrong.
> > 
> > nss_handshake_state_ should only be accessed on the NSS thread, but you're
> > binding it to a callback that executes on the I/O thread.
> > 
> > If you were using a retained (refcounted) copy it would be safe, but as it
> > presently stands, it's possible for this event to be posted, and then
> > subsequently an SSL record read that fails the handshake and potentially
> > invalidates this on the Core thread.
> > 
> > note: It's also not "safe" to bind the cert to the
|network_handshake_state_|,
> > since that structure may be getting written on the I/O thread when this is
> read
> > on the NSS thread.
> 
> Thanks for catching this, a clear bug.
> 
> Options:
> 
> 1)  Keep a reference.  This depends on the certs not being mutable from the
> point we post the event onwards.
> 
> 2)  Go back to walking through it on the current thread, at least for calls
from
> this file.
> 
> 3)  Log events on this thread.  Have LoadTimingObserver have special handling
> for events it cares about that occur on other threads (Looks like all it cares
> about on this thread is the SSL_CONNECTION event).
> 
> If we have a strong guarantee of non-mutability, 1) would be fine, and is the
> easiest to do.

Go with 1.

All X509Certificates are meant to be immutable from the point of creation.

(Technically, this isn't true, as you can mutate the OSCertHandle indirectly,
but from the pov of the X509Certificate and its functions, it's immutable and
thread-safe)

> 
> I'm not a huge fan of 2) or 3), but think 2)'s preferable, just in terms of
> keeping life simple.

[mmenke, 2012-06-12 17:43:52]

On 2012/06/12 17:40:28, Ryan Sleevi wrote:
> On 2012/06/12 17:37:24, Matt Menke wrote:
> >
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> > File net/socket/ssl_client_socket_nss.cc (right):
> > 
> >
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> > net/socket/ssl_client_socket_nss.cc:389: //                is needed.
> > On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> > > This was needed because existing consumers of NetLog were only filtering
for
> > > IOThread events.
> > > 
> > > The intent of the change to SSLClientSocketNSS::Core was meant to keep the
> > same
> > > (public) interface, hence all events continuing to be logged on the
> IOThread.
> > In
> > > particular, the chrome/browser/net/load_timing_observer only looked at IO
> > thread
> > > events.
> > 
> > Thanks for the explanation.
> > 
> >
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> > net/socket/ssl_client_socket_nss.cc:2534:
> > base::Unretained(nss_handshake_state_.server_cert.get()));
> > On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> > > I believe this is wrong.
> > > 
> > > nss_handshake_state_ should only be accessed on the NSS thread, but you're
> > > binding it to a callback that executes on the I/O thread.
> > > 
> > > If you were using a retained (refcounted) copy it would be safe, but as it
> > > presently stands, it's possible for this event to be posted, and then
> > > subsequently an SSL record read that fails the handshake and potentially
> > > invalidates this on the Core thread.
> > > 
> > > note: It's also not "safe" to bind the cert to the
> |network_handshake_state_|,
> > > since that structure may be getting written on the I/O thread when this is
> > read
> > > on the NSS thread.
> > 
> > Thanks for catching this, a clear bug.
> > 
> > Options:
> > 
> > 1)  Keep a reference.  This depends on the certs not being mutable from the
> > point we post the event onwards.
> > 
> > 2)  Go back to walking through it on the current thread, at least for calls
> from
> > this file.
> > 
> > 3)  Log events on this thread.  Have LoadTimingObserver have special
handling
> > for events it cares about that occur on other threads (Looks like all it
cares
> > about on this thread is the SSL_CONNECTION event).
> > 
> > If we have a strong guarantee of non-mutability, 1) would be fine, and is
the
> > easiest to do.
> 
> Go with 1.
> 
> All X509Certificates are meant to be immutable from the point of creation.
> 
> (Technically, this isn't true, as you can mutate the OSCertHandle indirectly,
> but from the pov of the X509Certificate and its functions, it's immutable and
> thread-safe)

Great, will do.  Thanks again for catching this.  Can't believe I missed it when
I had it staring me in the face.

[eroman, 2012-06-12 17:47:52]

https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
File net/socket/ssl_client_socket_nss.cc (right):

https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
net/socket/ssl_client_socket_nss.cc:2534:
base::Unretained(nss_handshake_state_.server_cert.get()));
On 2012/06/12 17:37:24, Matt Menke wrote:
> On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> > I believe this is wrong.
> > 
> > nss_handshake_state_ should only be accessed on the NSS thread, but you're
> > binding it to a callback that executes on the I/O thread.
> > 
> > If you were using a retained (refcounted) copy it would be safe, but as it
> > presently stands, it's possible for this event to be posted, and then
> > subsequently an SSL record read that fails the handshake and potentially
> > invalidates this on the Core thread.
> > 
> > note: It's also not "safe" to bind the cert to the
|network_handshake_state_|,
> > since that structure may be getting written on the I/O thread when this is
> read
> > on the NSS thread.
> 
> Thanks for catching this, a clear bug.
> 
> Options:
> 
> 1)  Keep a reference.  This depends on the certs not being mutable from the
> point we post the event onwards.
> 
> 2)  Go back to walking through it on the current thread, at least for calls
from
> this file.
> 
> 3)  Log events on this thread.  Have LoadTimingObserver have special handling
> for events it cares about that occur on other threads (Looks like all it cares
> about on this thread is the SSL_CONNECTION event).
> 
> If we have a strong guarantee of non-mutability, 1) would be fine, and is the
> easiest to do.
> 
> I'm not a huge fan of 2) or 3), but think 2)'s preferable, just in terms of
> keeping life simple.

It doesn't look like load_timing_observer actually consumes this event.

In which case there is a simpler solution: simply emit this directly from the
current thread!

... load timing observer really needs to go die
(http://code.google.com/p/chromium/issues/detail?id=77446)

[mmenke, 2012-06-12 17:50:46]

On 2012/06/12 17:47:52, eroman wrote:
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> File net/socket/ssl_client_socket_nss.cc (right):
> 
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> net/socket/ssl_client_socket_nss.cc:2534:
> base::Unretained(nss_handshake_state_.server_cert.get()));
> On 2012/06/12 17:37:24, Matt Menke wrote:
> > On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> > > I believe this is wrong.
> > > 
> > > nss_handshake_state_ should only be accessed on the NSS thread, but you're
> > > binding it to a callback that executes on the I/O thread.
> > > 
> > > If you were using a retained (refcounted) copy it would be safe, but as it
> > > presently stands, it's possible for this event to be posted, and then
> > > subsequently an SSL record read that fails the handshake and potentially
> > > invalidates this on the Core thread.
> > > 
> > > note: It's also not "safe" to bind the cert to the
> |network_handshake_state_|,
> > > since that structure may be getting written on the I/O thread when this is
> > read
> > > on the NSS thread.
> > 
> > Thanks for catching this, a clear bug.
> > 
> > Options:
> > 
> > 1)  Keep a reference.  This depends on the certs not being mutable from the
> > point we post the event onwards.
> > 
> > 2)  Go back to walking through it on the current thread, at least for calls
> from
> > this file.
> > 
> > 3)  Log events on this thread.  Have LoadTimingObserver have special
handling
> > for events it cares about that occur on other threads (Looks like all it
cares
> > about on this thread is the SSL_CONNECTION event).
> > 
> > If we have a strong guarantee of non-mutability, 1) would be fine, and is
the
> > easiest to do.
> > 
> > I'm not a huge fan of 2) or 3), but think 2)'s preferable, just in terms of
> > keeping life simple.
> 
> It doesn't look like load_timing_observer actually consumes this event.
> 
> In which case there is a simpler solution: simply emit this directly from the
> current thread!
> 
> ... load timing observer really needs to go die
> (http://code.google.com/p/chromium/issues/detail?id=77446)

Yea, I just noticed that.  It looks like the only SSL event it cares about
happens on the other thread as well, so we should be safe getting rid of the
extra net log thread stuff entirely (The DevTools observer doesn't care about
any of them).

[Ryan Sleevi, 2012-06-12 17:51:20]

On 2012/06/12 17:47:52, eroman wrote:
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> File net/socket/ssl_client_socket_nss.cc (right):
> 
>
https://chromiumcodereview.appspot.com/10539094/diff/14066/net/socket/ssl_cli...
> net/socket/ssl_client_socket_nss.cc:2534:
> base::Unretained(nss_handshake_state_.server_cert.get()));
> On 2012/06/12 17:37:24, Matt Menke wrote:
> > On 2012/06/12 17:14:38, Ryan Sleevi wrote:
> > > I believe this is wrong.
> > > 
> > > nss_handshake_state_ should only be accessed on the NSS thread, but you're
> > > binding it to a callback that executes on the I/O thread.
> > > 
> > > If you were using a retained (refcounted) copy it would be safe, but as it
> > > presently stands, it's possible for this event to be posted, and then
> > > subsequently an SSL record read that fails the handshake and potentially
> > > invalidates this on the Core thread.
> > > 
> > > note: It's also not "safe" to bind the cert to the
> |network_handshake_state_|,
> > > since that structure may be getting written on the I/O thread when this is
> > read
> > > on the NSS thread.
> > 
> > Thanks for catching this, a clear bug.
> > 
> > Options:
> > 
> > 1)  Keep a reference.  This depends on the certs not being mutable from the
> > point we post the event onwards.
> > 
> > 2)  Go back to walking through it on the current thread, at least for calls
> from
> > this file.
> > 
> > 3)  Log events on this thread.  Have LoadTimingObserver have special
handling
> > for events it cares about that occur on other threads (Looks like all it
cares
> > about on this thread is the SSL_CONNECTION event).
> > 
> > If we have a strong guarantee of non-mutability, 1) would be fine, and is
the
> > easiest to do.
> > 
> > I'm not a huge fan of 2) or 3), but think 2)'s preferable, just in terms of
> > keeping life simple.
> 
> It doesn't look like load_timing_observer actually consumes this event.
> 
> In which case there is a simpler solution: simply emit this directly from the
> current thread!

Please don't. The NetLog* (as all other members 'owned' by the
SSLClientSocketNSS) are guaranteed to not be accessed after Detach() has been
called. |detached_| 'lives' on the network thread (as do all of the members it
guards, including the NetLog).

The scenario is mostly one of shutdown - if the IOThread (which owns the
ChromeNetLog that ends up passed in here) is shutting down, it's possible that
this NSS thread may still be running. If we change the IOThread to first shut
down this thread, then we add shutdown jank for what will end up being an
abandoned task, which is why it wasn't done.

Effectively, like a worker thread :)

[eroman, 2012-06-12 18:05:20]

The shutdown race can be handled by guarding with a lock. I still see that as a
better alternative to copying the parameter and posting a task (posting a task
will still involve lock acquisition anyway).

@mmenke: My suggestion is to revert the already committed changes to these files
ASAP. You can then follow up with a standalone CL just for this and we can
continue the discussion there.

[Ryan Sleevi, 2012-06-12 18:09:59]

On 2012/06/12 18:05:20, eroman wrote:
> The shutdown race can be handled by guarding with a lock. I still see that as
a
> better alternative to copying the parameter and posting a task (posting a task
> will still involve lock acquisition anyway).

I'm not sure why. There's still the same number of copies involve. With the
current solution of using Callbacks with curried arguments, you still end up
making a copy of every argument (due to the base::internal::BindState combined
with base::internal::CallbackParamTraits<>::StorageType)

> 
> @mmenke: My suggestion is to revert the already committed changes to these
files
> ASAP. You can then follow up with a standalone CL just for this and we can
> continue the discussion there.

Sorry, didn't meant to hijack a closed CL. It seems like this could be fixed
with a one liner?

[mmenke, 2012-06-12 18:17:31]

On 2012/06/12 18:05:20, eroman wrote:
> The shutdown race can be handled by guarding with a lock. I still see that as
a
> better alternative to copying the parameter and posting a task (posting a task
> will still involve lock acquisition anyway).
> 
> @mmenke: My suggestion is to revert the already committed changes to these
files
> ASAP. You can then follow up with a standalone CL just for this and we can
> continue the discussion there.

I'm happy to revert, but since the issue only affects net-internals and
media-internals, think we're safe just landing a fix tonight, rather than a
revert.

I'm not following you on the lock bit.  What/Where would we be locking?  We'd
have to grab a lock that would prevent shutdown from happening until released.

[eroman, 2012-06-12 18:23:23]

Ok so I just chatted with Ryan, and I am now less uncomfortable about the
refcounted approach :)

The assumption that x509certs are threadsafe is fairly pervasive; sorry for the
noise.

Passing the parameter as a scoped_refptr<> therefore should be sufficient.

Conceptually I prefer the idea of logging directly from the worker thread (so
the event timing is more precise), but that approach would involve extra code
(my thinking was you would surround the NetLog code in worker thread with a
lock, which you would invalidate when detaching).

Either approach works for me, and I am fine with the fix being sent without
first reverting.

[mmenke, 2012-06-12 18:33:32]

On 2012/06/12 18:23:23, eroman wrote:
> Ok so I just chatted with Ryan, and I am now less uncomfortable about the
> refcounted approach :)
> 
> The assumption that x509certs are threadsafe is fairly pervasive; sorry for
the
> noise.
> 
> Passing the parameter as a scoped_refptr<> therefore should be sufficient.
> 
> Conceptually I prefer the idea of logging directly from the worker thread (so
> the event timing is more precise), but that approach would involve extra code
> (my thinking was you would surround the NetLog code in worker thread with a
> lock, which you would invalidate when detaching).
> 
> Either approach works for me, and I am fine with the fix being sent without
> first reverting.

Ahh, right.  Was thinking of locking on the NetLog, not the SSLClientSocketNSS. 
Despite the general preference for not using locks in Chrome, I think locks are
safer in this case, since they'd protect all logging calls.  The other ones all
just keep around single ints, so not a huge deal now, but it makes it harder to
do stupid things, like I did.

Unless Ryan disagrees, I'll go ahead and go the locking route.

[Ryan Sleevi, 2012-06-12 19:15:47]

On 2012/06/12 18:33:32, Matt Menke wrote:
> On 2012/06/12 18:23:23, eroman wrote:
> > Ok so I just chatted with Ryan, and I am now less uncomfortable about the
> > refcounted approach :)
> > 
> > The assumption that x509certs are threadsafe is fairly pervasive; sorry for
> the
> > noise.
> > 
> > Passing the parameter as a scoped_refptr<> therefore should be sufficient.
> > 
> > Conceptually I prefer the idea of logging directly from the worker thread
(so
> > the event timing is more precise), but that approach would involve extra
code
> > (my thinking was you would surround the NetLog code in worker thread with a
> > lock, which you would invalidate when detaching).
> > 
> > Either approach works for me, and I am fine with the fix being sent without
> > first reverting.
> 
> Ahh, right.  Was thinking of locking on the NetLog, not the
SSLClientSocketNSS. 
> Despite the general preference for not using locks in Chrome, I think locks
are
> safer in this case, since they'd protect all logging calls.  The other ones
all
> just keep around single ints, so not a huge deal now, but it makes it harder
to
> do stupid things, like I did.
> 
> Unless Ryan disagrees, I'll go ahead and go the locking route.

I may not be familiar enough with the design goals of the new-new-new NetLog
yet, and I may be missing something, but it seems like a Lock around logging
events "could" be dangerous.

For example, in the convoluted "what if" scenario:
  NSS thread ->
    Lock
    NetLog::AddEvent(...)
    (thread suspended while AddEvent is processing)
    [ Lock still acquired ]
  Network Thread
    TryLock(netlog lock)
    [ Waiting for NSS thread to give up lock ]
  NSS thread
    SomeDelegateNetLog::AddEvent(...) resumes
    [ Tries to get some lock held by Network thread ]
    [ Deadlock ]

Message passing, though understandably inefficient (due to copying), certainly
seems a better solution, because it's not possible to paint yourself into these
corners with locks.

Do I think it's a concern with the code today? Probably not - there's only a few
NetLog observers, and their code is fairly minimal. I just dislike having to
reason about code threaded through multiple layers (eg: reason about chrome/
code when changing code in net/).

Equally though, I understand the desire to not have to copy arguments if they
won't end up being needed.

That said, all of the bound logs are either pointer types (eg: X509Certificate*)
or POD, so the message passing doesn't seem to be incurring any (additional)
overhead over the existing system?

[mmenke, 2012-06-12 19:20:17]

On 2012/06/12 19:15:47, Ryan Sleevi wrote:
> On 2012/06/12 18:33:32, Matt Menke wrote:
> > On 2012/06/12 18:23:23, eroman wrote:
> > > Ok so I just chatted with Ryan, and I am now less uncomfortable about the
> > > refcounted approach :)
> > > 
> > > The assumption that x509certs are threadsafe is fairly pervasive; sorry
for
> > the
> > > noise.
> > > 
> > > Passing the parameter as a scoped_refptr<> therefore should be sufficient.
> > > 
> > > Conceptually I prefer the idea of logging directly from the worker thread
> (so
> > > the event timing is more precise), but that approach would involve extra
> code
> > > (my thinking was you would surround the NetLog code in worker thread with
a
> > > lock, which you would invalidate when detaching).
> > > 
> > > Either approach works for me, and I am fine with the fix being sent
without
> > > first reverting.
> > 
> > Ahh, right.  Was thinking of locking on the NetLog, not the
> SSLClientSocketNSS. 
> > Despite the general preference for not using locks in Chrome, I think locks
> are
> > safer in this case, since they'd protect all logging calls.  The other ones
> all
> > just keep around single ints, so not a huge deal now, but it makes it harder
> to
> > do stupid things, like I did.
> > 
> > Unless Ryan disagrees, I'll go ahead and go the locking route.
> 
> I may not be familiar enough with the design goals of the new-new-new NetLog
> yet, and I may be missing something, but it seems like a Lock around logging
> events "could" be dangerous.
> 
> For example, in the convoluted "what if" scenario:
>   NSS thread ->
>     Lock
>     NetLog::AddEvent(...)
>     (thread suspended while AddEvent is processing)
>     [ Lock still acquired ]
>   Network Thread
>     TryLock(netlog lock)
>     [ Waiting for NSS thread to give up lock ]
>   NSS thread
>     SomeDelegateNetLog::AddEvent(...) resumes
>     [ Tries to get some lock held by Network thread ]
>     [ Deadlock ]
> 
> Message passing, though understandably inefficient (due to copying), certainly
> seems a better solution, because it's not possible to paint yourself into
these
> corners with locks.
> 
> Do I think it's a concern with the code today? Probably not - there's only a
few
> NetLog observers, and their code is fairly minimal. I just dislike having to
> reason about code threaded through multiple layers (eg: reason about chrome/
> code when changing code in net/).
> 
> Equally though, I understand the desire to not have to copy arguments if they
> won't end up being needed.
> 
> That said, all of the bound logs are either pointer types (eg:
X509Certificate*)
> or POD, so the message passing doesn't seem to be incurring any (additional)
> overhead over the existing system?

I'm not following your scenario.  The lock would only be used by a single
SSLClientSocketNSS[::Core].  Also, all locks would only be around events handled
on a single thread, so there's not waiting for other threads to do stuff (Other
than release a lock, if they have it, which again, will be waiting solely for
stuff on that thread to occur).

[mmenke, 2012-06-12 19:21:48]

On 2012/06/12 19:20:17, Matt Menke wrote:
> On 2012/06/12 19:15:47, Ryan Sleevi wrote:
> > On 2012/06/12 18:33:32, Matt Menke wrote:
> > > On 2012/06/12 18:23:23, eroman wrote:
> > > > Ok so I just chatted with Ryan, and I am now less uncomfortable about
the
> > > > refcounted approach :)
> > > > 
> > > > The assumption that x509certs are threadsafe is fairly pervasive; sorry
> for
> > > the
> > > > noise.
> > > > 
> > > > Passing the parameter as a scoped_refptr<> therefore should be
sufficient.
> > > > 
> > > > Conceptually I prefer the idea of logging directly from the worker
thread
> > (so
> > > > the event timing is more precise), but that approach would involve extra
> > code
> > > > (my thinking was you would surround the NetLog code in worker thread
with
> a
> > > > lock, which you would invalidate when detaching).
> > > > 
> > > > Either approach works for me, and I am fine with the fix being sent
> without
> > > > first reverting.
> > > 
> > > Ahh, right.  Was thinking of locking on the NetLog, not the
> > SSLClientSocketNSS. 
> > > Despite the general preference for not using locks in Chrome, I think
locks
> > are
> > > safer in this case, since they'd protect all logging calls.  The other
ones
> > all
> > > just keep around single ints, so not a huge deal now, but it makes it
harder
> > to
> > > do stupid things, like I did.
> > > 
> > > Unless Ryan disagrees, I'll go ahead and go the locking route.
> > 
> > I may not be familiar enough with the design goals of the new-new-new NetLog
> > yet, and I may be missing something, but it seems like a Lock around logging
> > events "could" be dangerous.
> > 
> > For example, in the convoluted "what if" scenario:
> >   NSS thread ->
> >     Lock
> >     NetLog::AddEvent(...)
> >     (thread suspended while AddEvent is processing)
> >     [ Lock still acquired ]
> >   Network Thread
> >     TryLock(netlog lock)
> >     [ Waiting for NSS thread to give up lock ]
> >   NSS thread
> >     SomeDelegateNetLog::AddEvent(...) resumes
> >     [ Tries to get some lock held by Network thread ]
> >     [ Deadlock ]
> > 
> > Message passing, though understandably inefficient (due to copying),
certainly
> > seems a better solution, because it's not possible to paint yourself into
> these
> > corners with locks.
> > 
> > Do I think it's a concern with the code today? Probably not - there's only a
> few
> > NetLog observers, and their code is fairly minimal. I just dislike having to
> > reason about code threaded through multiple layers (eg: reason about chrome/
> > code when changing code in net/).
> > 
> > Equally though, I understand the desire to not have to copy arguments if
they
> > won't end up being needed.
> > 
> > That said, all of the bound logs are either pointer types (eg:
> X509Certificate*)
> > or POD, so the message passing doesn't seem to be incurring any (additional)
> > overhead over the existing system?
> 
> I'm not following your scenario.  The lock would only be used by a single
> SSLClientSocketNSS[::Core].  Also, all locks would only be around events
handled
> on a single thread, so there's not waiting for other threads to do stuff
(Other
> than release a lock, if they have it, which again, will be waiting solely for
> stuff on that thread to occur).

Oh, and I'm actually not terribly concerned about overhead in this situation. 
I'm concerned about thread safety.  The more code you have to pass junk between
threads, the more likely things are to break.  So using locks seems safest, in
this situation, than using callbacks.

[Ryan Sleevi, 2012-06-12 19:23:39]

On 2012/06/12 19:20:17, Matt Menke wrote:
> On 2012/06/12 19:15:47, Ryan Sleevi wrote:
> > On 2012/06/12 18:33:32, Matt Menke wrote:
> > > On 2012/06/12 18:23:23, eroman wrote:
> > > > Ok so I just chatted with Ryan, and I am now less uncomfortable about
the
> > > > refcounted approach :)
> > > > 
> > > > The assumption that x509certs are threadsafe is fairly pervasive; sorry
> for
> > > the
> > > > noise.
> > > > 
> > > > Passing the parameter as a scoped_refptr<> therefore should be
sufficient.
> > > > 
> > > > Conceptually I prefer the idea of logging directly from the worker
thread
> > (so
> > > > the event timing is more precise), but that approach would involve extra
> > code
> > > > (my thinking was you would surround the NetLog code in worker thread
with
> a
> > > > lock, which you would invalidate when detaching).
> > > > 
> > > > Either approach works for me, and I am fine with the fix being sent
> without
> > > > first reverting.
> > > 
> > > Ahh, right.  Was thinking of locking on the NetLog, not the
> > SSLClientSocketNSS. 
> > > Despite the general preference for not using locks in Chrome, I think
locks
> > are
> > > safer in this case, since they'd protect all logging calls.  The other
ones
> > all
> > > just keep around single ints, so not a huge deal now, but it makes it
harder
> > to
> > > do stupid things, like I did.
> > > 
> > > Unless Ryan disagrees, I'll go ahead and go the locking route.
> > 
> > I may not be familiar enough with the design goals of the new-new-new NetLog
> > yet, and I may be missing something, but it seems like a Lock around logging
> > events "could" be dangerous.
> > 
> > For example, in the convoluted "what if" scenario:
> >   NSS thread ->
> >     Lock
> >     NetLog::AddEvent(...)
> >     (thread suspended while AddEvent is processing)
> >     [ Lock still acquired ]
> >   Network Thread
> >     TryLock(netlog lock)
> >     [ Waiting for NSS thread to give up lock ]
> >   NSS thread
> >     SomeDelegateNetLog::AddEvent(...) resumes
> >     [ Tries to get some lock held by Network thread ]
> >     [ Deadlock ]
> > 
> > Message passing, though understandably inefficient (due to copying),
certainly
> > seems a better solution, because it's not possible to paint yourself into
> these
> > corners with locks.
> > 
> > Do I think it's a concern with the code today? Probably not - there's only a
> few
> > NetLog observers, and their code is fairly minimal. I just dislike having to
> > reason about code threaded through multiple layers (eg: reason about chrome/
> > code when changing code in net/).
> > 
> > Equally though, I understand the desire to not have to copy arguments if
they
> > won't end up being needed.
> > 
> > That said, all of the bound logs are either pointer types (eg:
> X509Certificate*)
> > or POD, so the message passing doesn't seem to be incurring any (additional)
> > overhead over the existing system?
> 
> I'm not following your scenario.  The lock would only be used by a single
> SSLClientSocketNSS[::Core].  Also, all locks would only be around events
handled
> on a single thread, so there's not waiting for other threads to do stuff
(Other
> than release a lock, if they have it, which again, will be waiting solely for
> stuff on that thread to occur).

The lock will need to be acquired by the SSLClientSocketNSS (on the IO thread)
when attempting to destroy the SSLClientSocketNSS.

The scenario I'm imagining has the lock held by the Core (on the NSS thread)
while it tries to call AddEvent. If the NetLog::ThreadSafeObserver (on the Core
thread) needs to call back into the IO thread, or if it needs to (also) acquire
a different lock (that's currently held by the IO thread), then you end up with
dead lock.

[Ryan Sleevi, 2012-06-12 19:27:57]

On 2012/06/12 19:21:48, Matt Menke wrote:
> Oh, and I'm actually not terribly concerned about overhead in this situation. 
> I'm concerned about thread safety.  The more code you have to pass junk
between
> threads, the more likely things are to break.  So using locks seems safest, in
> this situation, than using callbacks.

The point of the message passing is for exactly that - thread safety.

I think this is more fundamentally an issue with how liberally
base::Unretained() is applied throughout the code. Any time that
base::Unretained() appears, it's a sign that the thread-safety has to be very
carefully reasoned about and handled cautiously. I don't know if that's always
the case - I've certainly caught a few issues when doing reviews where
base::Unretained() was added because that's the dominant style in a file, even
though it was completely unsafe to do so.

Message passing means you only need to consider thread safety from within a
file/function/code segment. Locking necessarily means you have to consider
thread-safety of the entire implementation, which is why I'm always cautious
about locks, especially "doing work" while locks are held (as opposed to
"enqueing work to be done at a later point", which is the locking strategy used
by MessageLoop et all)

[mmenke, 2012-06-12 19:30:51]

On 2012/06/12 19:23:39, Ryan Sleevi wrote:
> On 2012/06/12 19:20:17, Matt Menke wrote:
> > On 2012/06/12 19:15:47, Ryan Sleevi wrote:
> > > On 2012/06/12 18:33:32, Matt Menke wrote:
> > > > On 2012/06/12 18:23:23, eroman wrote:
> > > > > Ok so I just chatted with Ryan, and I am now less uncomfortable about
> the
> > > > > refcounted approach :)
> > > > > 
> > > > > The assumption that x509certs are threadsafe is fairly pervasive;
sorry
> > for
> > > > the
> > > > > noise.
> > > > > 
> > > > > Passing the parameter as a scoped_refptr<> therefore should be
> sufficient.
> > > > > 
> > > > > Conceptually I prefer the idea of logging directly from the worker
> thread
> > > (so
> > > > > the event timing is more precise), but that approach would involve
extra
> > > code
> > > > > (my thinking was you would surround the NetLog code in worker thread
> with
> > a
> > > > > lock, which you would invalidate when detaching).
> > > > > 
> > > > > Either approach works for me, and I am fine with the fix being sent
> > without
> > > > > first reverting.
> > > > 
> > > > Ahh, right.  Was thinking of locking on the NetLog, not the
> > > SSLClientSocketNSS. 
> > > > Despite the general preference for not using locks in Chrome, I think
> locks
> > > are
> > > > safer in this case, since they'd protect all logging calls.  The other
> ones
> > > all
> > > > just keep around single ints, so not a huge deal now, but it makes it
> harder
> > > to
> > > > do stupid things, like I did.
> > > > 
> > > > Unless Ryan disagrees, I'll go ahead and go the locking route.
> > > 
> > > I may not be familiar enough with the design goals of the new-new-new
NetLog
> > > yet, and I may be missing something, but it seems like a Lock around
logging
> > > events "could" be dangerous.
> > > 
> > > For example, in the convoluted "what if" scenario:
> > >   NSS thread ->
> > >     Lock
> > >     NetLog::AddEvent(...)
> > >     (thread suspended while AddEvent is processing)
> > >     [ Lock still acquired ]
> > >   Network Thread
> > >     TryLock(netlog lock)
> > >     [ Waiting for NSS thread to give up lock ]
> > >   NSS thread
> > >     SomeDelegateNetLog::AddEvent(...) resumes
> > >     [ Tries to get some lock held by Network thread ]
> > >     [ Deadlock ]
> > > 
> > > Message passing, though understandably inefficient (due to copying),
> certainly
> > > seems a better solution, because it's not possible to paint yourself into
> > these
> > > corners with locks.
> > > 
> > > Do I think it's a concern with the code today? Probably not - there's only
a
> > few
> > > NetLog observers, and their code is fairly minimal. I just dislike having
to
> > > reason about code threaded through multiple layers (eg: reason about
chrome/
> > > code when changing code in net/).
> > > 
> > > Equally though, I understand the desire to not have to copy arguments if
> they
> > > won't end up being needed.
> > > 
> > > That said, all of the bound logs are either pointer types (eg:
> > X509Certificate*)
> > > or POD, so the message passing doesn't seem to be incurring any
(additional)
> > > overhead over the existing system?
> > 
> > I'm not following your scenario.  The lock would only be used by a single
> > SSLClientSocketNSS[::Core].  Also, all locks would only be around events
> handled
> > on a single thread, so there's not waiting for other threads to do stuff
> (Other
> > than release a lock, if they have it, which again, will be waiting solely
for
> > stuff on that thread to occur).
> 
> The lock will need to be acquired by the SSLClientSocketNSS (on the IO thread)
> when attempting to destroy the SSLClientSocketNSS.
> 
> The scenario I'm imagining has the lock held by the Core (on the NSS thread)
> while it tries to call AddEvent. If the NetLog::ThreadSafeObserver (on the
Core
> thread) needs to call back into the IO thread, or if it needs to (also)
acquire
> a different lock (that's currently held by the IO thread), then you end up
with
> dead lock.

Ahh....Good point.  None of the observers do anything other than getting message
queue/thread-related locks.  Of course, you could run into the same situation
with using NetLog itself on different threads as well.

So the question is which is worse:  Risking a lock on an ugly observer, or
making SSLClientSocketNSS the sole NetLog event producer that has to have
Callbacks that own all their arguments.

[Ryan Sleevi, 2012-06-12 19:38:24]

On 2012/06/12 19:30:51, Matt Menke wrote:
> On 2012/06/12 19:23:39, Ryan Sleevi wrote:
> > On 2012/06/12 19:20:17, Matt Menke wrote:
> > > On 2012/06/12 19:15:47, Ryan Sleevi wrote:
> > > > On 2012/06/12 18:33:32, Matt Menke wrote:
> > > > > On 2012/06/12 18:23:23, eroman wrote:
> > > > > > Ok so I just chatted with Ryan, and I am now less uncomfortable
about
> > the
> > > > > > refcounted approach :)
> > > > > > 
> > > > > > The assumption that x509certs are threadsafe is fairly pervasive;
> sorry
> > > for
> > > > > the
> > > > > > noise.
> > > > > > 
> > > > > > Passing the parameter as a scoped_refptr<> therefore should be
> > sufficient.
> > > > > > 
> > > > > > Conceptually I prefer the idea of logging directly from the worker
> > thread
> > > > (so
> > > > > > the event timing is more precise), but that approach would involve
> extra
> > > > code
> > > > > > (my thinking was you would surround the NetLog code in worker thread
> > with
> > > a
> > > > > > lock, which you would invalidate when detaching).
> > > > > > 
> > > > > > Either approach works for me, and I am fine with the fix being sent
> > > without
> > > > > > first reverting.
> > > > > 
> > > > > Ahh, right.  Was thinking of locking on the NetLog, not the
> > > > SSLClientSocketNSS. 
> > > > > Despite the general preference for not using locks in Chrome, I think
> > locks
> > > > are
> > > > > safer in this case, since they'd protect all logging calls.  The other
> > ones
> > > > all
> > > > > just keep around single ints, so not a huge deal now, but it makes it
> > harder
> > > > to
> > > > > do stupid things, like I did.
> > > > > 
> > > > > Unless Ryan disagrees, I'll go ahead and go the locking route.
> > > > 
> > > > I may not be familiar enough with the design goals of the new-new-new
> NetLog
> > > > yet, and I may be missing something, but it seems like a Lock around
> logging
> > > > events "could" be dangerous.
> > > > 
> > > > For example, in the convoluted "what if" scenario:
> > > >   NSS thread ->
> > > >     Lock
> > > >     NetLog::AddEvent(...)
> > > >     (thread suspended while AddEvent is processing)
> > > >     [ Lock still acquired ]
> > > >   Network Thread
> > > >     TryLock(netlog lock)
> > > >     [ Waiting for NSS thread to give up lock ]
> > > >   NSS thread
> > > >     SomeDelegateNetLog::AddEvent(...) resumes
> > > >     [ Tries to get some lock held by Network thread ]
> > > >     [ Deadlock ]
> > > > 
> > > > Message passing, though understandably inefficient (due to copying),
> > certainly
> > > > seems a better solution, because it's not possible to paint yourself
into
> > > these
> > > > corners with locks.
> > > > 
> > > > Do I think it's a concern with the code today? Probably not - there's
only
> a
> > > few
> > > > NetLog observers, and their code is fairly minimal. I just dislike
having
> to
> > > > reason about code threaded through multiple layers (eg: reason about
> chrome/
> > > > code when changing code in net/).
> > > > 
> > > > Equally though, I understand the desire to not have to copy arguments if
> > they
> > > > won't end up being needed.
> > > > 
> > > > That said, all of the bound logs are either pointer types (eg:
> > > X509Certificate*)
> > > > or POD, so the message passing doesn't seem to be incurring any
> (additional)
> > > > overhead over the existing system?
> > > 
> > > I'm not following your scenario.  The lock would only be used by a single
> > > SSLClientSocketNSS[::Core].  Also, all locks would only be around events
> > handled
> > > on a single thread, so there's not waiting for other threads to do stuff
> > (Other
> > > than release a lock, if they have it, which again, will be waiting solely
> for
> > > stuff on that thread to occur).
> > 
> > The lock will need to be acquired by the SSLClientSocketNSS (on the IO
thread)
> > when attempting to destroy the SSLClientSocketNSS.
> > 
> > The scenario I'm imagining has the lock held by the Core (on the NSS thread)
> > while it tries to call AddEvent. If the NetLog::ThreadSafeObserver (on the
> Core
> > thread) needs to call back into the IO thread, or if it needs to (also)
> acquire
> > a different lock (that's currently held by the IO thread), then you end up
> with
> > dead lock.
> 
> Ahh....Good point.  None of the observers do anything other than getting
message
> queue/thread-related locks.  Of course, you could run into the same situation
> with using NetLog itself on different threads as well.
> 
> So the question is which is worse:  Risking a lock on an ugly observer, or
> making SSLClientSocketNSS the sole NetLog event producer that has to have
> Callbacks that own all their arguments.

Today, it's just the Core, but one of the sticking points for me has been that
we don't log events for CertVerifierProcs. CertVerifierProcs are all run on
unjoined worker threads, started by the MultiThreadedCertVerifier.

Thus, a CertVerifierJob may outlive the IO thread (ergo, the ChromeNetLog). So
some form of invalidation will be needed.

In my mind, the single-threaded vs multi-threaded nature of (SSLClientSocketNSS,
MultiThreadedCertVerifier) is an implementation detail, and their 'interface' is
"Called on the IO thread, log on the IO thread". The fact that they use workers
to help them out is a detail that callers shouldn't have to know.

So I would think the message passing solution would be the 'correct' one,
because it matches the "SSLClientSocket*" and "CertVerifier*" interfaces of
"lives on a single thread".

We may want to rope willchan in on this conversation, since I know he's been
looking a fair bit at the threading guarantees of code in net/, and he certainly
has thoughts on the matter of "using worker threads within implementations".

My own vote would be message passing, and was how I'd planned to add logging to
the CertVerifier until this recent discussion that seems opposed to it.