test: Stop fake_upstream methods from accidentally succeeding

[mkbehr]

Description: FakeConnectionBase::waitForDisconnect and FakeHttpConnection::waitForNewStream were returning assertion successes when they timed out, because an AssertionResult constructed with a (non-empty) string counts as a success. Fix that.
Risk Level: Low (test only)
Testing: bazel test //test/...
Docs Changes: n/a
Release Notes: n/a

[mkbehr]

So, a few of the mac test cases do actually hit the 10-second timeout in that CI run. They're all RouterDownstreamDisconnectBeforeResponseComplete, and they all time out on waitForDisconnect. That test succeeds on Http2UpstreamIntegrationTest and Http2IntegrationTest, but it fails on SslIntegrationTest, UdsUpstreamIntegrationTest, and IntegrationTest.

In the tests where this succeeds, the methods take <100ms, so I wouldn't be surprised if this is spinning forever and the test framework bug stopped us from noticing.

How should we handle this?

[zuercher]

Hopefully these are the reason why the mac tests seem more flakey than the linux ones. (We currently re-run mac tests one when they fail to paper over this.)

I think we should try to fix these tests. If you don't have a mac dev environment handy, I can take a look on Monday.

[zuercher]

Empirically, this patch makes all three of those tests pass:

diff --git a/test/integration/http_integration.cc b/test/integration/http_integration.cc
index 1761bfd00..0d828abe6 100644
--- a/test/integration/http_integration.cc
+++ b/test/integration/http_integration.cc
@@ -592,6 +592,7 @@ void HttpIntegrationTest::testRouterDownstreamDisconnectBeforeResponseComplete(
   codec_client_->close();
 
   if (upstreamProtocol() == FakeHttpConnection::Type::HTTP1) {
+    ASSERT_TRUE(fake_upstream_connection_->close());
     ASSERT_TRUE(fake_upstream_connection_->waitForDisconnect());
   } else {
     ASSERT_TRUE(upstream_request_->waitForReset());

It seems to me that nothing in the HTTP1 stack closes the upstream connection when the downstream codec_client_ is closed in HttpIntegrationTest::testRouterDownstreamDisconnectBeforeResponseComplete. Or at least I can't see where that's supposed to happen. However, something must be closing it or the same error would occur under Linux.

@alyssawilk do you have any ideas?

[alyssawilk]

Ok, so in test we're sending half a request, making sure we establish a connection upstream, and killing the client connection, yeah?

Logically that should result in killing the upstream connection too - if it's halfway through streaming a HTTP/1.1 request it can't be used for a subsequent request. If the router filter doesn't handle that by closing the connection that could be an actual Envoy bug.

It's a bit tricky trying to visually find what happens on unexpected downstream disconnect. I assume we get an router onDestroy with an existing upstream_request_ which should result in resetStream which for HTTP/1.1 should kill the connection, which is what this test appears to be trying to test.

Can either of you pastebin the -l trace logs?

[zuercher]

Mac run, fails: https://pastebin.com/raw/yuyvrju1
Linux run, passes: https://pastebin.com/raw/UFXEiByJ

[alyssawilk]

I'll dig through traces but I have a theory, which is it's one of those "don't do upstream things without letting the client dispatcher progress" bugs. I bet we're just hanging on the upstream "waitfordisconnect" without the FIN getting shipped somehow.

linux side I do see the router resetting the pool request
[2018-08-28 16:28:04.381][23][debug][router] source/common/router/router.cc:916] [C1][S3959132024349198890] resetting pool request
right after it detects the early close
[2018-08-28 16:28:04.381][23][debug][connection] source/common/network/connection_impl.cc:410] [C1] remote early close

Mac side not so much. It looks like the client socket is getting closed
[2018-08-28 16:24:21.598][3734902][debug][connection] source/common/network/connection_impl.cc:133] [C0] closing socket: 1
but if it's a flushclose maybe the fin is behind some data? I'd try experimentally switching the waitForDisconnect to be like waitForNewStream or waitForHeadersComplete (allow client dispatcher action) and see if that helps

