Skip to content

kv/kvserver: TestStoreRangeMergeRaftSnapshot failed #46192

Closed
#46373
Closed
kv/kvserver: TestStoreRangeMergeRaftSnapshot failed#46192
#46373
Assignees
nvbOwenQian
Labels
C-test-failureBroken test (automatically or manually discovered).O-robotOriginated from a bot.branch-masterFailures and bugs on the master branch.
Milestone
20.1
@cockroach-teamcity

Description

@cockroach-teamcity
cockroach-teamcity
opened on Mar 17, 2020

(kv/kvserver).TestStoreRangeMergeRaftSnapshot failed on master@b6d26e2280d48d9f8bfb8a37965f00f0415f47c0:

Fatal error:

F200317 14:00:47.724541 101811 kv/kvserver/store_raft.go:334  [s3,r2/3:{a-b}] while applying snapshot: actual and expected SST indices [2] don't match
github.com/cockroachdb/cockroach/pkg/kv/kvserver_test.TestStoreRangeMergeRaftSnapshot.func1
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/client_merge_test.go:3026
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).applySnapshot
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/replica_raftstorage.go:908
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).handleRaftReadyRaftMuLocked
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/replica_raft.go:498
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRaftSnapshotRequest.func1
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:333
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).withReplicaForRequest
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:200
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRaftSnapshotRequest
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:274
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).receiveSnapshot
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_snapshot.go:842
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).HandleSnapshot.func1
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:59
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:302
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).HandleSnapshot
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:49
github.com/cockroachdb/cockroach/pkg/kv/kvserver_test.(*unreliableRaftHandler).HandleSnapshot
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/client_raft_helpers_test.go:121
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).RaftSnapshot.func1.1
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/raft_transport.go:415
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).RaftSnapshot.func1
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/raft_transport.go:416
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:323
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:1357
while applying snapshot
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).handleRaftReadyRaftMuLocked
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/replica_raft.go:500
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRaftSnapshotRequest.func1
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:333
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).withReplicaForRequest
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:200
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRaftSnapshotRequest
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:274
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).receiveSnapshot
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_snapshot.go:842
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).HandleSnapshot.func1
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:59
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:302
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).HandleSnapshot
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:49
github.com/cockroachdb/cockroach/pkg/kv/kvserver_test.(*unreliableRaftHandler).HandleSnapshot
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/client_raft_helpers_test.go:121
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).RaftSnapshot.func1.1
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/raft_transport.go:415
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).RaftSnapshot.func1
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/raft_transport.go:416
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:323
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:1357

Stack:

goroutine 101811 [running]:
github.com/cockroachdb/cockroach/pkg/util/log.getStacks(0xa246501, 0x0, 0x0, 0xc00036fd40)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/get_stacks.go:25 +0xc6
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0x987b280, 0xc000000004, 0x9037bf4, 0x19, 0x14e, 0xc0007f4600, 0x1129)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:212 +0xbe3
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x6eb5220, 0xc0049f82d0, 0xc000000004, 0x3, 0x5ea3244, 0x7, 0xc0018ced80, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:66 +0x291
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x6eb5220, 0xc0049f82d0, 0x2, 0xc000000004, 0x5ea3244, 0x7, 0xc0018ced80, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x9a
github.com/cockroachdb/cockroach/pkg/util/log.FatalfDepth(...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:174
github.com/cockroachdb/cockroach/pkg/kv/kvserver.maybeFatalOnRaftReadyErr(0x6eb5220, 0xc0049f82d0, 0x5ecf29d, 0x17, 0x6e33f00, 0xc004fecf00, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/replica_raft.go:831 +0x25e
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRaftSnapshotRequest.func1(0x6eb5220, 0xc0049f82d0, 0xc000576000, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:334 +0x324
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).withReplicaForRequest(0xc00060b800, 0x6eb5220, 0xc0049f82d0, 0xc0004151c0, 0xc0018cf0e0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:200 +0x2d3
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processRaftSnapshotRequest(0xc00060b800, 0x6eb5220, 0xc0019ca7b0, 0xc000415180, 0xef42575f55f64a6b, 0xa28fd9a0f821c9b4, 0xc0018a2840, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:274 +0x23c
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).receiveSnapshot(0xc00060b800, 0x6eb5220, 0xc0019ca7b0, 0xc000415180, 0x7fab13876ee0, 0xc00035a980, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_snapshot.go:842 +0x861
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).HandleSnapshot.func1(0x6eb5220, 0xc0019ca7b0, 0x1e, 0xc0019ca601)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:59 +0x286
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc0013fe000, 0x6eb5220, 0xc0019ca7b0, 0x5ee87bd, 0x1e, 0xc002161ac8, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:302 +0x151
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).HandleSnapshot(0xc00060b800, 0xc000415180, 0x7fab13876eb0, 0xc00035a980, 0xc0004235a0, 0xc002161b58)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/store_raft.go:49 +0x139
github.com/cockroachdb/cockroach/pkg/kv/kvserver_test.(*unreliableRaftHandler).HandleSnapshot(0xc001bf2d00, 0xc000415180, 0x7fab13876eb0, 0xc00035a980, 0xc00035a980, 0xc0009e43f0)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/client_raft_helpers_test.go:121 +0xc3
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).RaftSnapshot.func1.1(0x6f0fea0, 0xc00035a980, 0xc000b36000, 0x6eb5220, 0xc0019ca630, 0xc001bd01b0, 0xc001036391)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/raft_transport.go:415 +0x1a6
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).RaftSnapshot.func1(0x6eb5220, 0xc0019ca630)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/kvserver/raft_transport.go:416 +0x75
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1(0xc000bdb180, 0x6eb5220, 0xc0019ca630, 0xc0002e84c0, 0x32, 0x0, 0x0, 0xc0019ca660)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:323 +0x163
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:318 +0x14b
Log preceding fatal error

