Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[BUG] Fix new flaky test org.opensearch.search.DeletePitMultiNodeTests.testDeletePitWhileNodeDrop #4089

Closed
reta opened this issue Aug 2, 2022 · 7 comments
Closed

[BUG] Fix new flaky test org.opensearch.search.DeletePitMultiNodeTests.testDeletePitWhileNodeDrop #4089

reta opened this issue Aug 2, 2022 · 7 comments
Assignees
@dbwiddis
Labels
bug Something isn't working flaky-test Random test failure that succeeds on second run

Comments

@reta
Copy link
Collaborator

reta commented Aug 2, 2022

Describe the bug
New flaky test org.opensearch.search.DeletePitMultiNodeTests.testDeletePitWhileNodeDrop, first spotted in [1], introduced by [2]

[1] https://build.ci.opensearch.org/job/gradle-check/1269/testReport/junit/org.opensearch.search/DeletePitMultiNodeTests/testDeletePitWhileNodeDrop/
[2] #3949

To Reproduce

REPRODUCE WITH: ./gradlew ':server:test' --tests "org.opensearch.search.DeletePitMultiNodeTests.testDeletePitWhileNodeDrop" -Dtests.seed=EE2F2BD7A3204E93 -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=vi -Dtests.timezone=Asia/Choibalsan -Druntime.java=17

Expected behavior
Test must pass reliably

Plugins
Standard

Screenshots

java.lang.AssertionError
	at __randomizedtesting.SeedInfo.seed([EE2F2BD7A3204E93:1382E3163CB4D5A9]:0)
	at org.junit.Assert.fail(Assert.java:87)
	at org.junit.Assert.assertTrue(Assert.java:42)
	at org.junit.Assert.assertFalse(Assert.java:65)
	at org.junit.Assert.assertFalse(Assert.java:75)
	at org.opensearch.search.DeletePitMultiNodeTests$1.onNodeStopped(DeletePitMultiNodeTests.java:184)
	at org.opensearch.test.InternalTestCluster$NodeAndClient.closeForRestart(InternalTestCluster.java:1028)
	at org.opensearch.test.InternalTestCluster.restartNode(InternalTestCluster.java:1931)
	at org.opensearch.test.InternalTestCluster.restartRandomDataNode(InternalTestCluster.java:1879)
	at org.opensearch.search.DeletePitMultiNodeTests.testDeletePitWhileNodeDrop(DeletePitMultiNodeTests.java:176)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:938)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:974)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:988)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.apache.lucene.tests.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:44)
	at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
	at org.apache.lucene.tests.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:45)
	at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
	at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	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.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.tests.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:38)
	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.tests.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
	at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
	at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
	at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
	at org.apache.lucene.tests.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:47)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
	at java.base/java.lang.Thread.run(Thread.java:833)

Host/Environment (please complete the following information):

  • OS: [e.g. iOS]
  • Version [e.g. 22]

Additional context
Add any other context about the problem here.
@reta reta added bug Something isn't working flaky-test Random test failure that succeeds on second run labels Aug 2, 2022
@reta
Copy link
Collaborator Author

reta commented Aug 2, 2022

@bharath-techie could you please take a look before it became the problem? thank you.

@Bukhtawar Bukhtawar mentioned this issue Aug 8, 2022
Merged
5 tasks
@Poojita-Raj
Copy link
Contributor

Ran 100 times, reproduced failure locally once:

REPRODUCE WITH: ./gradlew 'null' --tests "org.opensearch.search.PitMultiNodeTests.testCreatePitWhileNodeDropWithAllowPartialCreationFalse" -Dtests.seed=892E2A0FCCF769CA -Dtests.locale=en-PH -Dtests.timezone=America/Hermosillo -Druntime.java=14

java.lang.AssertionError:
Expected :0
Actual :1

at __randomizedtesting.SeedInfo.seed([892E2A0FCCF769CA:12B965698CF4ED7B]:0)
at org.junit.Assert.fail(Assert.java:89)
at org.junit.Assert.failNotEquals(Assert.java:835)
at org.junit.Assert.assertEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:633)
at org.opensearch.search.PitMultiNodeTests.validatePitStats(PitMultiNodeTests.java:346)
at org.opensearch.search.PitMultiNodeTests$1.onNodeStopped(PitMultiNodeTests.java:101)
at org.opensearch.test.InternalTestCluster$NodeAndClient.closeForRestart(InternalTestCluster.java:1078)
at org.opensearch.test.InternalTestCluster.restartNode(InternalTestCluster.java:1995)
at org.opensearch.test.InternalTestCluster.restartRandomDataNode(InternalTestCluster.java:1943)
at org.opensearch.search.PitMultiNodeTests.testCreatePitWhileNodeDropWithAllowPartialCreationFalse(PitMultiNodeTests.java:95)
at jdk.internal.reflect.GeneratedMethodAccessor29.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:938)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:974)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:988)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at org.apache.lucene.tests.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:48)
at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
at org.apache.lucene.tests.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:45)
at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
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.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.tests.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:38)
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.tests.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
at org.apache.lucene.tests.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:47)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.base/java.lang.Thread.run(Thread.java:832)

@Poojita-Raj Poojita-Raj mentioned this issue Nov 15, 2022
Closed
37 tasks
@dbwiddis dbwiddis self-assigned this Dec 23, 2022
@dbwiddis
Copy link
Member

Reproduced again with:

for i in {1..100}; do gradle ':server:test' --tests "org.opensearch.search.PitMultiNodeTests.testCreatePitWhileNodeDropWithAllowPartialCreationFalse"; done
REPRODUCE WITH: ./gradlew ':server:test' --tests "org.opensearch.search.PitMultiNodeTests.testCreatePitWhileNodeDropWithAllowPartialCreationFalse" -Dtests.seed=C6274FB30F13698 -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=es-BO -Dtests.timezone=Africa/Maputo -Druntime.java=19

org.opensearch.search.PitMultiNodeTests > testCreatePitWhileNodeDropWithAllowPartialCreationFalse FAILED
    java.lang.AssertionError: expected:<0> but was:<1>
        at __randomizedtesting.SeedInfo.seed([C6274FB30F13698:97F53B9D70F2B229]:0)
        at org.junit.Assert.fail(Assert.java:89)
        at org.junit.Assert.failNotEquals(Assert.java:835)
        at org.junit.Assert.assertEquals(Assert.java:647)
        at org.junit.Assert.assertEquals(Assert.java:633)
        at org.opensearch.search.PitMultiNodeTests.validatePitStats(PitMultiNodeTests.java:346)
        at org.opensearch.search.PitMultiNodeTests$1.onNodeStopped(PitMultiNodeTests.java:101)
        at org.opensearch.test.InternalTestCluster$NodeAndClient.closeForRestart(InternalTestCluster.java:1078)
        at org.opensearch.test.InternalTestCluster.restartNode(InternalTestCluster.java:1995)
        at org.opensearch.test.InternalTestCluster.restartRandomDataNode(InternalTestCluster.java:1943)
        at org.opensearch.search.PitMultiNodeTests.testCreatePitWhileNodeDropWithAllowPartialCreationFalse(PitMultiNodeTests.java:95)


