Stop attempting to write to transport sockets in NSS on failure.

Stop attempting to write to transport sockets in NSS on failure.

On failure, future transport writes should synchronously return. This is
important on Chrome OS and Linux where we have a separate NSS task runner.
If we query the transport each time (in hopes that it will return the error
code) it becomes an asynchronous error and so the state machine keeps pumping
itself in response to the state change. (It alternates between "write pending"
and "write failed".)

Add a test that asserts we do not keep trying to write to the transport in a
loop.

This fixes one of the infinite loops in bug #381160, but not the other.

BUG=381160
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=278014

[davidben, 2014-06-13 21:30:32]

I'm not super-thrilled with the test, but asserting that we do not do something
is difficult.

I do not believe this is a full solution to #381160. It fixes one of the
infinite loops, but not the other. The net log is actually, in addition to the
SOCKET_WRITE_ERROR loop, also showing the same (well, almost; different error
code) retry loop failure mode as the Windows net-dev thread. I wouldn't be too
surprised if they're actually the same issue and the same thing is causing the
read loop to get stuck somewhere. It's harder to tell because the other net log
is missing the beginning.

Either way, I think this particular behavior is worth fixing independently, even
though someone using a socket in this way would fail to consume an error. We
shouldn't be spinning infinitely like this.

[wtc, 2014-06-16 19:57:21]

Patch set 2 LGTM.

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_nss.cc (right):

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:960: transport_send_error_(0),

I assume transport_send_error_ is a net:: error code. If so, it should be
initialized to OK (same value but more descriptive).

Make the same change on line 2144.

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2634: }

IMPORTANT: I think we should also set transport_send_error_ here, if we are on
the NSS task runner:

  if (OnNSSTaskRunner() && rv != ERR_IO_PENDING && rv < 0) {
    transport_send_error_ = rv;
  }

We may be able to combine these two if statements (not sure if that'll be more
readable though).

Note: it may be better to do this is line 2172, next to the
memio_PutWriteResult(nss_bufs_, MapErrorToNSS(rv)) call.

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2714: // spinning infinitely. See
https://crbug.com/381160.

Nit: it may be better to move this comment (starting with the second sentence
"Future calls to BufferSend...") to SSLClientSocketNSS::Core::BufferSend (line
2144), where there is more context to understand this comment.

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_unittest.cc (right):

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_unittest.cc:1379: FROM_HERE, loop.QuitClosure(),
base::TimeDelta::FromMilliseconds(100));

IMPORTANT: could this be a source of test flakiness? I guess not, because if the
test machine is heavily loaded, we may end up with no thread hops in the next
100 milliseconds, and the expected condition of line 1381 would still be true.
Correct?

[wtc, 2014-06-16 19:58:44]

David:

I forgot to mention that I only reviewed your CL but did not read bug 381160. So
I can't say if your CL is the best way to fix bug 381160. I trust your
judgement.

[davidben, 2014-06-16 20:15:24]

On 2014/06/16 19:58:44, wtc wrote:
> David:
> 
> I forgot to mention that I only reviewed your CL but did not read bug 381160.
So
> I can't say if your CL is the best way to fix bug 381160. I trust your
> judgement.

It doesn't quite fix it. The net log shows two infinite loops. One is this one
and the other is a HttpNetworkTransaction retry loop. This one showing up is
really symptomatic of the root cause which is as yet unknown, though I wouldn't
be surprised if it shares a root cause with the net-dev@ thread. But a failed
Write without a follow-up Read really shouldn't infinite loop like this and
https://codereview.chromium.org/305823003 will also tickle this case, so I
believe this is a worthwhile thing to fix despite not completely resolving bug
381160.

[Ryan Sleevi, 2014-06-16 22:07:07]

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_nss.cc (right):

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2145: return transport_send_error_;
Why introduce another member, when we already have the memio_PutWriteResult
tracking the write error?

Ultimately, the exact error doesn't matter - you can see that the BufferSend rv
gets swallowed in DoTransportIO, so the need for the exact error isn't even
needed. Heck, ERR_ABORTED would be sufficient to break the loop.

This also seems to ensure greater consistency with the existing implementation
(eg: it avoids the need to special-note on 2711-2714), and also avoids the issue
Wan-Teh noted where you're not storing the result in case of sync failure in
DoBufferSend (since we handle that below, on line 2172)

[davidben, 2014-06-16 23:02:13]

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_nss.cc (right):

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:960: transport_send_error_(0),
On 2014/06/16 19:57:21, wtc wrote:
> 
> I assume transport_send_error_ is a net:: error code. If so, it should be
> initialized to OK (same value but more descriptive).
> 
> Make the same change on line 2144.

