应用业务偶尔报500错误的原因定位

现象:

从23:35到次日早上07:30, 偶尔收到10.205.1.26/10.205.1.27服务器报警: 告警06:57:30 on 10.205.0.1.26 项目: Zabbix agent on 10.205.1.26 is unreachable for 5 minutes 详情:Agent ping:Down (1)

同时时不时也收到业务登陆告警/恢复报警: 告警主机:10.242.24.196 告警时间:2019.03.29 07:03:11 告警等级:Disaster 告警信息: user登录状态 告警项目:xx.userlogin 问题详情:xx_userlogin_status:500

告警主机:10.242.24.196 告警时间:2019.03.29 07:04:11 告警等级:recovery 告警信息: user登录状态 告警项目:xx.userlogin 问题详情:xx_userlogin_status:200

但业务未见投诉。

过程分析和解决过程:

1. 运维介入调查，初步判断网络故障，运维将10.205.1.26的网卡流量图(存在着大量的缺失, 所以怀疑是网络故障),反馈到公有云沟通群。
2. 公有云的云存储团队，内核团队介入调查，发现除了内存波动大，IO下降较快2点迹象外，没有其他的发现, 公有云技术团队同时在排查其他方面的因素。
3. 到公司后，加入调查故障原因的case中，联系公有云相关的技术一起排查，同时在zabbix proxy的中筛选出故障报警时刻的日志： 5388:20190328:233329.051 resuming Zabbix agent checks on host "10.0.1.26": connection restored 5388:20190328:233359.058 Zabbix agent item "app.site.code[127.0.0.1:6700/health]" on host "10.205.1.26" failed: first network error, wait for 15 seconds

zabbix-proxy的日志文件中断断续续存在这种日志，从日志看，这个时间点确实像是zabbix-proxy和zabbix-agent之间的socket连接存在问题。

4. 为了避免误判，于是分析目标主机10.205.1.26的其他监控指标, 发现ping和内存使用率的监控指标图均显示正常，未出现像网络接口流量图那样存在大量缺失的情况，说明故障时刻，ping和其他的cpu监控项的数据收集是正常的， 于是将网络层因素排除，将故障原因猜测集中到app.site.code[127.0.0.1:6700/health]单个监控项，zabbix down是由于app.site.code[127.0.0.1:6700/health]监控项响应缓慢导致 。（后期研读了zabbix-agent的部分代码，在主动模式下，zabbix-agent会存在着由于监控项执行超时而报 failed: first network error, wait for 15 seconds的问题）。