I200317 14:00:42.392738 100047 kv/kvserver/replica_raftstorage.go:780  [s2,r1/2:{-}] applying LEARNER snapshot [id=dd37bb96 index=21]
I200317 14:00:42.419813 100047 kv/kvserver/replica_raftstorage.go:801  [s2,r1/2:/M{in-ax}] applied LEARNER snapshot [total=26ms ingestion=4@20ms id=dd37bb96 index=21]
I200317 14:00:42.464683 99718 kv/kvserver/replica_command.go:1602  [s1,r1/1:/M{in-ax}] change replicas (add [(n2,s2):2] remove []): existing descriptor r1:/M{in-ax} [(n1,s1):1, (n2,s2):2LEARNER, next=3, gen=1]
I200317 14:00:42.485409 99718 kv/kvserver/replica_raft.go:241  [s1,r1/1:/M{in-ax},txn=365907ac] proposing SIMPLE(v2) ADD_REPLICA[(n2,s2):2]: after=[(n1,s1):1 (n2,s2):2] next=3
I200317 14:00:42.524696 99718 kv/kvserver/replica_command.go:1602  [s1,r1/1:/M{in-ax}] change replicas (add [(n3,s3):3LEARNER] remove []): existing descriptor r1:/M{in-ax} [(n1,s1):1, (n2,s2):2, next=3, gen=2]
I200317 14:00:42.603174 99718 kv/kvserver/replica_raft.go:241  [s1,r1/1:/M{in-ax},txn=d37fdfb9] proposing SIMPLE(l3) ADD_REPLICA[(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER] next=4
I200317 14:00:42.730733 99718 kv/kvserver/store_snapshot.go:975  [s1,r1/1:/M{in-ax}] sending LEARNER snapshot e30af1de at applied index 28
I200317 14:00:42.766767 99718 kv/kvserver/store_snapshot.go:1018  [s1,r1/1:/M{in-ax}] streamed snapshot to (n3,s3):3LEARNER: kv pairs: 87, log entries: 0, rate-limit: 8.0 MiB/sec, 0.06s
I200317 14:00:42.779417 100420 kv/kvserver/raft_snapshot_queue.go:126  [raftsnapshot,s1,r1/1:/M{in-ax}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):3LEARNER
I200317 14:00:42.790608 100318 kv/kvserver/replica_raftstorage.go:780  [s3,r1/3:{-}] applying LEARNER snapshot [id=e30af1de index=28]
I200317 14:00:42.801048 100318 kv/kvserver/replica_raftstorage.go:801  [s3,r1/3:/M{in-ax}] applied LEARNER snapshot [total=9ms ingestion=4@6ms id=e30af1de index=28]
I200317 14:00:42.814532 99718 kv/kvserver/replica_command.go:1602  [s1,r1/1:/M{in-ax}] change replicas (add [(n3,s3):3] remove []): existing descriptor r1:/M{in-ax} [(n1,s1):1, (n2,s2):2, (n3,s3):3LEARNER, next=4, gen=3]
I200317 14:00:43.030625 99718 kv/kvserver/replica_raft.go:241  [s1,r1/1:/M{in-ax},txn=87181320] proposing SIMPLE(v3) ADD_REPLICA[(n3,s3):3]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I200317 14:00:43.174751 99718 kv/kvserver/replica_command.go:397  [s1,r1/1:/M{in-ax}] initiating a split of this range at key "a" [r2] (manual)
I200317 14:00:43.565302 99718 kv/kvserver/replica_command.go:397  [s1,r2/1:{a-/Max}] initiating a split of this range at key "b" [r3] (manual)
I200317 14:00:43.590717 99854 gossip/gossip.go:1527  [n2] node has connected to cluster via gossip
I200317 14:00:43.783208 100148 gossip/gossip.go:1527  [n3] node has connected to cluster via gossip
I200317 14:00:44.683200 99718 kv/kvserver/replica_command.go:397  [s2,r3/2:{b-/Max}] initiating a split of this range at key "c" [r12] (manual)
I200317 14:00:45.864482 99718 kv/kvserver/replica_command.go:397  [s2,r12/2:{c-/Max}] initiating a split of this range at key "e" [r13] (manual)
I200317 14:00:46.297959 99718 kv/kvserver/replica_command.go:663  [s1,r2/1:{a-b}] initiating a merge of r3:{b-c} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=7] into this range (manual)
I200317 14:00:46.350780 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/19 Commit:19 Entries:[6/20 EntryNormal <omitted>]
I200317 14:00:46.356437 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/20 Commit:19 Entries:[6/21 EntryNormal <omitted>]
I200317 14:00:46.373547 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/21 Commit:20
I200317 14:00:46.385358 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/21 Commit:21
I200317 14:00:46.520011 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/21 Commit:21 Entries:[6/22 EntryNormal <omitted>]
I200317 14:00:46.531994 99747 kv/kvserver/store_remove_replica.go:122  [s1,r2/1:{a-b},txn=50bd7748] removing replica r3/1
I200317 14:00:46.558201 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/22 Commit:22
I200317 14:00:46.567758 99913 kv/kvserver/store_remove_replica.go:122  [s2,r2/2:{a-b}] removing replica r3/2
I200317 14:00:46.610758 99718 kv/kvserver/replica_command.go:663  [s1,r2/1:{a-c}] initiating a merge of r12:{c-e} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=8] into this range (manual)
I200317 14:00:46.626445 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/22 Commit:22 Entries:[6/23 EntryNormal <omitted>]
I200317 14:00:46.667904 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/23 Commit:23
I200317 14:00:46.795374 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/23 Commit:23 Entries:[6/24 EntryNormal <omitted>]
I200317 14:00:46.817668 99783 kv/kvserver/store_remove_replica.go:122  [s1,r2/1:{a-c},txn=f2a01961] removing replica r12/1
I200317 14:00:46.826769 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/24 Commit:24
I200317 14:00:46.856829 99718 kv/kvserver/replica_command.go:397  [s2,r12/2:{c-e}] initiating a split of this range at key "d" [r14] (manual)
I200317 14:00:46.887006 99865 kv/kvserver/store_remove_replica.go:122  [s2,r2/2:{a-c}] removing replica r12/2
I200317 14:00:47.121216 99718 kv/kvserver/replica_command.go:397  [s1,r2/1:{a-e}] initiating a split of this range at key "d" [r4] (manual)
I200317 14:00:47.250021 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/24 Commit:24 Entries:[6/25 EntryNormal <omitted>]
I200317 14:00:47.251250 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/25 Commit:24 Entries:[6/26 EntryNormal <omitted>]
I200317 14:00:47.262994 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/26 Commit:26
I200317 14:00:47.294589 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/26 Commit:26 Entries:[6/27 EntryNormal <omitted>]
I200317 14:00:47.351728 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/27 Commit:27
I200317 14:00:47.413952 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/27 Commit:27 Entries:[6/28 EntryNormal <omitted>]
I200317 14:00:47.469700 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/28 Commit:28
I200317 14:00:47.516660 100613 kv/kvserver/client_raft_helpers_test.go:71  dropping r2 Raft message 1->3 MsgApp Term:6 Log:6/28 Commit:28 Entries:[6/29 EntryNormal <omitted>]
I200317 14:00:47.563758 99718 kv/kvserver/client_merge_test.go:3124  restored traffic to store 2
I200317 14:00:47.642799 101711 kv/kvserver/store_snapshot.go:975  [raftsnapshot,s1,r2/1:{a-d}] sending RAFT snapshot 6b4af655 at applied index 29
I200317 14:00:47.679195 101711 kv/kvserver/store_snapshot.go:1018  [raftsnapshot,s1,r2/1:{a-d}] streamed snapshot to (n3,s3):3: kv pairs: 20, log entries: 0, rate-limit: 8.0 MiB/sec, 0.04s
I200317 14:00:47.713050 101811 kv/kvserver/replica_raftstorage.go:780  [s3,r2/3:{a-b}] applying RAFT snapshot [id=6b4af655 index=29]
I200317 14:00:47.721924 101811 kv/kvserver/replica_raftstorage.go:801  [s3,r2/3:{a-b}] applied RAFT snapshot [total=8ms subsumedReplicas=2@6ms ingestion=7@-9223372036855ms id=6b4af655 index=29]

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestStoreRangeMergeRaftSnapshot PKG=./pkg/kv/kvserver TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

See this test on roachdash
powered by pkg/cmd/internal/issues

Metadata

Metadata

Assignees

Labels

C-test-failureBroken test (automatically or manually discovered).O-robotOriginated from a bot.branch-masterFailures and bugs on the master branch.

Type

No type

Projects

No projects

Milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions