[CI] Connection issues in BasicDistributedJobsIT

[cbuescher]

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-windows-compatibility/1767/consoleFull

Does not reproduce with:

REPRODUCE WITH: gradlew :x-pack:plugin:ml:internalClusterTest \
  -Dtests.seed=98AB1BDCBBCE6890 \
  -Dtests.class=org.elasticsearch.xpack.ml.integration.BasicDistributedJobsIT \
  -Dtests.security.manager=true \
  -Dtests.locale=en-US \
  -Dtests.timezone=UTC

REPRODUCE WITH: gradlew :x-pack:plugin:ml:internalClusterTest \
  -Dtests.seed=98AB1BDCBBCE6890 \
  -Dtests.class=org.elasticsearch.xpack.ml.integration.BasicDistributedJobsIT \
  -Dtests.security.manager=true \
  -Dtests.locale=en-US \
  -Dtests.timezone=UTC

I found #29897 but this looks different in that I don't see an assertion failure in the logs. Rather something in the test cluster formation seems to be getting off track. Cluster starts up, then one node is shut down ([2018-07-19T10:11:05,813][INFO ][o.e.t.InternalTestCluster] Closing random node [node_t0], looks like this is done on purpose). After that I see socket failures and refused connections. Not sure if they are related to the test running of some general test cluster problem:

15:12:15   1> java.net.SocketException: Socket is closed
15:12:15   1> 	at java.net.Socket.getOutputStream(Socket.java:943) ~[?:1.8.0_172]
15:12:15   1> 	at org.elasticsearch.transport.MockTcpTransport$MockChannel.sendMessage(MockTcpTransport.java:412) [framework-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.transport.TcpTransport.internalSendMessage(TcpTransport.java:1163) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.transport.TcpTransport.sendResponse(TcpTransport.java:1252) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.transport.TcpTransport.sendResponse(TcpTransport.java:1220) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.transport.TcpTransportChannel.sendResponse(TcpTransportChannel.java:66) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.transport.TcpTransportChannel.sendResponse(TcpTransportChannel.java:60) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:54) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.discovery.zen.MembershipAction$LeaveRequestRequestHandler.messageReceived(MembershipAction.java:287) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.discovery.zen.MembershipAction$LeaveRequestRequestHandler.messageReceived(MembershipAction.java:282) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1679) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:723) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
15:12:15   1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_172]
15:12:15   1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_172]
15:12:15   1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_172]
15:12:15   1> [2018-07-19T10:11:05,835][WARN ][o.e.t.MockTcpTransport   ] [node_t3] send message failed [channel: MockChannel{profile='default', isOpen=false, localAddress=/127.0.0.1:56400, isServerSocket=false}]

[elasticmachine]

Pinging @elastic/ml-core

[davidkyle]

15:12:15 1> java.net.SocketException: Socket is closed

The test is an evil test that randomly takes down nodes in the cluster to assert the ml jobs relocate correctly so these log messages are expected.

The test failed because of zombie threads leaking

2> SEVERE: There are still zombie threads that couldn't be terminated:
2> 1) Thread[id=262, name=elasticsearch[node_t0][ml_autodetect][T#1], state=RUNNABLE, group=TGRP-BasicDistributedJobsIT]

2> INFO: Starting to interrupt leaked threads:
...
at org.elasticsearch.xpack.ml.job.process.autodetect.AutodetectCommunicator.waitFlushToCompletion(AutodetectCommunicator.java:282)

I see why we get the zombie threads because the interrupt is caught here returning null which causes this loop to continue.

Essentially the interrupt is ignored and we can fix that but the underlying question is why was the thread still running when the job should have been closed at the end of the test.

[benwtrent]

#32541 Addressed the zombie thread issue, but the root cause of the job being closed not causing it to completely die is still not known.

More data is required, and hopefully the aforementioned PR will provide some of that data if we see this test failure again.

[DaveCTurner]

@benwtrent I've assigned this to you (we're trying to cut down on unassigned test failure issues) but think this can probably be closed until it fails again.

[benwtrent]

@DaveCTurner Cool! I will Just close it then :D

[davidkyle]

I suspect the close job request in the teardown section timed out due to a slow machine/GC pause then there was a race between the job closing and the test framework interrupting the active threads. It hasn't happened since and if it does occur again we can consider increasing the timeout