[关闭]
@lxx3061313 2017-04-14T10:23:26.000000Z 字数 6546 阅读 182

一次批量开机故障的分析查找过程

背景

由于某些原因，公司部署在整个北京市区的远程设备的开关机功能需要移植到我这里。之前的方案不说，在我接手以后踏遍了无数的血坑，最终采用了我认为最靠谱的方案来实现。即，在树莓派(类似于微型前置机)上部署我自己的管理程序，并通过emqtt协议来完成和后端的通信。这样业务逻辑由后端服务保证，可靠的通信由emqtt保证，简直完美。
但是！！！！
灰度测试完成并完全部署后的第二天早晨，N条开机失败的报警把我从美梦中拉到现实。我赶紧跳起来连上公司VPN查看监控图，xxx地区设备全部开机失败！！！脑袋里蹦出的第一句话就是"WTF！怎么可能"。仔细研究监控图发现只有xxx地区开机失败，其他地区正常的不行不行的。

为什么呢

我脑海里冒出的第一个想法是xxx地区网络有问题，emqclient端和server端失联了。于是我开始信心满满的验证我的假设。

信心满满

我首先赶紧尝试通过后台手动开机所有的设备。幸运的是手动开启成功了，说明公司机房跟该地区的网络没问题。
接着我查看后端的开机日志

  1. [2017-04-12 06:45:01] 设备执行开机, hosCode:xxx, machineCodes:[10155, 10501, 10498, 10500, 10505, 10504, 10503, 10495, 10492, 10151, 10152, 10154, 10493, 10499, 10502, 10496, 10153, 10494, 10491, 10497]

以上日志说明，开关机规则配置没问题，后端在06:45准确的触发了开机请求。
那就只剩下三种情况(事情如果真有这么简单就好了)：

开始失落

