Connect timeout in SimpleNetty4TransportTests testAcceptedChannelCount

[droberts195]

SimpleNetty4TransportTests testAcceptedChannelCount failed in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=sles/2457/console

The REPRO command is:

./gradlew :modules:transport-netty4:test \
  -Dtests.seed=1EE97752BAF923E4 \
  -Dtests.class=org.elasticsearch.transport.netty4.SimpleNetty4TransportTests \
  -Dtests.method="testAcceptedChannelCount" \
  -Dtests.security.manager=true \
  -Dtests.locale=es-CO \
  -Dtests.timezone=America/Cordoba

This doesn't reproduce locally for me.

The error is this:

13:38:47 ERROR   60.1s J2 | SimpleNetty4TransportTests.testAcceptedChannelCount <<< FAILURES!
13:38:47    > Throwable #1: ConnectTransportException[[][127.0.0.1:37525] connect_timeout[30s]]
13:38:47    > 	at __randomizedtesting.SeedInfo.seed([1EE97752BAF923E4:1FBF0C96086BB0E]:0)
13:38:47    > 	at org.elasticsearch.transport.TcpChannel.awaitConnected(TcpChannel.java:184)
13:38:47    > 	at org.elasticsearch.transport.TcpTransport.openConnection(TcpTransport.java:615)
13:38:47    > 	at org.elasticsearch.transport.TcpTransport.connectToNode(TcpTransport.java:514)
13:38:47    > 	at org.elasticsearch.test.transport.MockTransportService$LookupTestTransport.connectToNode(MockTransportService.java:529)
13:38:47    > 	at org.elasticsearch.transport.TransportService.connectToNode(TransportService.java:331)
13:38:47    > 	at org.elasticsearch.transport.TransportService.connectToNode(TransportService.java:318)
13:38:47    > 	at org.elasticsearch.transport.AbstractSimpleTransportTestCase.setUp(AbstractSimpleTransportTestCase.java:145)
13:38:47    > 	at java.lang.Thread.run(Thread.java:748)

The test appears to have done nothing for a whole minute:

   1> [2018-05-25T10:37:41,465][INFO ][o.e.t.n.SimpleNetty4TransportTests] [testAcceptedChannelCount]: before test
   1> [2018-05-25T10:37:41,474][INFO ][o.e.t.t.MockTransportService] publish_address {127.0.0.1:39994}, bound_addresses {[::1]:39045}, {127.0.0.1:39994}
   1> [2018-05-25T10:37:41,481][INFO ][o.e.t.t.MockTransportService] publish_address {127.0.0.1:37525}, bound_addresses {[::1]:34079}, {127.0.0.1:37525}
   1> [2018-05-25T10:38:41,529][INFO ][o.e.t.n.SimpleNetty4TransportTests] [testAcceptedChannelCount]: after test

It's in the same suite as #29613, which was also not reproducible.

[elasticmachine]

Pinging @elastic/es-core-infra

[original-brownbear]

@tbrooks8 I think this one and #29613 may just be the same issue of lingering sockets that was fixed for some situations in #26764.

When I run the full SimpleNetty4TransportTests suite I'm left with ~700 lingering (I guess this could be an issue on CI when other tests ran before that that may have leaked some resources already as well) sockets in TIME_WAIT on my machine. If I run the suit in a loop it fails pretty quickly with either a timeout or a bind exception because of that.

If I force

bootstrap.option(ChannelOption.SO_LINGER, 0);

in org.elasticsearch.transport.netty4.Netty4Transport#createBootstrap I can run that suite in a loop of 1k+ iterations without trouble.

As far as I can see we're leaking those sockets when org.elasticsearch.transport.TcpTransport.NodeChannels#close is called, but the lifecycle check doesn't pass in

        @Override
        public void close() {
            if (closed.compareAndSet(false, true)) {
                try {
                    if (lifecycle.stopped()) {

because it's still in STARTED so the setting of linger to 0 doesn't happen in https://github.com/elastic/elasticsearch/blob/master/server/src/main/java/org/elasticsearch/transport/TcpTransport.java#L485 and we're stuck with a bunch of connections in TIME_WAIT.

I don't understand enough of how the lifecycle of those close calls and TcpTransport works here to fix this, but maybe the above helps a little :)

[Tim-Brooks]

Thanks for the research @original-brownbear. I think what is happening is that we only set SO_LINGER on client connections. But that means "accepted" connections are in TIME_WAIT. And client connections that are closed because of those closed accepted connections (before lifecycle has stopped), are also in TIME_WAIT.

I'll think about this some. I kind of think we should maybe just have a system property for the build that means we ALWAYS set SO_LINGER = 0. But do not mess with SO_LINGER for the actual running instances of Elasticsearch. @jasontedor / @s1monw thoughts?

[original-brownbear]

@tbrooks8

I kind of think we should maybe just have a system property for the build that means we ALWAYS set SO_LINGER = 0. But do not mess with SO_LINGER for the actual running instances of Elasticsearch.

Couldn't we get some other instabilities from all of a sudden sending RST everywhere instead of closing clean because we then throw "Connection reset by peer" instead of reading -1 (or empty) in some places? (I don't know enough about all our Netty handlers to answer that).
But if that's not a concern I think it's just fine :)

[s1monw]

@tbrooks8 @original-brownbear any updates on this and #29613

[original-brownbear]

@s1monw we're waiting on some feedback here I think, there's a question above in #30876 (comment) for you (I'm + 1 on the suggestion).

[s1monw]

@original-brownbear can we cut a PR for this and discuss it there please?

[original-brownbear]

@s1monw sure will add one for this shortly