开发者中心 > 专栏 > 内容详情
分享
  • 打开微信扫码分享

  • 点击前往QQ分享

  • 点击前往微博分享

  • 点击复制链接

一波四折 —— 记一次K8S集群应用故障排查

  • 京东云技术服务中台团队
  • 2021-01-08
  • 187浏览
Part1 初露端倪

一个周四的下午,客户的报障打破了微信群的平静。

“我们部署在自建K8S集群上的应用突然无法正常访问了,现在业务受到了影响!”

收到客户的报障,我们立刻响应,向客户了解了问题现象和具体报错信息。

客户反馈K8S集群部署在云主机上,K8S的应用pod example-app通过访问外部域名example-api.com调用接口,同时访问云数据库做数据查询后将结果返回客户端。客户排查应用pod日志,日志中有如下报错:


可以看到最关键的信息是Name or service not known。该报错一般为域名无法解析导致的。


由于客户的应用pod只访问example-api.com这一个外部域名,因此判断应该是pod解析该域名时出现异常。为了进一步验证,我们执行kubectl exec -it example-app /bin/sh命令进入pod内执行ping example-api.com命令,果然出现了相同的报错。


因此可以确认应用日志中的报错是域名解析失败导致的。

执行kubectl get pod example-app -o yaml|grep dnsPolicy查看pod的dns策略,是ClusterFirst模式,也就是pod使用K8S集群的kube-dns服务做域名解析。

执行命令kubectl get svc kube-dns -n kube-system,确认kube-dns服务的clusterIP是192.168.0.10 查看pod内的/etc/resolv.conf文件,nameserver设置的正是该IP。再执行kubectl describe svc kube-dns -n kube-system|grep Endpoints,可以看到dns服务关联了一个coredns pod作为后端。

执行kubectl get pods -n kube-system|grep coredns看到kube-dns关联的coredns pod处于running状态。

再执行kubectl logs coredns –n kube-system,看到pod日志中有大量和客户配置的外部dns服务器IP地址通讯超时的报错。


10.16.16.16和172.16.16.16为客户自建DNS服务器的IP地址

。为了确认是否是DNS服务器有问题,我们在example-app pod中分别执行nslookup example-api.com 10.16.16.16和nslookup example-api.com 172.16.16.16,均能解析出正确的IP地址。

因此判断问题应该出在coredns pod上。此时我们发现,coredns pod的状态变成了crashloobbackoff,稍后又变成了running。

观察一段时间后发现pod在这两个状态之间反复切换。鉴于整个集群只有一个coredns pod,我们修改了coredns的deploy,将pod副本数调至2,新扩的pod一直处于running状态,pod日志中也没有出现和10.16.16.16、172.16.16.16的通信超时的报错。而此时example-app pod也可以正常解析域名了!可以确认之前是集群唯一的coredns pod状态异常导致集群DNS服务不可用。


那么coredns pod为什么会出现异常呢?

再次查看异常的pod日志,发现除了和外部DNS服务器有通讯超时的记录,还有和集群api-server通讯超时的记录。因此有必要怀疑是pod所处的网络有问题。在客户的K8S集群网络规划中,pod使用和集群node不同的子网通讯。通过在K8S节点云主机上绑定pod子网的弹性网卡,在网卡上给节点的pod在pod子网中分配IP,实现pod的网络可达。

由于example-app pod是可以与外部通讯的,因此pod子网层面是没有问题的。我们将焦点移至coredns pod使用的弹性网卡上。弹性网卡在节点云主机操作系统中的设备名是eth1,pod子网网关是10.176.96.1在节点上执行ping -I eth1 10.176.96.1,结果如图:


可见云主机无法通过eth1 ping通子网网关,而且找不到eth1设备。执行ifconfig命令发现eth1设备没有被系统识别到。而弹性网卡底层是被正常挂载到云主机上的。

手动执行echo 1 > /sys/bus/pci/rescan命令重新扫描弹性网卡,发现eth1出现了,此时执行ping -I eth1 10.176.96.1也可以ping通了!而异常的coredns pod也恢复了正常。判断之前应该是系统异常导致的网卡没有被识别到导致。

通过这一问题也提醒我们如果集群需要使用kube-dns服务,coredns的pod一定要配置多副本,以免单个pod异常导致集群DNS不可用。


Part2 一波刚平一波又起