Suite: Test class org.opensearch.search.PitMultiNodeTests
  1> [2022-12-23T22:19:02,732][INFO ][o.o.s.PitMultiNodeTests  ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] before test
  1> [2022-12-23T22:19:02,739][INFO ][o.o.s.PitMultiNodeTests  ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] [PitMultiNodeTests#testCreatePitWhileNodeDropWithAllowPartialCreationFalse]: setting up test
  1> [2022-12-23T22:19:02,778][INFO ][o.o.t.InternalTestCluster] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] Setup InternalTestCluster [SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster] with seed [60BFC7D0275584E4] using [0] dedicated cluster-managers, [2] (data) nodes and [1] coord only nodes (min_cluster_manager_nodes are [auto-managed])
  1> [2022-12-23T22:19:03,045][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] version[3.0.0], pid[49739], build[unknown/unknown/unknown], OS[Mac OS X/12.6.1/x86_64], JVM[Eclipse Adoptium/OpenJDK 64-Bit Server VM/19.0.1/19.0.1+10]
  1> [2022-12-23T22:19:03,045][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] JVM home [/Users/widdisd/.gradle/caches/transforms-3/1b99b0caae74b0d6d3a5c1e42babd2ce/transformed/mac-19.0.1-x64.tar.gz/Contents/Home]
  1> [2022-12-23T22:19:03,047][DEPRECATION][o.o.d.n.Node             ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] no-jdk distributions that do not bundle a JDK are deprecated and will be removed in a future release
  1> [2022-12-23T22:19:03,047][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] JVM arguments [-Dgradle.dist.lib=/Users/widdisd/.gradle/wrapper/dists/gradle-7.6-all/9f832ih6bniajn45pbmqhk2cw/gradle-7.6/lib, -Dgradle.user.home=/Users/widdisd/.gradle, -Dgradle.worker.jar=/Users/widdisd/.gradle/caches/7.6/workerMain/gradle-worker.jar, -Dio.netty.noKeySetOptimization=true, -Dio.netty.noUnsafe=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Djava.awt.headless=true, -Djava.locale.providers=SPI,COMPAT, -Djava.security.manager=allow, -Djna.nosys=true, -Dopensearch.scripting.update.ctx_in_params=false, -Dopensearch.search.rewrite_sort=true, -Dopensearch.transport.cname_in_publish_address=true, -Dorg.gradle.internal.worker.tmpdir=/Users/widdisd/git/OpenSearch/server/build/tmp/test/work, -Dorg.gradle.native=false, -Dtests.artifact=server, -Dtests.gradle=true, -Dtests.jvm.argline=-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=C6274FB30F13698, -Dtests.task=:server:test, -XX:+HeapDumpOnOutOfMemoryError, -XX:TieredStopAtLevel=1, -XX:ReservedCodeCacheSize=64m, -esa, --add-opens=java.base/java.nio.file=ALL-UNNAMED, -XX:HeapDumpPath=/Users/widdisd/git/OpenSearch/server/build/heapdump, -javaagent:../../tmp/expandedArchives/org.jacoco.agent-0.8.8.jar_a33b649e552c51298e5a242c2f0d0e3c/jacocoagent.jar=destfile=../../jacoco/test.exec,append=true,inclnolocationclasses=false,dumponexit=true,output=file,jmx=false, -Xms512m, -Xmx3g, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=/Users/widdisd/git/OpenSearch/server/build/testrun/test/temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
  1> [2022-12-23T22:19:03,055][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] no modules loaded
  1> [2022-12-23T22:19:03,056][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.node.NodeMocksPlugin]
  1> [2022-12-23T22:19:03,056][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.script.MockScriptService$TestPlugin]
  1> [2022-12-23T22:19:03,056][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.search.MockSearchService$TestPlugin]
  1> [2022-12-23T22:19:03,056][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.MockHttpTransport$TestPlugin]
  1> [2022-12-23T22:19:03,056][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.OpenSearchIntegTestCase$AssertActionNamePlugin]
  1> [2022-12-23T22:19:03,057][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.OpenSearchIntegTestCase$TestSeedPlugin]
  1> [2022-12-23T22:19:03,057][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.TestGeoShapeFieldMapperPlugin]
  1> [2022-12-23T22:19:03,057][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.store.MockFSIndexStore$TestPlugin]
  1> [2022-12-23T22:19:03,057][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.transport.MockTransportService$TestPlugin]
  1> [2022-12-23T22:19:03,057][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.transport.nio.MockNioTransportPlugin]
  2> dic 23, 2022 10:19:03 PM org.apache.lucene.store.MMapDirectory lookupProvider
  2> ADVERTENCIA: You are running with Java 19. To make full use of MMapDirectory, please pass '--enable-preview' to the Java command line.
  1> [2022-12-23T22:19:03,092][INFO ][o.o.e.NodeEnvironment    ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] using [1] data paths, mounts [[/System/Volumes/Data (/dev/disk1s2)]], net usable_space [360.3gb], net total_space [465.6gb], types [apfs]
  1> [2022-12-23T22:19:03,092][INFO ][o.o.e.NodeEnvironment    ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] heap size [3gb], compressed ordinary object pointers [true]
  1> [2022-12-23T22:19:03,139][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] node name [node_s0], node ID [3x95DVcBRQSRsSKx-ol5Dg], cluster name [SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster], roles [ingest, remote_cluster_client, data, cluster_manager]
  1> [2022-12-23T22:19:04,578][INFO ][o.o.d.DiscoveryModule    ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] using discovery type [zen] and seed hosts providers [settings, file]
  1> [2022-12-23T22:19:04,892][WARN ][o.o.g.DanglingIndicesState] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] gateway.auto_import_dangling_indices is disabled, dangling indices will not be automatically detected or imported and must be managed manually
  1> [2022-12-23T22:19:05,098][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] initialized
  1> [2022-12-23T22:19:05,100][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] version[3.0.0], pid[49739], build[unknown/unknown/unknown], OS[Mac OS X/12.6.1/x86_64], JVM[Eclipse Adoptium/OpenJDK 64-Bit Server VM/19.0.1/19.0.1+10]
  1> [2022-12-23T22:19:05,100][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] JVM home [/Users/widdisd/.gradle/caches/transforms-3/1b99b0caae74b0d6d3a5c1e42babd2ce/transformed/mac-19.0.1-x64.tar.gz/Contents/Home]
  1> [2022-12-23T22:19:05,100][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] JVM arguments [-Dgradle.dist.lib=/Users/widdisd/.gradle/wrapper/dists/gradle-7.6-all/9f832ih6bniajn45pbmqhk2cw/gradle-7.6/lib, -Dgradle.user.home=/Users/widdisd/.gradle, -Dgradle.worker.jar=/Users/widdisd/.gradle/caches/7.6/workerMain/gradle-worker.jar, -Dio.netty.noKeySetOptimization=true, -Dio.netty.noUnsafe=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Djava.awt.headless=true, -Djava.locale.providers=SPI,COMPAT, -Djava.security.manager=allow, -Djna.nosys=true, -Dopensearch.scripting.update.ctx_in_params=false, -Dopensearch.search.rewrite_sort=true, -Dopensearch.transport.cname_in_publish_address=true, -Dorg.gradle.internal.worker.tmpdir=/Users/widdisd/git/OpenSearch/server/build/tmp/test/work, -Dorg.gradle.native=false, -Dtests.artifact=server, -Dtests.gradle=true, -Dtests.jvm.argline=-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=C6274FB30F13698, -Dtests.task=:server:test, -XX:+HeapDumpOnOutOfMemoryError, -XX:TieredStopAtLevel=1, -XX:ReservedCodeCacheSize=64m, -esa, --add-opens=java.base/java.nio.file=ALL-UNNAMED, -XX:HeapDumpPath=/Users/widdisd/git/OpenSearch/server/build/heapdump, -javaagent:../../tmp/expandedArchives/org.jacoco.agent-0.8.8.jar_a33b649e552c51298e5a242c2f0d0e3c/jacocoagent.jar=destfile=../../jacoco/test.exec,append=true,inclnolocationclasses=false,dumponexit=true,output=file,jmx=false, -Xms512m, -Xmx3g, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=/Users/widdisd/git/OpenSearch/server/build/testrun/test/temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
  1> [2022-12-23T22:19:05,101][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] no modules loaded
  1> [2022-12-23T22:19:05,101][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.node.NodeMocksPlugin]
  1> [2022-12-23T22:19:05,101][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.script.MockScriptService$TestPlugin]
  1> [2022-12-23T22:19:05,101][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.search.MockSearchService$TestPlugin]
  1> [2022-12-23T22:19:05,101][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.MockHttpTransport$TestPlugin]
  1> [2022-12-23T22:19:05,101][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.OpenSearchIntegTestCase$AssertActionNamePlugin]
  1> [2022-12-23T22:19:05,101][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.OpenSearchIntegTestCase$TestSeedPlugin]
  1> [2022-12-23T22:19:05,101][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.TestGeoShapeFieldMapperPlugin]
  1> [2022-12-23T22:19:05,102][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.store.MockFSIndexStore$TestPlugin]
  1> [2022-12-23T22:19:05,102][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.transport.MockTransportService$TestPlugin]
  1> [2022-12-23T22:19:05,102][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.transport.nio.MockNioTransportPlugin]
  1> [2022-12-23T22:19:05,105][INFO ][o.o.e.NodeEnvironment    ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] using [1] data paths, mounts [[/System/Volumes/Data (/dev/disk1s2)]], net usable_space [360.3gb], net total_space [465.6gb], types [apfs]
  1> [2022-12-23T22:19:05,105][INFO ][o.o.e.NodeEnvironment    ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] heap size [3gb], compressed ordinary object pointers [true]
  1> [2022-12-23T22:19:05,108][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] node name [node_s1], node ID [eZHGgdIDQVSNn3AIscXJbQ], cluster name [SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster], roles [ingest, remote_cluster_client, data, cluster_manager]
  1> [2022-12-23T22:19:05,122][INFO ][o.o.d.DiscoveryModule    ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] using discovery type [zen] and seed hosts providers [settings, file]
  1> [2022-12-23T22:19:05,133][WARN ][o.o.g.DanglingIndicesState] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] gateway.auto_import_dangling_indices is disabled, dangling indices will not be automatically detected or imported and must be managed manually
  1> [2022-12-23T22:19:05,141][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] initialized
  1> [2022-12-23T22:19:05,142][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] version[3.0.0], pid[49739], build[unknown/unknown/unknown], OS[Mac OS X/12.6.1/x86_64], JVM[Eclipse Adoptium/OpenJDK 64-Bit Server VM/19.0.1/19.0.1+10]
  1> [2022-12-23T22:19:05,143][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] JVM home [/Users/widdisd/.gradle/caches/transforms-3/1b99b0caae74b0d6d3a5c1e42babd2ce/transformed/mac-19.0.1-x64.tar.gz/Contents/Home]
  1> [2022-12-23T22:19:05,143][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] JVM arguments [-Dgradle.dist.lib=/Users/widdisd/.gradle/wrapper/dists/gradle-7.6-all/9f832ih6bniajn45pbmqhk2cw/gradle-7.6/lib, -Dgradle.user.home=/Users/widdisd/.gradle, -Dgradle.worker.jar=/Users/widdisd/.gradle/caches/7.6/workerMain/gradle-worker.jar, -Dio.netty.noKeySetOptimization=true, -Dio.netty.noUnsafe=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Djava.awt.headless=true, -Djava.locale.providers=SPI,COMPAT, -Djava.security.manager=allow, -Djna.nosys=true, -Dopensearch.scripting.update.ctx_in_params=false, -Dopensearch.search.rewrite_sort=true, -Dopensearch.transport.cname_in_publish_address=true, -Dorg.gradle.internal.worker.tmpdir=/Users/widdisd/git/OpenSearch/server/build/tmp/test/work, -Dorg.gradle.native=false, -Dtests.artifact=server, -Dtests.gradle=true, -Dtests.jvm.argline=-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=C6274FB30F13698, -Dtests.task=:server:test, -XX:+HeapDumpOnOutOfMemoryError, -XX:TieredStopAtLevel=1, -XX:ReservedCodeCacheSize=64m, -esa, --add-opens=java.base/java.nio.file=ALL-UNNAMED, -XX:HeapDumpPath=/Users/widdisd/git/OpenSearch/server/build/heapdump, -javaagent:../../tmp/expandedArchives/org.jacoco.agent-0.8.8.jar_a33b649e552c51298e5a242c2f0d0e3c/jacocoagent.jar=destfile=../../jacoco/test.exec,append=true,inclnolocationclasses=false,dumponexit=true,output=file,jmx=false, -Xms512m, -Xmx3g, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=/Users/widdisd/git/OpenSearch/server/build/testrun/test/temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
  1> [2022-12-23T22:19:05,143][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] no modules loaded
  1> [2022-12-23T22:19:05,144][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.node.NodeMocksPlugin]
  1> [2022-12-23T22:19:05,144][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.script.MockScriptService$TestPlugin]
  1> [2022-12-23T22:19:05,144][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.search.MockSearchService$TestPlugin]
  1> [2022-12-23T22:19:05,144][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.MockHttpTransport$TestPlugin]
  1> [2022-12-23T22:19:05,144][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.OpenSearchIntegTestCase$AssertActionNamePlugin]
  1> [2022-12-23T22:19:05,144][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.OpenSearchIntegTestCase$TestSeedPlugin]
  1> [2022-12-23T22:19:05,144][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.TestGeoShapeFieldMapperPlugin]
  1> [2022-12-23T22:19:05,144][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.store.MockFSIndexStore$TestPlugin]
  1> [2022-12-23T22:19:05,144][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.test.transport.MockTransportService$TestPlugin]
  1> [2022-12-23T22:19:05,145][INFO ][o.o.p.PluginsService     ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] loaded plugin [org.opensearch.transport.nio.MockNioTransportPlugin]
  1> [2022-12-23T22:19:05,147][INFO ][o.o.e.NodeEnvironment    ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] using [1] data paths, mounts [[/System/Volumes/Data (/dev/disk1s2)]], net usable_space [360.3gb], net total_space [465.6gb], types [apfs]
  1> [2022-12-23T22:19:05,148][INFO ][o.o.e.NodeEnvironment    ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] heap size [3gb], compressed ordinary object pointers [true]
  1> [2022-12-23T22:19:05,150][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] node name [node_s2], node ID [6M5Xsdy9TaOVsbYbO-LPzw], cluster name [SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster], roles []
  1> [2022-12-23T22:19:05,163][INFO ][o.o.d.DiscoveryModule    ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] using discovery type [zen] and seed hosts providers [settings, file]
  1> [2022-12-23T22:19:05,173][WARN ][o.o.g.DanglingIndicesState] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] gateway.auto_import_dangling_indices is disabled, dangling indices will not be automatically detected or imported and must be managed manually
  1> [2022-12-23T22:19:05,180][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] initialized
  1> [2022-12-23T22:19:05,183][INFO ][o.o.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster[T#2]]] starting ...
  1> [2022-12-23T22:19:05,183][INFO ][o.o.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster[T#3]]] starting ...
  1> [2022-12-23T22:19:05,183][INFO ][o.o.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster[T#1]]] starting ...
  1> [2022-12-23T22:19:05,214][INFO ][o.o.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster[T#3]]] publish_address {127.0.0.1:62071}, bound_addresses {[::1]:62068}, {127.0.0.1:62071}
  1> [2022-12-23T22:19:05,214][INFO ][o.o.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster[T#2]]] publish_address {127.0.0.1:62070}, bound_addresses {[::1]:62066}, {127.0.0.1:62070}
  1> [2022-12-23T22:19:05,214][INFO ][o.o.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster[T#1]]] publish_address {127.0.0.1:62069}, bound_addresses {[::1]:62067}, {127.0.0.1:62069}
  1> [2022-12-23T22:19:05,516][INFO ][o.o.c.c.Coordinator      ] [node_s0] setting initial configuration to VotingConfiguration{eZHGgdIDQVSNn3AIscXJbQ,3x95DVcBRQSRsSKx-ol5Dg}
  1> [2022-12-23T22:19:05,646][INFO ][o.o.c.s.MasterService    ] [node_s0] elected-as-cluster-manager ([2] nodes joined)[{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true} elect leader, {node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true} elect leader, _BECOME_CLUSTER_MANAGER_TASK_, _FINISH_ELECTION_], term: 1, version: 1, delta: cluster-manager node changed {previous [], current [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}]}, added {{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}}
  1> [2022-12-23T22:19:05,692][INFO ][o.o.c.c.CoordinationState] [node_s0] cluster UUID set to [BmmE-gGXTPC3CFOLmWB1Fw]
  1> [2022-12-23T22:19:05,692][INFO ][o.o.c.c.CoordinationState] [node_s1] cluster UUID set to [BmmE-gGXTPC3CFOLmWB1Fw]
  1> [2022-12-23T22:19:05,726][INFO ][o.o.c.s.ClusterApplierService] [node_s1] cluster-manager node changed {previous [], current [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}]}, added {{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}}, term: 1, version: 1, reason: ApplyCommitRequest{term=1, version=1, sourceNode={node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}}
  1> [2022-12-23T22:19:05,733][INFO ][o.o.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster[T#2]]] started
  1> [2022-12-23T22:19:05,736][INFO ][o.o.c.s.ClusterApplierService] [node_s0] cluster-manager node changed {previous [], current [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}]}, added {{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}}, term: 1, version: 1, reason: Publication{term=1, version=1}
  1> [2022-12-23T22:19:05,742][INFO ][o.o.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster[T#1]]] started
  1> [2022-12-23T22:19:05,747][INFO ][o.o.d.PeerFinder         ] [node_s0] setting findPeersInterval to [1s] as node commission status = [true] for local node [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}]
  1> [2022-12-23T22:19:05,749][INFO ][o.o.d.PeerFinder         ] [node_s1] setting findPeersInterval to [1s] as node commission status = [true] for local node [{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}]
  1> [2022-12-23T22:19:05,758][INFO ][o.o.c.r.a.DiskThresholdMonitor] [node_s0] skipping monitor as a check is already in progress
  1> [2022-12-23T22:19:05,828][INFO ][o.o.g.GatewayService     ] [node_s0] recovered [0] indices into cluster_state
  1> [2022-12-23T22:19:06,465][INFO ][o.o.c.s.MasterService    ] [node_s0] node-join[{node_s2}{6M5Xsdy9TaOVsbYbO-LPzw}{x7nuWYVoTQKUcXG16fBF9w}{127.0.0.1}{127.0.0.1:62071}{shard_indexing_pressure_enabled=true} join existing leader], term: 1, version: 4, delta: added {{node_s2}{6M5Xsdy9TaOVsbYbO-LPzw}{x7nuWYVoTQKUcXG16fBF9w}{127.0.0.1}{127.0.0.1:62071}{shard_indexing_pressure_enabled=true}}
  1> [2022-12-23T22:19:06,484][INFO ][o.o.c.s.ClusterApplierService] [node_s2] cluster-manager node changed {previous [], current [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}]}, added {{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true},{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}}, term: 1, version: 4, reason: ApplyCommitRequest{term=1, version=4, sourceNode={node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}}
  1> [2022-12-23T22:19:06,485][INFO ][o.o.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[27]-CLUSTER_SEED=[6971510445019858148]-HASH=[E2E88F864D33]-cluster[T#3]]] started
  1> [2022-12-23T22:19:06,485][INFO ][o.o.c.s.ClusterApplierService] [node_s1] added {{node_s2}{6M5Xsdy9TaOVsbYbO-LPzw}{x7nuWYVoTQKUcXG16fBF9w}{127.0.0.1}{127.0.0.1:62071}{shard_indexing_pressure_enabled=true}}, term: 1, version: 4, reason: ApplyCommitRequest{term=1, version=4, sourceNode={node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}}
  1> [2022-12-23T22:19:06,496][INFO ][o.o.c.s.ClusterApplierService] [node_s0] added {{node_s2}{6M5Xsdy9TaOVsbYbO-LPzw}{x7nuWYVoTQKUcXG16fBF9w}{127.0.0.1}{127.0.0.1:62071}{shard_indexing_pressure_enabled=true}}, term: 1, version: 4, reason: Publication{term=1, version=4}
  1> [2022-12-23T22:19:06,497][INFO ][o.o.d.PeerFinder         ] [node_s2] setting findPeersInterval to [1s] as node commission status = [true] for local node [{node_s2}{6M5Xsdy9TaOVsbYbO-LPzw}{x7nuWYVoTQKUcXG16fBF9w}{127.0.0.1}{127.0.0.1:62071}{shard_indexing_pressure_enabled=true}]
  1> [2022-12-23T22:19:06,534][DEPRECATION][o.o.d.c.s.Settings       ] [node_s0] [index.force_memory_term_dictionary] setting was deprecated in OpenSearch and will be removed in a future release! See the breaking changes documentation for the next major version.
  1> [2022-12-23T22:19:06,556][INFO ][o.o.p.PluginsService     ] [node_s0] PluginService:onIndexModule index:[tT5MiT1CRFi9ujmIeUmJIQ/wfKXsCjGR6WJH0cDuhai9g]
  1> [2022-12-23T22:19:06,681][INFO ][o.o.c.m.MetadataIndexTemplateService] [node_s0] adding template [random_index_template] for index patterns [*]
  1> [2022-12-23T22:19:06,707][INFO ][o.o.s.PitMultiNodeTests  ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] [PitMultiNodeTests#testCreatePitWhileNodeDropWithAllowPartialCreationFalse]: all set up test
  1> [2022-12-23T22:19:06,714][INFO ][o.o.p.PluginsService     ] [node_s0] PluginService:onIndexModule index:[index/S34yaL4NREO3cfcK0xSpmA]
  1> [2022-12-23T22:19:06,718][INFO ][o.o.c.m.MetadataCreateIndexService] [node_s0] [index] creating index, cause [api], templates [random_index_template], shards [2]/[0]
  1> [2022-12-23T22:19:06,774][INFO ][o.o.p.PluginsService     ] [node_s1] PluginService:onIndexModule index:[index/S34yaL4NREO3cfcK0xSpmA]
  1> [2022-12-23T22:19:06,828][INFO ][o.o.p.PluginsService     ] [node_s0] PluginService:onIndexModule index:[index/S34yaL4NREO3cfcK0xSpmA]
  1> [2022-12-23T22:19:07,031][INFO ][o.o.c.r.a.AllocationService] [node_s0] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[index][0]]]).
  1> [2022-12-23T22:19:07,136][INFO ][o.o.p.PluginsService     ] [node_s0] PluginService:onIndexModule index:[index/S34yaL4NREO3cfcK0xSpmA]
  1> [2022-12-23T22:19:07,139][INFO ][o.o.c.m.MetadataMappingService] [node_s0] [index/S34yaL4NREO3cfcK0xSpmA] create_mapping
  1> [2022-12-23T22:19:07,330][INFO ][o.o.t.InternalTestCluster] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] Restarting node [node_s0] 
  1> [2022-12-23T22:19:07,331][INFO ][o.o.t.InternalTestCluster] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] adding voting config exclusions [node_s0] prior to restart/shutdown
  1> [2022-12-23T22:19:07,405][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] stopping ...
  1> [2022-12-23T22:19:07,405][INFO ][o.o.c.c.Coordinator      ] [node_s0] abdicating to {node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true} with term 2
  1> [2022-12-23T22:19:07,407][INFO ][o.o.c.s.ClusterApplierService] [node_s2] cluster-manager node changed {previous [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}], current []}, term: 1, version: 12, reason: becoming candidate: joinLeaderInTerm
  1> [2022-12-23T22:19:07,407][INFO ][o.o.c.s.ClusterApplierService] [node_s0] cluster-manager node changed {previous [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}], current []}, term: 1, version: 12, reason: becoming candidate: after abdicating to {node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}
  1> [2022-12-23T22:19:07,410][INFO ][o.o.c.s.ClusterApplierService] [node_s1] cluster-manager node changed {previous [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}], current []}, term: 1, version: 12, reason: becoming candidate: joinLeaderInTerm
  1> [2022-12-23T22:19:07,412][INFO ][o.o.c.s.MasterService    ] [node_s1] elected-as-cluster-manager ([1] nodes joined)[{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true} elect leader, _BECOME_CLUSTER_MANAGER_TASK_, _FINISH_ELECTION_], term: 2, version: 13, delta: cluster-manager node changed {previous [], current [{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}]}
  1> [2022-12-23T22:19:07,416][INFO ][o.o.t.s.M.Listener       ] [node_s0] [index][1] start check index
  1> [2022-12-23T22:19:07,417][INFO ][o.o.c.c.JoinHelper       ] [node_s0] failed to join {node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true} with JoinRequest{sourceNode={node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}, minimumTerm=1, optionalJoin=Optional[Join{term=2, lastAcceptedTerm=1, lastAcceptedVersion=12, sourceNode={node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}, targetNode={node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}}]}
  1> org.opensearch.transport.NodeNotConnectedException: [node_s1][127.0.0.1:62070] Node not connected
  1>    at org.opensearch.transport.ClusterConnectionManager.getConnection(ClusterConnectionManager.java:206) ~[main/:?]
  1>    at org.opensearch.test.transport.StubbableConnectionManager.getConnection(StubbableConnectionManager.java:93) ~[framework-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.transport.TransportService.getConnection(TransportService.java:825) ~[main/:?]
  1>    at org.opensearch.transport.TransportService.sendRequest(TransportService.java:741) [main/:?]
  1>    at org.opensearch.cluster.coordination.JoinHelper.sendJoinRequest(JoinHelper.java:335) [main/:?]
  1>    at org.opensearch.cluster.coordination.JoinHelper.sendJoinRequest(JoinHelper.java:263) [main/:?]
  1>    at org.opensearch.cluster.coordination.JoinHelper.lambda$new$2(JoinHelper.java:201) [main/:?]
  1>    at org.opensearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:106) [main/:?]
  1>    at org.opensearch.transport.TransportService$8.doRun(TransportService.java:973) [main/:?]
  1>    at org.opensearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:806) [main/:?]
  1>    at org.opensearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:52) [main/:?]
  1>    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) [?:?]
  1>    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) [?:?]
  1>    at java.lang.Thread.run(Thread.java:1589) [?:?]
  1> [2022-12-23T22:19:07,423][INFO ][o.o.c.c.FollowersChecker ] [node_s1] FollowerChecker{discoveryNode={node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}, failureCountSinceLastSuccess=1, [cluster.fault_detection.follower_check.retry_count]=3} disconnected
  1> org.opensearch.transport.NodeNotConnectedException: [node_s0][127.0.0.1:62069] Node not connected
  1>    at org.opensearch.transport.ClusterConnectionManager.getConnection(ClusterConnectionManager.java:206) ~[main/:?]
  1>    at org.opensearch.test.transport.StubbableConnectionManager.getConnection(StubbableConnectionManager.java:93) ~[framework-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.transport.TransportService.getConnection(TransportService.java:825) ~[main/:?]
  1>    at org.opensearch.transport.TransportService.sendRequest(TransportService.java:741) [main/:?]
  1>    at org.opensearch.cluster.coordination.FollowersChecker$FollowerChecker.handleWakeUp(FollowersChecker.java:348) [main/:?]
  1>    at org.opensearch.cluster.coordination.FollowersChecker$FollowerChecker.start(FollowersChecker.java:336) [main/:?]
  1>    at org.opensearch.cluster.coordination.FollowersChecker.lambda$setCurrentNodes$2(FollowersChecker.java:178) [main/:?]
  1>    at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) [?:?]
  1>    at java.util.Iterator.forEachRemaining(Iterator.java:133) [?:?]
  1>    at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1921) [?:?]
  1>    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) [?:?]
  1>    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) [?:?]
  1>    at java.util.stream.StreamSpliterators$WrappingSpliterator.forEachRemaining(StreamSpliterators.java:310) [?:?]
  1>    at java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:734) [?:?]
  1>    at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762) [?:?]
  1>    at org.opensearch.cluster.coordination.FollowersChecker.setCurrentNodes(FollowersChecker.java:171) [main/:?]
  1>    at org.opensearch.cluster.coordination.Coordinator.publish(Coordinator.java:1307) [main/:?]
  1>    at org.opensearch.cluster.service.MasterService.publish(MasterService.java:349) [main/:?]
  1>    at org.opensearch.cluster.service.MasterService.runTasks(MasterService.java:331) [main/:?]
  1>    at org.opensearch.cluster.service.MasterService$Batcher.run(MasterService.java:206) [main/:?]
  1>    at org.opensearch.cluster.service.TaskBatcher.runIfNotProcessed(TaskBatcher.java:190) [main/:?]
  1>    at org.opensearch.cluster.service.TaskBatcher$BatchedTask.run(TaskBatcher.java:228) [main/:?]
  1>    at org.opensearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:747) [main/:?]
  1>    at org.opensearch.common.util.concurrent.PrioritizedOpenSearchThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedOpenSearchThreadPoolExecutor.java:282) [main/:?]
  1>    at org.opensearch.common.util.concurrent.PrioritizedOpenSearchThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedOpenSearchThreadPoolExecutor.java:245) [main/:?]
  1>    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) [?:?]
  1>    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) [?:?]
  1>    at java.lang.Thread.run(Thread.java:1589) [?:?]
  1> [2022-12-23T22:19:07,428][INFO ][o.o.c.c.JoinHelper       ] [node_s0] failed to join {node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true} with JoinRequest{sourceNode={node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}, minimumTerm=1, optionalJoin=Optional[Join{term=2, lastAcceptedTerm=1, lastAcceptedVersion=12, sourceNode={node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}, targetNode={node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}}]}
  1> org.opensearch.transport.NodeNotConnectedException: [node_s1][127.0.0.1:62070] Node not connected
  1>    at org.opensearch.transport.ClusterConnectionManager.getConnection(ClusterConnectionManager.java:206) ~[main/:?]
  1>    at org.opensearch.test.transport.StubbableConnectionManager.getConnection(StubbableConnectionManager.java:93) ~[framework-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.transport.TransportService.getConnection(TransportService.java:825) ~[main/:?]
  1>    at org.opensearch.transport.TransportService.sendRequest(TransportService.java:741) [main/:?]
  1>    at org.opensearch.cluster.coordination.JoinHelper.sendJoinRequest(JoinHelper.java:335) [main/:?]
  1>    at org.opensearch.cluster.coordination.JoinHelper.sendJoinRequest(JoinHelper.java:263) [main/:?]
  1>    at org.opensearch.cluster.coordination.JoinHelper.lambda$new$2(JoinHelper.java:201) [main/:?]
  1>    at org.opensearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:106) [main/:?]
  1>    at org.opensearch.transport.TransportService$8.doRun(TransportService.java:973) [main/:?]
  1>    at org.opensearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:806) [main/:?]
  1>    at org.opensearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:52) [main/:?]
  1>    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) [?:?]
  1>    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) [?:?]
  1>    at java.lang.Thread.run(Thread.java:1589) [?:?]
  1> [2022-12-23T22:19:07,429][WARN ][o.o.t.TransportService   ] [node_s0] Transport response handler not found of id [88]
  1> [2022-12-23T22:19:07,428][INFO ][o.o.c.c.FollowersChecker ] [node_s1] FollowerChecker{discoveryNode={node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}, failureCountSinceLastSuccess=1, [cluster.fault_detection.follower_check.retry_count]=3} marking node as faulty
  1> [2022-12-23T22:19:07,438][INFO ][o.o.t.s.M.Listener       ] [node_s0] [index][1] end check index
  1> [2022-12-23T22:19:07,439][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] stopped
  1> [2022-12-23T22:19:07,439][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] closing ...
  1> [2022-12-23T22:19:07,445][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] closed
  1> [2022-12-23T22:19:07,479][ERROR][o.o.a.s.TransportCreatePitAction] [node_s2] PIT creation failed while updating PIT ID for indices [[index]]
  1> [2022-12-23T22:19:08,422][INFO ][o.o.c.s.ClusterApplierService] [node_s2] cluster-manager node changed {previous [], current [{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}]}, term: 2, version: 13, reason: ApplyCommitRequest{term=2, version=13, sourceNode={node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}}
  1> [2022-12-23T22:19:08,424][INFO ][o.o.c.s.ClusterApplierService] [node_s1] cluster-manager node changed {previous [], current [{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}]}, term: 2, version: 13, reason: Publication{term=2, version=13}
  1> [2022-12-23T22:19:08,423][WARN ][o.o.c.NodeConnectionsService] [node_s2] failed to connect to {node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true} (tried [1] times)
  1> org.opensearch.transport.ConnectTransportException: [node_s0][127.0.0.1:62069] connect_exception
  1>    at org.opensearch.transport.TcpTransport$ChannelsConnectedListener.onFailure(TcpTransport.java:1076) ~[main/:?]
  1>    at org.opensearch.action.ActionListener.lambda$toBiConsumer$2(ActionListener.java:215) ~[main/:?]
  1>    at org.opensearch.common.concurrent.CompletableContext.lambda$addListener$0(CompletableContext.java:55) ~[opensearch-core-3.0.0-SNAPSHOT.jar:?]
  1>    at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
  1>    at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
  1>    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
  1>    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2194) ~[?:?]
  1>    at org.opensearch.common.concurrent.CompletableContext.completeExceptionally(CompletableContext.java:70) ~[opensearch-core-3.0.0-SNAPSHOT.jar:?]
  1>    at org.opensearch.nio.SocketChannelContext.connect(SocketChannelContext.java:160) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.EventHandler.handleConnect(EventHandler.java:130) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.transport.nio.TestEventHandler.handleConnect(TestEventHandler.java:139) ~[framework-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.attemptConnect(NioSelector.java:446) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.registerChannel(NioSelector.java:469) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.setUpNewChannels(NioSelector.java:458) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.preSelect(NioSelector.java:279) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.singleLoop(NioSelector.java:172) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.runLoop(NioSelector.java:148) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at java.lang.Thread.run(Thread.java:1589) [?:?]
  1> Caused by: java.net.ConnectException: Connection refused
  1>    at sun.nio.ch.Net.pollConnect(Native Method) ~[?:?]
  1>    at sun.nio.ch.Net.pollConnectNow(Net.java:672) ~[?:?]
  1>    at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:973) ~[?:?]
  1>    at org.opensearch.nio.SocketChannelContext.connect(SocketChannelContext.java:157) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    ... 9 more
  1> [2022-12-23T22:19:08,425][WARN ][o.o.c.NodeConnectionsService] [node_s1] failed to connect to {node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true} (tried [1] times)
  1> org.opensearch.transport.ConnectTransportException: [node_s0][127.0.0.1:62069] connect_exception
  1>    at org.opensearch.transport.TcpTransport$ChannelsConnectedListener.onFailure(TcpTransport.java:1076) ~[main/:?]
  1>    at org.opensearch.action.ActionListener.lambda$toBiConsumer$2(ActionListener.java:215) ~[main/:?]
  1>    at org.opensearch.common.concurrent.CompletableContext.lambda$addListener$0(CompletableContext.java:55) ~[opensearch-core-3.0.0-SNAPSHOT.jar:?]
  1>    at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
  1>    at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
  1>    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
  1>    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2194) ~[?:?]
  1>    at org.opensearch.common.concurrent.CompletableContext.completeExceptionally(CompletableContext.java:70) ~[opensearch-core-3.0.0-SNAPSHOT.jar:?]
  1>    at org.opensearch.nio.SocketChannelContext.connect(SocketChannelContext.java:160) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.EventHandler.handleConnect(EventHandler.java:130) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.transport.nio.TestEventHandler.handleConnect(TestEventHandler.java:139) ~[framework-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.attemptConnect(NioSelector.java:446) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.registerChannel(NioSelector.java:469) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.setUpNewChannels(NioSelector.java:458) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.preSelect(NioSelector.java:279) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.singleLoop(NioSelector.java:172) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.runLoop(NioSelector.java:148) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at java.lang.Thread.run(Thread.java:1589) [?:?]
  1> Caused by: java.net.ConnectException: Connection refused
  1>    at sun.nio.ch.Net.pollConnect(Native Method) ~[?:?]
  1>    at sun.nio.ch.Net.pollConnectNow(Net.java:672) ~[?:?]
  1>    at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:973) ~[?:?]
  1>    at org.opensearch.nio.SocketChannelContext.connect(SocketChannelContext.java:157) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    ... 9 more
  1> [2022-12-23T22:19:08,429][INFO ][o.o.d.PeerFinder         ] [node_s1] setting findPeersInterval to [1s] as node commission status = [true] for local node [{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}]
  1> [2022-12-23T22:19:08,436][INFO ][o.o.c.s.MasterService    ] [node_s1] node-left[{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true} reason: disconnected], term: 2, version: 14, delta: removed {{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}}
  1> [2022-12-23T22:19:08,504][INFO ][o.o.c.s.ClusterApplierService] [node_s2] removed {{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}}, term: 2, version: 14, reason: ApplyCommitRequest{term=2, version=14, sourceNode={node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}}
  1> [2022-12-23T22:19:08,505][INFO ][o.o.c.s.ClusterApplierService] [node_s1] removed {{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}}, term: 2, version: 14, reason: Publication{term=2, version=14}
  1> [2022-12-23T22:19:08,516][INFO ][o.o.d.PeerFinder         ] [node_s2] setting findPeersInterval to [1s] as node commission status = [true] for local node [{node_s2}{6M5Xsdy9TaOVsbYbO-LPzw}{x7nuWYVoTQKUcXG16fBF9w}{127.0.0.1}{127.0.0.1:62071}{shard_indexing_pressure_enabled=true}]
  1> [2022-12-23T22:19:08,516][INFO ][o.o.c.m.MetadataDeleteIndexService] [node_s1] [index/S34yaL4NREO3cfcK0xSpmA] deleting index
  1> [2022-12-23T22:19:08,545][INFO ][o.o.t.s.M.Listener       ] [node_s1] [index][0] start check index
  1> [2022-12-23T22:19:08,547][INFO ][o.o.t.s.M.Listener       ] [node_s1] [index][0] end check index
  1> [2022-12-23T22:19:08,561][INFO ][o.o.s.PitMultiNodeTests  ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] [PitMultiNodeTests#testCreatePitWhileNodeDropWithAllowPartialCreationFalse]: cleaning up after test
  1> [2022-12-23T22:19:08,592][INFO ][o.o.c.m.MetadataIndexTemplateService] [node_s1] removing template [random_index_template]
  1> [2022-12-23T22:19:08,615][INFO ][o.o.s.PitMultiNodeTests  ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] [PitMultiNodeTests#testCreatePitWhileNodeDropWithAllowPartialCreationFalse]: cleaned up after test
  1> [2022-12-23T22:19:08,616][INFO ][o.o.s.PitMultiNodeTests  ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] after test
  2> REPRODUCE WITH: ./gradlew ':server:test' --tests "org.opensearch.search.PitMultiNodeTests.testCreatePitWhileNodeDropWithAllowPartialCreationFalse" -Dtests.seed=C6274FB30F13698 -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=es-BO -Dtests.timezone=Africa/Maputo -Druntime.java=19
  2> java.lang.AssertionError: expected:<0> but was:<1>
        at __randomizedtesting.SeedInfo.seed([C6274FB30F13698:97F53B9D70F2B229]:0)
        at org.junit.Assert.fail(Assert.java:89)
        at org.junit.Assert.failNotEquals(Assert.java:835)
        at org.junit.Assert.assertEquals(Assert.java:647)
        at org.junit.Assert.assertEquals(Assert.java:633)
        at org.opensearch.search.PitMultiNodeTests.validatePitStats(PitMultiNodeTests.java:346)
        at org.opensearch.search.PitMultiNodeTests$1.onNodeStopped(PitMultiNodeTests.java:101)
        at org.opensearch.test.InternalTestCluster$NodeAndClient.closeForRestart(InternalTestCluster.java:1078)
        at org.opensearch.test.InternalTestCluster.restartNode(InternalTestCluster.java:1995)
        at org.opensearch.test.InternalTestCluster.restartRandomDataNode(InternalTestCluster.java:1943)
        at org.opensearch.search.PitMultiNodeTests.testCreatePitWhileNodeDropWithAllowPartialCreationFalse(PitMultiNodeTests.java:95)
  1> [2022-12-23T22:19:08,626][INFO ][o.o.n.Node               ] [suite] stopping ...
  1> [2022-12-23T22:19:08,628][INFO ][o.o.c.c.FollowersChecker ] [suite] FollowerChecker{discoveryNode={node_s2}{6M5Xsdy9TaOVsbYbO-LPzw}{x7nuWYVoTQKUcXG16fBF9w}{127.0.0.1}{127.0.0.1:62071}{shard_indexing_pressure_enabled=true}, failureCountSinceLastSuccess=0, [cluster.fault_detection.follower_check.retry_count]=3} disconnected
  1> [2022-12-23T22:19:08,628][INFO ][o.o.c.c.FollowersChecker ] [node_s1] FollowerChecker{discoveryNode={node_s2}{6M5Xsdy9TaOVsbYbO-LPzw}{x7nuWYVoTQKUcXG16fBF9w}{127.0.0.1}{127.0.0.1:62071}{shard_indexing_pressure_enabled=true}, failureCountSinceLastSuccess=0, [cluster.fault_detection.follower_check.retry_count]=3} marking node as faulty
  1> [2022-12-23T22:19:08,629][INFO ][o.o.n.Node               ] [suite] stopped
  1> [2022-12-23T22:19:08,629][INFO ][o.o.n.Node               ] [suite] closing ...
  1> [2022-12-23T22:19:08,629][INFO ][o.o.c.c.Coordinator      ] [node_s2] cluster-manager node [{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}] failed, restarting discovery
  1> org.opensearch.transport.NodeDisconnectedException: [node_s1][127.0.0.1:62070][disconnected] disconnected
  1> [2022-12-23T22:19:08,630][INFO ][o.o.c.s.ClusterApplierService] [node_s2] cluster-manager node changed {previous [{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}], current []}, term: 2, version: 18, reason: becoming candidate: onLeaderFailure
  1> [2022-12-23T22:19:08,632][INFO ][o.o.n.Node               ] [suite] closed
  1> [2022-12-23T22:19:08,633][INFO ][o.o.n.Node               ] [suite] stopping ...
  1> [2022-12-23T22:19:08,632][WARN ][o.o.c.NodeConnectionsService] [node_s2] failed to connect to {node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true} (tried [1] times)
  1> org.opensearch.transport.ConnectTransportException: [node_s1][127.0.0.1:62070] connect_exception
  1>    at org.opensearch.transport.TcpTransport$ChannelsConnectedListener.onFailure(TcpTransport.java:1076) ~[main/:?]
  1>    at org.opensearch.action.ActionListener.lambda$toBiConsumer$2(ActionListener.java:215) ~[main/:?]
  1>    at org.opensearch.common.concurrent.CompletableContext.lambda$addListener$0(CompletableContext.java:55) ~[opensearch-core-3.0.0-SNAPSHOT.jar:?]
  1>    at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
  1>    at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
  1>    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
  1>    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2194) ~[?:?]
  1>    at org.opensearch.common.concurrent.CompletableContext.completeExceptionally(CompletableContext.java:70) ~[opensearch-core-3.0.0-SNAPSHOT.jar:?]
  1>    at org.opensearch.nio.SocketChannelContext.connect(SocketChannelContext.java:160) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.EventHandler.handleConnect(EventHandler.java:130) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.transport.nio.TestEventHandler.handleConnect(TestEventHandler.java:139) ~[framework-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.attemptConnect(NioSelector.java:446) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.registerChannel(NioSelector.java:469) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.setUpNewChannels(NioSelector.java:458) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.preSelect(NioSelector.java:279) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.singleLoop(NioSelector.java:172) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at org.opensearch.nio.NioSelector.runLoop(NioSelector.java:148) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    at java.lang.Thread.run(Thread.java:1589) [?:?]
  1> Caused by: java.net.ConnectException: Connection refused
  1>    at sun.nio.ch.Net.pollConnect(Native Method) ~[?:?]
  1>    at sun.nio.ch.Net.pollConnectNow(Net.java:672) ~[?:?]
  1>    at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:973) ~[?:?]
  1>    at org.opensearch.nio.SocketChannelContext.connect(SocketChannelContext.java:157) ~[opensearch-nio-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
  1>    ... 9 more
  1> [2022-12-23T22:19:08,634][INFO ][o.o.n.Node               ] [suite] stopped
  1> [2022-12-23T22:19:08,634][INFO ][o.o.n.Node               ] [suite] closing ...
  1> [2022-12-23T22:19:08,636][INFO ][o.o.n.Node               ] [suite] closed
  2> NOTE: leaving temporary files on disk at: /Users/widdisd/git/OpenSearch/server/build/testrun/test/temp/org.opensearch.search.PitMultiNodeTests_C6274FB30F13698-001
  2> NOTE: test params are: codec=Asserting(Lucene95): {index_uuid=PostingsFormat(name=Asserting), field=Lucene90, _id=Lucene90, field.keyword=Lucene90, type=PostingsFormat(name=Asserting)}, docValues:{_seq_no=DocValuesFormat(name=Lucene90), field.keyword=DocValuesFormat(name=Asserting), _primary_term=DocValuesFormat(name=Lucene90), _version=DocValuesFormat(name=Lucene90)}, maxPointsInLeafNode=1966, maxMBSortInHeap=5.432256900458554, sim=Asserting(RandomSimilarity(queryNorm=true): {}), locale=es-BO, timezone=Africa/Maputo
  2> NOTE: Mac OS X 12.6.1 x86_64/Eclipse Adoptium 19.0.1 (64-bit)/cpus=12,threads=1,free=293158744,total=536870912
  2> NOTE: All tests run in this JVM: [PitMultiNodeTests]

@dbwiddis
Copy link
Member

Analysis so far:

Three-node cluster setup with node_s0 as cluster manager.

The test creates a random index which is replicated to 2 shards, apparently on node_s0 and node_s1:

  1> [2022-12-23T22:19:06,707][INFO ][o.o.s.PitMultiNodeTests  ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] [PitMultiNodeTests#testCreatePitWhileNodeDropWithAllowPartialCreationFalse]: all set up test
  1> [2022-12-23T22:19:06,714][INFO ][o.o.p.PluginsService     ] [node_s0] PluginService:onIndexModule index:[index/S34yaL4NREO3cfcK0xSpmA]
  1> [2022-12-23T22:19:06,718][INFO ][o.o.c.m.MetadataCreateIndexService] [node_s0] [index] creating index, cause [api], templates [random_index_template], shards [2]/[0]
  1> [2022-12-23T22:19:06,774][INFO ][o.o.p.PluginsService     ] [node_s1] PluginService:onIndexModule index:[index/S34yaL4NREO3cfcK0xSpmA]
  1> [2022-12-23T22:19:06,828][INFO ][o.o.p.PluginsService     ] [node_s0] PluginService:onIndexModule index:[index/S34yaL4NREO3cfcK0xSpmA]
  1> [2022-12-23T22:19:07,031][INFO ][o.o.c.r.a.AllocationService] [node_s0] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[index][0]]]).
  1> [2022-12-23T22:19:07,136][INFO ][o.o.p.PluginsService     ] [node_s0] PluginService:onIndexModule index:[index/S34yaL4NREO3cfcK0xSpmA]

