org.elasticsearch.cluster.SimpleDataNodesIT » testAutoExpandReplicasAdjustedWhenDataNodeJoins

[alpar-t]

Example build failure

https://scans.gradle.com/s/exu7mrkb4htbs/tests/kyv2y2z3r4v7m-cdlwdmcdh66q6

Reproduction line

does not reproduce locally

./gradlew :server:integTest --tests "org.elasticsearch.cluster.SimpleDataNodesIT.testAutoExpandReplicasAdjustedWhenDataNodeJoins" -Dtests.seed=A4B7524EEBD18A4 -Dtests.security.manager=true -Dtests.locale=en-FK -Dtests.timezone=Asia/Atyrau -Dcompiler.java=12 -Druntime.java=11

Example relevant log:

org.apache.lucene.store.AlreadyClosedException: FileLock invalidated by an external force: NativeFSLock(path=/var/lib/jenkins/workspace/elastic+elasticsearch+master+multijob+fast+part1/server/build/testrun/integTest/temp/org.elasticsearch.cluster.SimpleDataNodesIT_A4B7524EEBD18A4-001/tempDir-002/node_t1/node.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive invalid],creationTime=2019-08-05T10:23:13.542911Z)Close stacktrace
at __randomizedtesting.SeedInfo.seed([A4B7524EEBD18A4:4CD2DA2EA74514BC]:0)
at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:178)
at org.elasticsearch.env.NodeEnvironment.assertEnvIsLocked(NodeEnvironment.java:1122)
at org.elasticsearch.env.NodeEnvironment.nodeDataPaths(NodeEnvironment.java:880)
at org.elasticsearch.test.InternalTestCluster$NodeAndClient.markNodeDataDirsAsPendingForWipe(InternalTestCluster.java:959)
at org.elasticsearch.test.InternalTestCluster$NodeAndClient.close(InternalTestCluster.java:943)
at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:104)
at org.elasticsearch.core.internal.io.IOUtils.close(IOUtils.java:86)
at org.elasticsearch.test.InternalTestCluster.close(InternalTestCluster.java:801)
at org.elasticsearch.test.ESIntegTestCase.afterInternal(ESIntegTestCase.java:545)
at org.elasticsearch.test.ESIntegTestCase.cleanUpCluster(ESIntegTestCase.java:1962)
at jdk.internal.reflect.GeneratedMethodAccessor9.invoke(Unknown Source)
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:566)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:996)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:834)

[elasticmachine]

Pinging @elastic/es-distributed

[dnhatn]

If the index gets deleted while we are creating a retention lease for peer recovery, we can release the Store using CancellableThreads. And if we hold the last reference to the Store, we will verify the node lock before deleting the Store. Accessing the node lock (i.e, NativeFSLock) performs some I/O on FileChannel. If CancellableThreads is canceled, the node lock becomes invalid as its channel is closed.

I am working on the fix.

[polyfractal]

Possibly related test failure in SimpleIndexStateIT?

https://gradle-enterprise.elastic.co/s/a6as57hu5yt22/console-log#L4871

1> [2019-08-16T05:56:29,304][WARN ][o.e.i.IndicesService     ] [node_s0] [test/Dzo_hTd0QPW3C-Z3bRj-8w] failed to delete index
--
1> org.elasticsearch.env.ShardLockObtainFailedException: [test][0]: obtaining shard lock timed out after 0ms, previous lock details: [shard creation] trying to lock for [deleting index directory]
1> 	at org.elasticsearch.env.NodeEnvironment$InternalShardLock.acquire(NodeEnvironment.java:860) ~[main/:?]
1> 	at org.elasticsearch.env.NodeEnvironment.shardLock(NodeEnvironment.java:775) ~[main/:?]
1> 	at org.elasticsearch.env.NodeEnvironment.lockAllForIndex(NodeEnvironment.java:718) ~[main/:?]
1> 	at org.elasticsearch.env.NodeEnvironment.deleteIndexDirectorySafe(NodeEnvironment.java:670) ~[main/:?]
1> 	at org.elasticsearch.indices.IndicesService.deleteIndexStoreIfDeletionAllowed(IndicesService.java:800) [main/:?]
1> 	at org.elasticsearch.indices.IndicesService.deleteIndexStore(IndicesService.java:787) [main/:?]
1> 	at org.elasticsearch.indices.IndicesService.removeIndex(IndicesService.java:691) [main/:?]
1> 	at org.elasticsearch.indices.cluster.IndicesClusterStateService.deleteIndices(IndicesClusterStateService.java:375) [main/:?]
1> 	at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyClusterState(IndicesClusterStateService.java:241) [main/:?]
1> 	at org.elasticsearch.cluster.service.ClusterApplierService.lambda$callClusterStateAppliers$5(ClusterApplierService.java:508) [main/:?]
1> 	at java.lang.Iterable.forEach(Iterable.java:75) [?:?]
...
...

