Closed
Description
The test testIndexAndRelocateConcurrently() failed today: https://gradle-enterprise.elastic.co/s/ofdhpee6lbrvg
1> [2019-09-06T07:28:11,471][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] before test
--
1> [2019-09-06T07:28:11,472][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] [RelocationIT#testIndexAndRelocateConcurrently]: setting up test
1> [2019-09-06T07:28:11,472][INFO ][o.e.t.InternalTestCluster] [testIndexAndRelocateConcurrently] Setup InternalTestCluster [TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster] with seed [A96754595B745127] using [0] dedicated masters, [0] (data) nodes and [0] coord only nodes (min_master_nodes are [auto-managed])
1> [2019-09-06T07:28:11,473][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] [RelocationIT#testIndexAndRelocateConcurrently]: all set up test
1> [2019-09-06T07:28:11,483][INFO ][o.e.e.NodeEnvironment ] [testIndexAndRelocateConcurrently] using [1] data paths, mounts [[/ (/dev/sda1)]], net usable_space [99.3gb], net total_space [147.6gb], types [ext4]
1> [2019-09-06T07:28:11,483][INFO ][o.e.e.NodeEnvironment ] [testIndexAndRelocateConcurrently] heap size [491mb], compressed ordinary object pointers [true]
1> [2019-09-06T07:28:11,483][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] node name [node_t0], node ID [2a1-XMcHS9qNDDOjEZzqFw], cluster name [TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster]
1> [2019-09-06T07:28:11,484][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] version[7.5.0], pid[49701], build[unknown/unknown/unknown/unknown], OS[Linux/4.4.0-148-generic/amd64], JVM[Oracle Corporation/Java HotSpot(TM) 64-Bit Server VM/1.8.0_221/25.221-b11]
1> [2019-09-06T07:28:11,484][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] JVM home [/var/lib/jenkins/.java/oracle-8u221-linux/jre]
1> [2019-09-06T07:28:11,484][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] JVM arguments [-Dfile.encoding=UTF8, -Dbuild.snapshot=false, -Dcompiler.java=12, -Des.scripting.update.ctx_in_params=false, -Des.transport.cname_in_publish_address=true, -Dgradle.dist.lib=/var/lib/jenkins/.gradle/wrapper/dists/gradle-5.5-all/byeise1led9a3w3p149d02kfj/gradle-5.5/lib, -Dgradle.user.home=/var/lib/jenkins/.gradle, -Dgradle.worker.jar=/var/lib/jenkins/.gradle/caches/5.5/workerMain/gradle-worker.jar, -Djava.awt.headless=true, -Djava.security.manager=worker.org.gradle.process.internal.worker.child.BootstrapSecurityManager, -Djna.nosys=true, -Dorg.gradle.native=false, -Druntime.java=8, -Dtests.artifact=server, -Dtests.gradle=true, -Dtests.jvm.argline=-Dbuild.snapshot=false, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=D32833DAD93D8A40, -Dtests.task=:server:integTest, -esa, -XX:+HeapDumpOnOutOfMemoryError, -XX:HeapDumpPath=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+release-tests/server/build/heapdump, -Xms512m, -Xmx512m, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=./temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
1> [2019-09-06T07:28:11,485][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] no modules loaded
1> [2019-09-06T07:28:11,485][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.ESIntegTestCase$AssertActionNamePlugin]
1> [2019-09-06T07:28:11,485][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.ESIntegTestCase$TestSeedPlugin]
1> [2019-09-06T07:28:11,485][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.InternalSettingsPlugin]
1> [2019-09-06T07:28:11,486][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.MockHttpTransport$TestPlugin]
1> [2019-09-06T07:28:11,486][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.MockIndexEventListener$TestPlugin]
1> [2019-09-06T07:28:11,486][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.transport.MockTransportService$TestPlugin]
1> [2019-09-06T07:28:11,486][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
1> [2019-09-06T07:28:11,496][INFO ][o.e.d.DiscoveryModule ] [testIndexAndRelocateConcurrently] using discovery type [zen] and seed hosts providers [settings, file]
1> [2019-09-06T07:28:11,513][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] initialized
1> [2019-09-06T07:28:11,516][INFO ][o.e.e.NodeEnvironment ] [testIndexAndRelocateConcurrently] using [1] data paths, mounts [[/ (/dev/sda1)]], net usable_space [99.3gb], net total_space [147.6gb], types [ext4]
1> [2019-09-06T07:28:11,517][INFO ][o.e.e.NodeEnvironment ] [testIndexAndRelocateConcurrently] heap size [491mb], compressed ordinary object pointers [true]
1> [2019-09-06T07:28:11,517][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] node name [node_t1], node ID [tS-OdF2hRK-z-JvD4uxpBg], cluster name [TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster]
1> [2019-09-06T07:28:11,517][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] version[7.5.0], pid[49701], build[unknown/unknown/unknown/unknown], OS[Linux/4.4.0-148-generic/amd64], JVM[Oracle Corporation/Java HotSpot(TM) 64-Bit Server VM/1.8.0_221/25.221-b11]
1> [2019-09-06T07:28:11,517][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] JVM home [/var/lib/jenkins/.java/oracle-8u221-linux/jre]
1> [2019-09-06T07:28:11,517][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] JVM arguments [-Dfile.encoding=UTF8, -Dbuild.snapshot=false, -Dcompiler.java=12, -Des.scripting.update.ctx_in_params=false, -Des.transport.cname_in_publish_address=true, -Dgradle.dist.lib=/var/lib/jenkins/.gradle/wrapper/dists/gradle-5.5-all/byeise1led9a3w3p149d02kfj/gradle-5.5/lib, -Dgradle.user.home=/var/lib/jenkins/.gradle, -Dgradle.worker.jar=/var/lib/jenkins/.gradle/caches/5.5/workerMain/gradle-worker.jar, -Djava.awt.headless=true, -Djava.security.manager=worker.org.gradle.process.internal.worker.child.BootstrapSecurityManager, -Djna.nosys=true, -Dorg.gradle.native=false, -Druntime.java=8, -Dtests.artifact=server, -Dtests.gradle=true, -Dtests.jvm.argline=-Dbuild.snapshot=false, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=D32833DAD93D8A40, -Dtests.task=:server:integTest, -esa, -XX:+HeapDumpOnOutOfMemoryError, -XX:HeapDumpPath=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+release-tests/server/build/heapdump, -Xms512m, -Xmx512m, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=./temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
1> [2019-09-06T07:28:11,518][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] no modules loaded
1> [2019-09-06T07:28:11,518][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.ESIntegTestCase$AssertActionNamePlugin]
1> [2019-09-06T07:28:11,518][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.ESIntegTestCase$TestSeedPlugin]
1> [2019-09-06T07:28:11,518][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.InternalSettingsPlugin]
1> [2019-09-06T07:28:11,518][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.MockHttpTransport$TestPlugin]
1> [2019-09-06T07:28:11,518][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.MockIndexEventListener$TestPlugin]
1> [2019-09-06T07:28:11,518][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.transport.MockTransportService$TestPlugin]
1> [2019-09-06T07:28:11,518][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
1> [2019-09-06T07:28:11,527][INFO ][o.e.d.DiscoveryModule ] [testIndexAndRelocateConcurrently] using discovery type [zen] and seed hosts providers [settings, file]
1> [2019-09-06T07:28:11,538][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] initialized
1> [2019-09-06T07:28:11,541][INFO ][o.e.e.NodeEnvironment ] [testIndexAndRelocateConcurrently] using [1] data paths, mounts [[/ (/dev/sda1)]], net usable_space [99.3gb], net total_space [147.6gb], types [ext4]
1> [2019-09-06T07:28:11,542][INFO ][o.e.e.NodeEnvironment ] [testIndexAndRelocateConcurrently] heap size [491mb], compressed ordinary object pointers [true]
1> [2019-09-06T07:28:11,542][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] node name [node_t2], node ID [rJC8dlVaT9OV8BPl-uEhow], cluster name [TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster]
1> [2019-09-06T07:28:11,542][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] version[7.5.0], pid[49701], build[unknown/unknown/unknown/unknown], OS[Linux/4.4.0-148-generic/amd64], JVM[Oracle Corporation/Java HotSpot(TM) 64-Bit Server VM/1.8.0_221/25.221-b11]
1> [2019-09-06T07:28:11,542][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] JVM home [/var/lib/jenkins/.java/oracle-8u221-linux/jre]
1> [2019-09-06T07:28:11,542][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] JVM arguments [-Dfile.encoding=UTF8, -Dbuild.snapshot=false, -Dcompiler.java=12, -Des.scripting.update.ctx_in_params=false, -Des.transport.cname_in_publish_address=true, -Dgradle.dist.lib=/var/lib/jenkins/.gradle/wrapper/dists/gradle-5.5-all/byeise1led9a3w3p149d02kfj/gradle-5.5/lib, -Dgradle.user.home=/var/lib/jenkins/.gradle, -Dgradle.worker.jar=/var/lib/jenkins/.gradle/caches/5.5/workerMain/gradle-worker.jar, -Djava.awt.headless=true, -Djava.security.manager=worker.org.gradle.process.internal.worker.child.BootstrapSecurityManager, -Djna.nosys=true, -Dorg.gradle.native=false, -Druntime.java=8, -Dtests.artifact=server, -Dtests.gradle=true, -Dtests.jvm.argline=-Dbuild.snapshot=false, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=D32833DAD93D8A40, -Dtests.task=:server:integTest, -esa, -XX:+HeapDumpOnOutOfMemoryError, -XX:HeapDumpPath=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+release-tests/server/build/heapdump, -Xms512m, -Xmx512m, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=./temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
1> [2019-09-06T07:28:11,543][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] no modules loaded
1> [2019-09-06T07:28:11,543][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.ESIntegTestCase$AssertActionNamePlugin]
1> [2019-09-06T07:28:11,543][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.ESIntegTestCase$TestSeedPlugin]
1> [2019-09-06T07:28:11,543][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.InternalSettingsPlugin]
1> [2019-09-06T07:28:11,543][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.MockHttpTransport$TestPlugin]
1> [2019-09-06T07:28:11,543][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.MockIndexEventListener$TestPlugin]
1> [2019-09-06T07:28:11,543][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.transport.MockTransportService$TestPlugin]
1> [2019-09-06T07:28:11,543][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
1> [2019-09-06T07:28:11,553][INFO ][o.e.d.DiscoveryModule ] [testIndexAndRelocateConcurrently] using discovery type [zen] and seed hosts providers [settings, file]
1> [2019-09-06T07:28:11,564][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] initialized
1> [2019-09-06T07:28:11,567][INFO ][o.e.e.NodeEnvironment ] [testIndexAndRelocateConcurrently] using [1] data paths, mounts [[/ (/dev/sda1)]], net usable_space [99.3gb], net total_space [147.6gb], types [ext4]
1> [2019-09-06T07:28:11,567][INFO ][o.e.e.NodeEnvironment ] [testIndexAndRelocateConcurrently] heap size [491mb], compressed ordinary object pointers [true]
1> [2019-09-06T07:28:11,568][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] node name [node_t3], node ID [BFT3RUWtTSe7W2aUwC7WRQ], cluster name [TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster]
1> [2019-09-06T07:28:11,568][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] version[7.5.0], pid[49701], build[unknown/unknown/unknown/unknown], OS[Linux/4.4.0-148-generic/amd64], JVM[Oracle Corporation/Java HotSpot(TM) 64-Bit Server VM/1.8.0_221/25.221-b11]
1> [2019-09-06T07:28:11,568][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] JVM home [/var/lib/jenkins/.java/oracle-8u221-linux/jre]
1> [2019-09-06T07:28:11,568][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] JVM arguments [-Dfile.encoding=UTF8, -Dbuild.snapshot=false, -Dcompiler.java=12, -Des.scripting.update.ctx_in_params=false, -Des.transport.cname_in_publish_address=true, -Dgradle.dist.lib=/var/lib/jenkins/.gradle/wrapper/dists/gradle-5.5-all/byeise1led9a3w3p149d02kfj/gradle-5.5/lib, -Dgradle.user.home=/var/lib/jenkins/.gradle, -Dgradle.worker.jar=/var/lib/jenkins/.gradle/caches/5.5/workerMain/gradle-worker.jar, -Djava.awt.headless=true, -Djava.security.manager=worker.org.gradle.process.internal.worker.child.BootstrapSecurityManager, -Djna.nosys=true, -Dorg.gradle.native=false, -Druntime.java=8, -Dtests.artifact=server, -Dtests.gradle=true, -Dtests.jvm.argline=-Dbuild.snapshot=false, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=D32833DAD93D8A40, -Dtests.task=:server:integTest, -esa, -XX:+HeapDumpOnOutOfMemoryError, -XX:HeapDumpPath=/var/lib/jenkins/workspace/elastic+elasticsearch+7.x+release-tests/server/build/heapdump, -Xms512m, -Xmx512m, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=./temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
1> [2019-09-06T07:28:11,568][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] no modules loaded
1> [2019-09-06T07:28:11,568][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.ESIntegTestCase$AssertActionNamePlugin]
1> [2019-09-06T07:28:11,568][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.ESIntegTestCase$TestSeedPlugin]
1> [2019-09-06T07:28:11,568][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.InternalSettingsPlugin]
1> [2019-09-06T07:28:11,568][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.MockHttpTransport$TestPlugin]
1> [2019-09-06T07:28:11,568][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.MockIndexEventListener$TestPlugin]
1> [2019-09-06T07:28:11,568][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.test.transport.MockTransportService$TestPlugin]
1> [2019-09-06T07:28:11,568][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
1> [2019-09-06T07:28:11,578][INFO ][o.e.d.DiscoveryModule ] [testIndexAndRelocateConcurrently] using discovery type [zen] and seed hosts providers [settings, file]
1> [2019-09-06T07:28:11,591][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] initialized
1> [2019-09-06T07:28:11,592][INFO ][o.e.n.Node ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#1]]] starting ...
1> [2019-09-06T07:28:11,592][INFO ][o.e.n.Node ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#2]]] starting ...
1> [2019-09-06T07:28:11,593][INFO ][o.e.n.Node ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#3]]] starting ...
1> [2019-09-06T07:28:11,594][INFO ][o.e.n.Node ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#4]]] starting ...
1> [2019-09-06T07:28:11,596][INFO ][o.e.t.TransportService ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#3]]] publish_address {127.0.0.1:36069}, bound_addresses {[::1]:44838}, {127.0.0.1:36069}
1> [2019-09-06T07:28:11,596][INFO ][o.e.t.TransportService ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#2]]] publish_address {127.0.0.1:37985}, bound_addresses {[::1]:33809}, {127.0.0.1:37985}
1> [2019-09-06T07:28:11,597][INFO ][o.e.t.TransportService ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#4]]] publish_address {127.0.0.1:35701}, bound_addresses {[::1]:43805}, {127.0.0.1:35701}
1> [2019-09-06T07:28:11,597][INFO ][o.e.t.TransportService ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#1]]] publish_address {127.0.0.1:36431}, bound_addresses {[::1]:38719}, {127.0.0.1:36431}
1> [2019-09-06T07:28:11,603][INFO ][o.e.c.c.Coordinator ] [node_t1] setting initial configuration to VotingConfiguration{rJC8dlVaT9OV8BPl-uEhow,BFT3RUWtTSe7W2aUwC7WRQ,{bootstrap-placeholder}-node_t0,tS-OdF2hRK-z-JvD4uxpBg}
1> [2019-09-06T07:28:11,618][INFO ][o.e.c.s.MasterService ] [node_t1] elected-as-master ([4] nodes joined)[{node_t3}{BFT3RUWtTSe7W2aUwC7WRQ}{gABlyH2TT6yA_62gsOpTdg}{127.0.0.1}{127.0.0.1:35701}{dim}{color=red} elect leader, {node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue} elect leader, {node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue} elect leader, {node_t2}{rJC8dlVaT9OV8BPl-uEhow}{KKP_50sBT4-LavWQT2ob9g}{127.0.0.1}{127.0.0.1:36069}{dim}{color=red} elect leader, _BECOME_MASTER_TASK_, _FINISH_ELECTION_], term: 1, version: 1, reason: master node changed {previous [], current [{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}]}, added {{node_t3}{BFT3RUWtTSe7W2aUwC7WRQ}{gABlyH2TT6yA_62gsOpTdg}{127.0.0.1}{127.0.0.1:35701}{dim}{color=red},{node_t2}{rJC8dlVaT9OV8BPl-uEhow}{KKP_50sBT4-LavWQT2ob9g}{127.0.0.1}{127.0.0.1:36069}{dim}{color=red},{node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue},}
1> [2019-09-06T07:28:11,621][INFO ][o.e.c.c.CoordinationState] [node_t1] cluster UUID set to [K0T22JLjTSKeluF1q96EkA]
1> [2019-09-06T07:28:11,621][INFO ][o.e.c.c.CoordinationState] [node_t2] cluster UUID set to [K0T22JLjTSKeluF1q96EkA]
1> [2019-09-06T07:28:11,621][INFO ][o.e.c.c.CoordinationState] [node_t3] cluster UUID set to [K0T22JLjTSKeluF1q96EkA]
1> [2019-09-06T07:28:11,623][INFO ][o.e.c.s.ClusterApplierService] [node_t2] master node changed {previous [], current [{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}]}, added {{node_t3}{BFT3RUWtTSe7W2aUwC7WRQ}{gABlyH2TT6yA_62gsOpTdg}{127.0.0.1}{127.0.0.1:35701}{dim}{color=red},{node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue},{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue},}, term: 1, version: 1, reason: ApplyCommitRequest{term=1, version=1, sourceNode={node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}}
1> [2019-09-06T07:28:11,623][INFO ][o.e.c.c.CoordinationState] [node_t0] cluster UUID set to [K0T22JLjTSKeluF1q96EkA]
1> [2019-09-06T07:28:11,624][INFO ][o.e.n.Node ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#3]]] started
1> [2019-09-06T07:28:11,624][INFO ][o.e.c.s.ClusterApplierService] [node_t3] master node changed {previous [], current [{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}]}, added {{node_t2}{rJC8dlVaT9OV8BPl-uEhow}{KKP_50sBT4-LavWQT2ob9g}{127.0.0.1}{127.0.0.1:36069}{dim}{color=red},{node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue},{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue},}, term: 1, version: 1, reason: ApplyCommitRequest{term=1, version=1, sourceNode={node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}}
1> [2019-09-06T07:28:11,624][INFO ][o.e.n.Node ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#4]]] started
1> [2019-09-06T07:28:11,626][INFO ][o.e.c.s.ClusterApplierService] [node_t0] master node changed {previous [], current [{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}]}, added {{node_t3}{BFT3RUWtTSe7W2aUwC7WRQ}{gABlyH2TT6yA_62gsOpTdg}{127.0.0.1}{127.0.0.1:35701}{dim}{color=red},{node_t2}{rJC8dlVaT9OV8BPl-uEhow}{KKP_50sBT4-LavWQT2ob9g}{127.0.0.1}{127.0.0.1:36069}{dim}{color=red},{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue},}, term: 1, version: 1, reason: ApplyCommitRequest{term=1, version=1, sourceNode={node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}}
1> [2019-09-06T07:28:11,626][INFO ][o.e.n.Node ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#1]]] started
1> [2019-09-06T07:28:11,626][INFO ][o.e.c.s.ClusterApplierService] [node_t1] master node changed {previous [], current [{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}]}, added {{node_t3}{BFT3RUWtTSe7W2aUwC7WRQ}{gABlyH2TT6yA_62gsOpTdg}{127.0.0.1}{127.0.0.1:35701}{dim}{color=red},{node_t2}{rJC8dlVaT9OV8BPl-uEhow}{KKP_50sBT4-LavWQT2ob9g}{127.0.0.1}{127.0.0.1:36069}{dim}{color=red},{node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue},}, term: 1, version: 1, reason: Publication{term=1, version=1}
1> [2019-09-06T07:28:11,627][INFO ][o.e.n.Node ] [[test_TEST-TEST_WORKER_VM=[55]-CLUSTER_SEED=[-6239926015935360729]-HASH=[22BD260F518]-cluster[T#2]]] started
1> [2019-09-06T07:28:11,627][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] no modules loaded
1> [2019-09-06T07:28:11,627][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
1> [2019-09-06T07:28:11,638][INFO ][o.e.g.GatewayService ] [node_t1] recovered [0] indices into cluster_state
1> [2019-09-06T07:28:11,639][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] blue nodes: [node_t0, node_t1]
1> [2019-09-06T07:28:11,639][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] red nodes: [node_t2, node_t3]
1> [2019-09-06T07:28:11,639][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] no modules loaded
1> [2019-09-06T07:28:11,639][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
1> [2019-09-06T07:28:11,649][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] using custom data_path for index: [hzGoKCumwM]
1> [2019-09-06T07:28:11,651][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_t1] [test] creating index, cause [api], templates [], shards [1]/[1], mappings []
1> [2019-09-06T07:28:11,678][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] --> indexing [110] docs
1> [2019-09-06T07:28:11,678][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] no modules loaded
1> [2019-09-06T07:28:11,678][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
1> [2019-09-06T07:28:11,688][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] no modules loaded
1> [2019-09-06T07:28:11,688][INFO ][o.e.p.PluginsService ] [testIndexAndRelocateConcurrently] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
1> [2019-09-06T07:28:11,697][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] Index [110] docs async: [true] bulk: [false]
1> [2019-09-06T07:28:11,701][INFO ][o.e.c.m.MetaDataMappingService] [node_t1] [test/p5QNtI3SSgiG3JPLA4hNGg] create_mapping [type1]
1> [2019-09-06T07:28:11,708][INFO ][o.e.c.r.a.AllocationService] [node_t1] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[test][0]]]).
1> [2019-09-06T07:28:11,801][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] --> moving index to new nodes
1> [2019-09-06T07:28:11,826][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] --> indexing [110] more docs
1> [2019-09-06T07:28:11,828][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] Index [207] docs async: [true] bulk: [false]
1> [2019-09-06T07:28:12,025][WARN ][o.e.i.e.Engine ] [node_t1] [test][0] failed engine [failed to recover from translog]
1> org.elasticsearch.index.engine.EngineException: failed to recover from translog
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslogInternal(InternalEngine.java:464) ~[main/:?]
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslog(InternalEngine.java:434) [main/:?]
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslog(InternalEngine.java:124) [main/:?]
1> at org.elasticsearch.index.shard.IndexShard.recoverLocallyUpToGlobalCheckpoint(IndexShard.java:1429) [main/:?]
1> at org.elasticsearch.indices.recovery.PeerRecoveryTargetService.doRecovery(PeerRecoveryTargetService.java:176) [main/:?]
1> at org.elasticsearch.indices.recovery.PeerRecoveryTargetService.access$500(PeerRecoveryTargetService.java:77) [main/:?]
1> at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$RecoveryRunner.doRun(PeerRecoveryTargetService.java:550) [main/:?]
1> at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:773) [main/:?]
1> at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
1> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_221]
1> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_221]
1> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_221]
1> Caused by: org.elasticsearch.index.shard.IllegalIndexShardStateException: CurrentState[CLOSED] operation only allowed when recovering, origin [LOCAL_TRANSLOG_RECOVERY]
1> at org.elasticsearch.index.shard.IndexShard.ensureWriteAllowed(IndexShard.java:1727) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:742) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.applyTranslogOperation(IndexShard.java:1493) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.runTranslogRecovery(IndexShard.java:1524) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.lambda$recoverLocallyUpToGlobalCheckpoint$6(IndexShard.java:1423) ~[main/:?]
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslogInternal(InternalEngine.java:462) ~[main/:?]
1> ... 11 more
1> [2019-09-06T07:28:12,037][WARN ][o.e.i.c.IndicesClusterStateService] [node_t1] [test][0] marking and sending shard failed due to [shard failure, reason [failed to recover from translog]]
1> org.elasticsearch.index.engine.EngineException: failed to recover from translog
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslogInternal(InternalEngine.java:464) ~[main/:?]
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslog(InternalEngine.java:434) ~[main/:?]
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslog(InternalEngine.java:124) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.recoverLocallyUpToGlobalCheckpoint(IndexShard.java:1429) ~[main/:?]
1> at org.elasticsearch.indices.recovery.PeerRecoveryTargetService.doRecovery(PeerRecoveryTargetService.java:176) ~[main/:?]
1> at org.elasticsearch.indices.recovery.PeerRecoveryTargetService.access$500(PeerRecoveryTargetService.java:77) ~[main/:?]
1> at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$RecoveryRunner.doRun(PeerRecoveryTargetService.java:550) ~[main/:?]
1> at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:773) ~[main/:?]
1> at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[main/:?]
1> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_221]
1> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_221]
1> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_221]
1> Caused by: org.elasticsearch.index.shard.IllegalIndexShardStateException: CurrentState[CLOSED] operation only allowed when recovering, origin [LOCAL_TRANSLOG_RECOVERY]
1> at org.elasticsearch.index.shard.IndexShard.ensureWriteAllowed(IndexShard.java:1727) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:742) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.applyTranslogOperation(IndexShard.java:1493) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.runTranslogRecovery(IndexShard.java:1524) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.lambda$recoverLocallyUpToGlobalCheckpoint$6(IndexShard.java:1423) ~[main/:?]
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslogInternal(InternalEngine.java:462) ~[main/:?]
1> ... 11 more
1> [2019-09-06T07:28:12,262][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] --> waiting for relocation to complete
1> [2019-09-06T07:28:42,266][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] ensureGreen timed out, cluster state:
1> cluster uuid: K0T22JLjTSKeluF1q96EkA [committed: true]
1> version: 10
1> state uuid: SVVRBMmdTUqGQ1he2kUEug
1> from_diff: false
1> meta data version: 8
1> coordination_metadata:
1> term: 1
1> last_committed_config: VotingConfiguration{rJC8dlVaT9OV8BPl-uEhow,BFT3RUWtTSe7W2aUwC7WRQ,tS-OdF2hRK-z-JvD4uxpBg}
1> last_accepted_config: VotingConfiguration{rJC8dlVaT9OV8BPl-uEhow,BFT3RUWtTSe7W2aUwC7WRQ,tS-OdF2hRK-z-JvD4uxpBg}
1> voting tombstones: []
1> [test/p5QNtI3SSgiG3JPLA4hNGg]: v[8], mv[2], sv[2], av[1]
1> 0: p_term [1], isa_ids [qGMhYiLsTySO0-YUfTIiJQ, D-apipQ5RjOEyDhHLROGMg]
1> metadata customs:
1> index-graveyard: IndexGraveyard[[]]
1> nodes:
1> {node_t3}{BFT3RUWtTSe7W2aUwC7WRQ}{gABlyH2TT6yA_62gsOpTdg}{127.0.0.1}{127.0.0.1:35701}{dim}{color=red}
1> {node_t2}{rJC8dlVaT9OV8BPl-uEhow}{KKP_50sBT4-LavWQT2ob9g}{127.0.0.1}{127.0.0.1:36069}{dim}{color=red}
1> {node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue}
1> {node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}, master
1> routing_table (version 7):
1> -- index [[test/p5QNtI3SSgiG3JPLA4hNGg]]
1> ----shard_id [test][0]
1> --------[test][0], node[2a1-XMcHS9qNDDOjEZzqFw], [P], s[STARTED], a[id=D-apipQ5RjOEyDhHLROGMg]
1> --------[test][0], node[BFT3RUWtTSe7W2aUwC7WRQ], relocating [tS-OdF2hRK-z-JvD4uxpBg], [R], s[RELOCATING], a[id=qGMhYiLsTySO0-YUfTIiJQ, rId=grs3DhCfQHOvajBANZ5PYQ]
1> routing_nodes:
1> -----node_id[rJC8dlVaT9OV8BPl-uEhow][V]
1> -----node_id[2a1-XMcHS9qNDDOjEZzqFw][V]
1> --------[test][0], node[2a1-XMcHS9qNDDOjEZzqFw], [P], s[STARTED], a[id=D-apipQ5RjOEyDhHLROGMg]
1> -----node_id[BFT3RUWtTSe7W2aUwC7WRQ][V]
1> --------[test][0], node[BFT3RUWtTSe7W2aUwC7WRQ], relocating [tS-OdF2hRK-z-JvD4uxpBg], [R], s[RELOCATING], a[id=qGMhYiLsTySO0-YUfTIiJQ, rId=grs3DhCfQHOvajBANZ5PYQ]
1> -----node_id[tS-OdF2hRK-z-JvD4uxpBg][V]
1> --------[test][0], node[tS-OdF2hRK-z-JvD4uxpBg], relocating [BFT3RUWtTSe7W2aUwC7WRQ], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=grs3DhCfQHOvajBANZ5PYQ, rId=qGMhYiLsTySO0-YUfTIiJQ]
1> ---- unassigned
1> tasks: (0):
1> [2019-09-06T07:28:42,266][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] [RelocationIT#testIndexAndRelocateConcurrently]: cleaning up after test
1> [2019-09-06T07:28:42,294][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_t1] [test/p5QNtI3SSgiG3JPLA4hNGg] deleting index
1> [2019-09-06T07:28:42,317][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] stopping ...
1> [2019-09-06T07:28:42,318][INFO ][o.e.c.c.Coordinator ] [node_t0] master node [{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}] failed, restarting discovery
1> org.elasticsearch.transport.NodeDisconnectedException: [node_t1][127.0.0.1:37985][disconnected] disconnected
1> [2019-09-06T07:28:42,318][INFO ][o.e.c.s.MasterService ] [node_t1] node-left[{node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue} disconnected], term: 1, version: 12, reason: removed {{node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue},}
1> [2019-09-06T07:28:42,318][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] stopped
1> [2019-09-06T07:28:42,318][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] closing ...
1> [2019-09-06T07:28:42,320][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] closed
1> [2019-09-06T07:28:42,321][INFO ][o.e.c.s.ClusterApplierService] [node_t2] removed {{node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue},}, term: 1, version: 12, reason: ApplyCommitRequest{term=1, version=12, sourceNode={node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}}
1> [2019-09-06T07:28:42,321][INFO ][o.e.c.s.ClusterApplierService] [node_t3] removed {{node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue},}, term: 1, version: 12, reason: ApplyCommitRequest{term=1, version=12, sourceNode={node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}}
1> [2019-09-06T07:28:42,321][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] stopping ...
1> [2019-09-06T07:28:42,322][INFO ][o.e.c.s.ClusterApplierService] [node_t1] removed {{node_t0}{2a1-XMcHS9qNDDOjEZzqFw}{n9HfLhdjRdiyS_Pi34pvxw}{127.0.0.1}{127.0.0.1:36431}{dim}{color=blue},}, term: 1, version: 12, reason: Publication{term=1, version=12}
1> [2019-09-06T07:28:42,323][INFO ][o.e.c.c.Coordinator ] [node_t3] master node [{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}] failed, restarting discovery
1> org.elasticsearch.transport.NodeDisconnectedException: [node_t1][127.0.0.1:37985][disconnected] disconnected
1> [2019-09-06T07:28:42,323][INFO ][o.e.c.c.Coordinator ] [node_t2] master node [{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}] failed, restarting discovery
1> org.elasticsearch.transport.NodeDisconnectedException: [node_t1][127.0.0.1:37985][disconnected] disconnected
1> [2019-09-06T07:28:42,323][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] stopped
1> [2019-09-06T07:28:42,323][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] closing ...
1> [2019-09-06T07:28:42,323][INFO ][o.e.c.s.ClusterApplierService] [node_t3] master node changed {previous [{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}], current []}, term: 1, version: 12, reason: becoming candidate: onLeaderFailure
1> [2019-09-06T07:28:42,323][INFO ][o.e.c.s.ClusterApplierService] [node_t2] master node changed {previous [{node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue}], current []}, term: 1, version: 12, reason: becoming candidate: onLeaderFailure
1> [2019-09-06T07:28:42,323][WARN ][o.e.c.NodeConnectionsService] [node_t3] failed to connect to {node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue} (tried [1] times)
1> org.elasticsearch.transport.ConnectTransportException: [node_t1][127.0.0.1:37985] connect_exception
1> at org.elasticsearch.transport.TcpTransport$ChannelsConnectedListener.onFailure(TcpTransport.java:985) ~[main/:?]
1> at org.elasticsearch.action.ActionListener.lambda$toBiConsumer$3(ActionListener.java:161) ~[main/:?]
1> at org.elasticsearch.common.concurrent.CompletableContext.lambda$addListener$0(CompletableContext.java:42) ~[elasticsearch-core-7.5.0.jar:7.5.0]
1> at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760) ~[?:1.8.0_221]
1> at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) ~[?:1.8.0_221]
1> at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[?:1.8.0_221]
1> at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[?:1.8.0_221]
1> at org.elasticsearch.common.concurrent.CompletableContext.completeExceptionally(CompletableContext.java:57) ~[elasticsearch-core-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.SocketChannelContext.connect(SocketChannelContext.java:142) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.EventHandler.handleConnect(EventHandler.java:117) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.transport.nio.TestEventHandler.handleConnect(TestEventHandler.java:123) ~[framework-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.attemptConnect(NioSelector.java:428) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.registerChannel(NioSelector.java:451) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.setUpNewChannels(NioSelector.java:440) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.preSelect(NioSelector.java:261) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.singleLoop(NioSelector.java:155) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.runLoop(NioSelector.java:131) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_221]
1> Caused by: java.net.ConnectException: Connection refused
1> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?]
1> at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) ~[?:?]
1> at org.elasticsearch.nio.SocketChannelContext.connect(SocketChannelContext.java:139) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> ... 9 more
1> [2019-09-06T07:28:42,324][WARN ][o.e.c.NodeConnectionsService] [node_t2] failed to connect to {node_t1}{tS-OdF2hRK-z-JvD4uxpBg}{orb-z-ajRZW-cUuuIded5g}{127.0.0.1}{127.0.0.1:37985}{dim}{color=blue} (tried [1] times)
1> org.elasticsearch.transport.ConnectTransportException: [node_t1][127.0.0.1:37985] connect_exception
1> at org.elasticsearch.transport.TcpTransport$ChannelsConnectedListener.onFailure(TcpTransport.java:985) ~[main/:?]
1> at org.elasticsearch.action.ActionListener.lambda$toBiConsumer$3(ActionListener.java:161) ~[main/:?]
1> at org.elasticsearch.common.concurrent.CompletableContext.lambda$addListener$0(CompletableContext.java:42) ~[elasticsearch-core-7.5.0.jar:7.5.0]
1> at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760) ~[?:1.8.0_221]
1> at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) ~[?:1.8.0_221]
1> at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[?:1.8.0_221]
1> at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[?:1.8.0_221]
1> at org.elasticsearch.common.concurrent.CompletableContext.completeExceptionally(CompletableContext.java:57) ~[elasticsearch-core-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.SocketChannelContext.connect(SocketChannelContext.java:142) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.EventHandler.handleConnect(EventHandler.java:117) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.transport.nio.TestEventHandler.handleConnect(TestEventHandler.java:123) ~[framework-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.attemptConnect(NioSelector.java:428) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.registerChannel(NioSelector.java:451) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.setUpNewChannels(NioSelector.java:440) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.preSelect(NioSelector.java:261) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.singleLoop(NioSelector.java:155) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at org.elasticsearch.nio.NioSelector.runLoop(NioSelector.java:131) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_221]
1> Caused by: java.net.ConnectException: Connection refused
1> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?]
1> at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) ~[?:?]
1> at org.elasticsearch.nio.SocketChannelContext.connect(SocketChannelContext.java:139) ~[elasticsearch-nio-7.5.0.jar:7.5.0]
1> ... 9 more
1> [2019-09-06T07:28:42,327][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] closed
1> [2019-09-06T07:28:42,329][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] stopping ...
1> [2019-09-06T07:28:42,329][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] stopped
1> [2019-09-06T07:28:42,330][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] closing ...
1> [2019-09-06T07:28:42,330][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] closed
1> [2019-09-06T07:28:42,340][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] stopping ...
1> [2019-09-06T07:28:42,341][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] stopped
1> [2019-09-06T07:28:42,341][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] closing ...
1> [2019-09-06T07:28:42,342][INFO ][o.e.n.Node ] [testIndexAndRelocateConcurrently] closed
1> [2019-09-06T07:28:42,342][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] [RelocationIT#testIndexAndRelocateConcurrently]: cleaned up after test
1> [2019-09-06T07:28:42,342][INFO ][o.e.r.RelocationIT ] [testIndexAndRelocateConcurrently] after test
2> REPRODUCE WITH: ./gradlew ':server:integTest' --tests "org.elasticsearch.recovery.RelocationIT.testIndexAndRelocateConcurrently" -Dtests.seed=D32833DAD93D8A40 -Dtests.security.manager=true -Dbuild.snapshot=false -Dtests.jvm.argline="-Dbuild.snapshot=false" -Dtests.locale=es-VE -Dtests.timezone=Asia/Jayapura -Dcompiler.java=12 -Druntime.java=8
2> java.lang.AssertionError: timed out waiting for green state
at __randomizedtesting.SeedInfo.seed([D32833DAD93D8A40:C193257C53895E3]:0)
at org.junit.Assert.fail(Assert.java:88)
at org.elasticsearch.test.ESIntegTestCase.ensureColor(ESIntegTestCase.java:925)
at org.elasticsearch.test.ESIntegTestCase.ensureGreen(ESIntegTestCase.java:881)
at org.elasticsearch.test.ESIntegTestCase.ensureGreen(ESIntegTestCase.java:870)
at org.elasticsearch.recovery.RelocationIT.testIndexAndRelocateConcurrently(RelocationIT.java:497)
Here is my understanding:
The test creates a cluster of 4 nodes grouped by 2, the red nodes and the blue nodes. The index test is created and assigned to red nodes. Then documents are indexed and the test index settings are updated so that the index must be assigned on blue nodes only.
So the master updates the cluster state to reallocate shards appropriatly. It seems that the primary is correctly relocated to node_t0 (appears as STARTED in the custer state) and I think that it triggers the reinitialization of the replica on node_t1 (so that it will recover from the newly started primary).
Once this new cluster state update is processed by node_t1 the node will tear down the replica shard locally, but since there is an active recovery locally it produces logs like this:
[2019-09-06T07:28:12,025][WARN ][o.e.i.e.Engine ] [node_t1] [test][0] failed engine [failed to recover from translog]
--
1> org.elasticsearch.index.engine.EngineException: failed to recover from translog
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslogInternal(InternalEngine.java:464) ~[main/:?]
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslog(InternalEngine.java:434) [main/:?]
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslog(InternalEngine.java:124) [main/:?]
1> at org.elasticsearch.index.shard.IndexShard.recoverLocallyUpToGlobalCheckpoint(IndexShard.java:1429) [main/:?]
1> at org.elasticsearch.indices.recovery.PeerRecoveryTargetService.doRecovery(PeerRecoveryTargetService.java:176) [main/:?]
1> at org.elasticsearch.indices.recovery.PeerRecoveryTargetService.access$500(PeerRecoveryTargetService.java:77) [main/:?]
1> at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$RecoveryRunner.doRun(PeerRecoveryTargetService.java:550) [main/:?]
1> at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:773) [main/:?]
1> at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
1> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_221]
1> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_221]
1> at java.lang.Thread.run(Thread.java:748) [?:1.8.0_221]
1> Caused by: org.elasticsearch.index.shard.IllegalIndexShardStateException: CurrentState[CLOSED] operation only allowed when recovering, origin [LOCAL_TRANSLOG_RECOVERY]
1> at org.elasticsearch.index.shard.IndexShard.ensureWriteAllowed(IndexShard.java:1727) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:742) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.applyTranslogOperation(IndexShard.java:1493) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.runTranslogRecovery(IndexShard.java:1524) ~[main/:?]
1> at org.elasticsearch.index.shard.IndexShard.lambda$recoverLocallyUpToGlobalCheckpoint$6(IndexShard.java:1423) ~[main/:?]
1> at org.elasticsearch.index.engine.InternalEngine.recoverFromTranslogInternal(InternalEngine.java:462) ~[main/:?]
1> ... 11 more
But the test is failing waiting for the test index to be green again. I'm not sure why the intializing replica shard is not starting a recovery again:
[test][0], node[BFT3RUWtTSe7W2aUwC7WRQ], relocating [tS-OdF2hRK-z-JvD4uxpBg], [R], s[RELOCATING], a[id=qGMhYiLsTySO0-YUfTIiJQ, rId=grs3DhCfQHOvajBANZ5PYQ]
[test][0], node[tS-OdF2hRK-z-JvD4uxpBg], relocating [BFT3RUWtTSe7W2aUwC7WRQ], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=grs3DhCfQHOvajBANZ5PYQ, rId=qGMhYiLsTySO0-YUfTIiJQ]