一次不接受官方建议导致的事故

记录一下
一次Elasticsearch集群事故分析、排查、处理

背景介绍

事故发生的ElasticSearch集群共有7台机器：

10.163.204.193
10.163.204.194
10.163.204.195
10.163.220.73
10.163.220.74
10.163.220.220
10.163.220.221

其中193、194、195的机器配置一样，具体如下：

CPU：32核
内存：128G
磁盘：4T*3

系统盘单独挂载：40G

73、74、220、221的机器配置一样，具体如下：

CPU：32核
内存：128G
磁盘：10T

系统盘单独挂载：50G

以上7台机器用的都是阿里云的高效云盘，https://help.aliyun.com/zh/ecs/user-guide/disks-2
也就是说最大吞吐量(读+写上限)为140MB/s

问题

由于比较穷，所以集群的部署情况比较复杂，这7台机器上共有一个Kafka集群、一个ZooKeeper集群、两个ElasticSearch集群。
其中Kafka、ZooKeeper集群部署在193、194、195上；
两个ElasticSearch集群各有7个节点(也就是这个7台机器每个都有两个ElasticSearch集群的实例)；
193、194、195上的3块盘，Kafka、ZooKeeper、ElasticSearch(2个)集群都在用。

在这次事故之前发生过一次Kafka集群写入延迟，经分析是两个ElasticSearch集群与Kafka集群公用一块磁盘导致磁盘io满，造成Kafka集群集群延迟。

所以将193、194、195上的3块盘的使用调整为：

一块4T的盘单独给Kafka、ZooKeeper使用
另外两块4T的盘两个ElasticSearch集群混用(其中一个ElasticSearch集群的数据量，已经很小了，不到10G，所以可以忽略)

好了，前情回顾已经写完了，下面来说下这次出现的问题：

23号下午5点，ElasticSearch集群挂了
- 集群没有master
25号上午9点，ElasticSearch集群又开始rebalance shards

分析

因为23号的问题很紧急，所以当时采取的方案就是重启整个集群，先恢复。

193上当时没有master的异常日志

