某周日晚8点多,收到报警短信,我们一个pv统计服务的打点统计结果突然大幅减少。赶紧登VPN上内网,发现pv统计曲线,在故障发生后,对比上周日下降到1/3左右。

检查了统计计算程序,未发现异常。检查了一下机器列表(这个服务在电信、联通2个机房各有2台机器),发现有一台电信的机器(ds1)挂了,lvs上已经自动下线;另一台电信机器(ds2)CPU空闲率从81%下降到42% 。

因为在ds2上跑了几个统计结果入库等的程序,于是二话不说,先将这些程序 kill掉,并在 联通机房的 ls2 机器上启动起来。操作完毕后,ds2的CPU空闲率回升到70%多,但pv统计结果依然维持在1/3左右。

查看ds2上的打点日志(nginx的access log),发现竟然没有新日志写入。再查看nginx的错误日志,有如下字样:

[alert] 19963#0: *17264042335 write() to "/usr/local/nginx/logs/xxx.log" failed (28: No space left on device) while logging request

再用 df -lh命令查看:

Filesystem            Size  Used Avail Use% Mounted on
/dev/xvde1            493G  493G   0G  100% /
tmpfs                 2.0G     0  2.0G   0% /dev/shm

磁盘满了!!

清理一部分无用日志,重启nginx,再观察,统计结果终于回升了。

原来电信机房的ds1机器挂了之后,所有电信的流量都到ds2这一台机器上了,导致打点日志增长过快,加上之前有部分无用日志未及时清理,导致硬盘满了,所有电信网络打点请求的日志都没有记录下来。我们电信的请求量大约是联通的两倍,因此反映到统计结果上是下降到1/3。

这次问题的出现到解决,实际上经历了较长的时间。回过头来思考,其实问题是可以很快定位解决的。观察到日志下降到1/3的现象,就可以怀疑是整个电信的日志没有收集到,查一下电信机器上的打点日志 和 error log,很快可以看到问题。另外,出现程序执行不对劲,日志写入不了等等奇怪问题,都可以看看是否磁盘满了。

本文链接:http://tabalt.net/blog/a-nginx-log-problem-investigation-record/,转载请注明。