5. 此时公有云内核组反馈，发现在故障的时间段，io下降比较明显， 于是跟业务开发者确认，写日志是同步io还是异步io, 业务开发者反馈是异步io。 为了验证应用进程写磁盘是否是异步, 接着让运维同事准备一台user应用的主机【压测环境的】,上面运行的代码和产线环境一样，在监控机上每隔一秒运行 app.site.code[127.0.0.1:6700/health 的监控项的脚本， 然后在公有云的控制台中将该主机的云磁盘强制卸载掉，

观察监控项的运行脚本的响应，发现磁盘被卸载的情况下，user模块的应用监控app.site.code[127.0.0.1:6700/health并无报错或超时现象，确认了开发者说异步IO，排除io的因素。

6. 运维继续分析user模块的 程序日志，发现凌晨3点左右，报出文件句柄不足, 域名无法解析等错误。由于故障是从昨天晚上23:14分就开始了，到了凌晨3点的时候，出现文件句柄不足(进程达到最大的文件fd数)，由于域名解析也是需要创建socket fd，fd耗尽所以域名解析也会失败。运维在此前的疑问也被解决了：user模块有3台服务器，其中只有2台在报警，另外1台正常，另外1台主机应用进程的Max open files参数是10w, 故障的2台主机应用进程的Max open files是4096。Max open files=10w的那台主机由于是运维手工重启过应用进程，所以应用进程会继承终端环境 下Max open files= 10w , 由于这个值很大，所以可以支撑很长的时间而不会耗尽，因此第三台能正常工作的主机没有报出文件句柄耗尽的错误。但是另外2台主机的user模块进程是通过发布系统完成重启的，发布系统是通过salt-minion 来重启的，salt-minion的Max open files参数值:4096, 故业务进程就会继承salt-minion进程的Max open files:4096, 4096这个值比较小，支撑不了多长时间就会报fd耗尽，故应用进程在凌晨3点就报出文件句柄耗尽的错误。至于salt-minion的Max open files为什么是默认值:4096? 是因为: 在服务器初始化的时候，第一步就是安装salt-minion和启动salt-minion,此时的系统参数全部都是默认值，第二步才是系统参数的修改（Max open files=10w）,此时系统参数的修改影响不到处于启动状态的salt-minion进程(除非中途有人重启salt-minion进程)。 7. 运维分析故障时间段的nginx的日志和应用服务器的网络状态，通过分析nginx日志，发现响应耗时超过3s以上的请求均来自user模块login。通过日志可以分析出请求的拓扑: 登陆请求---->nginx 反向代理--> npsdk模块--服务器端接口请求---->nginx反向代理-->zuul gateway 路由转发--->user模块。在分析nginx日志 和监控数据的过程中，发现nginx的user模块的访问日志在故障时间段出现499, 同时user模块所在的服务器的TCP监控指标close-wait在故障时间段大幅上升。 499说明是调用端主动关闭连接所致【说明调用端有超时机制，被调用端响应太慢, 触发调用端有超时控制】，user模块所在的服务器的close-wait状态说明socket是被动关闭，刚好和nginx 499状态相互印证。close-wait这个状态大部分是由于程序对异常情况未做很好的处理所致: 调用端主动关闭连接的情况下，服务器端没有很好地处理这个socket【服务端收到了调用端发送的fin，服务器端在SO_LINGER参数是默认值的情况下，服务器端既没有shutdown该socket,也没有close 该socket】, 猜测可能服务器端存在bug。

8.从以上分析的各种迹象，判断问题出在模块user处理逻辑上， 运维在user模块和zuul gateway上抓包，同时运维将线上一台user模块接入到pinpoit，收集一段时间后运维发现user模块调用微信接口偶尔出现缓慢现象。

9. 通过dig 域名, ping IP地址后， 发现微信接口其中的一台服务器丢包率非常高，只要通过dns轮询到该台服务器，就会出现调用缓慢。

10. 联系开发人员查看代码，将排查信息同步给开发方，同时jstack 将jvm的进程堆栈发给开发，最后定位到：开发者在调用第三方接口的时候，未增加超时，导致线程阻塞， 最终导致socket fd全部被微信接口请求耗尽， 只剩下Max open files =10w的那台机器能够正常工作，所以概率地会出现登录500。(和步骤8中的猜测吻合)

故障回溯:

微信的部分服务器网络丢包，导致我方user应用调用微信接口挂起，而该接口没有超时机制，内部其他的子系统调用该接口都有超时机制，故内部其他子系统调用该接口由于超时主动关闭socket，导致该接口服务出现大量的close-wait，文件句柄fd泄露，很快造成文件句柄超过4096而耗尽, 进而导致无法域名解析【域名解析也需要创建新的fd】,本地healthcheck监控项因为fd耗尽的问题而阻塞导致zabbix-proxy主动收集监控项:(app.site.code[127.0.0.1:6700/health])超时报zabbix-agent unreachable, user模块由于fd耗尽阻塞了内部子系统的接口调用，从而导致调用端的应用进程报500(调用端发现user模块响应超时而主动关闭socket后后造成逻辑层错误)。zuul gateway号称有熔断机制，怎么没有将故障的节点下线？后来了解了一下，产线环境zuul gateway 的当前的熔断机制目前依赖 eureka 和各个服务 eureka client之间的TCP心跳，故障时刻eureka 和 eureka client的TCP长连接不会受到fd句柄耗尽的影响，所以故障时刻的应用并没有从eureka中剔除。由于zuul gateway的负载均衡功能，所以有概率访问到故障节点导致500。