{"type": "server", "timestamp": "2023-10-23T09:22:08,955Z", "level": "WARN", "component": "o.e.c.c.ClusterFormationFailureHelper", "cluster.name": "business-log", "node.name": "es-b-193", "message": "master not discovered or elected yet, an election requires at least 4 nodes with ids from [hYrrmhLHTx-QHoDmZ2wATg, jaNLhd1eT6SUYcLJkHpE1Q, 1VQFmt9jQ-6d7fCMjP-vnQ, uzGdH3VeRbOlcDIWeKdgIw, PhjlCea6TNKh4rdZPyPDkA, ZFQdNP4HSgCtPCnMfDdopw, 1WRaRyU-SuCPn8qbz3e4hg], have discovered [{es-b-193}{ZFQdNP4HSgCtPCnMfDdopw}{k0x5Rog-S0CFhAmorJ3V0Q}{10.163.204.193}{10.163.204.193:9301}{cdfhilmrstw}, {es-b-221}{jaNLhd1eT6SUYcLJkHpE1Q}{XkD-b14XQzq1-o3EiDSuKA}{10.163.220.221}{10.163.220.221:9301}{cdfhilmrstw}, {es-b-194}{PhjlCea6TNKh4rdZPyPDkA}{6pQJDRevScad3hr_hJcnTg}{10.163.204.194}{10.163.204.194:9301}{cdfhilmrstw}, {es-b-220}{hYrrmhLHTx-QHoDmZ2wATg}{Qyz9MF2bRmKQq9uPWgTBuw}{10.163.220.220}{10.163.220.220:9301}{cdfhilmrstw}, {es-b-195}{1VQFmt9jQ-6d7fCMjP-vnQ}{e_P2NNXnTIWGzg7vE8EWkA}{10.163.204.195}{10.163.204.195:9301}{cdfhilmrstw}, {es-b-74}{uzGdH3VeRbOlcDIWeKdgIw}{fhNTddq7Syi7zPDVCejDWQ}{10.163.220.74}{10.163.220.74:9301}{cdfhilmrstw}, {es-b-73}{1WRaRyU-SuCPn8qbz3e4hg}{1iRrVMWcSNGGxsuQYxePSg}{10.163.220.73}{10.163.220.73:9301}{cdfhilmrstw}] which is a quorum; discovery will continue using [10.163.204.194:9301, 10.163.204.195:9301] from hosts providers and [{es-b-220}{hYrrmhLHTx-QHoDmZ2wATg}{Qyz9MF2bRmKQq9uPWgTBuw}{10.163.220.220}{10.163.220.220:9301}{cdfhilmrstw}, {es-b-73}{1WRaRyU-SuCPn8qbz3e4hg}{1iRrVMWcSNGGxsuQYxePSg}{10.163.220.73}{10.163.220.73:9301}{cdfhilmrstw}, {es-b-193}{ZFQdNP4HSgCtPCnMfDdopw}{k0x5Rog-S0CFhAmorJ3V0Q}{10.163.204.193}{10.163.204.193:9301}{cdfhilmrstw}, {es-b-74}{uzGdH3VeRbOlcDIWeKdgIw}{fhNTddq7Syi7zPDVCejDWQ}{10.163.220.74}{10.163.220.74:9301}{cdfhilmrstw}, {es-b-194}{PhjlCea6TNKh4rdZPyPDkA}{6pQJDRevScad3hr_hJcnTg}{10.163.204.194}{10.163.204.194:9301}{cdfhilmrstw}, {es-b-221}{jaNLhd1eT6SUYcLJkHpE1Q}{XkD-b14XQzq1-o3EiDSuKA}{10.163.220.221}{10.163.220.221:9301}{cdfhilmrstw}, {es-b-195}{1VQFmt9jQ-6d7fCMjP-vnQ}{e_P2NNXnTIWGzg7vE8EWkA}{10.163.204.195}{10.163.204.195:9301}{cdfhilmrstw}] from last-known cluster state; node term 43, last-accepted version 397615 in term 43", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "ZFQdNP4HSgCtPCnMfDdopw"  }
{"type": "server", "timestamp": "2023-10-23T09:22:11,119Z", "level": "WARN", "component": "r.suppressed", "cluster.name": "business-log", "node.name": "es-b-193", "message": "path: /_cat/nodes, params: {h=ip,name,heap.percent,heap.current,heap.max,ram.percent,ram.current,ram.max,node.role,master,cpu,load_1m,load_5m,load_15m,disk.used_percent,disk.used,disk.total}", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "ZFQdNP4HSgCtPCnMfDdopw" ,


org.elasticsearch.cluster.block.ClusterBlockException: blocked by: [SERVICE_UNAVAILABLE/2/no master];\",\n","stream":"stdout","time":"2023-10-23T09:21:34.490903538Z"}
{"log":"\"at org.elasticsearch.cluster.block.ClusterBlocks.globalBlockedException(ClusterBlocks.java:179

恢复后，排查日志，主要看到的现象就是193节点频繁的added、removed

added {{es-b-193}{ZFQdNP4HSgCtPCnMfDdopw}{k0x5Rog-S0CFhAmorJ3V0Q}{10.163.204.193}{10.163.204.193:9301}{cdfhilmrstw}}, term: 43, version: 397620, reason: ApplyCommitRequest{term=43, version=397620, sourceNode={es-b-73}{1WRaRyU-SuCPn8qbz3e4hg}{1iRrVMWcSNGGxsuQYxePSg}{10.163.220.73}{10.163.220.73:9301}{cdfhilmrstw}{ml.machine_memory=133070966784, ml.max_open_jobs=512, xpack.installed=true, ml.max_jvm_size=33285996544, transform.node=true}}

removed {{es-b-193}{ZFQdNP4HSgCtPCnMfDdopw}{k0x5Rog-S0CFhAmorJ3V0Q}{10.163.204.193}{10.163.204.193:9301}{cdfhilmrstw}}, term: 43, version: 397621, reason: ApplyCommitRequest{term=43, version=397621, sourceNode={es-b-73}{1WRaRyU-SuCPn8qbz3e4hg}{1iRrVMWcSNGGxsuQYxePSg}{10.163.220.73}{10.163.220.73:9301}{cdfhilmrstw}{ml.machine_memory=133070966784, ml.max_open_jobs=512, xpack.installed=true, ml.max_jvm_size=33285996544, transform.node=true}}

导致193上的shard一直rebalance。但193上日志，不知道什么原因丢失了，能找到的最早的日志也是23号下午5点21分之后的日志了。经过日志排查问题到这里被卡主了。

回看发生问题前的一段时间各个节点的监控，CPU、内存、磁盘、写入量等都没有异常的波动，唯一发现的一个异常：

在这里插入图片描述

那么generic thread pool是做啥的呢？

=> 用于通用操作（例如，后台节点发现）它的线程池类型是动态缩放的

到这里也只是能印证了，节点间相互发现有问题。那么到底什么原因造成的集群宕机呢？

时间来到了今天上午也就是25号9点左右的时候，发现集群又开始rebalance shards，通过

GET /_cat/shards?h=index,shard,prirep,state,unassigned.reason

可以看到shard重新迁移的原因是node-left,到master节点的机器看下日志：

root@jiankunking-es-02:~# docker logs -f 1f741600dbcc |grep node-left
{"type": "server", "timestamp": "2023-10-23T09:33:18,042Z", "level": "INFO", "component": "o.e.c.s.MasterService", "cluster.name": "business-log", "node.name": "es-b-194", "message": "node-left[{es-b-221}{jaNLhd1eT6SUYcLJkHpE1Q}{XkD-b14XQzq1-o3EiDSuKA}{10.163.220.221}{10.163.220.221:9301}{cdfhilmrstw} reason: disconnected], term: 52, version: 399161, delta: removed {{es-b-221}{jaNLhd1eT6SUYcLJkHpE1Q}{XkD-b14XQzq1-o3EiDSuKA}{10.163.220.221}{10.163.220.221:9301}{cdfhilmrstw}}", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "PhjlCea6TNKh4rdZPyPDkA"  }
{"type": "server", "timestamp": "2023-10-25T01:52:35,140Z", "level": "INFO", "component": "o.e.c.s.MasterService", "cluster.name": "business-log", "node.name": "es-b-194", "message": "node-left[{es-b-193}{ZFQdNP4HSgCtPCnMfDdopw}{PPAowFAWQRiI9s5FoaDxWQ}{10.163.204.193}{10.163.204.193:9301}{cdfhilmrstw} reason: followers check retry count exceeded], term: 52, version: 404805, delta: removed {{es-b-193}{ZFQdNP4HSgCtPCnMfDdopw}{PPAowFAWQRiI9s5FoaDxWQ}{10.163.204.193}{10.163.204.193:9301}{cdfhilmrstw}}", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "PhjlCea6TNKh4rdZPyPDkA"  }
{"type": "server", "timestamp": "2023-10-25T01:53:24,564Z", "level": "INFO", "component": "o.e.c.s.MasterService", "cluster.name": "business-log", "node.name": "es-b-194", "message": "node-left[{es-b-193}{ZFQdNP4HSgCtPCnMfDdopw}{PPAowFAWQRiI9s5FoaDxWQ}{10.163.204.193}{10.163.204.193:9301}{cdfhilmrstw} reason: disconnected], term: 52, version: 404807, delta: removed {{es-b-193}{ZFQdNP4HSgCtPCnMfDdopw}{PPAowFAWQRiI9s5FoaDxWQ}{10.163.204.193}{10.163.204.193:9301}{cdfhilmrstw}}", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "PhjlCea6TNKh4rdZPyPDkA"  }
{"type": "server", "timestamp": "2023-10-25T01:53:30,879Z", "level": "INFO", "component": "o.e.c.s.MasterService", "cluster.name": "business-log", "node.name": "es-b-194", "message": "node-left[{es-b-193}{ZFQdNP4HSgCtPCnMfDdopw}{PPAowFAWQRiI9s5FoaDxWQ}{10.163.204.193}{10.163.204.193:9301}{cdfhilmrstw} reason: disconnected], term: 52, version: 404810, delta: removed {{es-b-193}{ZFQdNP4HSgCtPCnMfDdopw}{PPAowFAWQRiI9s5FoaDxWQ}{10.163.204.193}{10.163.204.193:9301}{cdfhilmrstw}}", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "PhjlCea6TNKh4rdZPyPDkA"  }

按理说 193 194 195这些机器与另外4台机器相比，区别点在于挂了多块盘，那性能应该更好啊，为啥连不上的会是他们呢？

又回看了下节点日志，发现节点间互连存在大量的超时

master(194)节点日志：

{"type": "server", "timestamp": "2023-10-25T01:35:18,510Z", "level": "WARN", "component": "o.e.t.OutboundHandler", "cluster.name": "business-log", "node.name": "es-b-194", "message": "sending transport message [MessageSerializer{Request{indices:data/write/bulk[s][r]}{70758574}{false}{false}{false}}] of size [21075] on [Netty4TcpChannel{localAddress=/10.163.204.194:57580, remoteAddress=10.163.204.193/10.163.204.193:9301, profile=default}] took [29403ms] which is above the warn threshold of [5000ms]", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "PhjlCea6TNKh4rdZPyPDkA"  }
{"type": "server", "timestamp": "2023-10-25T01:35:18,510Z", "level": "WARN", "component": "o.e.t.OutboundHandler", "cluster.name": "business-log", "node.name": "es-b-194", "message": "sending transport message [MessageSerializer{Request{indices:data/write/bulk[s]}{70758608}{false}{false}{false}}] of size [1992] on [Netty4TcpChannel{localAddress=/10.163.204.194:57580, remoteAddress=10.163.204.193/10.163.204.193:9301, profile=default}] took [29403ms] which is above the warn threshold of [5000ms]", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "PhjlCea6TNKh4rdZPyPDkA"  }
{"type": "server", "timestamp": "2023-10-25T01:35:18,510Z", "level": "WARN", "component": "o.e.t.OutboundHandler", "cluster.name": "business-log", "node.name": "es-b-194", "message": "sending transport message [MessageSerializer{Request{indices:data/write/bulk[s]}{70758614}{false}{false}{false}}] of size [5563] on [Netty4TcpChannel{localAddress=/10.163.204.194:57580, remoteAddress=10.163.204.193/10.163.204.193:9301, profile=default}] took [29403ms] which is above the warn threshold of [5000ms]", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "PhjlCea6TNKh4rdZPyPDkA"  }
{"type": "server", "timestamp": "2023-10-25T01:35:18,510Z", "level": "WARN", "component": "o.e.t.OutboundHandler", "cluster.name": "business-log", "node.name": "es-b-194", "message": "sending transport message [MessageSerializer{Request{indices:data/write/bulk[s][r]}{70758686}{false}{false}{false}}] of size [9103] on [Netty4TcpChannel{localAddress=/10.163.204.194:57580, remoteAddress=10.163.204.193/10.163.204.193:9301, profile=default}] took [28603ms] which is above the warn threshold of [5000ms]", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "PhjlCea6TNKh4rdZPyPDkA"  }
{"type": "server", "timestamp": "2023-10-25T01:35:18,510Z", "level": "WARN", "component": "o.e.t.OutboundHandler", "cluster.name": "business-log", "node.name": "es-b-194", "message": "sending transport message [MessageSerializer{Request{indices:data/write/bulk[s][r]}{70758737}{false}{false}{false}}] of size [12666] on [Netty4TcpChannel{localAddress=/10.163.204.194:57580, remoteAddress=10.163.204.193/10.163.204.193:9301, profile=default}] took [28603ms] which is above the warn threshold of [5000ms]", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "PhjlCea6TNKh4rdZPyPDkA"  }

普通节点(193)

{"type": "server", "timestamp": "2023-10-25T01:34:46,866Z", "level": "WARN", "component": "o.e.t.OutboundHandler", "cluster.name": "business-log", "node.name": "es-b-193", "message": "sending transport message [MessageSerializer{Request{indices:data/write/bulk[s]}{73855747}{false}{false}{false}}] of size [3828] on [Netty4TcpChannel{localAddress=/10.163..204.193:38616, remoteAddress=10.163.220.221/10.163.220.221:9301, profile=default}] took [35027ms] which is above the warn threshold of [5000ms]", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "ZFQdNP4HSgCtPCnMfDdopw"  }
{"type": "server", "timestamp": "2023-10-25T01:34:46,866Z", "level": "WARN", "component": "o.e.t.OutboundHandler", "cluster.name": "business-log", "node.name": "es-b-193", "message": "sending transport message [MessageSerializer{Request{indices:data/write/bulk[s]}{73855763}{false}{false}{false}}] of size [14563] on [Netty4TcpChannel{localAddress=/10.163.204.193:38616, remoteAddress=10.163.220.221/10.163.220.221:9301, profile=default}] took [35027ms] which is above the warn threshold of [5000ms]", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "ZFQdNP4HSgCtPCnMfDdopw"  }
{"type": "server", "timestamp": "2023-10-25T01:34:46,866Z", "level": "WARN", "component": "o.e.t.OutboundHandler", "cluster.name": "business-log", "node.name": "es-b-193", "message": "sending transport message [MessageSerializer{Request{indices:data/write/bulk[s]}{73855795}{false}{false}{false}}] of size [12940] on [Netty4TcpChannel{localAddress=/10.163.204.193:38616, remoteAddress=10.163.220.221/10.163.220.221:9301, profile=default}] took [35027ms] which is above the warn threshold of [5000ms]", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "ZFQdNP4HSgCtPCnMfDdopw"  }
{"type": "server", "timestamp": "2023-10-25T01:34:46,866Z", "level": "WARN", "component": "o.e.t.OutboundHandler", "cluster.name": "business-log", "node.name": "es-b-193", "message": "sending transport message [MessageSerializer{Request{indices:data/write/bulk[s][r]}{73855813}{false}{false}{false}}] of size [10721] on [Netty4TcpChannel{localAddress=/10.163.204.193:38616, remoteAddress=10.163.220.221/10.163.220.221:9301, profile=default}] took [35027ms] which is above the warn threshold of [5000ms]", "cluster.uuid": "ArYy-qmCTbCQTDUI8ogsBg", "node.id": "ZFQdNP4HSgCtPCnMfDdopw"  }

看到到这里难道是网络或者网卡打满了？

看下带宽Bandwidth:

root@jiankunking-es-02:~# ethtool eth0 | grep Speed
        Speed: Unknown!
root@jiankunking-es-02:~#

再看下网卡实时流量

iftop -n

在这里插入图片描述

找负责机器的同事核对，得到以下信息

瓶颈是按照网卡上限看，不看两个服务器之间链路 =>也就是服务器间的网络带宽应该是远大于机器网卡的，所以服务器的网卡更容易成为瓶颈
服务器网卡上限是:内网带宽(bit/s) 10.00Gpbs=>也就是服务器网卡总流量的上限是 10/8 大约是1G的流量

同时要了下阿里云的监控图

在这里插入图片描述

从阿里云的监控可以判断出这时候网卡并没有满的(进+出，也就能到阈值10%的样子),我们再看下23号傍晚的阿里云监控

在这里插入图片描述

这里的要注意下，对于阿里云来说，比如网卡有阈值，但短时间阿里云是允许突破限制的(虽然这里并没有满)

既然网络没有问题，那问题出在哪？

算了，找一个节点频繁added remove的时间在master(193)上抓包一下

在这里插入图片描述

从抓包中可以看出以下信息：

网络连接正常，建立连接–发送数据–连接关闭
是master节点主动断开的连接

但是master节点为什么断开的连接，就不清楚了。追查到这里，感觉问题应该不是在网络还是es自身哪里出了问题。

继续一顿Google，找到了这么一个issue:https://github.com/elastic/elasticsearch/issues/67873

虽然各种异常提示都不太一样，但现象是一样的

在这里插入图片描述

在issue中发现shard数太多会对于集群造成一些不利的影响。

我们回看了下集群shard监控
在这里插入图片描述

发现shard数一直在增加，整个集群已经到达6w+。要不我们也删除部分历史索引试试？

这时候74节点一直在added removed，我手动重启了74节点，并将尝试将7、8月份的索引删除，集群逐步恢复到70%+的时候，又有节点下线了；

我们再次尝试删除9月份加10月份1号-6号的索引，这时候集群恢复成功了（这时候集群shard数已经从6w降到了4w）。

问题暂时得到了处理，观察一段时间再没有发现node-left的情况，但根本原因并没有找到。（比如23号重启集群后，shard数也是接近6w,但也重启成功了，但25号却一直没有成功）。

如果大家有这方面的资料或者最佳实践，欢迎留言。

小结

经过这件事之后，我最大的一个感触就是官方的推荐值还是要参考一下：
Elasticsearch 集群内应该设置多少个分片(shard)？

主要是因为要控制成本所以只要集群不出问题，官方的建议，我们一般是这么个态度：

在这里插入图片描述

其实对于shard大小跟每个节点推荐的数据量一样，我们都没有接受他们的建议。比如这次排查为什么没有怀疑过30T数据量太多呢？因为之前都是40T+。
在这里插入图片描述

其实经过这件事，还有以下几个点想分享一下

各种集群间应该资源隔离，也就是机器不要共用
不要在各种边缘上运行
- 比如我们es的磁盘其实一直就是瓶颈，只要触发rebalance shards，磁盘io一定是满的，就会导致写入速率下降等各种问题
集群内各个相同功能的节点配置要一样，比如我们的es集群，磁盘大小不一样，当到达磁盘阈值的时候，集群负载就会不均衡

一次不接受官方建议导致的事故

背景介绍

问题

分析

小结

相关文章

Boris FX Mocha Pro 2023：Mac/win全能影像处理神器

医院安全（不良）事件管理系统源代码（B/S架构）：事件全程监管质量持续改进

三、【常用的几种抠图方式二】

conda 实践

手把手教你入门Three.js（初识篇）

题解_notion(持续更新ing)

8年经验之谈 —— Redis的性能测试与优化！

ae如何去除视频水印？分享三个简单的方法！

NUUO摄像头远程命令执行漏洞复现 [附POC]

如何用个人数据Milvus Cloud知识库构建 RAG 聊天机器人？（上）

Spring MVC 中文文档

target采退、测评养号购物下单操作教程

ELK学习（一）

PDFgear——一款接入AI智能化模型的免费PDF聊天软件

Hadoop学习总结（搭建Hadoop集群(伪分布式模式)）

JS防抖与节流(含实例各二种写法介绍原理)

美摄AI商品图解决方案

C语言KR圣经笔记 2.7类型转换

如何用.bat文件直接安装jar包

深入理解数据结构（2）——用数组实现队列