[CI] IndicesQueryCache.close assertion failure in internal cluster tests

[davidkyle]

The timing suggests these failures are related to the change moving the ML config out of the cluster state.

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+matrix-java-periodic/ES_BUILD_JAVA=java11,ES_RUNTIME_JAVA=zulu8,nodes=virtual&&linux/152/console
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+matrix-java-periodic/ES_BUILD_JAVA=java11,ES_RUNTIME_JAVA=zulu11,nodes=virtual&&linux/149/console
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.6+periodic/57/console

The log contains an assertion failure

java.lang.AssertionError: {org.apache.lucene.index.IndexReader$CacheKey@b62bec8=org.elasticsearch.indices.IndicesQueryCache$StatsAndCount@30fd04c3}
	at __randomizedtesting.SeedInfo.seed([374793047E6CA339:C9896ED516320174]:0)
	at org.elasticsearch.indices.IndicesQueryCache.close(IndicesQueryCache.java:191)
	at org.elasticsearch.core.internal.io.IOUtils.closeWhileHandlingException(IOUtils.java:145)
	at org.elasticsearch.core.internal.io.IOUtils.closeWhileHandlingException(IOUtils.java:130)
	at org.elasticsearch.indices.IndicesService.doClose(IndicesService.java:296)
	at org.elasticsearch.common.component.AbstractLifecycleComponent.close(AbstractLifecycleComponent.java:103)
	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:103)
	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:61)
	at org.elasticsearch.node.NodeService.close(NodeService.java:135)
	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:103)
	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:85)
	at org.elasticsearch.node.Node.close(Node.java:847)
	at org.elasticsearch.test.InternalTestCluster$NodeAndClient.close(InternalTestCluster.java:990)
	at org.elasticsearch.core.internal.io.IOUtils.closeWhileHandlingException(IOUtils.java:145)
	at org.elasticsearch.test.InternalTestCluster.close(InternalTestCluster.java:818)
	at org.elasticsearch.test.ESIntegTestCase.afterInternal(ESIntegTestCase.java:586)
	at org.elasticsearch.test.ESIntegTestCase.cleanUpCluster(ESIntegTestCase.java:2225)

Then the suite fails with a thread leak error.
thread-leak.txt

Does not reproduce:

./gradlew :x-pack:plugin:ml:unitTest \
  -Dtests.seed=374793047E6CA339 \
  -Dtests.class=org.elasticsearch.license.MachineLearningLicensingTests \
  -Dtests.method="testMachineLearningStopDatafeedActionNotRestricted" \
  -Dtests.security.manager=true \
  -Dtests.locale=ar-SD \
  -Dtests.timezone=BET \
  -Dcompiler.java=11 \
  -Druntime.java=8

./gradlew :x-pack:plugin:ml:unitTest \
  -Dtests.seed=B805872D5C817758 \
  -Dtests.class=org.elasticsearch.license.MachineLearningLicensingTests \
  -Dtests.method="testAutoCloseJobWithDatafeed" \
  -Dtests.security.manager=true \
  -Dtests.locale=zh-Hans-HK \
  -Dtests.timezone=Etc/GMT-5 \
  -Dcompiler.java=11 \
  -Druntime.java=11

./gradlew :x-pack:plugin:ml:unitTest \
  -Dtests.seed=CB48E860FD3AC07E \
  -Dtests.class=org.elasticsearch.license.MachineLearningLicensingTests \
  -Dtests.method="testAutoCloseJobWithDatafeed" \
  -Dtests.security.manager=true \
  -Dtests.locale=de-GR \
  -Dtests.timezone=America/Rankin_Inlet \
  -Dcompiler.java=11 \
  -Druntime.java=8

[elasticmachine]

Pinging @elastic/ml-core

[droberts195]

The assertion that's failing is

elasticsearch/server/src/main/java/org/elasticsearch/indices/IndicesQueryCache.java

Line 191 in 0000e7c

assert stats2.isEmpty() : stats2;

Can anyone from @elastic/es-search offer any advice on what might cause this? Is it because ML is doing some operation on the index while it's being closed?

[droberts195]

One more thing is that many failures of this type seem to be running in the Zulu JVM.

However, I found one that isn't: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=opensuse/165/consoleText

