postfix疯狂外发垃圾邮件之分析与解决

早上起床，手机收到不少报警内容：

Trigger: Disk I/O is overloaded on nginx_189
Trigger status: PROBLEM
Trigger severity: Warning
Trigger URL:
Item values:
1. CPU iowait time (nginx_189:system.cpu.util[,iowait]): 36.59 %
2014-02-28 09-17

我台服务器主要功能是nginx负载从+静态服务器+NFS（文件服务器），也就是把图片等网页静态内容，用nginx来解析出去。开始以为，这IO会不会是因为FNS造成的？打开站长统计平台，看了下最近的流量统计，结果今天的流量和平时差不多，所以，不可能是因为NFS造成的。打开top看下，如：

top - 09:00:13 up 299 days, 15:18,  1 user,  load average: 3.42, 6.62, 7.22

Tasks: 676 total,   1 running, 675 sleeping,   0 stopped,   0 zombie

Cpu(s):  0.5%us,  0.8%sy,  0.0%ni, 88.9%id,  9.7%wa,  0.0%hi,  0.1%si,  0.0%st

Mem:  16323624k total, 16095648k used,   227976k free,   429972k buffers

Swap:  4194296k total,    89880k used,  4104416k free, 13756348k cached

 PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                            

18364 root      20   0 78824 2552 2372 S  2.0  0.0 104:04.11 master                                                            

24359 root      20   0  242m 5616 1008 S  1.7  0.0  84:37.57 rsyslogd                                                          

5471 www       20   0  563m  43m  968 S  1.3  0.3 244:38.98 nginx                                                              

2532 mysql     20   0 6544m  87m 3484 S  1.0  0.6  74:23.93 mysqld                                                            

18928 postfix   20   0 78912 3668 2652 S  1.0  0.0   0:04.17 trivial-rewrite                                                    

2632 root      20   0     0    0    0 S  0.7  0.0 125:53.99 nfsd                                                              

5466 www       20   0  563m  33m  968 S  0.7  0.2 245:24.31 nginx                                                              

5467 www       20   0  562m  32m  968 S  0.7  0.2 246:10.91 nginx                                                              

18367 postfix   20   0 92796  16m 2436 S  0.7  0.1  66:19.27 qmgr                                                              

19024 postfix   20   0 78784 3244 2404 S  0.7  0.0   0:00.11 error                                                              

20291 postfix   20   0 78808 3208 2380 S  0.7  0.0   0:00.07 bounce                                                            

20308 postfix   20   0 78808 3212 2380 D  0.7  0.0   0:00.06 bounce                                                            

20627 root      20   0 15428 1704  956 R  0.7  0.0   0:00.08 top                                                                

1267 root      20   0     0    0    0 D  0.3  0.0  28:54.38 jbd2/sda5-8                                                        

5473 www       20   0  564m  44m  968 S  0.3  0.3 245:18.47 nginx                                                              

5475 www       20   0  561m  41m  968 S  0.3  0.3 245:24.89 nginx                                                              

5478 www       20   0  564m  44m  972 S  0.3  0.3 245:15.26 nginx                                                              

5480 www       20   0  560m  40m  968 S  0.3  0.3 244:23.20 nginx                                                              

18007 postfix   20   0 78976 3588 2688 S  0.3  0.0   0:00.07 smtp                                                              

18061 postfix   20   0 78976 3580 2684 S  0.3  0.0   0:00.05 smtp                                                              

18116 postfix   20   0 78784 3244 2404 S  0.3  0.0   0:00.11 error

再看vmstat:

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----

r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st

0 21  89968 174376 435440 13724224    0    0     0  2344 10295 14796  1  1 48 51  0

0 20  89968 172764 435472 13724476    0    0     0  2168 11165 14036  1  1 45 53  0

0 15  89968 174144 435500 13724932    0    0     0  2284 10924 14465  1  1 56 41  0

1 14  89968 173416 435524 13725220    0    0     0  2236 11184 14114  1  1 50 48  0

0 23  89968 173664 435548 13725568    0    0     0  2124 10656 14672  1  1 52 46  0

0 21  89968 173424 435572 13725868    0    0     0  2068 9471 12507  1  1 50 48  0

0 21  89968 169780 435592 13726180    0    0     0  2440 11110 13856  1  1 54 44  0

0 20  89968 171068 435644 13726592    0    0     0  3052 11531 16560  1  1 47 51  0

1 21  89968 170284 435672 13726868    0    0     0  2532 10400 18581  1  1 47 50  0

0  4  89968 171284 435696 13727168    0    0     0  2352 10578 19785  1  1 42 55  0

1 18  89968 169640 435740 13727576    0    0     0  2296 11212 19899  1  2 52 46  0

0 22  89968 170520 435752 13727868    0    0     0  1888 10769 20069  1  1 52 46  0

0 22  89968 169844 435772 13728196    0    0     0  2700 11599 20887  1  2 43 54  0

0 26  89968 169388 435804 13728508    0    0     0  1852 10066 22187  1  1 38 60  0

1 33  89968 167868 435828 13728788    0    0     0  2280 10427 17010  1  1 31 67  0

0 28  89968 164760 435856 13729048    0    0     0  2240 9965 18557  1  1 35 63  0

0 23  89968 162884 435872 13729348    0    0     0  1408 10064 18835  1  1 40 58  0

0 30  89968 163520 435884 13729620    0    0     0  1996 9547 17489  1  1 45 53  0

0  4  89968 162344 435924 13729912    0    0     0  1740 10241 17469  1  1 41 56  0

1 22  89968 159048 435936 13730084    0    0     0  6552 9550 14428  1  1 41 56  0

1 21  89968 161040 435980 13730284    0    0     0  1336 9299 19970  1  2 41 57  0

0  1  89968 162676 435988 13730336    0    0     0  2408 4878 8640  0  1 71 28  0

0 23  89968 163336 436004 13730504    0    0     0  2164 8385 29363  1  3 59 36  0

1 20  89968 165344 436020 13730880    0    0     0  1880 10232 13989  1  1 50 48  0

0 15  89968 162088 436032 13731188    0    0     0  1940 11081 11315  1  1 53 45  0

0 20  89968 157988 436068 13731504    0    0     0  2288 11366 14245  1  1 54 44  0

从进程中看到，好像是postfix有问题。我这postfix主要是用来给程序发达邮件用的，如报警，程序外发邮件等。平时postfix进程不会像现在这样异常，这在postf主进程CPU占用高，其它的相关进程，也占用很高，如smtp,qmgr等。当然，也看到了不少error的进程，而且属主是postfix，所以可以判断是postfix出问题了，为了证实，把postfix服务停掉，观察top状态，服务器负载都下去了，而且磁盘写入，上下文切换都降低了，所以，postfix异常是正确的。

这是刚停止postfix以后的vmstat

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----

r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st

1  0  88736 600328 448020 13682256    0    0     0     5    0    0  0  0 99  0  0

0  0  88736 600164 448020 13682256    0    0     0     0 3500  725  0  0 99  0  0

0  0  88736 600448 448020 13682256    0    0     0     0 4008  842  0  0 99  0  0

0  0  88736 600544 448020 13682256    0    0     0     0 3197  668  0  0 100  0  0

0  0  88736 600296 448020 13682256    0    0     0     0 2736  613  0  0 100  0  0

0  0  88736 601216 448020 13682256    0    0     0     0 3311  679  0  0 100  0  0

0  0  88736 600860 448020 13682256    0    0     0     0 3268  719  0  0 99  0  0

0  0  88736 600896 448020 13682256    0    0     0    16 2818  698  0  0 100  0  0

0  0  88736 600268 448020 13682256    0    0     0     0 2998  592  0  0 99  0  0

0  0  88736 601060 448020 13682256    0    0     0     0 3163  596  0  0 99  0  0

0  0  88736 600680 448020 13682256    0    0     0    24 3092  657  0  0 99  0  0

0  0  88736 600952 448020 13682256    0    0     0     0 2628  489  0  0 100  0  0

0  0  88736 600080 448020 13682256    0    0     0     0 3192  629  0  0 99  0  0

0  0  88736 600492 448020 13682256    0    0     0    16 3448  634  0  0 99  0  0

0  0  88736 600596 448020 13682256    0    0     0     0 4024  683  1  0 99  0  0

0  0  88736 599820 448020 13682256    0    0     0     0 2931  552  0  0 100  0  0

0  0  88736 600332 448020 13682256    0    0     0     0 3147  665  0  0 99  0  0

0  0  88736 600880 448020 13682256    0    0     0     0 2971  619  0  0 99  0  0

0  0  88736 600096 448020 13682256    0    0     0     0 3233  602  0  0 99  0  0

0  0  88736 600752 448020 13682256    0    0     0     0 2872  518  0  0 100  0  0

1  0  88736 600364 448020 13682256    0    0     0     0 3152  648  0  0 99  0  0

0  0  88736 601008 448020 13682256    0    0     0     0 2251  504  0  0 100  0  0

0  0  88736 601132 448020 13682256    0    0     0     0 2834  624  0  0 99  0  0

0  0  88736 601536 448020 13682256    0    0     0     0 2747  600  0  0 100  0  0

0  0  88736 600904 448020 13682256    0    0     0     0 2758  529  0  0 99  0  0

1  0  88736 601168 448020 13682256    0    0     0     0 2883  627  0  0 100  0  0

因为对postfix不是很熟悉，所以，在网上找了一篇文章：

参考文档：http://www.myhack58.com/Article/60/sort095/2012/35334.htm

按他的思路和方法，我打开maillog日志，发现日志是写入很快，用tail -f可以看是狂刷屏，而且日志文件有几个G大了。日志大概如上：

Feb 28 10:08:27 mail postfix/error[10442]: DC467C1AE4: to=<gmiglicco@comcast.net>, relay=none, delay=12332, delays=12324/3.5/0/4, dsn=4.0.0, status=deferred (delivery temporarily suspended: host mx1.comcast.net[68.87.26.147] refused to talk to me: 554 imta33.westchester.pa.mail.comcast.net comcast 124.172.223.189 Comcast block for spam.  Please see http://postmaster.comcast.net/smtp-error-codes.php#BL000000)

Feb 28 10:08:27 mail postfix/error[10943]: 6BA87C6222: to=<tinajones10@yahoo.com>, relay=none, delay=760, delays=751/9.2/0/0.18, dsn=4.4.2, status=deferred (delivery temporarily suspended: lost connection with mta5.am0.yahoodns.net[66.196.118.33] while sending RCPT TO)

Feb 28 10:08:27 mail postfix/error[10397]: 6C12AC5559: to=<fisher.price30@yahoo.com>, relay=none, delay=2988, delays=2979/9.1/0/0.18, dsn=4.4.2, status=deferred (delivery temporarily suspended: lost connection with mta5.am0.yahoodns.net[66.196.118.33] while sending RCPT TO)

Feb 28 10:08:27 mail postfix/error[12092]: 65E5FC155C: to=<chef.jr@hotmail.com>, relay=none, delay=13123, delays=13114/8.6/0/0.89, dsn=4.4.2, status=deferred (delivery temporarily suspended: lost connection with mx3.hotmail.com[65.54.188.126] while sending RCPT TO)

Feb 28 10:08:27 mail postfix/error[10392]: 9F869C19FA: to=<fmdry@aol.com>, relay=none, delay=12457, delays=12446/8.3/0/2.3, dsn=4.7.1, status=deferred (delivery temporarily suspended: host mailin-04.mx.aol.com[64.12.88.132] refused to talk to me: 421 4.7.1 : (DYN:T1) http://postmaster.info.aol.com/errors/421dynt1.html)

Feb 28 10:08:27 mail postfix/error[10423]: 6CE90C24F9: to=<nothingbetter0811@yahoo.com>, relay=none, delay=10968, delays=10959/8.5/0/0.89, dsn=4.4.2, status=deferred (delivery temporarily suspended: lost connection with mta5.am0.yahoodns.net[66.196.118.33] while sending RCPT TO)

Feb 28 10:08:27 mail postfix/error[10942]: 659D0C3636: to=<chdp@yahoo.com>, relay=none, delay=8958, delays=8949/8.6/0/0.89, dsn=4.4.2, status=deferred (delivery temporarily suspended: lost connection with mta5.am0.yahoodns.net[66.196.118.33] while sending RCPT TO)

然后用postcat -q命令查看其中一封邮件的内容： 如 postcat -q 659D0C3636，可以看到，邮件是用test@xxx.com发送的，再仔细分析日志，确实是挺多from test@xxx.com记录。登陆test@xxx.com邮箱，发现有8000多封退信，而且还在增加中。到此，问题所在可以真正找出来了。因为test@xxx.com是以前开发程序时所创建的帐号，有可能是密码设的太简单，被人破解，被用于狂发邮件。果断把test@xxx.com封掉。然后再用postsuper -d ALL 把其它postfix缓存清空，到此故障完全排除。有些排查和解决步骤，那篇文章中出现的，我这里就没写出来了，思路是借鉴他的。