down peer与pending peer在同一个store上,无法自动处理

Bug 反馈
清晰准确地描述您发现的问题,提供任何可能复现问题的步骤有助于研发同学及时处理问题
监控中存在down peer,一直无法自动恢复


查看region down peer,发现region的down peer和pending peer在同一个store上,PD上手动remove peer,提示成功,但是region信息没有变化,这个store上查看region的信息,提示没有这个region的副本
【 Bug 的影响】

【可能的问题复现步骤】

【看到的非预期行为】

【期望看到的行为】

【相关组件及具体版本】
v4.0.14
【其他背景信息或者截图】
如集群拓扑,系统和内核版本,应用 app 信息等;如果问题跟 SQL 有关,请提供 SQL 语句和相关表的 Schema 信息;如果节点日志存在关键报错,请提供相关节点的日志内容或文件;如果一些业务敏感信息不便提供,请留下联系方式,我们与您私下沟通。

region 221722354
{
“id”: 221722354,
“start_key”: “7480000000000000FFCB5F7285DF292A1DFFA0DE320000000000FA”,
“end_key”: “7480000000000000FFCB5F7285DF3B6812FF3627B40000000000FA”,
“epoch”: {
“conf_ver”: 9,
“version”: 75
},
“peers”: [
{
“id”: 221722355,
“store_id”: 221712183
},
{
“id”: 222317092,
“store_id”: 220115097
},
{
“id”: 222400367,
“store_id”: 222298555
},
{
“id”: 222400368,
“store_id”: 4,
“is_learner”: true
}
],
“leader”: {
“id”: 222317092,
“store_id”: 220115097
},
“down_peers”: [
{
“peer”: {
“id”: 222400368,
“store_id”: 4,
“is_learner”: true
},
“down_seconds”: 2438557
}
],
“pending_peers”: [
{
“id”: 222400368,
“store_id”: 4,
“is_learner”: true
}
],
“written_bytes”: 1420,
“read_bytes”: 45,
“written_keys”: 8,
“read_keys”: 1,
“approximate_size”: 34,
“approximate_keys”: 51362
}

2赞

补充store 4上查询region信息,提示没有:
./tikv-ctl --host 127.0.0.1:20273 raft region -r 221722354
[2021/10/28 11:34:22.198 +08:00] [INFO] [] [“TCP_USER_TIMEOUT is available. TCP_USER_TIMEOUT will be used thereafter”]
[2021/10/28 11:34:22.200 +08:00] [INFO] [] [“New connected subchannel at 0x7f9c4d42e210 for subchannel 0x7f9c508135c0”]
DebugClient::region_info: RpcFailure: 5-NOT_FOUND info for region 221722354

1赞

另外提一个小建议,这region信息中可不可以增加一个last heartbeat time,因为存在一种情况,就是其实region已经没有leader了,但是PD的信息都是leader上报的,导致从PD的视角看,region总是存在leader的,这就造成误导,增加一个heartbeat信息,这样就可以快速判断出这个region其实已经没有leader了,因为上一次心跳距离现在太久了,当集群规模大的时候,尤其是遇到一些问题的时候在,这个信息还是很管用的

1赞

