不正認証のメールをパスワード変更でブロックしたときのログ

辞書攻撃などで不正にパスワードを入手した輩のスパム送信に日々悩まされています。。。

先日、スパム送信されているアカウントを見つけ、パスワードを変更し、メール送信ができないように防いだのですが、流しで見てるログを「grep」していると、ちゃんと防げたかどうかがぱっと見わからなかったので、処理結果を追いかけてみました。

何年、運用してても覚えれない…

環境の概要
事象発生からログ出力の推移について
その他：色々試験した結果
1. telnetで接続して、パス認証成功
2. telnetで接続して、パス認証失敗

環境の概要

SMTP：postfix
- multiinstance利用、587のsubmissionポートでユーザー認証。認証先はdovecot。
POP/IMAP：dovecot

事象発生からログ出力の推移について

アカウント乗っ取りが発生した際のmaillog

※日時やメッセージIDなど一部省略/アドレスやIPを変換しています。

認証が成功してメールのリレーをしてしまっている状態。

$ tail -f /var/log/maillog
client=unknown[92.37.217.221], sasl_method=PLAIN, sasl_username=hoge
from=<hoge@piteki.com>, size=7832, nrcpt=2 (queue active)
to=<hoge@gmail.com>, relay=192.168.1.1:25, delay=2.7, delays=2.5/0/0.01/0.23, dsn=2.0.0, status=sent

ユーザー名で抽出するとこんな感じで、単一IPでは無く、色々なIPからログインされています。
※gmailから利用してたりすると、IPがころころ変わることもあります。

$ tail -f /var/log/maillog | grep sasl_username=hoge
client=unknown[92.37.217.221], sasl_method=PLAIN, sasl_username=hoge
client=unknown[123.200.18.214], sasl_method=PLAIN, sasl_username=hoge
client=unknown[185.65.253.57], sasl_method=PLAIN, sasl_username=hoge
client=unknown[123.200.18.214], sasl_method=PLAIN, sasl_username=hoge
client=unknown[92.37.217.221], sasl_method=PLAIN, sasl_username=hoge

念のため、どこの国からのログイン情報かチェックします。
日本でも無く、様々な国からアクセスされているので、不正なアクセス濃厚です。

$ whois 92.37.217.221 | grep country
country:        ru
$ whois 123.200.18.214 | grep country
country:        BD
$ whois 185.65.253.57 | grep country
country:        IQ

パスワード変更実施後のmaillog

アカウントのパスワードを変更し、ログインできなくさせて、maillogを先ほどと同様に確認しても、何も出てきません。

$ tail -f /var/log/maillog | grep sasl_username=hoge
　　：
＜出力無し＞

ユーザー名の抽出をやめ、IPで抽出するように変更してみると、このように出力されました。
できれば参考のような「failed」で出力してほしいのですが、接続の仕方によっては出ないケースもあるみたいです。

$ tail -f /var/log/maillog | grep sasl_username=hoge
disconnect from unknown[92.37.217.221] ehlo=2 starttls=1 auth=1 mail=15 rcpt=29 data=15 rset=15 commands=78

＜参考＞
warning: unknown[92.37.217.221]: SASL plain authentication failed:

認証失敗ログを追いかけてdovecotのログ

postfix経由の接続なので、IPではgrepできませんが、user名で認証失敗を見つけることができました。

$ tail -f /var/log/pop.log grep hoge
auth-worker<1>: pam(hoge,127.0.0.1): pam_authenticate() failed: Authentication failure (Password mismatch?)

その他：色々試験した結果

たぶんpostfix側でdovecotの認証情報をキャッシュしてる（詳細は未調査）

telnetで接続して、パス認証成功

$ telnet localhost 587
Trying 127.0.0.1...
Connected to piteki.com.
Escape character is '^]'.
220 piteki.com ESMTP
helo hoge
250 piteki.com
auth plain bmV3aG9wZQZuZXdob3BlAGhvZ2Vob2dl
235 2.7.0 Authentication successful

この後にメール送信する
- maillog：認証成功のログ出力あり
- pop.log：何も出ない
この後に何もせずにquitで切断する
- maillog：認証成功のログ出力なし
- pop.log：何も出ない

telnetで接続して、パス認証失敗

$ telnet localhost 587
Trying 127.0.0.1...
Connected to piteki.com.
Escape character is '^]'.
220 piteki.com ESMTP
helo hoge
250 piteki.com
auth plain bmV3aG9wZQZuZXdob3BlAGhvZ2Vob2dl
535 5.7.8 Error: authentication failed:
quit