Nov 212006
 

    今天一台邮件服务器出问题,表现为Courier的pop3服务连接困难,有时甚至连接超时。简单察看了一下服务器状况,负载不是很高,Postfix倒是有些问题,发现邮件队列里面堆了不少尚未处理的信。简单察看了一下日志,貌似是一些垃圾邮件的退信。于是乎没怎么在意,专门检查pop服务    但是这里的情况就比较诡异了,发现110端口正常监听,并且并无过多连接,远端telnet也是通的,说明网络状况一切正常。唯一不正常的是,telnet连通之后服务器就再未返回任何数据,所以看不到正常的“+OK”握手信息,这种情况会持续60s,直到连接超时断开。
    第一反应是数据报中途被某些设备拦截并未到达服务器(没办法,最近GFW敏感症),于是tcpdump抓包,然而从结果来看,3次握手完全正常,而后确实服务器并未发送进一步的数据,此推理排除。
    而后重起过pop服务,发现刚重起一段时间后可以正常连接,然而很快就又故障了,怀疑服务器本身存在连接限制,直接干掉iptables规则,无效,检查pop3d服务配置文件,发现默认有每IP最大4连接数限制,调大为100(这两步操作的意义是用最简单有效甚至粗暴的办法排除干扰因素,乃快速故障排除的必胜法门),仍无效,说明又找错问题,郁闷了。
    到此只能停下来先分析一下故障情景了,首先这台服务器正常运行已经有一段时间了,不太可能存在误配置,其次出现问题的时候服务器软硬件操作系统无任何故障现象,只是Postfix因为垃圾邮件退信运行有些缓慢而已。而Postfix和Courier pop3d属于2个不同的服务,不太可能存在互相干扰的问题。而此时系统负载不过2而已,也不太可能是CPU或内存资源耗尽等问题。貌似到此基本找不到任何思路了。
    无奈间还是只能用最粗暴的办法排查,停掉webmail,停掉postfix,发现pop3d可以正常连接了!然后启动前2者,过几分钟发现又出现故障。然后进一步测试,发现问题是与poftfix相关的。停掉postfix后,系统负载并未下降,但pop3d服务立刻恢复正常。由此得出一个本人十分不原意认同的结论,是postfix竞争某种资源导致了pop3d的故障。
    然后就到了最难的阶段,查找这个所谓的“资源”。这期间的过程就是不停的检查日志中的可疑错误,监控各项资源的使用情况。过程不详述,概括说就是动用了各种想的到的工具来检查,然而结果也不甚明朗,排除CPU问题,排除内存问题,而问题最可能出现在网络连接和磁盘i/o上。论据是1,垃圾邮件退信来时会有大量的tcp连接进来,2,netstat看到不少SYN_RCVD状态,3,邮件文件夹所在分区存在bo比较大的情况。
    到目前为止,还是只有一个结论:postfix收到大量的垃圾邮件退信导致了pop3d服务的异常,而这个结论怎么看都不太可能,因为postfix跑25,pop3d跑110,井水不犯河水,二者可能相互影响的原因往死里推也只得到了:1,postfix占用大量的tcp连接导致网络缓冲区用光而pop3d无法得到正常工作所需资源(听起来有点滑稽,不过这问题本身就滑稽)2,到达了磁盘I/O瓶颈(也似乎没什么大的嫌疑吧)
    问题至此,只能走一步算一步了。我做了如下操作:
1,strace pop3d的进程,看看有没什么系统调用failed或者block的情况
2,优化一下tcp/ip协议栈的内核缓冲区,看看有没缓解。
3,优化一下磁盘性能,例如常用的什么noatime,async等。
4,放狗找找有没人碰到同样或类似问题,依葫芦画瓢。
结果如下:
1,strace出来了,停在写完pop3d连接日志之后“Connecting from X.X.X.X”,貌似看不出接下来这个pop3d在干什么。
2,貌似无效,何况telnet 110端口测试本身连接没问题,可以放弃此种推论
3,bo少了些,不过貌似也无甚效果。
4,找到一些优化postfix的文章,但基本没有提到pop3d的性能的文章,也没有出现类似问题的。而postfix文章大多也集中提到postfix参数配置以及系统性能优化方面,最多提到的也是系统协议栈和磁盘性能等,貌似曾提到的我也都基本作过了。
    至此感觉似乎再找不到更好的办法了,难不成真要gdb加上源代码一行一行的检查?我可没那么多时间,也没那么深厚的功力一定可以找出原因。无聊只能一遍又一遍的放狗找答案,而突然看到有篇文章提到,写log也是很耗费i/o的,可以考虑不些log。我突然想到,我的postfix和courier-pop3d配置的是都把log写到同一个文件的,难道是写log的系统调用被block了导致的问题?想想看前面strace的结果,难道是系统调用block在write日志而不是write日志的下一步?天方夜谭了吧(这个问题本身就接近天方夜谭-_-b)。死马当活马医,把syslog中关于maillog的项目调整为async,具体方法是修改syslog.conf中关于mail的一行:
mail.* -/var/log/maillog
与原来唯一的不同就是前面加了一个“-”,这样打开异步日志写入,避免syslogd老是不停的sync日志。
    然而貌似奇迹没有出现,问题依旧,回头想想自己确实已经是属于乱抓救命稻草了,用脚趾头想问题也不应该处在这里吧。    戏剧性的一幕出现在十几分钟后,我突然发现我用于测试的OE连pop服务正常了,反复测试了十几次全部OK,然后回服务器这头一看,妈呀,系统负载高达40,并且还在往上窜,再看mailq,队列里面的6000多封信在以光速消失,ps一看进程,700多个-_-b,貌似postfix突然睡醒了发起飚来,拼了老命的在处理信件。进一步检查一下,发现postfix重起过n多次,问了一下同事,果然是他干的,他说是这个postfix莫名其妙的有问题,需要反复restart(我超级汗)。同事貌似以前也碰到过类似问题,同样未果,最后只能是掐断垃圾邮件退信来源。同事还说,他也简单debug过,说问题可能出在文件系统的flock()函数上。我昏,难道这还真的是因为log的缘故造成的?我的思路完全混乱了。

    回头再理一下思路,推断出问题最可能的原因:大量的并发垃圾邮件退信导致postfix不停的写日志,而写日志所触发的syslogd的sync操作反过来影响postfix处理速度,导致了postfix的队列堆积。同时,syslogd的sync操作导致了flock(),而此时pop3d服务的写log请求被block,所以最后表现为pop3端口连接超时。
    然后再想想处理过程中的一些可能被忽略的现象:通过vmstat看到的i/o子系统的bo增长速度频繁且不稳定;top中的system部分占用比大大的高于user;kjournald的CPU占用率居高不下。看来并不是不可以发现问题,而是被我忽略了而已。
    从pop3d的问题追到postfix最终追到syslogd的过程不可谓不艰辛,虽然中途的灵异事件(没有立即生效,而是postfix重起后才生效,而且关键在并非我验证出现)使我还不可能100%断定推论一定成立,然而至少解决问题的成就感是有了。
    最后不得不再次感慨,知识和经验再怎么丰富也不嫌多,貌似最近又要多一项任务–研究内核的syslogd的处理流程。sys admin真不是人干的活,干多了铁定成超人……….

  2 Responses to “Postfix & Courier imapd 之头疼医脚”

  1. 说了半天问题搞定了没有?

  2. 强人
    今天公司网络问题,丢包严重,导致postfix pop3收邮件经常失败。google 到这篇 发现问题
    MAXPERIP=4
    呵呵,谢谢楼主 学习楼主解决问题的思路

 Leave a Reply

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>