[CI] RemoteClusterClientTests#testConnectAndExecuteRequest fails

[cbuescher]

On master: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=debian-9/369/console

Couldn't reproduce with:

./gradlew :server:test --tests "org.elasticsearch.transport.RemoteClusterClientTests.testConnectAndExecuteRequest" \
  -Dtests.seed=5BFCD458F15F6DA4 \
  -Dtests.security.manager=true \
  -Dtests.locale=tr \
  -Dtests.timezone=America/Atka \
  -Dcompiler.java=12 \
  -Druntime.java=11

java.lang.AssertionError
	at __randomizedtesting.SeedInfo.seed([5BFCD458F15F6DA4:248A7562ED2FB133]:0)
	at org.junit.Assert.fail(Assert.java:86)
	at org.junit.Assert.assertTrue(Assert.java:41)
	at org.junit.Assert.assertTrue(Assert.java:52)
	at org.elasticsearch.transport.RemoteClusterClientTests.testConnectAndExecuteRequest(RemoteClusterClientTests.java:60)

[elasticmachine]

Pinging @elastic/es-search

[cbuescher]

Also seems to be an occasional issue on 7.x
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.x+intake/1248/console

[cbuescher]

The assertion thats failing is checking that a remote node is connected through the remote cluster service (which is coming from a mock in this case since its ESTestCase). The log shows test timeouts:

 1> [2019-05-02T02:40:58,730][WARN ][o.e.t.RemoteClusterConnection] [org.elasticsearch.transport.RemoteClusterClientTests] fetching nodes from external cluster [test] failed
  1> org.elasticsearch.common.util.CancellableThreads$ExecutionCancelledException: operation was cancelled reason [connect handler is closed]
  1> 	at org.elasticsearch.common.util.CancellableThreads.checkForCancel(CancellableThreads.java:65) ~[main/:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.common.util.CancellableThreads.executeIO(CancellableThreads.java:130) ~[main/:8.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler.collectRemoteNodes(RemoteClusterConnection.java:446) [main/:?]
  1> 	at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler$1.doRun(RemoteClusterConnection.java:434) [main/:?]
  1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
  1> 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
  1> 	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
  1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:687) [main/:?]
  1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
  1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
  1> 	at java.lang.Thread.run(Thread.java:834) [?:?]
  1> 	Suppressed: java.lang.IllegalStateException: Future got interrupted
  1> 		at org.elasticsearch.common.util.concurrent.FutureUtils.get(FutureUtils.java:60) ~[main/:?]
  1> 		at org.elasticsearch.action.support.AdapterActionFuture.actionGet(AdapterActionFuture.java:34) ~[main/:?]
  1> 		at org.elasticsearch.transport.ConnectionManager.internalOpenConnection(ConnectionManager.java:209) ~[main/:?]
  1> 		at org.elasticsearch.transport.ConnectionManager.openConnection(ConnectionManager.java:80) ~[main/:?]
  1> 		at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler.lambda$collectRemoteNodes$2(RemoteClusterConnection.java:452) ~[main/:?]
  1> 		at org.elasticsearch.common.util.CancellableThreads.executeIO(CancellableThreads.java:108) ~[main/:8.0.0-SNAPSHOT]
  1> 		at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler.collectRemoteNodes(RemoteClusterConnection.java:446) [main/:?]
  1> 		at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler$1.doRun(RemoteClusterConnection.java:434) [main/:?]
  1> 		at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
  1> 		at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
  1> 		at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
  1> 		at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:687) [main/:?]
  1> 		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
  1> 		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
  1> 		at java.lang.Thread.run(Thread.java:834) [?:?]
  1> 	Caused by: java.lang.InterruptedException
  1> 		at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1040) ~[?:?]
  1> 		at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1345) ~[?:?]

I can trigger this kind of error by adding a wait of more than 30s in RemoteClusterConnection#collectRemoteNodes() in the IOInterruptible function passed there, but I wonder why such a long wait could happen in practice, especially since this isn't an integration test.

There has been another instance of this on 5.4. (https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=debian-9/372/console) which also shows the same kind of timeout.

[cbuescher]

This part of the stack trace shows the ConnectionManger hangs somewhere when opening the internal connection. The future that gets interupted is a listener passed to Transport#openConnection() which in this case is probably the MockNioTransport.