Done.

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2145: return transport_send_error_;
On 2014/06/16 22:07:07, Ryan Sleevi wrote:
> Why introduce another member, when we already have the memio_PutWriteResult
> tracking the write error?
> 
> Ultimately, the exact error doesn't matter - you can see that the BufferSend
rv
> gets swallowed in DoTransportIO, so the need for the exact error isn't even
> needed. Heck, ERR_ABORTED would be sufficient to break the loop.
> 
> This also seems to ensure greater consistency with the existing implementation
> (eg: it avoids the need to special-note on 2711-2714), and also avoids the
issue
> Wan-Teh noted where you're not storing the result in case of sync failure in
> DoBufferSend (since we handle that below, on line 2172)

Good point. That's much cleaner. Done.

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2634: }
On 2014/06/16 19:57:21, wtc wrote:
> 
> IMPORTANT: I think we should also set transport_send_error_ here, if we are on
> the NSS task runner:
> 
>   if (OnNSSTaskRunner() && rv != ERR_IO_PENDING && rv < 0) {
>     transport_send_error_ = rv;
>   }
> 
> We may be able to combine these two if statements (not sure if that'll be more
> readable though).
> 
> Note: it may be better to do this is line 2172, next to the
> memio_PutWriteResult(nss_bufs_, MapErrorToNSS(rv)) call.

Done. And then did Ryan's suggestion.

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2714: // spinning infinitely. See
https://crbug.com/381160.
On 2014/06/16 19:57:21, wtc wrote:
> 
> Nit: it may be better to move this comment (starting with the second sentence
> "Future calls to BufferSend...") to SSLClientSocketNSS::Core::BufferSend (line
> 2144), where there is more context to understand this comment.

Done.

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_unittest.cc (right):

https://codereview.chromium.org/337823002/diff/20001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_unittest.cc:1379: FROM_HERE, loop.QuitClosure(),
base::TimeDelta::FromMilliseconds(100));
On 2014/06/16 19:57:21, wtc wrote:
> 
> IMPORTANT: could this be a source of test flakiness? I guess not, because if
the
> test machine is heavily loaded, we may end up with no thread hops in the next
> 100 milliseconds, and the expected condition of line 1381 would still be true.
> Correct?

Yeah, it might flakily pass when it shouldn't, but it shouldn't flakily fail.

[Ryan Sleevi, 2014-06-17 00:56:32]

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_unittest.cc (right):

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_unittest.cc:1418: loop.Run();
What about using RunUntilIdle here? Or explicitly scoping this to NSS, where you
can supply the TaskRunner?

I just get emsaddened by PostDelayedTask, since this forces this test to always
take AtLeast 100ms :/

[wtc, 2014-06-17 18:24:06]

Patch set 4 LGTM.

https://codereview.chromium.org/337823002/diff/60001/net/base/nss_memio.h
File net/base/nss_memio.h (right):

https://codereview.chromium.org/337823002/diff/60001/net/base/nss_memio.h#new...
net/base/nss_memio.h:98: * has been no error.

Please clarify that the error is an NSPR error code.

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_nss.cc (right):

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2143: // If there was an error, return it
synchronously rather than call

Nit: "return it" is no longer accurate because you are now returning
ERR_ABORTED. The CL's description says "On failure, future transport writes
should synchronously return the error" and would also need to be updated.

Rather than updating the comment, you can also just return the last write error
here.

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2153: memio_GetWriteParams(nss_bufs_, &buf1,
&len1, &buf2, &len2);

Another option is to make memio_GetWriteParams return the last write error.
There are only two calls to memio_GetWriteParams (the other call is in
ssl_server_socket_nss.cc), so this would be a simple change as well.

[Ryan Sleevi, 2014-06-17 19:43:40]

LGTM as well; the testing comment I think is more a nit/suggestion than
something I think should block for a cycle.

Two further comments below, also on the order of nit.

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_nss.cc (right):

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2153: memio_GetWriteParams(nss_bufs_, &buf1,
&len1, &buf2, &len2);
On 2014/06/17 18:24:06, wtc wrote:
> 
> Another option is to make memio_GetWriteParams return the last write error.
> There are only two calls to memio_GetWriteParams (the other call is in
> ssl_server_socket_nss.cc), so this would be a simple change as well.

+1

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_unittest.cc (right):

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_unittest.cc:1380: EXPECT_EQ(OK, rv);
Seems like you might want this to be ASSERT_EQ (ditto 1393/1392) - no need to
force a 100ms pump on 1416-1417 if we know things are failing early, and it does
seem like we'd be violating further APIs (possibly causing DCHECKs) if these
values failed.