[2019-08-16T05:56:29,419][WARN ][o.e.e.NodeEnvironment    ] [node_s1] lock assertion failed
--
1> java.nio.channels.ClosedByInterruptException: null
1> 	at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:199) ~[?:?]
1> 	at sun.nio.ch.FileChannelImpl.endBlocking(FileChannelImpl.java:162) ~[?:?]
1> 	at sun.nio.ch.FileChannelImpl.size(FileChannelImpl.java:388) ~[?:?]
1> 	at org.apache.lucene.mockfile.FilterFileChannel.size(FilterFileChannel.java:85) ~[lucene-test-framework-8.2.0.jar:8.2.0 31d7ec7bbfdcd2c4cc61d9d35e962165410b65fe - ivera - 2019-07-19 15:05:58]
1> 	at org.apache.lucene.mockfile.FilterFileChannel.size(FilterFileChannel.java:85) ~[lucene-test-framework-8.2.0.jar:8.2.0 31d7ec7bbfdcd2c4cc61d9d35e962165410b65fe - ivera - 2019-07-19 15:05:58]
1> 	at org.apache.lucene.mockfile.FilterFileChannel.size(FilterFileChannel.java:85) ~[lucene-test-framework-8.2.0.jar:8.2.0 31d7ec7bbfdcd2c4cc61d9d35e962165410b65fe - ivera - 2019-07-19 15:05:58]
1> 	at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:182) ~[lucene-core-8.2.0.jar:8.2.0 31d7ec7bbfdcd2c4cc61d9d35e962165410b65fe - ivera - 2019-07-19 15:05:56]
1> 	at org.elasticsearch.env.NodeEnvironment.assertEnvIsLocked(NodeEnvironment.java:1122) [main/:?]
1> 	at org.elasticsearch.env.NodeEnvironment.availableShardPaths(NodeEnvironment.java:940) [main/:?]
1> 	at org.elasticsearch.env.NodeEnvironment.deleteShardDirectoryUnderLock(NodeEnvironment.java:608) [main/:?]
1> 	at org.elasticsearch.indices.IndicesService.deleteShardStore(IndicesService.java:829) [main/:?]
1> 	at org.elasticsearch.index.IndexService.onShardClose(IndexService.java:507) [main/:?]
1> 	at org.elasticsearch.index.IndexService$StoreCloseListener.accept(IndexService.java:594) [main/:?]
1> 	at org.elasticsearch.index.IndexService$StoreCloseListener.accept(IndexService.java:581) [main/:?]
1> 	at org.elasticsearch.index.store.Store.closeInternal(Store.java:434) [main/:?]
1> 	at org.elasticsearch.index.store.Store$1.closeInternal(Store.java:159) [main/:?]
...
...

[2019-08-16T05:56:29,429][WARN ][o.e.i.c.IndicesClusterStateService] [node_s1] [[test/Dzo_hTd0QPW3C-Z3bRj-8w]] failed to complete pending deletion for index
--
1> org.apache.lucene.store.AlreadyClosedException: FileLock invalidated by an external force: NativeFSLock(path=/var/lib/jenkins/workspace/elastic+elasticsearch+master+multijob+fast+part1/server/build/testrun/integTest/temp/org.elasticsearch.indices.state.SimpleIndexStateIT_27949ECA20AAFCA0-001/tempDir-002/node_s1/d0/node.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive invalid],creationTime=2019-08-15T17:56:27.11435Z)
1> 	at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:178) ~[lucene-core-8.2.0.jar:8.2.0 31d7ec7bbfdcd2c4cc61d9d35e962165410b65fe - ivera - 2019-07-19 15:05:56]
1> 	at org.elasticsearch.env.NodeEnvironment.assertEnvIsLocked(NodeEnvironment.java:1122) ~[main/:?]
1> 	at org.elasticsearch.env.NodeEnvironment.indexPaths(NodeEnvironment.java:921) ~[main/:?]
1> 	at org.elasticsearch.env.NodeEnvironment.deleteIndexDirectoryUnderLock(NodeEnvironment.java:686) ~[main/:?]
1> 	at org.elasticsearch.indices.IndicesService.processPendingDeletes(IndicesService.java:1099) ~[main/:?]
1> 	at org.elasticsearch.indices.cluster.IndicesClusterStateService$1.doRun(IndicesClusterStateService.java:410) [main/:?]
1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:769) [main/:8.0.0-SNAPSHOT]
1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:8.0.0-SNAPSHOT]
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) [?:?]
...
...