However, there is no triggering of PluginService:onIndexModule() for node_s2.

ClusterState updated on node_s0.

  1> [2022-12-23T22:19:07,139][INFO ][o.o.c.m.MetadataMappingService] [node_s0] [index/S34yaL4NREO3cfcK0xSpmA] create_mapping

Then node_s0 is rebooted, node_s1 becomes new cluster manager.

  1> [2022-12-23T22:19:07,330][INFO ][o.o.t.InternalTestCluster] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] Restarting node [node_s0] 
  1> [2022-12-23T22:19:07,331][INFO ][o.o.t.InternalTestCluster] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] adding voting config exclusions [node_s0] prior to restart/shutdown
  1> [2022-12-23T22:19:07,405][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] stopping ...
  1> [2022-12-23T22:19:07,405][INFO ][o.o.c.c.Coordinator      ] [node_s0] abdicating to {node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true} with term 2
  1> [2022-12-23T22:19:07,407][INFO ][o.o.c.s.ClusterApplierService] [node_s2] cluster-manager node changed {previous [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}], current []}, term: 1, version: 12, reason: becoming candidate: joinLeaderInTerm
  1> [2022-12-23T22:19:07,407][INFO ][o.o.c.s.ClusterApplierService] [node_s0] cluster-manager node changed {previous [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}], current []}, term: 1, version: 12, reason: becoming candidate: after abdicating to {node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}
  1> [2022-12-23T22:19:07,410][INFO ][o.o.c.s.ClusterApplierService] [node_s1] cluster-manager node changed {previous [{node_s0}{3x95DVcBRQSRsSKx-ol5Dg}{DyW3q4Z_SNyrGFyyoI9XWQ}{127.0.0.1}{127.0.0.1:62069}{dimr}{shard_indexing_pressure_enabled=true}], current []}, term: 1, version: 12, reason: becoming candidate: joinLeaderInTerm
  1> [2022-12-23T22:19:07,412][INFO ][o.o.c.s.MasterService    ] [node_s1] elected-as-cluster-manager ([1] nodes joined)[{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true} elect leader, _BECOME_CLUSTER_MANAGER_TASK_, _FINISH_ELECTION_], term: 2, version: 13, delta: cluster-manager node changed {previous [], current [{node_s1}{eZHGgdIDQVSNn3AIscXJbQ}{yPtCrC35SwyvbCjFfSV5wQ}{127.0.0.1}{127.0.0.1:62070}{dimr}{shard_indexing_pressure_enabled=true}]}

Node is closed and PIT fails (as expected):

  1> [2022-12-23T22:19:07,439][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] stopped
  1> [2022-12-23T22:19:07,439][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] closing ...
  1> [2022-12-23T22:19:07,445][INFO ][o.o.n.Node               ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] closed
  1> [2022-12-23T22:19:07,479][ERROR][o.o.a.s.TransportCreatePitAction] [node_s2] PIT creation failed while updating PIT ID for indices [[index]]

Index is then deleted (08.516) and then tested (08.545-08.547) and test fails before "after test" (08.561).

Test failure is because the index count is still 1.

  1> [2022-12-23T22:19:08,516][INFO ][o.o.c.m.MetadataDeleteIndexService] [node_s1] [index/S34yaL4NREO3cfcK0xSpmA] deleting index
  1> [2022-12-23T22:19:08,545][INFO ][o.o.t.s.M.Listener       ] [node_s1] [index][0] start check index
  1> [2022-12-23T22:19:08,547][INFO ][o.o.t.s.M.Listener       ] [node_s1] [index][0] end check index
  1> [2022-12-23T22:19:08,561][INFO ][o.o.s.PitMultiNodeTests  ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] [PitMultiNodeTests#testCreatePitWhileNodeDropWithAllowPartialCreationFalse]: cleaning up after test

Suspect race condition where 29 ms is not long enough to check result.

@dbwiddis
Copy link
Member

Reproduced again (run 109 of 500). This time s1 original cluster manager and rebooted node, s0 became new manager. Again short time between deleting and "after test":

  1> [2022-12-23T19:17:24,017][INFO ][o.o.c.m.MetadataDeleteIndexService] [node_s0] [index/xejA8AEXTJmpCQCWAQyUHw] deleting index
  1> [2022-12-23T19:17:24,017][INFO ][o.o.d.PeerFinder         ] [node_s2] setting findPeersInterval to [1s] as node commission status = [true] for local node [{node_s2}{SBAZyfprQe2hJ39c8NQ5SQ}{zRiwxHMkTrexfnBP50Isow}{127.0.0.1}{127.0.0.1:58482}{shard_indexing_pressure_enabled=true}]
  1> [2022-12-23T19:17:24,062][INFO ][o.o.s.PitMultiNodeTests  ] [testCreatePitWhileNodeDropWithAllowPartialCreationFalse] [PitMultiNodeTests#testCreatePitWhileNodeDropWithAllowPartialCreationFalse]: cleaning up after test

@dbwiddis
Copy link
Member

dbwiddis commented Dec 27, 2022 •
edited
Loading

NOTE: this comment has been copied here. Continue further discussion there.

Have spent several hours digging into this issue.

Initial failure in subject line (...Delete...) is different than the failure reported in this comment. (...Create...).

For the create failure; it's obviously a race condition and close to a Heisenbug. While regularly reproducible at least once in a run of size 500, adding logging extended successful runs with a failure on run 2463.

Commonalities when it fails:

  • the dropped node was always the cluster manager
  • there is always an uncommitted operation in the translog

Tracing through the debug logs I added, I'm at the "how did this ever work" phase of debugging. The boolean allowPartialSearchResults is never referred to in the create workflow called as part of this. In particular, the PIT creation failure occurs in this block of code:

OpenSearch/server/src/main/java/org/opensearch/action/search/CreatePitController.java

Lines 123 to 153 in ea1cc9d

void executeCreatePit(Task task, SearchRequest searchRequest, StepListener<SearchResponse> createPitListener) {
logger.debug(
() -> new ParameterizedMessage("Executing creation of PIT context for indices [{}]", Arrays.toString(searchRequest.indices()))
);
transportSearchAction.executeRequest(
task,
searchRequest,
TransportCreatePitAction.CREATE_PIT_ACTION,
true,
new TransportSearchAction.SinglePhaseSearchAction() {
@Override
public void executeOnShardTarget(
SearchTask searchTask,
SearchShardTarget target,
Transport.Connection connection,
ActionListener<SearchPhaseResult> searchPhaseResultActionListener
) {
searchTransportService.createPitContext(
connection,
new TransportCreatePitAction.CreateReaderContextRequest(
target.getShardId(),
PIT_INIT_KEEP_ALIVE.get(clusterService.getSettings())
),
searchTask,
ActionListener.wrap(r -> searchPhaseResultActionListener.onResponse(r), searchPhaseResultActionListener::onFailure)
);
}
},
createPitListener
);
}

The getter searchRequest.allowPartialSearchResults() is never referred to here; call hierarchy indicates it's called on multi phase requests at the beginning of AbstractSearchAsyncAction.executeNextPhase() but there is no reference to it in SinglePhaseSearchAction which is called here. The SearchRequest variable request isn't even passed to the constructor, just the search task.

Looks like this code was implemented in #3921. @bharath-techie do you have any observations/comments that can further help debug this?

@dbwiddis dbwiddis mentioned this issue Dec 27, 2022
Open
@dbwiddis
Copy link
Member

NOTE: The subject line of this Issue indicates it was likely fixed by #4632. However comments starting here are related to a different failure and belong on issue #4259.

TLDR:

@dbwiddis dbwiddis mentioned this issue Dec 29, 2022
Merged
3 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dbwiddis dbwiddis

Labels
bug Something isn't working flaky-test Random test failure that succeeds on second run
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@reta @dbwiddis @Poojita-Raj