reconfirm 失败排查指南

reconfirm 超时是测试环境中比较常见的问题，通常在 server 异常时发生，比如内存耗尽、断网等。本文将列举reconfirm 超时的常见原因以及排查步骤。

reconfirm 整体执行过程概述

在 OceanBase 数据库中，每个 partition 要正常提供读写服务，必须选出一个 leader，整个选主的流程大致如下：

1. Election 模块根据优先级选出 leader。
2. Clog 模块从 Election 模块得知当前 leader，leader 执行 reconfirm 过程。
3. leader 执行 takeover 等操作，正式上任。

reconfirm 过程的主要目的是对于滑动窗口中遗留的未确认日志进行重确认，并同步给 follower。 确认状态是指：每条 Clog 日志由 leader 发送给 follower，follower 本地写盘成功后会给 leader 回复 ack 消息，leader 收到了多数派的 ack 消息后再给 follower 发送一个确认消息，表示这条日志已经安全地形成多数派，达到了确认状态，可以从滑动窗口滑出并回放到 memtable 了。如果 leader 突然宕机，那么可能会有一些日志已经发给 follower 但还未达到确认状态，这些日志会由下一任 leader 在 reconfirm 阶段进行重新确认，这就是 reconfirm 阶段的意义。

reconfirm 过程包含如下几个阶段：

1. INITED 阶段：尝试将已确认日志提交回放，本地写 prepare 日志，更新 proposal_id。
2. FLUSHING_PREPARE_LOG 阶段：发送 proposal_id 给所有 follower，等待 follower 回复各自的max_flushed_log_id，收到多数派回复后进入下个阶段。
3. FETCH_MAX_LSN 阶段：等待 max_flushed_log_id 达到了多数派(含自己)，则统计收到的最大 max_flushed_id 值，并做一些准备工作。
4. RECONFIRMING 阶段：首先尝试将滑动窗口左侧已确认的 log 从滑动窗口滑出并提交回放，直到遇到第一条未确认 的 log 为止，然后对所有未确认日志执行重确认过程，即从多数派成员收集、确定该日志内容，然后同步给所有 follower ；最后进入 START_WORKING 状态，写一条 start_working 日志。
5. START_WORKING 阶段：等待 start_working 日志形成多数派。
6. FINISHED 阶段：结束。

各阶段关键日志

阶段 2 的关键日志如下：

 [2017-09-21 20:28:05.146918] INFO  [CLOG] ob_log_reconfirm.cpp:595 [127240][Y0-0000000000000000] [lt=22  
] max_log_ack_list not majority(partition_key={tid:1099511627777, partition_id:0, part_cnt:1}, majority_cnt=2, max_log_ack_list=1{serve  
r:“10.101.162.151:26176”, timestamp:-1, flag:0}, receive_previous_max_log_ts=false, recofirm_start_time=1505996885134451, current_time=  
 1505996885146912)

收到多数派的回复的标志日志如下（如果无法看到该日志说明本阶段被卡住了）：

[2017-09-21 20:28:06.142985] INFO  [CLOG] ob_log_reconfirm.cpp:598 [127240][Y0-0000000000000000] [lt=25] max_log_ack_list majority(partition_key={tid:1099511627777, partition_id:0, part_cnt:1}, majority_cnt=2, max_log_ack_list=1{server:“10.101.162.151:26176”, timestamp:-1, flag:0})

reconfirm 过程的超时时间是 10s，即如果 10s 没有执行完会打印 ERROR 级别的超时日志，关键字为：

is_reconfirm_role_change_or_sync_timeout_

reconfirm 超时常见原因

reconfirm 通常由于卡在如上各个阶段而超时，卡住的原因主要有：无法提交回放、网络不通、日志盘满等。

本地磁盘慢

reconfirm 超时附近同一个线程会打印关键字为 current log_task 相关的日志，示例如下：

