问题描述
一台2004年配置的RedFlag Server 4.1数据库服务器,基本软件是Oracle9i,没有按照X窗口系统。一次发现日志磁盘分区无法写入,问题是sendmail导致大量小的文件,占满了inode编号,从而导致虽然磁盘仍有空间,但是inode用完的局面。由于本系统用途为单一的数据库服务器,所以邮件几乎没什么用途,于是删除了这些小文件,然后chkconfig停止了sendmail服务。于是之后发生了如下的故事...
理论上说,纯命令行的Linux系统相当稳定,可是这台机器最近总是不定期一周左右死掉。症状为:系统无法登陆,以登陆还是重复显示登陆提示符,系统的各项服务如sshd和最基本的数据库服务也不能工作。由于已经无法登入系统,所以排错相当困难。硬重启后系统则正常,只是不久后问题依旧,非常烦人。
排错过程
maillog日志文件占满分区空间
照例查看系统日志,/var/log/message、/var/log/secure、dmesg等,没有发现异常。df -h发现日志所在的文件系统分区使用率100%了,是不是因为这个原因系统死掉呢?如如何根据日志判断呢?(ToDo)。
记得之前有一次因为这个分区占用较大,一气之下把/var/log整个目录都rm -rf了,导致了一些关键的目录和文件被删除,如/var/log/rflogview/以及其下面的文件,这些是系统日志文件,文件不存在了,syslogd也就无法写入(syslogd不会自动创建不存在的日志文件),所以一些关键的系统日志都被丢失了。
du -sh 查看找到了一个巨大的文件/var/log/mailog。head、tail查看内容,发现全是同样的内容行,如下:
May 13 15:29:23 lcha2 postfix/postdrop[1443]: warning: mail_queue_enter: create file maildrop/383480.1443: No such file or directory
May 13 15:29:23 lcha2 postfix/postdrop[1269]: warning: mail_queue_enter: create file maildrop/330426.1269: No such file or directory
May 13 15:29:23 lcha2 postfix/postdrop[1439]: warning: mail_queue_enter: create file maildrop/357169.1439: No such file or directory
May 13 15:29:23 lcha2 postfix/postdrop[1654]: warning: mail_queue_enter: create file maildrop/984222.1654: No such file or directory
May 13 15:29:23 lcha2 postfix/postdrop[1269]: warning: mail_queue_enter: create file maildrop/330426.1269: No such file or directory
May 13 15:29:23 lcha2 postfix/postdrop[1439]: warning: mail_queue_enter: create file maildrop/357169.1439: No such file or directory
May 13 15:29:23 lcha2 postfix/postdrop[1654]: warning: mail_queue_enter: create file maildrop/984222.1654: No such file or directory
使用 tail -f /var/log/maillog,发现每秒都有几乎相同的文本行输出。按照上面的日志内容,判定是postfix这个套件的postdrop程序发出的日志。是谁启动了postdrop呢?
使用pstree,结果如下:
init-+-aacraid
|-atd
|-bdflush
|-crond---125*[crond---sendmail---postdrop]
可见crond守护进程启动了sendmail,进而启动了postdrop。查看crond的配置, crontab -e,都没有发现几秒就启动的程序,所以可能是sendmail自己一旦邮件发送不成功,就持续重新发送而导致持续启动postdrop,而postdrop总是执行失败,导致持续写入日志到日志文件。日志文件增大的速率超过了logrotate的删除频率,所以占据了100%的磁盘空间。
由于sendmail没有退出,导致启动它的crond也不能退出,从而导致多个crond进程并存。
找到了问题,解决起来相对简单。一种方式就是不让postdrop产生的日志写入日志文件,这通过修改/etc/syslog.conf文件达成;第二种方式是增大logrotate的删除频率,这通过修改logrotate的crond像以及/etc/logrotate.conf配置文件达成;第三就是找到postdrop失败的原因,修正使其能够成功进行。最简单的就是第一种了,也能满足目前的需要,所以就采取了第一种方式。
修改syslog.conf使得不记录mail的warning信息,修改前如下:
mail.* /var/log/maillog
修改后
mail.err
这样就通过提高日志记录的级别来舍弃了mail类的warning级别日志。
service syslog restart重新启动syslogd。然后tail -f /var/log/maillog,在没有上面类似日志的输出了。
文件打开数量达到极限
然而,几天后重新出现死机的现象,不过这次在现场显示器上看到了类似 "cannot open shared object file: Too many open files in system"的信息。在Linux中,“一切都是文件”,程序文件本身、各种库文件、管道、设备、网络连接等等都是文件。上述信息说明,系统打开的文件数量到达了极限,从而导致无法打开新文件,当然也就无法执行程序。通过 sysctl -a 可以看到fs.file-max = 131072,这个数字也不小了。那么是谁打开了这么多的文件呢?通过lsof 查看发现名为sendmail和postdrop的多个进程,每个进程都打开了多个文件。通过 ps -e | grep sendmail | cut -d ' ' -f2 | xargs kill,以及ps -e | grep postdrop| cut -d ' ' -f2 | xargs kill,杀死所有sendmail和postdrop进程后,再lsof发现打开的文件数骤减。
前面已经给出了pstree的结果,发现是cron启动了sendmail,sendmail启动了postdrop。临时写了一个小的测试脚本,来看sendmai的启动频率。
while true
do
date +%H:%M:%S >> 1.txt
ps -e | grep sendmail | wc >>1.txt
sleep 5
done
从结果文件1.txt中发现每10分钟,就会启动一个sendmail进程。crontab里有个没有这个频率的启动项,但有一个每5分钟自动网络校时的启动项。把这个项注视掉,重新启动crond,发现仍然有sendmail的启动,从而排除了这个原因。难道是crond本身每10分钟就自动发送邮件吗?按照man 5 crontab的解释,把/etc/crontab的MAILTO设为"",这样crond就不会发送邮件了。重新启动crond服务,发现crond仍然10分钟启动一次sendmail,太奇怪了!干脆直接关闭crond服务,然后再也没有新的sendmail进程产生。难道是crontab被黑了?为什么MAILTO=""了,还会调用sendmail呢?把所有的sendmail进程都kill掉,然后启动crond, 仍然会生产sendmail,看来crond和sendmail的关系绝非一般。
被忽略的/etc/cron.d
弄了半天,发现了/etc/cron.d目录下存在一个文件,而crond会自动读取其中的配置信息,正好这个文件里有一个项就是每10分钟执行一次systat软件包的命令,测试表明这个命令由于所写日志文件不存在而导致报错,一旦报错,crond就会sendemail(不管MAILTO的值如何?)。在这条命令后面加上 &>/dev/null后,发现crond不再启动sendmail进程。
原来内容:
# run system activity accounting tool every 10 minutes
*/10 * * * * root /usr/lib/sa/sa1 1 1
# generate a daily summary of process accounting at 23:53
53 23 * * * root /usr/lib/sa/sa2 -A
*/10 * * * * root /usr/lib/sa/sa1 1 1
# generate a daily summary of process accounting at 23:53
53 23 * * * root /usr/lib/sa/sa2 -A
其中的命令会报错:
[root@lcha2 root]# /usr/lib/sa/sa1 1 1
Cannot open /var/log/sa/sa20: No such file or directory
Cannot open /var/log/sa/sa20: No such file or directory
修改后:
# run system activity accounting tool every 10 minutes
*/10 * * * * root /usr/lib/sa/sa1 1 1 &>/dev/null
# generate a daily summary of process accounting at 23:53
53 23 * * * root /usr/lib/sa/sa2 -A &>/dev/null
*/10 * * * * root /usr/lib/sa/sa1 1 1 &>/dev/null
# generate a daily summary of process accounting at 23:53
53 23 * * * root /usr/lib/sa/sa2 -A &>/dev/null
全过程总结
![](http://img2.tuicool.com/nANBby.png!web)
心得体会
- 日志文件是系统分析的关键,要确保所有日志文件目录可用,如果不可用,syslogd不会自动创建它们,也就失去了记录日志的机会!
- crond,logrotate,syslogd相互配合
- crond和sendmail的关系绝非一般,crontab中MAILTO设置了空,crond仍然会调用sendmail发送邮件,解决方式是把crond执行的命令最后加上 &> /dev/null。
- 要全面了解一个软件包,比如cron.d是crond的一部分,作者就就吃亏在这个上面
- 多动手测试,熟练使用bash命令