合并切主失败问题排查

轮转合并过程中 RS 需要在两个 Primary Zone 之间切主，在合并某个 Primary Zone 之前，需要先把 leader 切到另一个Primary Zone（属于 primary region），如果另一个 Primary Zone 的副本无法当主（如被 stop server、被 stop zone、缺副本、选举优先级不够高等原因），会导致 RS 打印如下日志：

obfundtrade-[  rootservice.log  [2019-08-14 16:22:59.657326] ERROR [RS] set_zone_merging (ob_daily_merge_scheduler.cpp:654) [56663][**YB420A34659E-00058BB3C222646D**] [lt=12] cant switch leader for daily merge, please check it(zone=alipay.et15_1, fail_time=4) BACKTRACE:0x31471b9 0x30d51d7 0x8b5426 0x8a70ef 0x8ab817 0x8ad5e3 0x8adb70 0x8ae180 0x8aeaac 0x318f3cd 0x318d16e 0x7f65e6faddc5 0x7f65e58eaced

排查步骤

针对这种问题一般的排查流程如下：

1. 首先确认 primary region 中非 Leader 所在的其他 Zone 是否有如下情况：

   • 发生了stop Server：如果 Server 被 stop ，则需要先拉起服务。
   • 发生了 stop Zone：另一个 Primary Zone 被 stop了，也会导致无法切主成功。
   • 目标 Zone 缺副本：查询 __all_meta_table 查看是否缺副本，如果是则需要先补副本。

2. 如果没有上述中所说的几种情况，就是选举优先级不符合要求，需到 RS 所在机器，利用上面 error 日志中的 trace_id **YB420A34659E-00058BB3C222646D** 来 grep 到完整的 trace 日志，能够看到类似下面的日志：

   $grep YB420A34659E-00058BB3C68E8756 log/rootservice.log
   

   输出结果如下：

   [2019-08-14 17:41:46.722215] INFO [RS] ob_daily_merge_sequence_generator.cpp:529 [56663][YB420A34659E-00058BB3C68E8756] [lt=45] add conflict pair(first=alipay.em14_7, second=alipay.et15_1, same_count=5801)
   [2019-08-14 17:41:46.722273] INFO [RS] ob_daily_merge_sequence_generator.cpp:529 [56663][YB420A34659E-00058BB3C68E8756] [lt=55] add conflict pair(first=alipay.et15_1, second=alipay.em14_7, same_count=5801)
   [2019-08-14 17:41:46.722282] INFO [RS] ob_daily_merge_sequence_generator.cpp:529 [56663][YB420A34659E-00058BB3C68E8756] [lt=8] add conflict pair(first=alipay.su18_6, second=g1.gtj_4, same_count=5801)
   [2019-08-14 17:41:46.722289] INFO [RS] ob_daily_merge_sequence_generator.cpp:529 [56663][YB420A34659E-00058BB3C68E8756] [lt=5] add conflict pair(first=g1.gtj_4, second=alipay.su18_6, same_count=5801)
   [2019-08-14 17:41:46.722295] INFO [RS] ob_daily_merge_sequence_generator.cpp:529 [56663][YB420A34659E-00058BB3C68E8756] [lt=5] add conflict pair(first=ZUI_3, second=, same_count=0)
   [2019-08-14 17:41:46.722302] INFO [RS] ob_daily_merge_sequence_generator.cpp:496 [56663][YB420A34659E-00058BB3C68E8756] [lt=5] daily merge sequence generator rebuild finish(process_time=900988)
   [2019-08-14 17:41:46.722384] INFO [RS] ob_daily_merge_sequence_generator.cpp:317 [56663][YB420A34659E-00058BB3C68E8756] [lt=4] zone is ready to merge by conflict pairs(zone=alipay.et15_1, concurrency_count_=1, to_merge_count=1)
   [2019-08-14 17:41:46.959411] INFO [RS] ob_leader_coordinator.cpp:4569 [56663][YB420A34659E-00058BB3C68E8756] [lt=11] candidate zone infos(candidate_zone_info_array=[{zone:"alipay.et15_1", region_score:0, candidate_count:482}, {zone:"ZUI_3", region_score:9223372036854775807, candidate_count:482}, {zone:"g1.gtj_4", region_score:9223372036854775807, candidate_count:482}, {zone:"alipay.su18_6", region_score:9223372036854775807, candidate_count:482}])
   [2019-08-14 17:41:46.959456] INFO [RS] ob_leader_coordinator.cpp:4055 [56663][YB420A34659E-00058BB3C68E8756] [lt=27] tenant full replica num(tenant_id=1002, full_replica_num=5)
   [2019-08-14 17:41:46.959502] INFO [SHARE] ob_event_history_table_operator.h:236 [56663][YB420A34659E-00058BB3C68E8756] [lt=9] event table add task(ret=0, event_table_name="__all_rootservice_event_history", sql=INSERT INTO __all_rootservice_event_history (gmt_create, module, event, name1, value1, name2, value2, name3, value3, name4, value4, name5, value5, name6, value6, extra_info, rs_svr_ip, rs_svr_port) VALUES (usec_to_time(1565775706959470), 'leader_coordinator', 'check_daily_merge_switch_leader', 'tenant_id', 1002, 'table_id', 1101710651031687, 'partition_id', 0, '', '', '', '', '', '', '"10.190.91.98:2882";"10.213.153.163:2882";"10.248.1.118:2882";"10.52.101.158:2882"', '10.52.101.158', 2882))
   [2019-08-14 17:41:46.975646] INFO [SHARE] ob_event_history_table_operator.h:236 [56663][YB420A34659E-00058BB3C68E8756] [lt=50] event table add task(ret=0, event_table_name="__all_rootservice_event_history", sql=INSERT INTO __all_rootservice_event_history (gmt_create, module, event, name1, value1, name2, value2, name3, value3, name4, value4, name5, value5, name6, value6, extra_info, rs_svr_ip, rs_svr_port) VALUES (usec_to_time(1565775706975610), 'leader_coordinator', 'non_candidate_info', 'tenant_id', 1002, 'table_id', 1101710651031687, 'partition_id', 0, 'server_addr', '"11.146.221.55:2882"', '', '', '', '', 'role:2, is_candidate:0, membership_version:1565764999246796, log_id:18284, locality:0, sys_score:0, is_tenant_active:1, on_revoke_blacklist:0, on_loop_blacklist:0, server_status:2, is_clog_disk_full:0, is_offline:0', '10.52.101.158', 2882))
   [2019-08-14 17:41:46.975717] INFO [RS] ob_leader_coordinator.cpp:4066 [56663][YB420A34659E-00058BB3C68E8756] [lt=23] **partition candidate**(tenant_id=1002, table_id=1101710651031687, partition_id=0, **candidates**=["10.190.91.98:2882", "10.213.153.163:2882", "10.248.1.118:2882", "10.52.101.158:2882"])
   [2019-08-14 17:41:46.976205] ERROR [RS] set_zone_merging (ob_daily_merge_scheduler.cpp:654) [56663][YB420A34659E-00058BB3C68E8756] [lt=12] can't switch leader for daily merge, please check it(zone=alipay.et15_1, fail_time=112) BACKTRACE:0x31471b9 0x30d51d7 0x8b5426 0x8a70ef 0x8ab817 0x8ad5e3 0x8adb70 0x8ae180 0x8aeaac 0x318f3cd 0x318d16e 0x7f65e6faddc5 0x7f65e58eaced
   [2019-08-14 17:41:46.976290] INFO [SHARE] ob_event_history_table_operator.h:236 [56663][YB420A34659E-00058BB3C68E8756] [lt=65] event table add task(ret=0, event_table_name="__all_rootservice_event_history", sql=INSERT INTO __all_rootservice_event_history (gmt_create, module, event, name1, value1, rs_svr_ip, rs_svr_port) VALUES (usec_to_time(1565775706976271), 'daily_merge', 'switch_leader_fail', 'zone', 'alipay.et15_1', '10.52.101.158', 2882))
   [2019-08-14 17:41:46.976332] INFO [RS] ob_daily_merge_scheduler.cpp:543 [56663][YB420A34659E-00058BB3C68E8756] [lt=8] set zone merging(*zone=alipay.et15_1)
   [2019-08-14 17:41:46.976354] INFO [RS] ob_daily_merge_scheduler.cpp:1313 [56663][YB420A34659E-00058BB3C68E8756] [lt=11] switch leader failed, sleep shortly(switch_leader_check_interval_=120000000)
   

3. 分析日志发现 tenant_id=1002, table_id=1101710651031687, partition_id=0 这个分区只有 4 个 candidates，对于 5 副本的场景，预期应该是 5 个 candidates（与 member_list 一致），导致 RS 认为当前无法切主。

4. 如果截止到目前 RS 依然没有执行切主（或依然报上面的错误），就利用上面找到的 pkey 去查询 __all_virtual_election_priority，查看目前是否存在 is_candidate 为 0 的副本，若存在则说明这个副本目前选举优先级不适合做 Leader，至于原因，可以通过其他列信息得出，几个常见的原因如下：

   • server_status != 1：这一列表示该 Server 与 RS 的心跳是否正常，加入某个 Server 被 stop 了，那么该列会不为 1，且该 Server 上的副本都无法当选为 Leader，遇到这种情况，需要将该 Server 拉起。
   • log_id 过小：能够成为 candidate 的条件之一是，该副本上 clog 落后于 Leader 不超过 5000 条，如果超过 5000 条，需要排查该副本为何会落后的原因，如可能发生了回放卡住、内存爆等异常。
   • is_clog_disk_full = 1：表示该副本上 clog 盘已经满了，停写了，无法当主。

5. 如果当前已经恢复，完成了切主，可以联系技术支持排查之前失败的原因。