域名解析的问题解决,本以为已经结案,谁知新的问题接踵而来。客户调用应用,不再报错域名解析失败。但是仍然不能正常返回结果。排查应用日志,报错如下:


通过报错判断是应用pod连接云数据库超时导致。排查云数据库所在子网的路由、ACL和白名单设置,均无异常。连接pod后可以ping通数据库域名,判断pod与数据库的网络链路是正常的。但是pod内无法telnet通数据库域名的3306端口,判断这就是导致连接数据库超时的原因了!

排查pod内的防火墙,没有开启。pod所在的子网ACL,没有限制。表面的分析没有任何线索,于是只能祭出网络问题排查的经典手段——tcpdump抓包!

由于pod内的容器一般CPU、内存、网络资源和存储空间有限,在pod内抓包会占用大量资源和存储空间,抓包结束后数据包取出也比较繁琐。而且有的容器镜像是无法安装tcpdump工具的。所以通常我们不会在容器内抓包。

基于K8S集群的网络架构,pod的网络通讯是通过所在节点云主机的辅助弹性网卡收发数据的。因此我们只要在pod所在节点云主机上对相应的网卡进行抓包即可。

在客户的场景下,应用pod使用所在节点的eth1网卡,所以pod telnet云数据库的3306端口时,我们直接在节点上抓取eth1网卡上与云数据库IP交互的数据包即可。

pod的IP是10.176.98.29,云数据库的IP是10.176.46.4。在pod的容器内执行telnet 10.176.46.4 3306,同时在节点上执行tcpdump -i eth1 host 10.176.46.4 -w /tmp/mysql.cap。pod内telnet超时后,我们结束抓包,将cap文件取出后发现居然一片空白,一个包都没有抓到!


这不科学!


之前pod内可以ping通云数据库,说明一定有数据包从pod所在云主机发出并收到了回包。为了验证pod telnet请求的包是否正常发出,我们干脆不把抓包范围局限在eth1网卡,而是使用tcpdump -i any host 10.176.46.4 -w /tmp/mysql.cap对云主机所有网络接口抓包。这次终于抓到了数据包,发现telnet发出后,没有收到数据库的任何回包。


在telnet的同时,集群中有其他pod可以正常连接云数据库,所以因为云数据库侧异常导致没有回包的可能性不大。云主机可以和外界通讯的网卡只有eth0和eth1,莫非……为了验证我们的猜想,在telnet时,节点上执行tcpdump -i eth0 host 10.176.46.4,果然看到了pod发出的到云数据库的数据包!


所以pod 容器telnet不通云数据库3306端口的原因也真相大白了。因为pod telnet云数据库的数据包没有走eth1,而是走了eth0,数据包发送至云数据库后,云数据库的回包发给了pod的子网网关。

SDN网络OVS判断来包是从node子网网关发出(eth0),而回包却是发往pod子网(eth1)源和目的地址不一致,因此将数据包丢弃。pod也就无法收到数据库的回包了。之前可以ping通是因为ICMP协议是代答的,即使源和目的地址不一致,也可以正常收到回包。

那么,pod的所有网络请求正常是应该通过云主机上的辅助网卡收发的,为什么走了云主机主网卡了呢?正常的K8S集群节点上配置了table 2路由规则,定义了pod的网络请求默认路由的下一跳是pod子网网关,并且走辅助网卡,如下图所示:


而在客户的应用pod所在节点执行ip r show table 2,我们看到的结果和第一次抓包一样,空空如也。。。


路由是由K8S集群的网络插件维护,路由缺失问题在网络插件日志中没有发现任何线索,具体原因不得而知。

当务之急是修复问题。


可以通过重启ipamd容器恢复table 2路由。

执行docker ps | grep ipamd | grep sh找到ipamd的容器ID。

然后执行docker restart 容器ID重启容器。

再次执行ip r show table 2,终于看到了路由规则!

Finally,此时在应用pod内测试可以telnet通云数据库的3306端口。客户的应用调用也终于可以成功返回结果。

然鹅,如果各位看官觉得这个case到这里就结束了,那就和当时排障的攻城狮一样图样图森破了。


Part3 慢=不可用

就在攻城狮以为一切都恢复正常时,客户的追加反馈表明这个问题只是进入了下一个阶段。

客户反馈应用虽然可以正常调用,但是一次调用要超过一分钟才能有返回结果,之前正常的速度是仅需几秒就可以返回结果。现在这样的速度完全不能满足业务要求,相当于还是不可用的。


