TestSplitConfChangeSnapshotUnreliableRecoverConcurrentPartition3B遇到两个概率很小的bug

☄️ 学习与认证 Talent Plan
1

一个bug是报test_test.go:326: region is not split。

另一个是报panic: [region 1] 2 meta corruption detected，这个错误是peerMsgHandler中destroyPeer函数meta.regionRanges.Delete这一句后触发的。

出错概率很迷惑，我有的时候100多遍都没问题，有时大概10多次出现一次，两个bug概率差不多。

  1. 对于region is not split这个错误，看Log发现根本没有生成过Split 的Log，外部请求只有50次左右的样子，都没有达到生成Split的Size要求，然后所有store线程都stop了，正常来说外部请求应该很多，而且就算请求没成功也会有超时之类的错误，但看日志一切都很正常，没有报错，没有外部cmd请求重发，直接正常apply一些外部cmd后就结束了，很迷惑。

  2. 对于meta corruption detected这个错误，意思是regionRanges中没有了这个Region，有3个地方调用了destroy函数，跑了很多次这3个调用的地方都有可能引发错误，但Log显示destroy函数只被调用了一次，而要destroy的节点要么是一开始就创建的节点，要么是addNode出来的节点（收到了snapshot，也就是apply的时候更新了它的regionRanges，自己regionRanges在split的两个相关region和applySnapshot后这两个地方有更新，confchange最后一个测试跑了300多遍没出错，应该自己的regionRanges更新是没有问题的）

根据Log分析，也就是说有地方没调destroy()函数，也没将d.stopped设置为true，但是删除了regionRanges，看了下删除regionRanges的函数，应该不在自己添加的代码中，同样很迷惑，找不出问题。

请问有大佬对这两个Bug有什么想法吗

2

补充下部分Log： 首先是region is not split，正常apply着，才到50多条，直接store stop了

2022/07/22 21:41:40 storeID,peerId,RegionId[4,4,1] -- -[{EntryNormal 16 56 [10 14 8 1 18 4 8 4 16 4 34 4 8 3 16 1 18 25 8 4 42 21 10 7 100 101 102 97 117 108 116 18 10 52 32 48 48 48 48 48 48 48 50] {} [] 0}]
2022/07/22 21:41:40 storeID,peerId,RegionId[4,4,1] -- Apply[Normal]Command(index,term,request) -- entry-[56,16,[cmd_type:Delete delete:<cf:"default" key:"4 00000002" > ]]
2022/07/22 21:41:40 [5]--AE_Request--UpdateCommit--Success--:oldCommitIndex-55,nxtCommitMax-56
2022/07/22 21:41:40 storeID,peerId,RegionId[2,2,1] -- -[{EntryNormal 16 56 [10 14 8 1 18 4 8 4 16 4 34 4 8 3 16 1 18 25 8 4 42 21 10 7 100 101 102 97 117 108 116 18 10 52 32 48 48 48 48 48 48 48 50] {} [] 0}]
2022/07/22 21:41:40 storeID,peerId,RegionId[2,2,1] -- Apply[Normal]Command(index,term,request) -- entry-[56,16,[cmd_type:Delete delete:<cf:"default" key:"4 00000002" > ]]
2022/07/22 21:41:40 storeID,peerId,RegionId[5,5,1] -- -[{EntryNormal 16 56 [10 14 8 1 18 4 8 4 16 4 34 4 8 3 16 1 18 25 8 4 42 21 10 7 100 101 102 97 117 108 116 18 10 52 32 48 48 48 48 48 48 48 50] {} [] 0}]
2022/07/22 21:41:40 storeID,peerId,RegionId[5,5,1] -- Apply[Normal]Command(index,term,request) -- entry-[56,16,[cmd_type:Delete delete:<cf:"default" key:"4 00000002" > ]]
2022/07/22 21:41:40 [4]--AE_Response--UpdateMatch-56--:success append to [2],myTerm_16
2022/07/22 21:41:40 [4]--AE_Response--Ignore-:success append to [2]
2022/07/22 21:41:40 [4]--AE_Response--Ignore-:success append to [5]
2022/07/22 21:41:40 [4]--doHeartBeat--:begin to send HeartBeat-Term-16