Suppressed: java.lang.IllegalStateException: Future got interrupted
  1> 		at org.elasticsearch.common.util.concurrent.FutureUtils.get(FutureUtils.java:60) ~[main/:?]
  1> 		at org.elasticsearch.action.support.AdapterActionFuture.actionGet(AdapterActionFuture.java:34) ~[main/:?]
  1> 		at org.elasticsearch.transport.ConnectionManager.internalOpenConnection(ConnectionManager.java:209) ~[main/:?]

[droberts195]

The same problem as #41745 (comment) occurred in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.x+intake/1360/, although the failing test was RemoteClusterConnectionTests.testNodeDisconnected rather than RemoteClusterClientTests.testConnectAndExecuteRequest.

14:29:21   1> [2019-05-08T08:29:21,244][WARN ][o.e.t.RemoteClusterConnection] [org.elasticsearch.transport.RemoteClusterConnectionTests] fetching nodes from external cluster [test-cluster] failed
14:29:21   1> org.elasticsearch.common.util.CancellableThreads$ExecutionCancelledException: operation was cancelled reason [connect handler is closed]
14:29:21   1> 	at org.elasticsearch.common.util.CancellableThreads.checkForCancel(CancellableThreads.java:65) ~[main/:7.2.0-SNAPSHOT]
14:29:21   1> 	at org.elasticsearch.common.util.CancellableThreads.executeIO(CancellableThreads.java:130) ~[main/:7.2.0-SNAPSHOT]
14:29:21   1> 	at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler.collectRemoteNodes(RemoteClusterConnection.java:446) [main/:?]
14:29:21   1> 	at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler.access$900(RemoteClusterConnection.java:336) [main/:?]
14:29:21   1> 	at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler$1.doRun(RemoteClusterConnection.java:434) [main/:?]
14:29:21   1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
14:29:21   1> 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_212]
14:29:21   1> 	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
14:29:21   1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:688) [main/:?]
14:29:21   1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
14:29:21   1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
14:29:21   1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
14:29:21   1> 	Suppressed: java.lang.IllegalStateException: Future got interrupted
14:29:21   1> 		at org.elasticsearch.common.util.concurrent.FutureUtils.get(FutureUtils.java:60) ~[main/:?]
14:29:21   1> 		at org.elasticsearch.action.support.AdapterActionFuture.actionGet(AdapterActionFuture.java:34) ~[main/:?]
14:29:21   1> 		at org.elasticsearch.transport.ConnectionManager.internalOpenConnection(ConnectionManager.java:209) ~[main/:?]
14:29:21   1> 		at org.elasticsearch.transport.ConnectionManager.openConnection(ConnectionManager.java:80) ~[main/:?]
14:29:21   1> 		at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler.lambda$collectRemoteNodes$2(RemoteClusterConnection.java:452) ~[main/:?]
14:29:21   1> 		at org.elasticsearch.common.util.CancellableThreads.executeIO(CancellableThreads.java:108) ~[main/:7.2.0-SNAPSHOT]
14:29:21   1> 		at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler.collectRemoteNodes(RemoteClusterConnection.java:446) [main/:?]
14:29:21   1> 		at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler.access$900(RemoteClusterConnection.java:336) [main/:?]
14:29:21   1> 		at org.elasticsearch.transport.RemoteClusterConnection$ConnectHandler$1.doRun(RemoteClusterConnection.java:434) [main/:?]
14:29:21   1> 		at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
14:29:21   1> 		at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_212]
14:29:21   1> 		at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
14:29:21   1> 		at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:688) [main/:?]
14:29:21   1> 		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
14:29:21   1> 		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
14:29:21   1> 		at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
14:29:21   1> 	Caused by: java.lang.InterruptedException
14:29:21   1> 		at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998) ~[?:1.8.0_212]
14:29:21   1> 		at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304) ~[?:1.8.0_212]
14:29:21   1> 		at org.elasticsearch.common.util.concurrent.BaseFuture$Sync.get(BaseFuture.java:252) ~[main/:?]
14:29:21   1> 		at org.elasticsearch.common.util.concurrent.BaseFuture.get(BaseFuture.java:87) ~[main/:?]
14:29:21   1> 		at org.elasticsearch.common.util.concurrent.FutureUtils.get(FutureUtils.java:57) ~[main/:?]
14:29:21   1> 		... 15 more

[cbuescher]

Talked to @original-brownbear who was investigating similar looking problems elsewhere lately and who suggested using e.g. Yourkit to identify potential locks and determine how much time threads spend waiting on them as a next step.

[original-brownbear]

I opened #42000 to get us more useful logging on this situation