一次Web服务异常排查

前情提要

2021/11/28 23:00(UTC +8) 收到消息有个web服务不可用。
自己Chrome访问了一下，在转圈，尝试SSH登录，登录不上去。
由于没有设置密码登录的账号，无法通过其他手段登录机器（IPMI，GCP串口）。
先重启恢复业务吧（重启大法好！）。

日志排查

syslog

23:41左右重启机器后登录检查日志，发现大量fork: Cannot allocate memory日志，日志时间为UTC。

sshd log

同时检查sshd日志，发现同样存在大量fork: Cannot allocate memory。

fork: Cannot allocate memory

查询fork: Cannot allocate memory这个错误，有两种说法，

一种是机器内存不够

一种是可能是进程数超限导致。系统内部的总进程数达到了 pid_max 时，再创建新进程时会报 “fork：Cannot allocate memory” 错

• 内存不够

这台机器没有做监控，无法查看历史内存使用状况。不过机器本身配置较高：8核32G，机器上也没有部署什么吃内存的程序。并且没有从日志中有搜索到OOM的日志，我不倾向这个原因。

• 进程数超限

搜索日志的时候发现了一个supervisor相关的日志，supervisor一直在重启一个进程，这个进程是我已经下线过的进程

查看supervisor日志发现，这个进程一直在被重启，因为相关数据库依赖下线，所以进程一直跑不起来。怀疑是这个导致的进程数超限

分析

已知问题产生的原因，但是这个原因是怎么直接影响服务的呢？

在查看syslog日志的时候发现dhcp的报错日志

dhclient出现fork: Cannot allocate memory的时间与supervisor 最终停止en2joy的时间吻合，

26796 2021-11-28 06:19:06,714 INFO spawnerr: unknown error during fork for 'en2joy': ENOMEM
2021-11-28 06:19:07,747 INFO spawnerr: unknown error during fork for 'en2joy': ENOMEM
2021-11-28 06:19:09,747 INFO spawnerr: unknown error during fork for 'en2joy': ENOMEM
2021-11-28 06:30:14,336 INFO spawnerr: unknown error during fork for 'en2joy': ENOMEM
2021-11-28 06:30:35,690 INFO gave up: en2joy entered FATAL state, too many start retries too quickly

关于dhclient

dhclient是dhcp的客户端，关于dhcp协议的信息可以看这里，Linux上运行的这个客户端用于到DHCP服务器获取ip，日志中11:56到15:43中间明显出现日志断层，推测是DHCP无法创建新进程，导致获取不到ip信息。

测试

这次测试将通过kill掉dhclient进程，看服务器发生什么变化，同时因为服务器ip获取不到，ssh将失效，需要准备其他方式登录机器。

测试准备

将测试域名绑定到测试服务机，添加有密码的账号，并添加root权限，方便在ip出问题的时候能通过GCP的串口登录到机器检查

测试前ip信息

80端口

访问80端口，后端程序简单返回。

测试开始

kill掉dhcilent的进程

root@localhost:/# kill 691

GCP串口连接到服务器

测试结果

由于dhclient每次获取ip的时候都有实效性，在kill掉dhclient进程的时候不会马上失效。
在忙完其他事情的时候回来检查，果然ssh连接掉了。
通过GCP串口登录到机器查看，ipv4已经没有了。

这时候访问域名，发现显示超时，这与当时出现问题的时候访问转圈是同样的现象。问题重现！

总结

supervisor管理的一个进程被无限重启，进程数超过上限，导致其他服务fork不了进程。

同时dhcp也fork不了进程，机器的ip信息不能更新，也就是没有ip。

这个时候访问域名，解析到ip，又因为这个ip已经跟原来的机器没有绑定了，所以没有响应，直到超时。

ps:

其实结果不够严谨，奈何当时机器没有设置账号密码，GCP串口登录不上去，无法第一时间登录现场查看，并且时间也有限(领导也着急要个结果)，只能查个大概了。

比如说supervisor的日志里面显示的ENOMEM，就是内存不够的标志。但是内存不足一般会存在OOM的情况，所有日志排查完了都没有发现有OOM，然后进程被kill的情况。