一次ES集群重启引发的灾难
背景
目前我们生产环境自建了一套 ELK 日志数据采集展示平台。平台采集了应用日志数据、模块调用链数据，部分组件监控数据，并通过 kibana 创建视图看板，监控线上应用状态。生产部署架构如下，其中 ES 集群由双机房 6 台物理机节点组成。这里需要使用自签名的 SSL 证书对集群数据加固，证书 host 与 IP 绑定，就没有部署单机多实例。
以上是集群部署情况，事件背景是在一次 ES 集群发布过程中，批量重启了集群中所有节点。重启之后集群状态不可用，应用访问集群持续报错。对开发及运维同事查看应用日志，监控线上系统状态带来很严重的影响。
排查过程
分析日志
遇到问题首先看 ES 集群中节点服务日志，登录线上节点机器，查看集群部分节点报错日志如下。
[WARN][r.suppressed] [node6] path: /_monitoring/bulk, params:{system_id=logstash, system_api_version=7, interval=1s}
org.elasticsearch.cluster.block.ClusterBlockException: blocked by:[SERVICE_UNAVAILABLE/2/no master];通过分析集群节点日志可以看到，首先应用数据无法写入是由于集群没有主节点导致集群服务不可用，数据无法写入。具体无法选出主节点的原因又有以下一些报错 :
[INFO ][o.e.c.c.JoinHelper] [node6] failed to join {node5}{Tbvl2t0DQYSxm5mFxYz4pw}{JgBGUVetTJCqTQ3ZN_yxVg}{node5.elastic.com}{10.128.132.12:9600}{dilm}{ml.machine_memory=201123762176, ml.max_open_jobs=20, xpack.installed=true} with JoinRequest{sourceNode={node6}{J771EigpSKWMdGrtwfEYPQ}{_0Z4H4f6QOmMK64Kp0NzkQ}{node6.elastic.com}{10.128.132.13:9600}{dilm}{ml.machine_memory=201123770368, xpack.installed=true, ml.max_open_jobs=20}, optionalJoin=Optional[Join{term=4150, lastAcceptedTerm=4148, lastAcceptedVersion=42267, sourceNode={node6}{J771EigpSKWMdGrtwfEYPQ}{_0Z4H4f6QOmMK64Kp0NzkQ}{node6.elastic.com}{10.128.132.13:9600}{dilm}{ml.machine_memory=201123770368, xpack.installed=true, ml.max_open_jobs=20}, targetNode={node5}{Tbvl2t0DQYSxm5mFxYz4pw}{JgBGUVetTJCqTQ3ZN_yxVg}{node5.elastic.com}{10.128.132.12:9600}{dilm}{ml.machine_memory=201123762176, ml.max_open_jobs=20, xpack.installed=true}}]}
org.elasticsearch.transport.RemoteTransportException: [node5][10.128.132.12:9600 [internal:cluster/coordination/join]
Caused by: org.elasticsearch.cluster.coordination.CoordinationStateRejectedException: incoming term 4150 does not match current term 4152[INFO ][o.e.c.c.JoinHelper] [node6] failed to join {node2}{lOAG1R-LSsSpJxsFT-yChw}{loMY8rBdRZmKWyRZKcHrDg}{node2.elastic.com}{10.128.4.29:9600}{dilm}{ml.machine_memory=201088536576, ml.max_open_jobs=20, xpack.installed=true} with JoinRequest{sourceNode={node6}{J771EigpSKWMdGrtwfEYPQ}{_0Z4H4f6QOmMK64Kp0NzkQ}{node6.elastic.com}{10.128.132.13:9600}{dilm}{ml.machine_memory=201123770368, xpack.installed=true, ml.max_open_jobs=20}, optionalJoin=Optional[Join{term=4149, lastAcceptedTerm=4148, lastAcceptedVersion=42267, sourceNode={node6}{J771EigpSKWMdGrtwfEYPQ}{_0Z4H4f6QOmMK64Kp0NzkQ}{node6.elastic.com}{10.128.132.13:9600}{dilm}{ml.machine_memory=201123770368, xpack.installed=true, ml.max_open_jobs=20}, targetNode={node2}{lOAG1R-LSsSpJxsFT-yChw}{loMY8rBdRZmKWyRZKcHrDg}{node2.elastic.com}{10.128.4.29:9600}{dilm}{ml.machine_memory=201088536576, ml.max_open_jobs=20, xpack.installed=true}}]}
org.elasticsearch.transport.RemoteTransportException: [node2][10.128.4.29:9600][internal:cluster/coordination/join]
Caused by: org.elasticsearch.cluster.coordination.FailedToCommitClusterStateException: node is no longer master for term 4149 while handling publication[INFO ][o.e.c.c.JoinHelper] [node3] failed to join {node4}{6ADTDv1eTW28_mf9zEGwyg}{KlPl2EmbQ523CkCCHR7IbA}{node4.elastic.com}{10.128.132.10:9600}{dilm}{ml.machine_memory=201111511040, ml.max_open_jobs=20, xpack.installed=true} with JoinRequest{sourceNode={node3}{Kf3xB4F3RIOKsh5_iVyE0w}{etewxY1FTgiivoIFT6vqPw}{node3.elastic.com}{10.128.4.43:9600}{dilm}{ml.machine_memory=201088536576, xpack.installed=true, ml.max_open_jobs=20}, optionalJoin=Optional[Join{term=34, lastAcceptedTerm=0, lastAcceptedVersion=0, sourceNode={node3}{Kf3xB4F3RIOKsh5_iVyE0w}{etewxY1FTgiivoIFT6vqPw}{node3.elastic.com}{10.128.4.43:9600}{dilm}{ml.machine_memory=201088536576, xpack.installed=true, ml.max_open_jobs=20}, targetNode={node4}{6ADTDv1eTW28_mf9zEGwyg}{KlPl2EmbQ523CkCCHR7IbA}{node4.elastic.com}{10.128.132.10:9600}{dilm}{ml.machine_memory=201111511040, ml.max_open_jobs=20, xpack.installed=true}}]}
org.elasticsearch.transport.ReceiveTimeoutTransportException: [node4][10.128.132.10:9600][internal:cluster/coordination/join] request_id [346] timed out after [60042ms]从日志内容来看是集群选出了其中一台节点( node2 或者 node5 )作为主节点，但是其他节点( node6 )在加入集群过程中报错了，报错原因是选出来的主节点( node2 )在某一任期( 4149 )不再是主节点，或者新加入的节点( node6 )任期( 4150 )与当前集群任期( 4152 )不匹配，又或者节点加入集群的某一请求超时。
我想大部分同学在看到这个报错日志和我一样，报错真多，同时一脸懵逼，这都是啥和啥呀。
查看源码
因为日志里有具体程序报错的堆栈信息，我们部署的是开源社区版本，这里下载 ES 源码先大致分析下是哪里的报错以及集群选主的过程中做了哪些操作。
- incoming term 4150 does not match current term 4152.
首先，查阅其他相关资料可以将 join 请求理解为集群选举投票操作。上面可以看到，在 handleJoin 方法中，首先会校验集群中发起投票节点的任期，目前是集群中某一节点发起投票的任期 (join.getTerm():4150) 与集群内存保存的任 (getCurrentTerm():4152)不匹配，这里可以看到 4150 明显是 2 个任期之前的投票，导致节点发起集群投票请求失败。
- node is no longer master for term 4149 while handling publication.
选举产生的 master 节点在发布集群状态变更时失败，当前内存中集群的任期 (getCurrentTerm()) 已经不等于发布事件的任期(clusterChangedEvent.state().term())，该节点已经不再是主节点了。
- request_id 346 timed out after 60042ms
这里应该是处理节点 join 请求超时了，可以通过 cluster.join.timeout 这个参数来调整节点发送 join 请求之后的超时时间，默认是 60s。这个配置我们没有修改，但是 ES 集群这个配置一般不用修改，算是开箱即用的配置，一般请求发送出去 60s 的处理时间应该也够了，除非网络访问有问题，但是我们此次发布没有网络变更，并且机器之间相互ping也没有超时。
集群选举流程
通过以上源码只能大概定位到是哪里报错了，基本上都和集群任期 term 有关。这里还是要继续分析节点重启之后集群主节点的选举过程。ES 在 7.0 之后基于 raft 分布式共识算法重新实现了集群选举的算法，新增了 coordination 包，主要任务就是实现集群选举，新的选举算法大致如下
- 首先，节点在选举过程中有三种状态， CANDIDATE，LEADER，FOLLOWER 枚举值
public enum Mode {
CANDIDATE,LEADER,FOLLOWER- 在 node 节点启动之后会初始化为 CANDIDATE，调用 peerFinder.activate 方法发现其他节点
void becomeCandidate(String method) {
assert Thread.holdsLock(mutex) : "Coordinator mutex not held";
logger.debug("{}: coordinator becoming CANDIDATE in term {} (was {}, lastKnownLeader was [{}])", method, getCurrentTerm(), mode, lastKnownLeader);
if (mode != Mode.CANDIDATE) {
final Mode prevMode = mode;
mode = Mode.CANDIDATE;
cancelActivePublication("become candidate: " + method);
joinAccumulator.close(mode);
joinAccumulator = joinHelper.new CandidateJoinAccumulator();
// 发现其他节点, 发起投票请求
peerFinder.activate(coordinationState.get().getLastAcceptedState().nodes());
clusterFormationFailureHelper.start();
if (getCurrentTerm() == ZEN1_BWC_TERM) {
discoveryUpgradeService.activate(lastKnownLeader, coordinationState.get().getLastAcceptedState());
}
leaderChecker.setCurrentNodes(DiscoveryNodes.EMPTY_NODES);
leaderChecker.updateLeader(null);
followersChecker.clearCurrentNodes();
followersChecker.updateFastResponseState(getCurrentTerm(), mode);
lagDetector.clearTrackedNodes();
if (prevMode == Mode.LEADER) {
cleanMasterService();
}
if (applierState.nodes().getMasterNodeId() != null) {
applierState = clusterStateWithNoMasterBlock(applierState);
clusterApplier.onNewClusterState("becoming candidate: " + method, () -> applierState, (source, e) -> {
});
}
}
preVoteCollector.update(getPreVoteResponse(), null);
}- 如果 discovery 发现集群已经存在 LEADER，则直接加入集群，切换到 FOLLOWER 状态，这里我们集群中的节点是批量重启的，当前一开始还未选出 master 节点。
- 如果 CANDIDATE 收到足够的投票，则转换为 LEADER，如何判断是否收到足够的投票，这里有具体的算法
public boolean hasQuorum(Collection<String> votes) {
final HashSet<String> intersection = new HashSet<>(nodeIds);
intersection.retainAll(votes);
return intersection.size() * 2 > nodeIds.size();//收到的选票大于集群中的半数节点
}整个节点状态切换流程如下：
这里可以看到 discovery 的 join 有两种模式，ZenDiscovery 是 7.0 以前的选举模式，算法相对简单，没有任期概念，只要某一节点获得的选票大于半数即可为主节点，选举时间较长。新增的集群协调层 Coordinator 基于 Raft 算法，引入任期 term，选举耗时为纳秒级。两种选举模式可以通过节点配置 discovery.type 来设置。
上面两张图也可以看到，集群选举的几乎所有方法都是串行同步的，保证多线程操作安全。而集群的 term 是集群的元数据记录在磁盘一个global-0.st 的文件中的。当请求量大的时候有可能会有线程阻塞。
分析线程状态
经过以上分析，大致可以确定是节点在回复其他节点选举投票或者其他请求慢了，导致超时。那么到底是什么原因导致节点处理请求这么慢呢。这时，就需要用到 jstack 工具了，查看集群中节点线程运行的任务状态。经过多次 jstack，其中有两次 jstack 中间时间间隔 10min，发现有大量线程 block 在 updateMaxTermSeen 这个方法，这个方法需要将集群最大任期更新到集群的元数据中。
elasticsearch[node4][generic][T#314]" #678 daemon prio =5 os_prio=0 tid=0x00000000172b647a0 nid=0x5f00e waiting for monitor entry
java.lang.Thread.State: BLOCKED (on object monitor)
at org.elasticsearch.cluster.coordination.Coordinator.updateMaxTermSeen(Coordinator.java:367)
- waiting to lock <0x00007f7b3c1010000> (a java.lang.Object)
....而这个方法 wating 的对象是 fsync 函数
elasticsearch[node4][generic][T#11]" #375 daemon prio =5 os_prio=0 tid=0x00007f7b3c1010000 nid=0x5f00e
java.lang.Thread.State: RUNNABLE
at sun ...
at sun ...
at sun ...
at org.apache.lucene.util.IOUtils.fsync(IOUtils.java:471)
...fsync 函数不同于 sync 将数据缓冲区排入写队列，而是直接通过 fd 文件句柄同步刷盘写。我们还一度以为是磁盘故障，导致线程卡住。使用 DD 工具对机器磁盘磁道检测，结果发现磁盘读写完全正常，写操作超过1G/s，读操作超过3G/s。
前面可以看到集群选举的方法都是同步操作的，必须保证元数据成功更新才会释放对象锁。当更新元数据线程卡住之后，某一节点发起的投票请求响应超时，导致该节点不断重试，继续发起投票请求，集群 term 持续增长。
集群数据恢复流程
这里还有另一个重要信息：集群是批量重启的，并非按节点滚动重启。节点重启之后要加载索引的分片数据，保证恢复集群中的数据，也就是 shard allocation 与上面的节点选举是同时进行的。shard allocation 会对集群中未分配的分片进行处理。
allocateUnassigned 的流程需要遍历所有 unassigned shard 依次处理，先选出索引主分片，再同步副本分片，通过 decider 决策分配，期间可能需要 fetchData 获取这个 shard 对应的元数据。如果决策结果为 YES，就将其初始化
这里根据我们目前使用场景，当前集群的分片数据也是非常多的。我们是根据系统模块维度每天创建索引，而且每个索引都是设置的 2 分片 1 副本，单个索引就有 4 个分片，并且数据未做归档处理，保存了近1年半的数据。在集群重启之前，集群分片数大约在 1.8w 左右，平均每个节点分片数高达 3k，远超官方推荐的单节点分片数不超过 1k。
确定问题
通过以上一些关键信息分析，这里目前有可能存在两个问题，
- 集群元数据更新线程卡住导致选举请求超时，节点不断发起选举重试，进一步增加了处理请求的压力。
- 集群未分配分片过多，导致 allocateUnassigned 请求量过大，也加大了集群数据更新的压力。
解决方案
确定了问题，我们就可以“对症下药”，这里目前的解决方案是
- 清理历史数据
因为集群大部份是应用日志数据，对于很久以前的历史数据可以直接清理。但是集群此时还是不可用状态，只能通过已有的集群元数据找到历史索引 id 对应的物理文件夹，将其移动到备份文件目录中。 - 元数据异步刷盘
因为腾讯云同事之前云上有遇到相关案例，腾讯云自研 ES 版本中，将元数据刷盘改为了异步操作。这里直接使用腾讯云自研 ES 代码包替换线上集群，并且开启异步刷盘配置。 - 删除集群元数据
删除集群元数据，重置集群当前 term，保证集群重新开始选举，最后重启集群
后续优化
规范集群重启过程
集群重启流程规范化，按照步骤依次滚动重启集群节点，先关闭集群分片路由，通过设置 cluster.routing.allocation.enable":"none"，这样可以在集群重启过程尽量中不产生 allocateUnassigned 请求，减少集群 IO 操作。待节点重启完之后再开启分片路由。
数据归档
通过 ilm template 设置索引生命周期，对于一些历史数据可以及时从集群中清理，减少集群分片压力
按周创建索引
目前按照天创建索引导致很多索引单分片大小不大，有些索引一天可能也就几千条数据量，分片大小不到 1 g，容易造成集群分片碎片化，俗话说 “乱拳打死老师傅”，这些小的分片量大起来了很容易造成集群IO压力。
建立索引模板
索引模板是很好管理索引mapping的手段，可以防止索引字段膨胀。数据量不大索引单分片单副本完全够用，需要根据索引数据量合理设置分片数。另外，副本数可以动态修改，但是索引一旦建立，分片数就不可以更改，除非重新 reindex.
数据定时备份
定时快照通过 ES SLM(Manage the snapshot lifecycle) 定时任务创建快照定时备份，将重要数据备份到 COS 云资源上
PUT /_slm/policy/nightly-snapshots
{
"schedule": "0 0 19 * * ?",
"name": "<vb-es-snap-{now/d}>",
"repository": "es_cos_backup",
"config": {
"indices": ["*"]
},
"retention": {
"expire_after": "30d",
"min_count": 5,
"max_count": 50
}
}
# 每天国际时间19点(北京时间凌晨3点)执行 snapshot 任务，快照30天有效，最少5张，最多50张经过以上一些优化措施后，集群总分片数常态化维持在 1.9k 左右，相对未归档前分片数下降了近 10 倍。期间，修复 ES 日志漏洞，机器更新系统补丁，物理机更新内存条等操作对集群多次重启都未发生故障。
总结
这篇文章记录了一次 ES 集群重启后，集群无法选主的问题。当时出现问题的时候由于自己对集群选举流程不清晰，看了很多相关的文章，请腾讯云同事一起排查了近一周时间。现在回看起来还是很感谢腾讯云的一些 ES 研发同学，感谢他们专业的知识以及无私的精神，后续遇到问题还是要深入地多想多实践多总结。
参考资料