...

2022/07/22 21:41:41 [5]--HB_Request--:Term-16
2022/07/22 21:41:41.755596 node.go:198: e[0;37m[info] stop raft store thread, storeID: 1e[0m
2022/07/22 21:41:41.755656 node.go:198: e[0;37m[info] stop raft store thread, storeID: 2e[0m
2022/07/22 21:41:41.755685 node.go:198: e[0;37m[info] stop raft store thread, storeID: 3e[0m
2022/07/22 21:41:41.755717 node.go:198: e[0;37m[info] stop raft store thread, storeID: 4e[0m
2022/07/22 21:41:41.755743 node.go:198: e[0;37m[info] stop raft store thread, storeID: 5e[0m
3

然后是meta corruption detected，删除的是初始创建的节点，其他节点删除了它，然后自己的删除Log还没Apply，触发了这个问题

2022/07/22 19:59:22.127178 peer_msg_handler.go:940: e[0;37m[info] [region 1] 2 peer id:2 store_id:2  receives gc message, trying to removee[0m
2022/07/22 19:59:22.127187 peer_msg_handler.go:1007: e[0;37m[info] [region 1] 2 starts destroye[0m
2022/07/22 19:59:22.127190 peer.go:209: e[0;37m[info] [region 1] 2 begin to destroye[0m
2022/07/22 19:59:22.127199 peer_storage.go:301: e[0;37m[info] [region 1] clear peer 1 meta key 1 apply key 1 raft key and 3 raft logs, takes 4.954µse[0m
2022/07/22 19:59:22 [8]--HB_Request--:Term-7
2022/07/22 19:59:22.138942 peer.go:248: e[0;37m[info] [region 1] 2 destroy itself, takes 11.750885mse[0m
panic: [region 1] 2 meta corruption detected

goroutine 179 [running]:
github.com/pingcap-incubator/tinykv/kv/raftstore.(*peerMsgHandler).destroyPeer(0xc17be51e20)
	/home/remote/myCode/my_tinykv/kv/raftstore/peer_msg_handler.go:1025 +0x29f
github.com/pingcap-incubator/tinykv/kv/raftstore.(*peerMsgHandler).handleGCPeerMsg(0xc17be51e20, 0xc206d3e600)
	/home/remote/myCode/my_tinykv/kv/raftstore/peer_msg_handler.go:942 +0x10e
github.com/pingcap-incubator/tinykv/kv/raftstore.(*peerMsgHandler).onRaftMsg(0xc17be51e20, 0xc206d3e600)
	/home/remote/myCode/my_tinykv/kv/raftstore/peer_msg_handler.go:802 +0x1df
github.com/pingcap-incubator/tinykv/kv/raftstore.(*peerMsgHandler).HandleMsg(0xc17be51e20, {0xc17be51df0?, 0x1?, {0xb3e6e0?, 0xc206d3e600?}})
	/home/remote/myCode/my_tinykv/kv/raftstore/peer_msg_handler.go:552 +0x85
github.com/pingcap-incubator/tinykv/kv/raftstore.(*raftWorker).run(0xc0000f40c0, 0xc000098ba0, 0x0?)
	/home/remote/myCode/my_tinykv/kv/raftstore/raft_worker.go:63 +0x505
created by github.com/pingcap-incubator/tinykv/kv/raftstore.(*Raftstore).startWorkers
	/home/remote/myCode/my_tinykv/kv/raftstore/raftstore.go:275 +0x17b
4

这个有解决吗:joy:

5

region is not split不知道什么问题，只是概率变小了很多，几百次出现一次的样子（改了很多地方，我也不知道为什么概率小了），另一个是因为给的代码里生成SchedulerAskSplitTask任务时传的region是个指针，而分配peerId和peerMsgHandler是异步的，导致有可能过时的split被执行