log/observer.log.20210706103014:[2021-07-06 10:29:49.584343] INFO  [CLOG] ob_log_state_mgr.cpp:2464 [5676][0][Y0-0000000000000000-0-0] [lt=18] [dc=0] current log_task status(partition_key={tid:1101710651081554, partition_id:1152921522055151625, part_idx:4, subpart_idx:9}, role=1, state=3, start_id=28, *log_task={log_type_:201, proposal_id_:{time_to_usec:1625487530074041, server:"100.88.105.195:4059"}, log_buf_len_:0, generation_timestamp:1625535749037029, submit_timestamp_:1625535749037029, next_replay_log_ts_:1625535749037029, data_checksum:858767142, epoch_id_:1625487530074041, accum_checksum_:1815198558, state_map:{val:588}, ack_list:0, submit_cb:null, majority_cnt:1, log_cursor:{file_id:4294967295, offset:0, size:0}})

这条日志会把滑动窗口中第一条日志的状态打印出来，最后一个字段是 log_cursor ，表示这条日志在磁盘的文件id、offset 信息，上面的日志显示该 cursor 是一个无效值，如果 log_task 其他字段是有效的（比如submit_timestamp），则说明它写盘超时未返回，需要排查本地 clog 盘是否有异常，用 tsar、vsar 或者 dmesg -T 等分析工具。

ack_list 表示该条日志在多数派的确认，0 表示没有收到 follower 应答，可以检查 follower 是否出现盘满等问题。

回放卡住

reconfirm 过程中需要将滑动窗口左侧已经确认的日志全部提交回放，一但回放由于各种异常（内存分配失败、回放出错）卡住的话，滑动窗口就会发生积压，积压的日志数量达到阈值(目前是 2 万)后，滑动窗口就满了，无法接收新的日志，reconfirm 也就无法正常执行下去。

如果滑动窗口中有已确认的日志需要提交回放，则可以看到如下日志(回放卡住时会不断打印该日志)：

[2017-10-19 01:25:50.272544] INFO  [CLOG] ob_log_reconfirm.cpp:683 [45715][Y0-0000000000000000] [lt=12] there are confirmed logs in sw, try again(partition_key={tid:1106108697592670, partition_id:0, part_cnt:1}, ret=-4023, new_start_id=371801833, start_id=371802703)

至于回放卡住的原因则有很多，诸如 alloc memory failed 这样的内存分配错误、replay error 这种回放错误可以通过执行如下命令确认：

grep ERROR observer.log | grep STORAGE | grep 'alloc memory'  
grep ERROR observer.log | grep STORAGE | grep replay

Clog 盘满

reconfirm 过程中需要写 prepare、start_working 等日志，且需要达成多数派确认，如果部分 server 的 Clog 盘满了导致无法写这些日志，且剩余正常 server 不够多数派，那么 reconfirm 也会失败。

Clog 盘满的关键日志如下：

[2017-09-14 14:59:53.877021] WARN  [CLOG] receive_log (ob_partition_log_service.cpp:966) [53893][Y72F80B8AF44E-00055913896E9CAD] [lt=11] log outof disk space(partition_key={tid:1102810162709414, partition_id:46, part_cnt:0}, server=“11.138.244.78:29432”, ret=-4264, free_quota=-3381817344)

可以在各个 server 上使用如下命令确认是否为该原因：

grep 'log outof disk space' observer.log

或者

grep '\-4264' observer.log

网络不通

reconfirm 过程中候选 leader 需要与各个 follower 在多个阶段进行通信，因此如果网络出现问题，导致无法收发包或收发包延迟太大也可能导致 reconfirm 失败。

网络不通会导致 reconfirm 多个阶段均会失败，比如发送完 prepare 日志后一直收不到 follower 的回复，会导致本机一直打印如下关键字的日志直至超时失败：

max_log_ack_list not majority

后续的写 start_working 日志也可能由于网络异常而导致无法收到多数派 ack，进而超时失败。

很多原因可能导致网络不通，排查步骤如下：

1. 执行 ping 命令，如果能通说明网络正常。
2. 执行 sudo iptables -L , 看是否有网络隔离。
3. 查看对端租户队列日志，看是否队列满了，无法处理请求。

死锁

死锁会引起连锁反应，只要卡住了 clog 的 handle_request 调用过程，就会导致 500 租户的请求队列积压满，无法处理新的 rpc 请求，reconfirm 相关的消息处理也会停滞(leader 端日志显示，follower 一直没有回复任何请求，与网络不通相似)。

排查方法如下：