接下来我需要一一验证上述问题。
1. 登录树莓派
ssh xx@rasp01.oh.xx.prd.bmsre.com
咦，顺利登录。说明树莓派没挂掉。
2. 切换root账户
为什么要切换root呢？
因为远程设备的运维是通过salt来管理的，而要运行salt命令需要root权限。而我需要通过salt来查看树莓派和设备的网络情况以及设备自身的一些状态。
sudo su -
......等待
......等待
......等待
root@rasp01:/home/***#
终于切换成功了。咦？为什么这么慢(这里的慢其实能看出一些端倪的)？看来xxx地区网络真有的问题，尽管能连上，但是卡卡卡。等我上班了要找启神"兴师问罪"。
经过一番操作，证明树莓派和设备网络没问题，设备本身也非常健康。难道管理程序挂掉了？
3. 验证程序是否正常运行
sh raspiop.sh status
raspmanager-1.0.0.jar is running! (pid=18982)
咦？running！管理程序没挂！
我又打开日志查看，发现没有收到开机请求。

跌落谷底

让我来捋捋。

  1.  开关机规则配置正确
  2.  服务端准时出发了开机请求
  3.  公司机房跟该地区网络正常
  4.  树莓派没挂
  5.  管理程序没挂
  6.  树莓派跟设备网络没问题

所有的流程都没问题，但是管理程序确实没有接受到开机请求。于是我开始怀疑人生了，难道我有问题？

怀疑人生

上班后，我第一时间找到启神（网络大神），描述了一下我遇到的问题。并咨询了一下xxx地区跟其他地区的网络有什么差别。得到答案是xxx地区没有直连公司机房，网络是通过###地区转发的。
难道这就是特别之处？但是这个答案根本无法解释我遇到的现象。
我不信邪，我重新打开管理程序的日志，希望能找到蛛丝马迹。果然，在我重新打开日志的时候，我竟然发现在延迟50分钟后程序收到并执行了开机命令（虽然此时执行这些命令没什么卵用）。在我确认当时没人手动触发过emq后，我又一次陷入了迷茫。因为网络转发再慢也不可能延迟这么久。什么原因能导致上述流程完全没问题的情况下让消息延迟这么久才收到。

迎来曙光

由于网络连通性没问题，现在只能来验证每个逻辑网段的数据可达性。
1. 测试公司机房和树莓派的数据可达性。

  1. tcpdump -i eth0 host 192.168.113.44 -n -vvv

tcpdump：dump the traffic on a network， 根据使用者的定义对网络上的数据包进行截获的包分析工具。

于是我打开一个双窗口，分别用来显示xxx地区的日志和###地区的日志。然后我手动触发一个emq命令。抓到如下数据包。

  1. 23:14:41.407661 IP (tos 0x0, ttl 64, id 18820, offset 0, flags [DF], proto TCP (6), length 54)
  2.     192.168.9.9.56518 > 192.168.113.44.82: Flags [P.], cksum 0xfbae (incorrect -> 0x674e), seq 848:850, ack 820, win 1324, options [nop,nop,TS val 33389971 ecr 379590659], length 2
  3. 23:14:41.413639 IP (tos 0x0, ttl 55, id 25158, offset 0, flags [DF], proto TCP (6), length 52)
  4.     192.168.113.44.82 > 192.168.9.9.56518: Flags [.], cksum 0x07ac (correct), seq 820, ack 850, win 1432, options [nop,nop,TS val 379598658 ecr 33389971], length 0
  5. 23:14:41.414448 IP (tos 0x0, ttl 55, id 25159, offset 0, flags [DF], proto TCP (6), length 54)
  6.     192.168.113.44.82 > 192.168.9.9.56518: Flags [P.], cksum 0x37a0 (correct), seq 820:822, ack 850, win 1432, options [nop,nop,TS val 379598659 ecr 33389971], length 2
  7. 23:14:41.454440 IP (tos 0x0, ttl 64, id 18821, offset 0, flags [DF], proto TCP (6), length 52)
  8.     192.168.9.9.56518 > 192.168.113.44.82: Flags [.], cksum 0xfbac (incorrect -> 0x0810), seq 850, ack 822, win 1324, options [nop,nop,TS val 33389976 ecr 379598659], length 0

通过对比发现两个地区的树莓派都能同时收到上述所示的数据请求包。说明在触发emq请求后，树莓派收到了数据。这样证明了公司机房到树莓派是数据可达的。
2. 测试传输层到应用层的数据可达性

  1. strace -s 10000 -fp 18982 -t -e trace=network

strace is a diagnostic, debugging and instructional userspace utility for Linux. It is used to monitor and tamper with interactions between processes and the Linux kernel, which include system calls, signal deliveries, and changes of process state.
在没有触发任何emq命令的时候，两个地区的树莓派会不停的打印上述信息。

  1. <unfinished ...>
  2. [pid 19438] 20:04:24 send(9, "\300\0", 2, 0) = 2
  3. [pid 19437] 20:04:24 <... recv resumed> "\320", 1, 0) = 1
  4. [pid 19437] 20:04:24 recv(9, "\0", 1, 0) = 1
  5. [pid 19437] 20:04:24 recv(9,
  8.  <unfinished ...>
  9. [pid 19438] 20:04:32 send(9, "\300\0", 2, 0) = 2
  10. [pid 19437] 20:04:32 <... recv resumed> "\320", 1, 0) = 1
  11. [pid 19437] 20:04:32 recv(9, "\0", 1, 0) = 1
  12. [pid 19437] 20:04:32 recv(9,

因为了解到strace追踪的是系统调用，所以很容易分析出上述的追踪信息表示的是emqclient每隔8秒跟emqServer保持的长连接心跳。

  1. 至于为什么是8秒，也是踩过的一个血坑。哎。。

从上述心跳信息可以证明，传输层到应用层的数据传输是没有问题的。

成功

我们再来捋捋目前掌握的情况

  1. 开关机配置规则正确。
  2. 服务端规则解析正确。
  3. 树莓派没挂。
  4. 客户端管理程序正常运行。
  5. 公司机房到该地区树莓派数据可达。
  6. 树莓派传输层到应用层数据可达。
  7. 但是！！！消息没有及时接收到，还延迟那么久。

那只剩下最后一种假设，消息到达应用层后全部阻塞住了。
于是我场景复现，手动去触发开机命令。依然是双开窗口，分别展示xxx地区的树莓派日志和###地区的树莓派日志(开机消息采用广播模式，###也会受到xxx地区的开机消息)
咦？效果立现了。对于###地区的树莓派可以很快得到响应，而xxx地区的树莓派反应明显非常缓慢。于是我仔细的分析两个追踪系统调用序列的差异，果然见到了曙光。
###地区正常的情况

  1. [pid 30263] 21:22:07 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 10
  2. [pid 30263] 21:22:07 connect(10, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.113.23")}, 16) = 0
  3. [pid 30263] 21:22:07 send(10, "\307\355\1\0\0\1\0\0\0\0\0\0\6rasp01\2oh\3fcx\3prd\5bmsre\3com\0\0\1\0\1", 45, MSG_NOSIGNAL) = 45
  4. [pid 30263] 21:22:07 recvfrom(10, "\307\355\205\200\0\1\0\1\0\0\0\0\6rasp01\2oh\3fcx\3prd\5bmsre\3com\0\0\1\0\1\300\f\0\1\0\1\0\0\0\0\0\4\300\250m\t", 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.113.23")}, [16]) = 61
  5. [pid 30263] 21:22:07 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 10
  6. [pid 30263] 21:22:07 connect(10, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.113.23")}, 16) = 0
  7. [pid 30263] 21:22:07 send(10, "]\333\1\0\0\1\0\0\0\0\0\0\0019\003109\003168\003192\7in-addr\4arpa\0\0\f\0\1", 44, MSG_NOSIGNAL) = 44
  8. [pid 30263] 21:22:07 recvfrom(10, "]\333\205\200\0\1\0\1\0\0\0\0\0019\003109\003168\003192\7in-addr\4arpa\0\0\f\0\1\300\f\0\f\0\1\0\0\1,\0\35\6rasp01\2oh\3fcx\3prd\5bmsre\3com\0", 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.113.23")}, [16]) = 85

xxx地区异常的情况

  1. [pid 11392] 21:07:24 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 5
  2. [pid 11392] 21:07:24 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.11.23")}, 16) = 0
  3. [pid 11392] 21:07:24 send(5, "\34\245\1\0\0\1\0\0\0\0\0\0\6rasp01\2oh\3fcx\3prd\5bmsre\3com\2oh\3fcx\3prd\5bmsre\3com\0\0\1\0\1", 66, MSG_NOSIGNAL) = 66
  4. [pid 11392] 21:07:29 send(5, "\34\245\1\0\0\1\0\0\0\0\0\0\6rasp01\2oh\3fcx\3prd\5bmsre\3com\2oh\3fcx\3prd\5bmsre\3com\0\0\1\0\1", 66, MSG_NOSIGNAL) = 66
  5. [pid 11392] 21:07:34 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 5
  6. [pid 11392] 21:07:34 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.11.23")}, 16) = 0
  7. [pid 11392] 21:07:34 send(5, "\217\264\1\0\0\1\0\0\0\0\0\0\6rasp01\2oh\3fcx\3prd\5bmsre\3com\0\0\1\0\1", 45, MSG_NOSIGNAL) = 45

看出差异没？正常的一个send都会对应一个recvfrom，而异常的两个send也没有一个recvfrom。另外从htons(53)可以找到这个请求是发送给DNS域名解析服务器的，因为DNS的默认端口是53。这里可以肯定的是192.168.113.23是公司的DNS服务器在###地区的映射IP，而192.168.11.23是公司的DNS服务器在xxx地区映射IIP。
等等！xxx地区都是通过###地区来跟公司机房通信的，那么DNS为什么要配置成192.168.11.23？于是我将xxx地区树莓派的/etc/resolv.conf文件，更新为192.168.113.23。验证一下，果然成功了。

后记

这里要说两点内容
1. 上面说到其实在sudo su -的时候就应该发现一些端倪。因为在xxx地区的树莓派上切换sudo su -的时候会明显停顿很久，而在###地区的树莓派上则不会。造成这种现象的原因是在进行sudo su -切换的时候，它首先会查询机器的hostname，即/etc/hostname的值。假设这个值为my-machine，那么紧接着它会在/etc/hosts查看my-machine是否有相应的映射配置。如果没有，系统则会向DNS查询my-machine对应的IP。
2. 通过上述分析，可知在我的代码里一定有一个地方请求了机器的hostname，而hostname在hosts文件中也没有相应的映射。经过查找果然发现在我程序的某一处有调用InetAddress.getLocalHost().getHostName()。并且消息的接收和处理都是同步进行，导致累积了很多的请求挂起处于等待状态。这也解释了为什么触发开机消息后，树莓派会延迟那么久才得到执行。

总结

  1. 事实证明，不要随便用膝盖去猜测程序可能哪里产生问题，所有不负责任的猜测都是耍流氓。
  2. 问题的查找需要有清晰的思路，顺藤摸瓜总会抓到问题的根源。
  3. 踩坑是种财富，没有踩坑就没有成长。
  4. 一些看似简单的问题，其实背后往往没有那么简单。
    image_1bdk0r4tj1r0c707dfj1a1034n9.png-307.9kB
添加新批注
在作者公开此批注前，只有你和作者可见。
回复批注