问题尚未解决,攻城狮仍需努力!


分析应用调用返回慢的问题,一是着眼于应用流程的各个环节,如客户端,服务端对业务请求的处理时间,另外一个就是排查数据传输链路是否有延迟。在客户的场景下,就是确认pod和云数据库在处理请求上是否有瓶颈,还有就是pod到云数据库之间的网络传输是否有延迟。在pod内ping云数据库IP,没有超时丢包,延迟很低。


要想确认pod和云数据库在处理请求时的时长,还是要依靠tcpdump工具抓包分析。于是我们在pod对数据库发起一次完整的请求过程中,依然使用tcpdump -i eth1 host 10.176.46.4 -w /tmp/mysql.cap命令在pod所在节点抓包。将数据包取出后分析发现,一次完整的业务请求,pod会对数据库做13次查询。对比第一次查询和最后一次查询的时间,如图所示:


可以发现13次请求用了1分钟左右,与业务调用耗时吻合。排查云数据库监控,发现内存

使用接近100%


同时实例慢查询日志中有大量慢sql记录,可以看到几乎每次查询都耗时较长


可见如果业务调用的13次请求,每次都是慢查询,耗时4秒左右,就会导致我们看到的完整请求耗时一分钟左右。

因此判断瓶颈应该主要在云数据库上,建议客户对数据库慢查询进行优化,降低内存负载。然后观察应用调用时长是否恢复正常。


part4 问题的真相只有一个!


当我们天真地以为优化完数据库慢查询后,一切就都尘埃落定时。客户的反馈几乎让人崩溃——优化慢查询后,数据库内存使用已降至30%,慢日志中也几乎没有慢sql记录。而应用的调用时长仍然没有缩短!

一定还有哪个环节有疏漏。

为了完整了解应用pod在应用调用过程中都产生了哪些数据交互,我们决定再次抓包分析,但焦点不再集中在云数据库上,而是以pod维度进行抓包。使用tcpdump -i eth1 host <podIP> -w /tmp/app.cap命令在pod所在节点抓取所有和pod相关的包,分析数据包后果然有了新的发现:pod与100.64.249.132这个地址有文件传输交互。


查看数据包详细数据发现这个地址是OSS对象存储解析到的域名!pod还会与oss传输文件这个重要环节在此前是不知道的,客户也没有主动告知。


这也提醒我们在分析应用问题时,务必要搞清完整的业务调用流程,应用架构和涉及到的产品环节,否则挤牙膏似的信息输出和被问题现象牵着鼻子走,会浪费大量时间,甚至严重阻碍问题排查。

我们在pod内测试ping 100.64.249.132,延时非常感人。


与客户确认,客户反馈OSS域名解析的IP貌似不对。在业务架构规划时,为了保证客户pod与oss的网络性能,配置了通过专线连接oss。当前解析的IP没有走专线网段,而是走了普通的网段,无法满足性能要求。正常走专线的域名解析IP应该是10.219.226.2。


但是域名解析为什么会出现问题呢?


各位童鞋是否还记得part1中我们提到客户的pod使用的是kube-dns提供的dns解析,而kube-dns配置的上游服务器是客户自建的dns服务器?经过客户测试发现,自建dns服务器对oss域名的解析就是100.64.249.132。应该是近期客户侧维护dns服务器的时候误操作修改了解析导致的。。。将自建dns服务器的域名解析地址修改回正确地址后。再次在pod内测试,结果如下:


再次测试应用调用,终于恢复到了正常的时长!可喜可贺!


 至此客户的问题已解,总结问题排查过程,有几点值得分享:

1、  k8s集群如果使用kube-dns服务,coredns pod务必配置多副本,避免单点故障导致集群dns服务不可用。

2、  排查K8S集群的pod网络问题时,可以在pod所在节点抓取pod使用的辅助网卡的相应网络数据包,避免直接在pod内抓包。

3、  应用系统性能排查涉及到各个节点设备和网络传输,务必了解清楚完整的系统架构,调用流程,再针对涉及的每个环节逐一分析。


以上就是一次“波折”的K8S应用问题排查过程,感谢各位童鞋阅读,如果能够对大家有所帮助,欢迎点赞转发评论。

关注我们的公众号:云服务飞行团,更多精彩内容会持续放送!


共0条评论