[davidben, 2014-06-17 20:27:43]

https://codereview.chromium.org/337823002/diff/60001/net/base/nss_memio.h
File net/base/nss_memio.h (right):

https://codereview.chromium.org/337823002/diff/60001/net/base/nss_memio.h#new...
net/base/nss_memio.h:98: * has been no error.
On 2014/06/17 18:24:06, wtc wrote:
> 
> Please clarify that the error is an NSPR error code.

Squashed into memio_GetWriteParams and clarified there.

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_nss.cc (right):

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2143: // If there was an error, return it
synchronously rather than call
On 2014/06/17 18:24:06, wtc wrote:
> 
> Nit: "return it" is no longer accurate because you are now returning
> ERR_ABORTED. The CL's description says "On failure, future transport writes
> should synchronously return the error" and would also need to be updated.
> 
> Rather than updating the comment, you can also just return the last write
error
> here.

Done.

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2153: memio_GetWriteParams(nss_bufs_, &buf1,
&len1, &buf2, &len2);
On 2014/06/17 19:43:39, Ryan Sleevi wrote:
> On 2014/06/17 18:24:06, wtc wrote:
> > 
> > Another option is to make memio_GetWriteParams return the last write error.
> > There are only two calls to memio_GetWriteParams (the other call is in
> > ssl_server_socket_nss.cc), so this would be a simple change as well.
> 
> +1

Done.

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_unittest.cc (right):

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_unittest.cc:1380: EXPECT_EQ(OK, rv);
On 2014/06/17 19:43:39, Ryan Sleevi wrote:
> Seems like you might want this to be ASSERT_EQ (ditto 1393/1392) - no need to
> force a 100ms pump on 1416-1417 if we know things are failing early, and it
does
> seem like we'd be violating further APIs (possibly causing DCHECKs) if these
> values failed.

Done.

https://codereview.chromium.org/337823002/diff/60001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_unittest.cc:1418: loop.Run();
On 2014/06/17 00:56:32, Ryan Sleevi wrote:
> What about using RunUntilIdle here? Or explicitly scoping this to NSS, where
you
> can supply the TaskRunner?

Hrm. I'm... not sure if it works. There's a lot of hopping around between this
TaskRunner and the NSS TaskRunner. It's possible that we're not actually
guaranteed that, at the point Write returns, another task would have already
been queued to the network thread try DoBufferSend again. (Not that we're
guaranteed the threads do their thing in 100ms either.) Ideally we'd run until
both were idle or something. I dunno.

I've added a TODO to poke at it.

> I just get emsaddened by PostDelayedTask, since this forces this test to
always
> take AtLeast 100ms :/

Yeah. :-/

[davidben, 2014-06-17 20:51:57]

The CQ bit was checked by davidben@chromium.org

[commit-bot: I haz the power, 2014-06-17 20:52:23]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/davidben@chromium.org/337823002/80001

[wtc, 2014-06-17 22:48:55]

Review comments on patch set 5:

https://codereview.chromium.org/337823002/diff/80001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_nss.cc (right):

https://codereview.chromium.org/337823002/diff/80001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2146: if (memio_GetWriteParams(nss_bufs_,
&buf1, &len1, &buf2, &len2)) {

IMPORTANT: please update the memio_GetWriteParams call in
ssl_server_socket_nss.cc. Now it is necessary to check the return value of
memio_GetWriteParams.

[davidben, 2014-06-17 23:01:38]

The CQ bit was unchecked by davidben@chromium.org

[davidben, 2014-06-17 23:04:44]

Whoops. Removed from CQ.

https://codereview.chromium.org/337823002/diff/80001/net/socket/ssl_client_so...
File net/socket/ssl_client_socket_nss.cc (right):

https://codereview.chromium.org/337823002/diff/80001/net/socket/ssl_client_so...
net/socket/ssl_client_socket_nss.cc:2146: if (memio_GetWriteParams(nss_bufs_,
&buf1, &len1, &buf2, &len2)) {
On 2014/06/17 22:48:55, wtc wrote:
> 
> IMPORTANT: please update the memio_GetWriteParams call in
> ssl_server_socket_nss.cc. Now it is necessary to check the return value of
> memio_GetWriteParams.

Done.

[wtc, 2014-06-17 23:11:33]

Patch set 6 LGTM.

[davidben, 2014-06-17 23:45:53]

The CQ bit was checked by davidben@chromium.org

[commit-bot: I haz the power, 2014-06-17 23:47:37]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/davidben@chromium.org/337823002/100001

[commit-bot: I haz the power, 2014-06-18 10:22:28]

Change committed as 278014