So it may be that there's something about the Zulu JVM that makes these failures more likely to occur, but it's not the root cause of the problem.

[alpar-t]

another one here: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+intake/906/console

[davidkyle]

There was a failure in BasicDistributedJobsIT that looks like it has the same root cause

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+matrix-java-periodic/ES_BUILD_JAVA=java11,ES_RUNTIME_JAVA=java8,nodes=virtual&&linux/172/console

java.lang.AssertionError: 2
	at __randomizedtesting.SeedInfo.seed([3EDB4FBFCECABCD4:D16E134409CDA259]:0)
	at org.elasticsearch.indices.IndicesQueryCache.close(IndicesQueryCache.java:189)
	at org.elasticsearch.core.internal.io.IOUtils.closeWhileHandlingException(IOUtils.java:145)
	at org.elasticsearch.core.internal.io.IOUtils.closeWhileHandlingException(IOUtils.java:130)
	at org.elasticsearch.indices.IndicesService.doClose(IndicesService.java:297)
	at org.elasticsearch.common.component.AbstractLifecycleComponent.close(AbstractLifecycleComponent.java:105)
	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:103)
	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:61)
	at org.elasticsearch.node.NodeService.close(NodeService.java:135)
	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:103)
	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:85)
	at org.elasticsearch.node.Node.close(Node.java:946)
	at org.elasticsearch.test.InternalTestCluster$NodeAndClient.close(InternalTestCluster.java:1008)
	at org.elasticsearch.test.InternalTestCluster.stopNodesAndClients(InternalTestCluster.java:1651)
	at org.elasticsearch.test.InternalTestCluster.stopNodesAndClient(InternalTestCluster.java:1637)
	at org.elasticsearch.test.InternalTestCluster.stopRandomDataNode(InternalTestCluster.java:1531)
	at org.elasticsearch.xpack.ml.integration.BasicDistributedJobsIT.testFailOverBasics_withDataFeeder(BasicDistributedJobsIT.java:121)

In this test a node is shutdown tripping the assertion which doesn't kill the node but leaves it half running. Later there is the error message from the shutdown node:

  1> [2019-01-10T22:27:02,402][WARN ][o.e.t.TcpTransport       ] [node_t1] send message failed [channel: MockChannel{profile='default', isOpen=false, localAddress=/127.0.0.1:39548, isServerSocket=false}]
  1> java.net.SocketException: Socket is closed
  1> 	at java.net.Socket.getOutputStream(Socket.java:943) ~[?:1.8.0_192]
  1> 	at org.elasticsearch.transport.MockTcpTransport$MockChannel.sendMessage(MockTcpTransport.java:437) [framework-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.TcpTransport.internalSendMessage(TcpTransport.java:758) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.TcpTransport.sendResponse(TcpTransport.java:844) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.TcpTransport.sendResponse(TcpTransport.java:815) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.TcpTransportChannel.sendResponse(TcpTransportChannel.java:64) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:54) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.HandledTransportAction$ChannelActionListener.onResponse(HandledTransportAction.java:103) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.HandledTransportAction$ChannelActionListener.onResponse(HandledTransportAction.java:87) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.search.SearchService$2.onResponse(SearchService.java:360) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.search.SearchService$2.onResponse(SearchService.java:356) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.search.SearchService$4.doRun(SearchService.java:1116) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]
  1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:759) [elasticsearch-6.7.0-SNAPSHOT.jar:6.7.0-SNAPSHOT]

The working theory is that some request hits the node during shutdown I've added some debug logging around the likely candidates in 92b519b

[davidkyle]

@jpountz could you take a look at the assertion failures in IndicesQueryCache.close thrown up by this test please. Any insights you have into what the cause may be are much appreciated.

java.lang.AssertionError: {org.apache.lucene.index.IndexReader$CacheKey@b62bec8=org.elasticsearch.indices.IndicesQueryCache$StatsAndCount@30fd04c3}
	at __randomizedtesting.SeedInfo.seed([374793047E6CA339:C9896ED516320174]:0)
	at org.elasticsearch.indices.IndicesQueryCache.close(IndicesQueryCache.java:191)

and

