前言
目前Push小组推送文章时使用的Storm、Hadoop和HBase等基础设施都是由其小组自己维护，连续两周周末都出现了实时计算集群崩溃的情况，个别机器分配到Storm Worker后会出现无法连接其他机器的提示。考虑到由于计算资源紧张，其Storm集群由A和B两个DC服务器构成，而且Push小组的集群中部署有Mesos/Marathon/Docker/HDFS/HBase等众多组件，问题查起来比较费劲，为此首先联系了公司运维帮忙查看两个机房之间网络和带宽情况，得到的反馈是没有问题，但是某一台机器TIME_WAIT居然可以到21万。
顺藤摸瓜
除了上述信息外，运维还透露了一下TIME_WAIT较多的机器ip和端口为10.12.6.6并且端口为50010，除了Storm日志中呈现的其他服务器无法连接该台服务器外，隐约记得Push组同学说起该IP上部署有DataNode且当天掉线了一次(没有保留好原始日志，暂时不呈现)，于是登录到服务器上面进行问题确认。首先检查磁盘，内存，负载等常见指标：
[mesos@10.12.6.6 ~]$ df -hT
文件系统 类型 容量 已用 可用 已用% 挂载点
/dev/sda2 xfs 275G 23G 252G 9% /
devtmpfs devtmpfs 63G 0 63G 0% /dev
tmpfs tmpfs 63G 8.0K 63G 1% /dev/shm
tmpfs tmpfs 63G 4.0G 59G 7% /run
tmpfs tmpfs 63G 0 63G 0% /sys/fs/cgroup
/dev/sdj1 xfs 745G 6.4G 739G 1% /ssd9
/dev/sdd1 xfs 745G 9.5G 736G 2% /ssd3
/dev/sdi1 xfs 745G 11G 735G 2% /ssd8
/dev/sdl1 xfs 745G 8.0G 737G 2% /ssd11
/dev/sdm1 xfs 745G 8.7G 737G 2% /ssd12
/dev/sdc1 xfs 745G 8.9G 736G 2% /ssd2
/dev/sdb1 xfs 745G 9.3G 736G 2% /ssd1
/dev/sdk1 xfs 745G 10G 735G 2% /ssd10
/dev/sdh1 xfs 745G 11G 735G 2% /ssd7
/dev/sde1 xfs 745G 14G 732G 2% /ssd4
/dev/sdf1 xfs 745G 11G 735G 2% /ssd5
/dev/sdg1 xfs 745G 11G 734G 2% /ssd6
/dev/sda1 xfs 797M 165M 632M 21% /boot
tmpfs tmpfs 13G 0 13G 0% /run/user/0
cm_processes tmpfs 63G 76M 63G 1% /run/cloudera-scm-agent/process
tmpfs tmpfs 13G 0 13G 0% /run/user/1000
tmpfs tmpfs 13G 0 13G 0% /run/user/10261
tmpfs tmpfs 13G 0 13G 0% /run/user/1001
[mesos@10.12.6.6 ~]$ df -hT
文件系统 类型 容量 已用 可用 已用% 挂载点
/dev/sda2 xfs 275G 23G 252G 9% /
devtmpfs devtmpfs 63G 0 63G 0% /dev
tmpfs tmpfs 63G 8.0K 63G 1% /dev/shm
tmpfs tmpfs 63G 4.0G 59G 7% /run
tmpfs tmpfs 63G 0 63G 0% /sys/fs/cgroup
/dev/sdj1 xfs 745G 6.4G 739G 1% /ssd9
/dev/sdd1 xfs 745G 9.5G 736G 2% /ssd3
/dev/sdi1 xfs 745G 11G 735G 2% /ssd8
/dev/sdl1 xfs 745G 8.0G 737G 2% /ssd11
/dev/sdm1 xfs 745G 8.7G 737G 2% /ssd12
/dev/sdc1 xfs 745G 8.9G 736G 2% /ssd2
/dev/sdb1 xfs 745G 9.3G 736G 2% /ssd1
/dev/sdk1 xfs 745G 10G 735G 2% /ssd10
/dev/sdh1 xfs 745G 11G 735G 2% /ssd7
/dev/sde1 xfs 745G 14G 732G 2% /ssd4
/dev/sdf1 xfs 745G 11G 735G 2% /ssd5
/dev/sdg1 xfs 745G 11G 734G 2% /ssd6
/dev/sda1 xfs 797M 165M 632M 21% /boot
tmpfs tmpfs 13G 0 13G 0% /run/user/0
cm_processes tmpfs 63G 76M 63G 1% /run/cloudera-scm-agent/process
tmpfs tmpfs 13G 0 13G 0% /run/user/1000
tmpfs tmpfs 13G 0 13G 0% /run/user/10261
tmpfs tmpfs 13G 0 13G 0% /run/user/1001
[mesos@10.12.6.6 ~]$ df -hT 文件系统 类型 容量 已用 可用 已用% 挂载点 /dev/sda2 xfs 275G 23G 252G 9% / devtmpfs devtmpfs 63G 0 63G 0% /dev tmpfs tmpfs 63G 8.0K 63G 1% /dev/shm tmpfs tmpfs 63G 4.0G 59G 7% /run tmpfs tmpfs 63G 0 63G 0% /sys/fs/cgroup /dev/sdj1 xfs 745G 6.4G 739G 1% /ssd9 /dev/sdd1 xfs 745G 9.5G 736G 2% /ssd3 /dev/sdi1 xfs 745G 11G 735G 2% /ssd8 /dev/sdl1 xfs 745G 8.0G 737G 2% /ssd11 /dev/sdm1 xfs 745G 8.7G 737G 2% /ssd12 /dev/sdc1 xfs 745G 8.9G 736G 2% /ssd2 /dev/sdb1 xfs 745G 9.3G 736G 2% /ssd1 /dev/sdk1 xfs 745G 10G 735G 2% /ssd10 /dev/sdh1 xfs 745G 11G 735G 2% /ssd7 /dev/sde1 xfs 745G 14G 732G 2% /ssd4 /dev/sdf1 xfs 745G 11G 735G 2% /ssd5 /dev/sdg1 xfs 745G 11G 734G 2% /ssd6 /dev/sda1 xfs 797M 165M 632M 21% /boot tmpfs tmpfs 13G 0 13G 0% /run/user/0 cm_processes tmpfs 63G 76M 63G 1% /run/cloudera-scm-agent/process tmpfs tmpfs 13G 0 13G 0% /run/user/1000 tmpfs tmpfs 13G 0 13G 0% /run/user/10261 tmpfs tmpfs 13G 0 13G 0% /run/user/1001
并且对组网机器抽样进行ping测试然而没有发现明显异常，由于采用Mesos+Docker部署的Storm计算集群，因此决定翻翻日志看是否可以发现有价值的线索：
[mesos@10.12.6.6 ~]$ sudo tailf /var/log/messages
Mar 23 20:46:41 10.12.6.6 systemd: Starting user-1001.slice.
Mar 23 20:46:41 10.12.6.6 systemd-logind: New session 315531 of user mesos.
Mar 23 20:46:41 10.12.6.6 systemd: Started Session 315531 of user mesos.
Mar 23 20:46:41 10.12.6.6 systemd: Starting Session 315531 of user mesos.
Mar 23 20:46:41 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
Mar 23 20:46:46 10.12.6.6 docker: time="2019-03-23T20:46:46.678336194+08:00" level=info msg="GET /v1.20/containers/json"
Mar 23 20:47:01 10.12.6.6 systemd: Started Session 315532 of user worker.
Mar 23 20:47:01 10.12.6.6 systemd: Starting Session 315532 of user worker.
Mar 23 20:47:04 10.12.6.6 smartd[1190]: Device: /dev/sdj [SAT], open() failed: No such device
Mar 23 20:47:11 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
Mar 23 20:47:21 10.12.6.6 mesos-slave[14215]: I0323 20:47:21.962821 14267 slave.cpp:4374] Current disk usage 8.33%. Max allowed age: 5.717025255624850days
Mar 23 20:47:42 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
Mar 23 20:48:01 10.12.6.6 systemd: Started Session 315533 of user worker.
Mar 23 20:48:01 10.12.6.6 systemd: Starting Session 315533 of user worker.
Mar 23 20:48:12 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
Mar 23 20:48:21 10.12.6.6 mesos-slave[14215]: I0323 20:48:21.963692 14243 slave.cpp:4374] Current disk usage 8.33%. Max allowed age: 5.717027301642546days
Mar 23 20:48:42 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
[mesos@10.12.6.6 ~]$ sudo tailf /var/log/messages
Mar 23 20:46:41 10.12.6.6 systemd: Starting user-1001.slice.
Mar 23 20:46:41 10.12.6.6 systemd-logind: New session 315531 of user mesos.
Mar 23 20:46:41 10.12.6.6 systemd: Started Session 315531 of user mesos.
Mar 23 20:46:41 10.12.6.6 systemd: Starting Session 315531 of user mesos.
Mar 23 20:46:41 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
Mar 23 20:46:46 10.12.6.6 docker: time="2019-03-23T20:46:46.678336194+08:00" level=info msg="GET /v1.20/containers/json"
Mar 23 20:47:01 10.12.6.6 systemd: Started Session 315532 of user worker.
Mar 23 20:47:01 10.12.6.6 systemd: Starting Session 315532 of user worker.
Mar 23 20:47:04 10.12.6.6 smartd[1190]: Device: /dev/sdj [SAT], open() failed: No such device
Mar 23 20:47:11 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
Mar 23 20:47:21 10.12.6.6 mesos-slave[14215]: I0323 20:47:21.962821 14267 slave.cpp:4374] Current disk usage 8.33%. Max allowed age: 5.717025255624850days
Mar 23 20:47:42 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
Mar 23 20:48:01 10.12.6.6 systemd: Started Session 315533 of user worker.
Mar 23 20:48:01 10.12.6.6 systemd: Starting Session 315533 of user worker.
Mar 23 20:48:12 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
Mar 23 20:48:21 10.12.6.6 mesos-slave[14215]: I0323 20:48:21.963692 14243 slave.cpp:4374] Current disk usage 8.33%. Max allowed age: 5.717027301642546days
Mar 23 20:48:42 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
[mesos@10.12.6.6 ~]$ sudo tailf /var/log/messages Mar 23 20:46:41 10.12.6.6 systemd: Starting user-1001.slice. Mar 23 20:46:41 10.12.6.6 systemd-logind: New session 315531 of user mesos. Mar 23 20:46:41 10.12.6.6 systemd: Started Session 315531 of user mesos. Mar 23 20:46:41 10.12.6.6 systemd: Starting Session 315531 of user mesos. Mar 23 20:46:41 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned. Mar 23 20:46:46 10.12.6.6 docker: time="2019-03-23T20:46:46.678336194+08:00" level=info msg="GET /v1.20/containers/json" Mar 23 20:47:01 10.12.6.6 systemd: Started Session 315532 of user worker. Mar 23 20:47:01 10.12.6.6 systemd: Starting Session 315532 of user worker. Mar 23 20:47:04 10.12.6.6 smartd[1190]: Device: /dev/sdj [SAT], open() failed: No such device Mar 23 20:47:11 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned. Mar 23 20:47:21 10.12.6.6 mesos-slave[14215]: I0323 20:47:21.962821 14267 slave.cpp:4374] Current disk usage 8.33%. Max allowed age: 5.717025255624850days Mar 23 20:47:42 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned. Mar 23 20:48:01 10.12.6.6 systemd: Started Session 315533 of user worker. Mar 23 20:48:01 10.12.6.6 systemd: Starting Session 315533 of user worker. Mar 23 20:48:12 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned. Mar 23 20:48:21 10.12.6.6 mesos-slave[14215]: I0323 20:48:21.963692 14243 slave.cpp:4374] Current disk usage 8.33%. Max allowed age: 5.717027301642546days Mar 23 20:48:42 10.12.6.6 kernel: XFS (sdj1): xfs_log_force: error -5 returned.
从日志中发现了标志性提示：kernel: XFS (sdj1): xfs_log_force: error -5 returned.看来是其中一块SSD-/dev/sdj1对应的是ssd9似乎是坏掉了，再次进行确认：
[mesos@10.12.6.6 ssd9]$ ls
ls: 无法打开目录.: 输入/输出错误
[mesos@10.12.6.6 ssd9]$ cd /ssd10
[mesos@10.12.6.6 ssd10]$ ls
dfs impala mapred yarn
[mesos@10.12.6.6 ssd9]$ ls
ls: 无法打开目录.: 输入/输出错误
[mesos@10.12.6.6 ssd9]$ cd /ssd10
[mesos@10.12.6.6 ssd10]$ ls
dfs impala mapred yarn
[mesos@10.12.6.6 ssd9]$ ls ls: 无法打开目录.: 输入/输出错误 [mesos@10.12.6.6 ssd9]$ cd /ssd10 [mesos@10.12.6.6 ssd10]$ ls dfs impala mapred yarn
至此基本可以确认问题所在，可能有的同学会想一块坏掉的SSD为什么会和网络挂上钩，这里请注意50010端口哦！为了恢复SSD并实现重新挂载进行如下尝试：
[mesos@10.12.6.6 ~]$ sudo lsof|grep ssd9
lsof: WARNING: can't stat() xfs file system /ssd9
Output information may be incomplete.
bash 3877316 zhang cwd unknown /ssd9 (stat: Input/output error)
[mesos@10.12.6.6 ~]$ sudo kill -9 3877316
[mesos@10.12.6.6 ~]$ sudo umount /ssd9
[mesos@10.12.6.6 ~]$ sudo mount -a
[mesos@10.12.6.6 ssd9]$ ls
dfs yarn
[mesos@10.12.6.6 ~]$ sudo lsof|grep ssd9
lsof: WARNING: can't stat() xfs file system /ssd9
Output information may be incomplete.
bash 3877316 zhang cwd unknown /ssd9 (stat: Input/output error)
[mesos@10.12.6.6 ~]$ sudo kill -9 3877316
[mesos@10.12.6.6 ~]$ sudo umount /ssd9
[mesos@10.12.6.6 ~]$ sudo mount -a
[mesos@10.12.6.6 ssd9]$ ls
dfs yarn
[mesos@10.12.6.6 ~]$ sudo lsof|grep ssd9
lsof: WARNING: can't stat() xfs file system /ssd9
Output information may be incomplete.
bash 3877316 zhang cwd unknown /ssd9 (stat: Input/output error)
[mesos@10.12.6.6 ~]$ sudo kill -9 3877316
[mesos@10.12.6.6 ~]$ sudo umount /ssd9
[mesos@10.12.6.6 ~]$ sudo mount -a
[mesos@10.12.6.6 ssd9]$ ls
dfs yarn
再次启动Strom任务发现Worker分配和网络连接恢复正常，并且此时TIME_WAIT数量大大减少，任务恢复正常并且开始消费堆积数据。
转载请注明：雪后西塘 » kernel: XFS (sdj1): xfs_log_force: error -5 returned