今回はLinux環境でPostfixを使ってメールサーバーを運用している場合の簡単なログの見方やログの確認ポイントをLinux初心者向けに紹介していきます。
当記事の環境
当記事では古い環境を元にした内容になっていますが、新しい環境でもそれほど変わらないと思います。
ご了承下さい。
CentOS：5.11
Postfix：2.8.3
Postfixのログの場所
Postfixのログは標準では以下の場所にあります。
/var/log/maillog
尚、既定ではログファイルは自動的にローテートされます。
ローテートされた世代の古いログファイルは maillog.1、maillog.2 という様にファイル名の末尾に番号が振られて保存されていきます。
ケース毎のPostfixのログの見方
当項では、ケース毎にPostfixログを確認する場合の見方や、確認すべきポイントを紹介していきます。
特定のメールアドレスの送信時のログを抜き出したい
特定のメールアドレスの送信ログを抜き出したい場合は以下のコマンドを実行します。
# cat /var/log/maillog | grep "from=<test_user@example.com>"
上記の例ではメールアドレス test_user@example.com がメールサーバーから送信した際のログを抜き出します。
上記のコマンドを実行することで、例えば以下の様なログが確認できます。
ここから更に詳しく調べたい送信タイミングのログを絞り込んでいきます。
Dec 8 11:15:01 xxxxxx postfix/qmgr[23557]: A2F9F8A017B: from=<test_user@example.com>, size=1092, nrcpt=1 (queue active) Dec 8 13:18:06 xxxxxx postfix/qmgr[23557]: 559678A0088: from=<test_user@example.com>, size=6681, nrcpt=1 (queue active) Dec 8 14:39:55 xxxxxx postfix/qmgr[23557]: D1E8D8A004D: from=<test_user@example.com>, size=1295, nrcpt=1 (queue active) Dec 8 14:49:18 xxxxxx postfix/qmgr[23557]: AA2F18A0088: from=<test_user@example.com>, size=4484, nrcpt=1 (queue active) Dec 8 14:58:39 xxxxxx postfix/qmgr[23557]: 5AEF28A017B: from=<test_user@example.com>, size=10050, nrcpt=4 (queue active) Dec 8 15:32:31 xxxxxx postfix/qmgr[23557]: 3079A8A0142: from=<test_user@example.com>, size=6747, nrcpt=1 (queue active) Dec 8 15:47:45 xxxxxx postfix/qmgr[23557]: 9D5A38A0142: from=<test_user@example.com>, size=8403, nrcpt=1 (queue active)
尚、上記の例では、from が対象のメールアドレスのログを抜き出しましたが、対象のメールアドレスが to になっている送信ログを抜き出したい場合は以下のコマンドになります。
※from を to に書き変えるだけですが参考まで。
# cat /var/log/maillog | grep "to=<test_user@example.com>"
特定のメール送信時の一連のログを抜き出したい
上記の様にいったん調査をしたいメールアドレスの送信時のログを抽出したら、次は更にその送信時の一連の処理についてログを確認したい場合は、対象の送信時のログの行に表示されている「キューID」を使用してgrepします。
「キューID」とは、メールの送信や受信時に割り当てられる番号であり、Postfixが接続を受け入れてからメールの送信や受信の一連の処理が完了するまで同じキューIDが使用されます。
そのキューIDでログを抽出することで、特定のメール送信時や受信時の一連の処理ログを抜き出すことができます。
上記のログの例で言えば、 from= の前に置かれている A2F9F8A017B や 559678A0088 などの文字列が「キューID」になります。
具体的には以下の様なコマンドを実行します。
# cat /var/log/maillog | grep "3079A8A0142"
上記のコマンドを実行することで、例えば以下の様なログを抽出することができます。
Dec 8 15:32:31 xxxxxx postfix/smtpd[32746]: 3079A8A0142: client=connection_source_hostname[xxx.xxx.xxx.xxx], sasl_method=PLAIN, sasl_username=test_user Dec 8 15:32:31 xxxxxx postfix/cleanup[32608]: 3079A8A0142: message-id=<xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx@example.com> Dec 8 15:32:31 xxxxxx postfix/qmgr[23557]: 3079A8A0142: from=<test_user@example.com>, size=6747, nrcpt=1 (queue active) Dec 8 15:32:31 xxxxxx postfix/smtp[1090]: 3079A8A0142: to=<dummy@example.net>, relay=abcd.example.net[xxx.xxx.xxx.xxx]:25, delay=0.23, delays=0.04/0.01/0.09/0.09, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5941937834) Dec 8 15:32:31 xxxxxx postfix/qmgr[23557]: 3079A8A0142: removed
本当は、この上記ログの前後には、セッションが接続したConnectionのログと、切断したDisconnectのログも存在します。
ただ、キューIDは接続した後に記録される為、キューIDだけで絞り込んだ場合はそのログは抽出されません。
ご注意ください。
「SMTP-AUTH」のログイン試行失敗を検出したい
SMTPによるメール送信時にユーザー名とパスワードでの認証を行い、認証に成功した場合にメールを送信できる仕組みを「SMTP-AUTH」と呼びます。
ただ、メールサーバーをインターネット上で公開していると、何らかの方法で知り得たメールアカウントを使用して様々なパスワードを試して認証を通そうと不正にアクセスしてくるセッションが非常に多く発生します。
数回の認証失敗であれば正規のユーザーが本当に間違えた可能性が高いですが、認証失敗のログが大量に発生している場合は、不正に認証を通そうとしている可能性が高いと言えます。
その場合、例えば接続元IPアドレスを明示的にブロックし、以降はそのIPアドレスからの接続を受け付けないように対策をするといったことが必要です。
まずは「SMTP-AUTH」の失敗ログを以下のコマンドで抜き出します。
# tail -n 1000 /var/log/maillog | grep "authentication failed"
上記の例では、 tail コマンドを指定し、ログの認証失敗行をログファイルの末尾から取得し1000行を抜き出します。
また、リアルタイムで現在発生している認証失敗ログを取得するには tailf コマンドを使用します。
# tailf /var/log/maillog | grep "authentication failed"
上記のコマンドを実行した場合に出力例は以下です。
Dec 8 14:08:41 xxxxxx postfix/smtpd[22226]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:08:44 xxxxxx postfix/smtpd[21543]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:08:45 xxxxxx postfix/smtpd[22451]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:08:46 xxxxxx postfix/smtpd[22434]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:08:54 xxxxxx postfix/smtpd[21701]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:08:54 xxxxxx postfix/smtpd[21766]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:08:55 xxxxxx postfix/smtpd[21569]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:09:02 xxxxxx postfix/smtpd[22438]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:09:03 xxxxxx postfix/smtpd[21747]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:09:04 xxxxxx postfix/smtpd[21906]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:09:09 xxxxxx postfix/smtpd[22434]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:09:11 xxxxxx postfix/smtpd[22451]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:09:12 xxxxxx postfix/smtpd[21543]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:09:16 xxxxxx postfix/smtpd[21701]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:09:18 xxxxxx postfix/smtpd[21766]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:09:19 xxxxxx postfix/smtpd[21569]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure Dec 8 14:09:23 xxxxxx postfix/smtpd[22226]: warning: unknown[45.142.120.xxx]: SASL LOGIN authentication failed: authentication failure
上記のログ出力例は、一部は加工して伏字にしていますが、実際に会社のメールサーバーに残っていたログです。
unknown[45.142.120.xxx] と表示されていますが、これは、送信元のIPアドレスからホスト名が逆引きできないことを表しています。
また、[45.142.120.xxx] のIPアドレスから1秒から数秒置きにSMTP認証を試みられていることが確認できます。
このIPアドレスはロシアの様です。
おそらく辞書攻撃で手当たり次第で認証を試みており、もし攻撃者が実際に存在するメールアドレスを使用して認証を試みていれば、何時かは認証が通ってしまう恐れがある為、何らかの対策が必要だということがわかります。
もしロシアの企業や顧客とメールでやり取りをする予定が無いのであれば、ロシアのIPアドレスを範囲指定で丸っとブロックしてしまうのが良さそうです。
最後に
今回はPostfixのログについて、初心者が実務で使用できるように、調査の最初の部分で利用できるコマンド例や出力内容の解説を紹介させていただきました。
次回の記事では、今回のログ調査で判明したロシアの接続元IPアドレスの通信をREJECTする具体的な手順や設定方法を紹介していきます。
↓続きの記事はこちら
今回の記事はここまで。
今回も読んでいただきありがとうございました。