java.lang.AssertionError: 2
	at __randomizedtesting.SeedInfo.seed([3EDB4FBFCECABCD4:D16E134409CDA259]:0)
	at org.elasticsearch.indices.IndicesQueryCache.close(IndicesQueryCache.java:189)

[cbuescher]

Talking to @droberts195, he thinks these failures from today look related. Its a different test though:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=amazon/223/console

 ./gradlew :x-pack:plugin:ml:internalClusterTest \
  -Dtests.seed=2D587A9A8B6E70D8 \
  -Dtests.class=org.elasticsearch.xpack.ml.integration.MlDistributedFailureIT \
  -Dtests.method="testFullClusterRestart" \
  -Dtests.security.manager=true \
  -Dtests.locale=es-PE \
  -Dtests.timezone=America/St_Thomas \
  -Dcompiler.java=11 \
  -Druntime.java=8

The logs contain similar failures:

13:53:28 ERROR   12.1s J1 | MlDistributedFailureIT.testFullClusterRestart <<< FAILURES!
13:53:28    > Throwable #1: java.lang.AssertionError: {org.apache.lucene.index.IndexReader$CacheKey@714f684a=org.elasticsearch.indices.IndicesQueryCache$StatsAndCount@3d9dc3df, org.apache.lucene.index.IndexReader$CacheKey@1875360d=org.elasticsearch.indices.IndicesQueryCache$StatsAndCount@46a79038}
13:53:28    > 	at org.elasticsearch.indices.IndicesQueryCache.close(IndicesQueryCache.java:191)
13:53:28    > 	at org.elasticsearch.core.internal.io.IOUtils.closeWhileHandlingException(IOUtils.java:145)
13:53:28    > 	at org.elasticsearch.core.internal.io.IOUtils.closeWhileHandlingException(IOUtils.java:130)
13:53:28    > 	at org.elasticsearch.indices.IndicesService.doClose(IndicesService.java:284)
13:53:28    > 	at org.elasticsearch.common.component.AbstractLifecycleComponent.close(AbstractLifecycleComponent.java:100)
13:53:28    > 	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:103)
13:53:28    > 	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:61)
13:53:28    > 	at org.elasticsearch.node.NodeService.close(NodeService.java:135)
13:53:28    > 	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:103)
13:53:28    > 	at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:85)
13:53:28    > 	at org.elasticsearch.node.Node.close(Node.java:857)
13:53:28    > 	at org.elasticsearch.test.InternalTestCluster$NodeAndClient.close(InternalTestCluster.java:1039)
13:53:28    > 	at org.elasticsearch.test.InternalTestCluster$NodeAndClient.closeForRestart(InternalTestCluster.java:961)
13:53:28    > 	at org.elasticsearch.test.InternalTestCluster.fullRestart(InternalTestCluster.java:1860)
13:53:28    > 	at org.elasticsearch.test.InternalTestCluster.fullRestart(InternalTestCluster.java:1745)
13:53:28    > 	at org.elasticsearch.xpack.ml.integration.MlDistributedFailureIT.lambda$testFullClusterRestart$5(MlDistributedFailureIT.java:113)
13:53:28    > 	at org.elasticsearch.xpack.ml.integration.MlDistributedFailureIT.run(MlDistributedFailureIT.java:293)

[droberts195]

I changed the title of the issue because the things that all these failures have in common are:

1. assert stats2.isEmpty() : stats2; fails in IndicesQueryCache.close
2. They're all using the internal cluster test framework

The stats2 variable and the assertion were added in 38f5cc2. The code then underwent a major refactor in 44c653f. The locking was changed but the assertion in close stayed the same. Could it be a problem with visibility of changes between threads that only manifests itself in the internal cluster tests?

[droberts195]

Another example in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.7+internalClusterTest/49/consoleText

[dakrone]

I spent all day trying to reproduce this, but I was unable to.

The only thing I could think of that would cause it was related to what @droberts195 says about thread visibility, specifically maybe making this:

elasticsearch/server/src/main/java/org/elasticsearch/indices/IndicesQueryCache.java

Line 209 in 431c4fd

int count;

be volatile since that is the determinant of whether stats are removed from the stats2 map; but that is a shot in the dark and I don't have a way to test it since I haven't been able to reproduce this.

I'm curious if anyone else has any ideas.