这个问题通过重启问题store,然后人工在PD上手动remove peer修复。但是我查看TiKV日志的时候发现,这个down peer所在的store一直打印如下的日子,而其他store确没有类似的日志,重启这个store,问题仍然存在。
[2021/10/29 11:21:27.583 +08:00] [INFO] [raft.rs:923] ["[logterm: 5, index: 5] sent request to 221662017"] [msg=MsgRequestPreVote] [term=5] [id=221662017] [log_index=5] [log_term=5] [raft_id=221662016] [region_id=221662015]
[2021/10/29 11:21:27.684 +08:00] [ERROR] [util.rs:342] [“request failed, retry”] [err_code=KV:Unknown] [err=“Grpc(RpcFinished(Some(RpcStatus { status: 1-CANCELLED, details: Some(“Cancelled”) })))”]
[2021/10/29 11:21:27.684 +08:00] [ERROR] [util.rs:387] [“request failed”] [err_code=KV:PD:gRPC] [err=“Grpc(RpcFailure(RpcStatus { status: 2-UNKNOWN, details: Some(“invalid store ID 9, not found”) }))”]
[2021/10/29 11:21:27.684 +08:00] [INFO] [util.rs:462] [“connecting to PD endpoint”] [endpoints=http://10.36.68.167:2383]
[2021/10/29 11:21:27.684 +08:00] [INFO] [] [“New connected subchannel at 0x7fcaa623c940 for subchannel 0x7fc7c6ff0180”]
[2021/10/29 11:21:27.685 +08:00] [INFO] [util.rs:462] [“connecting to PD endpoint”] [endpoints=http://10.36.144.171:2383]
[2021/10/29 11:21:27.686 +08:00] [INFO] [util.rs:527] [“connected to PD leader”] [endpoints=http://10.36.144.171:2383]
[2021/10/29 11:21:27.686 +08:00] [INFO] [util.rs:225] [“heartbeat sender and receiver are stale, refreshing …”]
[2021/10/29 11:21:27.686 +08:00] [ERROR] [client.rs:457] [“failed to send heartbeat”] [err_code=KV:PD:gRPC] [err=“Grpc(RpcFinished(Some(RpcStatus { status: 1-CANCELLED, details: Some(“Cancelled”) })))”]
[2021/10/29 11:21:27.686 +08:00] [ERROR] [util.rs:342] [“request failed, retry”] [err_code=KV:Unknown] [err=“Grpc(RpcFinished(Some(RpcStatus { status: 1-CANCELLED, details: Some(“Cancelled”) })))”]
[2021/10/29 11:21:27.778 +08:00] [WARN] [util.rs:243] [“updating PD client done”] [spend=93.699425ms]
[2021/10/29 11:21:27.778 +08:00] [ERROR] [util.rs:387] [“request failed”] [err_code=KV:PD:gRPC] [err=“Grpc(RpcFailure(RpcStatus { status: 2-UNKNOWN, details: Some(“invalid store ID 9, not found”) }))”]
[2021/10/29 11:21:27.778 +08:00] [ERROR] [util.rs:396] [“reconnect failed”] [err_code=KV:PD:Unknown] [err=“Other(”[components/pd_client/src/util.rs:181]: cancel reconnection due to too small interval")"]
[2021/10/29 11:21:28.779 +08:00] [ERROR] [util.rs:387] [“request failed”] [err_code=KV:PD:gRPC] [err=“Grpc(RpcFailure(RpcStatus { status: 2-UNKNOWN, details: Some(“invalid store ID 9, not found”) }))”]
[2021/10/29 11:21:28.779 +08:00] [INFO] [util.rs:462] [“connecting to PD endpoint”] [endpoints=http://10.36.68.167:2383]
[2021/10/29 11:21:28.779 +08:00] [INFO] [] [“New connected subchannel at 0x7fcaa623cdc0 for subchannel 0x7fc7c6ff3980”]
[2021/10/29 11:21:28.780 +08:00] [INFO] [util.rs:462] [“connecting to PD endpoint”] [endpoints=http://10.36.144.171:2383]
[2021/10/29 11:21:28.780 +08:00] [INFO] [util.rs:527] [“connected to PD leader”] [endpoints=http://10.36.144.171:2383]
[2021/10/29 11:21:28.780 +08:00] [INFO] [util.rs:225] [“heartbeat sender and receiver are stale, refreshing …”]
[2021/10/29 11:21:28.780 +08:00] [ERROR] [client.rs:457] [“failed to send heartbeat”] [err_code=KV:PD:gRPC] [err=“Grpc(RpcFinished(Some(RpcStatus { status: 1-CANCELLED, details: Some(“Cancelled”) })))”]
[2021/10/29 11:21:28.780 +08:00] [ERROR] [util.rs:342] [“request failed, retry”] [err_code=KV:Unknown] [err=“Grpc(RpcFinished(Some(RpcStatus { status: 1-CANCELLED, details: Some(“Cancelled”) })))”]
[2021/10/29 11:21:28.868 +08:00] [WARN] [util.rs:243] [“updating PD client done”] [spend=89.768229ms]
[2021/10/29 11:21:28.869 +08:00] [ERROR] [util.rs:387] [“request failed”] [err_code=KV:PD:gRPC] [err=“Grpc(RpcFailure(RpcStatus { status: 2-UNKNOWN, details: Some(“invalid store ID 9, not found”) }))”]
[2021/10/29 11:21:28.869 +08:00] [ERROR] [util.rs:396] [“reconnect failed”] [err_code=KV:PD:Unknown] [err=“Other(”[components/pd_client/src/util.rs:181]: cancel reconnection due to too small interval")"]
[2021/10/29 11:21:29.869 +08:00] [ERROR] [util.rs:387] [“request failed”] [err_code=KV:PD:gRPC] [err=“Grpc(RpcFailure(RpcStatus { status: 2-UNKNOWN, details: Some(“invalid store ID 9, not found”) }))”]
[2021/10/29 11:21:29.869 +08:00] [ERROR] [transport.rs:137] [“resolve store address failed”] [err=“Other(”[src/server/resolve.rs:72]: description() is deprecated; use Display")"] [store_id=9]
[2021/10/29 11:21:29.869 +08:00] [WARN] [mod.rs:89] [“handle task resolve store 9 address”] [takes=5470]

这里我看到它尝试解析store 9,但是目前PD中没有store 9,应该是一个已经废弃的store,相关的信息在pd上是被清理掉了。

1赞

之前对 store9 进行了什么操作?是否有过强制下线和 remove tombstone 等?

1赞

应该是执行过,store 9已经不在了

1赞

通常来说,我们是不建议进行 强制下线+ remove tombstone 的,这样会导致没有下线完成的 region 在其他节点的 peer 仍然残留已经被清除的 store 的 peer 的信息,而 pd 又不知道;

是否尝试通过 pd-ctl 手动删除掉 down peer 信息?

1赞

手动删除可以清理掉down peer,但是down peer的位置并不是已经墓碑的store
我只是看到无法自动清理down peer的所在的store上正好打印了这些异常的信息,但是这个异常的打印看起来跟当前down peer关系不大

1赞

之前运维tidb的同学须告诉我,只下线一个store,仍然会有peer调度过去,下线过程非常漫长,因此一般会强制下线,然后标记为墓碑以加速这个过程。
通常主动下线一个store是因为要么机器故障了,需要维修,或者磁盘满了导致这个节点无法启动。
从之前的经验上看,确实下线一个store时间很长,存在很大的风险,期间如果遇到其他的节点异常,那么可能就会造成集群不可用。

1赞

只下线一个store,仍然会有peer调度过去

这个说法是不成立的,下线 store 后就不会将其作为 store 的 target 的,只可能是因为持续写入 split 在 offline 的节点上才可能出现新 peer

强制下线,然后标记为墓碑以加速这个过程。

强制下线和标记为墓碑不会加速这个过程;而且如果 remove tombstone,还会导致没有下线完成的 region 在其他节点的 peer 仍然残留已经被清除的 store 的 peer 的信息,而 pd 又不知道;极其不推荐这样的作法

如果想加速,可以考虑调整 store limit,比如在不影响业务前提下调大剩余可用节点的 add peer limit。

确实下线一个store时间很长,存在很大的风险,期间如果遇到其他的节点异常,那么可能就会造成集群不可用。

对于,“在下线不可用的节点时,再挂掉一个节点”的场景下,强制下线和不强制下线,丢数据风险是一样的;

但是对于,正常缩容,下线可用的节点的时候,强制下线的风险是高于正常下线的。

综上,强制下线不能加速下线速度,而且会在某些情况下带来更高的风险,因此我们不推荐这一方式。

2赞