1. 搜索 leader 或 follower 的 observer.log，关键字是 dump tenant，如果 500 租户队列满了，可以看到类似如下日志：

   observer.log.20171129181406:[2017-11-29 18:13:54.020089] INFO  [SERVER.OMT] ob_multi_tenant.cpp:533 [116676][Y0-0000000000000000] [lt=42] dump tenant info(tenant={id:500, unit_min_cpu:"10.000000000000", unit_max_cpu:"10.000000000000", slice:"0.000000000000", slice_remain:"0.000000000000", token_cnt:40, ass_token_cnt:40, lq_tokens:12, used_lq_tokens:0, stopped:false, idle_us:0, recv_hp_rpc_cnt:380082895, recv_np_rpc_cnt:0, recv_lp_rpc_cnt:0, recv_mysql_cnt:0, recv_task_cnt:0, recv_large_req_cnt:0, tt_large_quries:0, actives:40, workers:40, lq waiting workers:0, req_queue:total_size=65537 queue[0]=65537 queue[1]=0 queue[2]=0 queue[3]=0 queue[4]=0 queue[5]=0 , large queued:0})
   

2. pstack 出相关堆栈信息，搜索 handle_request ，看是否处理请求的线程卡住了。

3. 如果有（2）中的现象，那么继续搜索 lock 相关信息，看是否有线程一直在等锁，根据等锁的调用栈查看对应源码文件，看是否有重复加锁操作，找到当前持有锁的位置。

工作线程不足

看是否存在如下 easy 包处理超时的日志：

[2018-02-02 11:12:12.103] easy_request.c:420(tid:7fe2cdc9f700)[57136] rpc time, packet_id :2425446521, pcode :4096, client_start_time :1517541127590356, start_send_diff :8, send_connect_diff: 0, connect_write_diff: 5, request_fly_ts: 188, arrival_push_diff: 2, wait_queue_diff: 4508603, pop_process_start_diff :2, process_handler_diff: 4184, process_end_response_diff: 1, response_fly_ts: 447, read_end_diff: 1, client_end_time :1517541132103797, dst: 10.101.72.106:37293

可以看到 wait_queue_diff 达到了几秒级别，说明工作线程处理比较慢，检查 cpu_quota （cpu_quota_concurrency、workers_per_cpu_quota、system_cpu_quota）相关配置项是否配置过小。

该问题会导致类似于随机丢包的现象，比如日志显示 follower 能收到 prepare 请求，也发了 prepare response，但 leader 却收不到 response，从而 max_log_ack_list 一直无法达到多数派；还会导致一些黑名单日志出现。**

租户内存爆（memstore）

租户 MEMSTORE 内存满之后，clog 模块无法继续 receive log，这也会导致 reconfirm 失败，因为 reconfirm 期间需要做 clog 同步，且 leader 可能需要找多数派 follower 拉取日志，如果 leader 上租户内存爆了，就会无法收取 follower 发来的日志。

这种情况的关键日志搜索方式如下：

由于这条日志是整体限流的，所以不要带pkey去搜，直接搜下面的关键字即可。

grep 'cannot receive log'  observer.log

日志内容如下：

[2022-04-06 17:51:38.790897] WARN  [CLOG] receive_log (ob_partition_log_service.cpp:1281) [118645][1564][Y0-0000000000000000] [lt=15] [dc=0] tenant is out of memory, cannot receive log(ret=-4030, partition_key={tid:1109407232476025, partition_id:93, part_cnt:0})

遇到这种情况时，leader 上 reconfirm 超时前会持续打印如下日志，表示某一条日志没有收到多数派的回应：

observer.log.20220406174645:[2022-04-06 16:58:55.531277] INFO  [CLOG] ob_log_reconfirm.cpp:735 [122477][3242][Y0-0000000000000000] [lt=9] [dc=35] this log does not get majority response(partition_key={tid:1109407232425989, partition_id:0, part_cnt:0}, ret=0, next_id=741)

集群恢复

可以先尝试将日志级别调到 ERROR（kill -42 pid），通常如果 partition 数量很多且一直刷日志的话，调整为 ERROR 级别后，核心表可恢复，集群可连接。

如果有 easy 包超时日志，wait_queue_diff 很长的话，检查 cpu_quota 相关配置项是否太小，导致工作线程处理不过来，如果太小，需要调大。