[alyssawilk]

alternately you could add a std::cerr on the actual socket close to see if the client is actually closing it before we go and block on the upstream waitForDisconnect. That'd be a fast way to sanity check my theory.

[zuercher]

I guess the difference is that the linux version sees "[C1] remote early close" which seems to trigger closing the upstream connection where the Mac version doesn't.

[alyssawilk]

Yeah, but looking more closely at the test I'm a bit more confused why we don't get that disconnect. We wrote the headers but verified they came through so it's not like the FIN might be behind them. I could maybe see the SslIntegrationTest failing if there's some ssl close time delay but that doesn't explain the IntegrationTest failures. But basically it looks like either the FIN isn't being written immediately in the stack of close() or Envoy isn't reading it for some reason, and given I've seen a bunch of things fail with the former failure pattern I'm still betting on it :-P

[zuercher]

So adding waitForNewStream made the test pass: after ten seconds of waiting for a new stream and failing, it called waitForDisconnect and after 5 more seconds, we got a timeout on the upstream connection that closed it. Later C1 gets closed.

I also hacked waitForDisconnect to take a Dispatcher and that doesn't fix the test either, still no close on C1.

I grabbed this during the test. 57956 is the listener port.

Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)    
tcp4       0      0  127.0.0.1.57956        127.0.0.1.57957        CLOSE_WAIT 
tcp4       0      0  127.0.0.1.57957        127.0.0.1.57956        FIN_WAIT_2 
tcp4       0      0  127.0.0.1.57956        *.*                    LISTEN     

[zuercher]

(I should add that I removed the waitForNewStream when I added the hacked waitForDisconnect and the netstat dump is from the latter test.)

[zuercher]

So, I've hacked up ConnectionImpl and FileEventImpl. Seems that the listener side of the downstream connection reads the 62 byte request, and then readDisabled is invoked. The upstream handles the request and writes its partial body and the client side of the downstream is closed. Because I've moved filtering of events into the libevent callback I can see that when that close happens a read event is sent on the listener side of the connection where on Linux we get a close event.

[zuercher]

Confirmed that if that read event is allowed through, we attempt to read, get 0 bytes and detect the connection is closed. I suppose this is some strange interaction between OSX and libevent?

[zuercher]

So, after a lot of digging, I've come to the conclusion that libevent doesn't support EV_FEATURE_EARLY_CLOSE on OSX. If I modify dispatcher_impl.cc to require the feature it fails to initialize libevent (I've verified that it succeeds under Linux). From reading the definition of EV_CLOSED and the detect_early_close_-related comments in ConnectionImpl, it seems that's exactly what we're depending on in this test and it was just never working correctly and not detected before this change.

It's possible there's some way to gain support for that under OSX, but I'll have to some digging.

[zuercher]

The EV_FEATURE_EARLY_CLOSE is epoll-only.

[alyssawilk]

Ok, if EV_FEATURE_EARLY_CLOSE isn't supported on OSX we should just disable the HTTP/1 test for OSX noting that the downstream close will not be detected when envoy has paused reading during request handling, yeah?
#ifdef APPLE
if (downstream_protocol_ == Http::CodecClient::Type::HTTP1) { return; }
#endif
with explanatory comments?

[zuercher]

@alyssawilk yes, that's the conclusion I came too as well. I'm going to write this up in an issue that we can refer to where it's disabled.

[zuercher]

@mkbehr Let's disable HttpIntegrationTest::testRouterDownstreamDisconnectBeforeResponseComplete as described in #4232 (comment) and note #4294 in the comment. Sorry for the delay.

[zuercher]

And have to add the disable block in SslIntegrationTest's RouterDownstreamDisconnectBeforeResponseComplete test case.

[zuercher]

This is the request version of the test, which works. Conditional needs to be on the next one "RouterDownstreamDisconnectBeforeResponseComplete"

[mkbehr]

Oops, right.

[zuercher]

Thanks!