Skip to content

[CI] CCR: FollowerFailOverIT.testFailOverOnFollower failure #35403

@tvernum

Description

@tvernum

Doesn't reproduce for me.
Could just be a timeout issue, but I don't know the CCR code well enough to make that call.

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+g1gc/70/consoleFull

./gradlew :x-pack:plugin:ccr:internalClusterTest \ -Dtests.seed=71D42FEBD6289D1E \ -Dtests.class=org.elasticsearch.xpack.ccr.FollowerFailOverIT \ -Dtests.method="testFailOverOnFollower" \ -Dtests.security.manager=true \ -Dtests.jvm.argline="-XX:-UseConcMarkSweepGC -XX:+UseG1GC" \ -Dtests.locale=es-HN \ -Dtests.timezone=America/Thule \ -Dcompiler.java=11 \ -Druntime.java=8 
03:14:10 1> -----node_id[EzmV_EamS9CrPbyDEdvQNw][V] 03:14:10 1> --------[follower-index][0], node[EzmV_EamS9CrPbyDEdvQNw], [P], s[STARTED], a[id=Iqbazc8iQ9-6RR12ZZhtkg] 03:14:10 1> -----node_id[vtkxFTkwTReEy-_pIHq1aQ][V] 03:14:10 1> ---- unassigned 03:14:10 1> tasks: (0): 03:14:10 1> [2018-11-08T23:13:49,827][INFO ][o.e.x.c.a.ShardFollowNodeTask] [followerd4] [follower-index][0] shard follow task has been stopped 03:14:10 1> [2018-11-08T23:13:59,856][INFO ][o.e.c.m.MetaDataDeleteIndexService] [leaderm2] [leader-index/LOXtlSQRRIecv-2pJuHHlg] deleting index 03:14:10 1> [2018-11-08T23:13:59,892][INFO ][o.e.c.m.MetaDataDeleteIndexService] [followerm0] [follower-index/vTH2BwSvRTSC4CrI_oFbMA] deleting index 03:14:10 1> [2018-11-08T23:13:59,928][INFO ][o.e.x.c.FollowerFailOverIT] [testFailOverOnFollower] after test 03:14:10 FAILURE 42.3s J2 | FollowerFailOverIT.testFailOverOnFollower <<< FAILURES! 03:14:10 > Throwable #1: java.lang.AssertionError: timed out waiting for green state 03:14:10 >	at org.elasticsearch.xpack.CcrIntegTestCase.ensureColor(CcrIntegTestCase.java:278) 03:14:10 >	at org.elasticsearch.xpack.CcrIntegTestCase.ensureFollowerGreen(CcrIntegTestCase.java:253) 03:14:10 >	at org.elasticsearch.xpack.ccr.FollowerFailOverIT.testFailOverOnFollower(FollowerFailOverIT.java:99) 03:14:10 >	at java.lang.Thread.run(Thread.java:748)Throwable #2: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:848) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:822) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.assertSeqNos(InternalTestCluster.java:1278) 03:14:10 >	at org.elasticsearch.xpack.CcrIntegTestCase.afterTest(CcrIntegTestCase.java:155) 03:14:10 >	at java.lang.Thread.run(Thread.java:748) 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 >	Suppressed: java.lang.AssertionError: [follower-index][0], node[PlW87Mz-R7qy3LrIOT4BMg], [R], recovery_source[peer recovery], s[INITIALIZING], a[id=ksgilEsJToy6WtU0qNPM0Q], unassigned_info[[reason=NODE_LEFT], at[2018-11-09T03:13:19.536Z], delayed=true, details[node_left[PlW87Mz-R7qy3LrIOT4BMg]], allocation_status[no_attempt]] seq_no_stats mismatch 03:14:10 > Expected: <SeqNoStats{maxSeqNo=257, localCheckpoint=140, globalCheckpoint=140}> 03:14:10 > but: was <SeqNoStats{maxSeqNo=257, localCheckpoint=-1, globalCheckpoint=140}> 03:14:10 >	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 03:14:10 >	at org.elasticsearch.test.InternalTestCluster.lambda$assertSeqNos$7(InternalTestCluster.java:1311) 03:14:10 >	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836) 03:14:10 >	... 38 more 03:14:10 1> [2018-11-08T23:14:00,051][INFO ][o.e.x.c.FollowerFailOverIT] [testAddNewReplicasOnFollower] before test 03:14:10 1> [2018-11-08T23:14:00,051][INFO ][o.e.n.Node ] [testAddNewReplicasOnFollower] stopping ... 

Metadata

Metadata

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions