ある日、メールの送信失敗率が急上昇した。
(上記画像は対処して落ち着いた後に取ったもの)
慌ててメールキューを確認するとエラーメールが大量に・・・
調べてみると、全てある１ユーザに関するもの。
ログを確認していくと、そのユーザが、さまざまなIPアドレスからSMTP認証をかけてきて、認証に成功した上でSPAM送信が行われているじゃないですか。
Jul 22 18:47:21 mailserver qmail: 1374486441.012502 starting delivery 77399: msg 90220 to local example.com-hello@example.com
Jul 22 18:47:21 mailserver qmail: 1374486441.012529 status: local 2/100 remote 0/50
Jul 22 18:47:21 mailserver spamd[937]: spamd: connection from localhost.localdomain [127.0.0.1] at port 43120
Jul 22 18:47:21 mailserver spamd[937]: spamd: handle_user unable to find user: 'hello@example.com'
Jul 22 18:47:21 mailserver spamd[937]: spamd: processing message <201307220947.r6M9lLNe013087@mailserver.example.com> for hello@example.com:109
Jul 22 18:47:26 mailserver spamd[937]: spamd: clean message (0.0/18.0) for hello@example.com:109 in 5.9 seconds, 2050 bytes.
Jul 22 18:47:26 mailserver spamd[937]: spamd: result: . 0 - AWL,BAYES_20,CONTENT_TYPE_PRESENT,INVALIDYAHOOJP,ISO2022JP_BODY,ISO2022JP_CHARSET,SUBJECT_NEEDS_ENCODING,SUBJ_ILLEGAL_CHARS,URI_HEX scantime=5.9,size=2050,user=hello@example.com,uid=109,required_score=18.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=43120,mid=<201307220947.r6M9lLNe013087@mailserver.example.com>,bayes=0.090684,autolearn=disabled
Jul 22 18:52:46 mailserver vpopmail[17115]: vchkpw-submission: (PLAIN) login success hello@example.com:83.242.101.27
Jul 22 18:52:57 mailserver qmail: 1374486777.611039 new msg 90219
Jul 22 18:52:57 mailserver qmail: 1374486777.611077 info msg 90219: bytes 1364 from <hello@example.com> qp 17121 uid 103
Jul 22 18:52:57 mailserver qmail: 1374486777.638528 starting delivery 77421: msg 90219 to remote ～@～
Jul 22 18:52:57 mailserver qmail: 1374486777.638582 status: local 0/100 remote 1/50
Jul 22 18:52:57 mailserver qmail: 1374486777.641128 starting delivery 77422: msg 90219 to remote ～@～
Jul 22 18:52:57 mailserver qmail: 1374486777.641155 status: local 0/100 remote 2/50
Jul 22 18:52:57 mailserver qmail: 1374486777.641173 starting delivery 77423: msg 90219 to remote ～@～
Jul 22 18:52:57 mailserver qmail: 1374486777.641192 status: local 0/100 remote 3/50
Jul 22 18:52:57 mailserver qmail: 1374486777.641314 starting delivery 77424: msg 90219 to remote ～@～
Jul 22 18:52:57 mailserver qmail: 1374486777.641339 status: local 0/100 remote 4/50
Jul 22 18:52:57 mailserver qmail: 1374486777.641518 starting delivery 77425: msg 90219 to remote ～@～
Jul 22 18:52:57 mailserver qmail: 1374486777.641543 status: local 0/100 remote 5/50
そう、そのユーザのメールアカウント情報がどこかで漏れ、SPAMシステムに投入されたようなのです。
とりあえず、該当アカウントのパスワード変更し、メールキュー内のエラーメール群を消去したあと、対処開始。
確認すると、約２４時間の間に、880のIPアドレスからSMTP認証のloginが行われているという事態。
また、ほとんどのIPアドレスからは１回しかアクセスがなかったので、相当大規模なシステムである模様。
# cat /var/log/maillog.? |grep vchkpw-submission|grep hello@example.com|grep succ|awk '{ print $10 }'|awk -F: '{ print $2 }' |sort|uniq -c|sort|wc
880 1760 19476
# cat /var/log/maillog.? |grep vchkpw-submission|grep hello@example.com|grep succ|awk '{ print $10 }'|awk -F: '{ print $2 }' |sort|uniq -c|sort | tail
2 93.85.128.230
2 94.156.244.75
2 94.170.246.170
2 94.180.194.222
2 95.52.132.238
3 178.125.185.161
3 46.118.66.80
3 93.175.125.67
3 93.78.3.92
3 95.42.37.153
#
そんな確認を行っていると、３０分が経過。
すると、いままで出ていた「password fail」のログが消えた。
そう、どうやらSPAM送信システム側で、このサーバでは送れない、という認識がされたようだ。
これで終わりかな？と思ったのですが、その後も１２時間ごとに１０回のメール送信を試みてる形跡が確認されています。
Jul 24 07:11:42 mailserver vpopmail[32749]: vchkpw-submission: password fail hello@example.com:91.225.163.32
Jul 24 07:16:21 mailserver vpopmail[1287]: vchkpw-submission: password fail hello@example.com:89.74.114.28
Jul 24 07:20:57 mailserver vpopmail[2147]: vchkpw-submission: password fail hello@example.com:192.162.224.10
Jul 24 19:13:23 mailserver vpopmail[8339]: vchkpw-submission: password fail hello@example.com:94.139.211.248
Jul 24 19:18:54 mailserver vpopmail[9449]: vchkpw-submission: password fail hello@example.com:178.120.193.67
Jul 24 19:24:18 mailserver vpopmail[10359]: vchkpw-submission: password fail hello@example.com:178.127.107.5
Jul 24 19:29:58 mailserver vpopmail[11422]: vchkpw-submission: password fail hello@example.com:114.41.229.41
Jul 24 19:35:23 mailserver vpopmail[13866]: vchkpw-submission: password fail hello@example.com:178.122.175.143
Jul 24 19:40:48 mailserver vpopmail[14894]: vchkpw-submission: password fail hello@example.com:46.211.194.44
Jul 24 19:46:03 mailserver vpopmail[16036]: vchkpw-submission: password fail hello@example.com:91.230.30.142
Jul 24 19:56:39 mailserver vpopmail[18000]: vchkpw-submission: password fail hello@example.com:176.115.59.82
Jul 24 20:02:02 mailserver vpopmail[19925]: vchkpw-submission: password fail hello@example.com:37.215.9.145
Jul 24 20:12:06 mailserver vpopmail[21887]: vchkpw-submission: password fail hello@example.com:115.187.55.14
