なにかと面倒なメールログ調査
どうも、やまもとやまです。
サーバー運用をしていると、よくあるのがメール関連のお問い合わせ。
メールログの調査はシンプルでいて奥が深い・・・かもしれない。
そこで、メール送受信の履歴をワンライナーで出力してみます。
環境
シェルはBashを想定し、MTAにPostfixを利用した一般的な環境になります。
今回の対象サーバーはたまたまPleskが入っていますが、ログへの大きな影響はないでしょう。
たぶん。
やってみよう！
それでは、「yamamoto@example.com」というメールアドレスから送信されたメールを抽出してみます。
# grep 'from=<yamamoto@example.com>' /var/log/maillog
Apr 27 08:43:07 mail postfix/qmgr[32219]: 29BAC20D3102B: from=<yamamoto@example.com>, size=14727442, nrcpt=3 (queue active)
Apr 27 09:50:53 mail postfix/qmgr[32219]: A9DEF205EB61F: from=<yamamoto@example.com>, size=4353931, nrcpt=1 (queue active)
Apr 27 09:50:59 mail postfix/qmgr[32219]: 11FAF20524B59: from=<yamamoto@example.com>, size=4354495, nrcpt=1 (queue active)
Apr 27 11:10:36 mail postfix/qmgr[32219]: DD1EF20794099: from=<yamamoto@example.com>, size=23030, nrcpt=3 (queue active)どうやら4通送信されているようですね。
それぞれ1件ずつ調べても良いのですが、それも面倒です。
というわけで、awkで6カラム目のキューIDだけ取り出します。
# grep 'from=<yamamoto@example.com>' /var/log/maillog | awk '{print $6}'
29BAC20D3102B:
A9DEF205EB61F:
11FAF20524B59:
DD1EF20794099:取り出せましたね。
では、それぞれのキューIDに対して、forループを使ってgrepでログ検索を行います（日本語あってる？）。
# for queueid in `grep 'from=<yamamoto@example.com>' /var/log/maillog | awk '{print $6}'`; do grep ${queueid} /var/log/maillog; done
Apr 27 08:42:54 mail postfix/smtpd[18880]: 29BAC20D3102B: client=client.example.com[xxx.xxx.xxx.xxx], sasl_method=DIGEST-MD5, sasl_username=yamamoto@example.com
Apr 27 08:42:54 mail postfix/cleanup[17175]: 29BAC20D3102B: message-id=<000201d859c7$5962f0d0$0c28d270$@example.com>
Apr 27 08:43:07 mail postfix/qmgr[32219]: 29BAC20D3102B: from=<yamamoto@example.com>, size=14727442, nrcpt=3 (queue active)
Apr 27 08:43:07 mail postfix/pipe[24267]: 29BAC20D3102B: to=<yama@example.com>, relay=plesk_virtual, delay=13, delays=13/0.01/0/0.26, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Apr 27 08:43:07 mail postfix/pipe[19291]: 29BAC20D3102B: to=<moto@example.com>, relay=plesk_virtual, delay=13, delays=13/0/0/0.28, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Apr 27 08:43:58 mail postfix/smtp[23955]: 29BAC20D3102B: to=<motoyama@test.example.com>, relay=test.example.com[xxx.xxx.xxx.xxx]:25, delay=64, delays=13/0/0.92/50, dsn=2.0.0, status=sent (250 2.0.0 OK 1651016638 p24-20020a637f58000000b003c14249f5a1si763086pgn.410)
Apr 27 08:43:58 mail postfix/qmgr[32219]: 29BAC20D3102B: removed
Apr 27 09:50:49 mail postfix/smtpd[20348]: A9DEF205EB61F: client=client.example.com[xxx.xxx.xxx.xxx], sasl_method=DIGEST-MD5, sasl_username=yamamoto@example.com
Apr 27 09:50:49 mail postfix/cleanup[19047]: A9DEF205EB61F: message-id=<000801d859d0$d6915cf0$83b416d0$@example.com>
Apr 27 09:50:53 mail postfix/qmgr[32219]: A9DEF205EB61F: from=<yamamoto@example.com>, size=4353931, nrcpt=1 (queue active)
Apr 27 09:50:54 mail postfix/smtp[22297]: A9DEF205EB61F: to=<maya@example.jp>, relay=mail.example.jp[xxx.xxx.xxx.xxx]:25, delay=5, delays=4.1/0/0.02/0.85, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as CE1CB81A97)
Apr 27 09:50:54 mail postfix/qmgr[32219]: A9DEF205EB61F: removed
Apr 27 09:50:55 mail postfix/smtpd[9084]: 11FAF20524B59: client=sv.example.com[xxx.xxx.xxx.xxx]
Apr 27 09:50:55 mail postfix/cleanup[19763]: 11FAF20524B59: message-id=<000801d859d0$d6915cf0$83b416d0$@example.com>
Apr 27 09:50:59 mail postfix/qmgr[32219]: 11FAF20524B59: from=<yamamoto@example.com>, size=4354495, nrcpt=1 (queue active)
Apr 27 09:50:59 mail postfix/pipe[13627]: 11FAF20524B59: to=<yama@example.com>, relay=plesk_virtual, delay=4.2, delays=4/0/0/0.17, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Apr 27 09:50:59 mail postfix/qmgr[32219]: 11FAF20524B59: removed
Apr 27 11:10:34 mail postfix/smtpd[30399]: DD1EF20794099: client=client.example.com[xxx.xxx.xxx.xxx], sasl_method=DIGEST-MD5, sasl_username=yamamoto@example.com
Apr 27 11:10:35 mail postfix/cleanup[25427]: DD1EF20794099: message-id=<001701d859db$fac67690$f05363b0$@example.com>
Apr 27 11:10:36 mail postfix/qmgr[32219]: DD1EF20794099: from=<yamamoto@example.com>, size=23030, nrcpt=3 (queue active)
Apr 27 11:10:36 mail postfix/smtp[532]: DD1EF20794099: to=<yamayama@sample.example.com>, relay=sample.example.com[xxx.xxx.xxx.xxx]:25, delay=1.8, delays=1.4/0/0.08/0.32, dsn=2.0.0, status=sent (250 Message received: 20220427021036.QSYZ28492)
Apr 27 11:10:36 mail postfix/smtp[532]: DD1EF20794099: to=<mayamaya@sample.example.com>, relay=sample.example.com[xxx.xxx.xxx.xxx]:25, delay=1.8, delays=1.4/0/0.08/0.32, dsn=2.0.0, status=sent (250 Message received: 20220427021036.QSYZ28492)
Apr 27 11:10:37 mail postfix/pipe[31472]: DD1EF20794099: to=<motomoto@example.com>, relay=plesk_virtual, delay=2.5, delays=1.4/0/0/1.1, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Apr 27 11:10:37 mail postfix/qmgr[32219]: DD1EF20794099: removedずらずら出てきました。
出てきたのはいいけど、びっくりするくらい読みにくいです。
仕方ないので、もう1回awkを使って整形してやります。
# for queueid in `grep 'from=<yamamoto@example.com>' /var/log/maillog | awk '{print $6}'`; do grep ${queueid} /var/log/maillog | grep 'to=<' | awk '{print $1,$2,$3,"from=<yamamoto@example.com>",$7}'; done
Apr 27 08:43:07 from=<yamamoto@example.com> to=<yama@example.com>,
Apr 27 08:43:07 from=<yamamoto@example.com> to=<moto@example.com>,
Apr 27 08:43:58 from=<yamamoto@example.com> to=<motoyama@test.example.com>,
Apr 27 09:50:54 from=<yamamoto@example.com> to=<maya@example.jp>,
Apr 27 09:50:59 from=<yamamoto@example.com> to=<yama@example.com>,
Apr 27 11:10:36 from=<yamamoto@example.com> to=<yamayama@sample.example.com>,
Apr 27 11:10:36 from=<yamamoto@example.com> to=<mayamaya@sample.example.com>,
Apr 27 11:10:37 from=<yamamoto@example.com> to=<motomoto@example.com>,なんだか最後のカンマが格好悪い。。
# for queueid in `grep 'from=<yamamoto@example.com>' /var/log/maillog | awk '{print $6}'`; do grep ${queueid} /var/log/maillog | grep 'to=<' | awk '{print $1,$2,$3,"from=<yamamoto@example.com>",$7}'|tr -d ','; done
Apr 27 08:43:07 from=<yamamoto@example.com> to=<yama@example.com>
Apr 27 08:43:07 from=<yamamoto@example.com> to=<moto@example.com>
Apr 27 08:43:58 from=<yamamoto@example.com> to=<motoyama@test.example.com>
Apr 27 09:50:54 from=<yamamoto@example.com> to=<maya@example.jp>
Apr 27 09:50:59 from=<yamamoto@example.com> to=<yama@example.com>
Apr 27 11:10:36 from=<yamamoto@example.com> to=<yamayama@sample.example.com>
Apr 27 11:10:36 from=<yamamoto@example.com> to=<mayamaya@sample.example.com>
Apr 27 11:10:37 from=<yamamoto@example.com> to=<motomoto@example.com>これでよし。
履歴が無事ワンライナーで表示できました。ばんざい。
受信についても同様に対応可能です。まとめてやろうと思うとちょっと面倒かも。
とりあえずできた
今回取り上げたケースはあまりややこしくはないですが、もっと複雑な場合も分割していけば一応は力業でワンライナー処理できます。
また、本来は送受信完了のチェックとかする必要があるので、もう少し複雑になるはずですね。
他にも、力業でforループを使いすぎるとログ行数が大きくなると計算量が爆発したり、めちゃくちゃ流量の多いメールサーバーだとキューIDかぶりとか出てきて考慮することも多くなります。
とはいえシンプルなケースでは十分使えるので、練習がてらいろいろ試してみてはいかがでしょうか。
それではまた！
