2016.09.07

メールサーバーが出すログの記述を把握する

160907_email_mv

こんにちは。フリーエンジニアの木下です。
メールサーバーの配送ログはトラブルシューティングに必要な情報の一つです。
もしこのメールログ、読めない、という場合には知識として知っておいたほうがいい要素です。

今回はよく使われる有名なMTAプログラム(Mail Transfer Agent または Message Transfer Agent)から、qmail、sendmail、postfixの三大MTAにおいて記録されるメール送信(配送)成功ログをもとに、どのようなログが記録されていればメールの送信が成功しているのか、を確認します。すべてが解説できるわけではありませんが正常動作ログが把握できていれば、これ以外の記述がログになされていることで正常動作外の処理が発生したということが分かるようになります。

メールサーバー管理者に任命されたばかりでログの読み方がよく分からない方や、なんとなくは分かっているけどしっかりとメールサーバーのログを読めるようになりたいという読者の方に役に立つよう、メールログをできるだけ分かりやすく解説しています。

Ⅰ.qmail配送成功のログ例

以下は社内メールサーバーではqmailを利用していて自IPが192.168.10.5で上位メールサーバーのIP192.168.101.15にメールリレーが成功した場合のログです。
架空のアドレスtestuser@gmoacademy.comというアドレスにメールを送信した場合、と言うケースでのログを掲載しています。

2016-03-15 10:54:07.457341500 info msg 9012312: bytes 1940 from <testuser@gmoacademy.com> qp 3858 uid 1000

2016-03-15 10:54:07.474204500 starting delivery 1029396: msg 9012312 to remote testuser@gmoacademy.com

2016-03-15 10:54:07.574229500 status: local 0/80 remote 1/802016-03-15 10:54:07.728275500 delivery 1029396: success: 192.168.101.15_accepted_message./Remote_host_said:_250_2.0.0_p2F1sViP003966_Message_accepted_for_delivery/2016-03-15 10:54:07.728283500 status: local 0/80 remote 0/80

2016-03-15 10:54:07.728288500 end msg 9012312

の行で、msg 9012312というIDのメッセージ送信処理が始まっています。この「9012312」が含まれる行は一連のメール送信動作に関わる記録だと判断できます。

最後にend msg 9012312で処理が終了しています。starting deliveryの一つ前にある「info msg 9012312」から「end msg 9012312」の一区切りが"一通のメールを送信するというログの始まりと終わり"になります。

行目にて「msg 9012312」というIDに「starting delivery 1029396」という配送IDが割り当てられ、送信処理が開始したことが分かります。
行目でリモートへの送信用にキュー(他のサーバーへ送信するための処理待ち)された「remote 1/80」が見えます。

行目で「delivery 1029396: success: 」と記載があって配送が完了したことが分かります。
行目では「delivery 1029396: success:」とあり、リレーホスト(電子メールの受け取り手のサーバー)のIP「192.168.101.15」への送信が完了したメッセージ「accepted_message.」および「Message_accepted_for_delivery」が表記されていることから、リレー先でメールを受け取ってもらえた、ということが分かります。なお「Remote_host_said」に続くメッセージが送信先メールサーバーが出力した正常受信メッセージです。

最終的にこの「accepted_message」があれば自ホストからエラーなくメールが送信された、という判断できます。逆にエラーの場合には「accepted_message」の部分がエラーを意味する単語に変わります。


Ⅱ.sendmail配送成功の場合

先のqmailメールサーバーで送信したリレー先IP192.168.101.15がsendmailだったという仮定で、そのsendomailのログを見えてみましょう。
そのメールの送信ログが下記のようになります。
メールサーバーがqmailの時と同様、配送が成功した場合のログで、記述されたホスト名やIPアドレスは架空のものになっています。

Mar 15 10:54:31 mxhost sendmail[3966]: p2F1PiVs015001: from=<testuser@gmoacademy.com>, size=1940, class=0, nrcpts=1, msgid=<TinNvkXLAL_1Ed7EGX5VY0C+45jp+CJ2uSBxaihU=DnS@gmoacademy.com>, proto=SMTP, daemon=MTA-v6, relay=mail.local [192.168.10.5]

Mar 15 10:54:32 mxhost sendmail[3972]: STARTTLS=client, relay=gm-smtp.gmoacademy.com., version=TLSv1/SSLv3, verify=FAIL, cipher=RC4-SHA, bits=128/128

Mar 15 10:54:33 mxhost sendmail[3972]: p2F1PiVs015001: to=<testuser@gmoacademy.com>, delay=00:00:02, xdelay=00:00:02, mailer=esmtp, pri=121940, relay=gm-smtp.gmoacademy.com. [XX.XX.XX.XX], dsn=2.0.0, stat=Sent (OK 1300154073 x11si7819867wfd.81)

①行目のログ記述で「relay=mail.local [192.168.10.5]」と記載があり、リレー元のメールサーバーからメールを受け取ったことが分かります。このメールを再度自ホストから送信するようキュー(他のサーバーへ送信するための処理待ち)に入れています。

sendmailでは配送の成功は「stat=」とあるところを見えるようにします。最終行に「to=<testuser@gmoacademy.com>」と、記述がありまして、「stat=Sent (OK」と記述があります。

この「stat=Sent (OK~」の記述があれば自ネットワーク内のメールサーバーからエラーなく外部のメールサーバーに送信された、と判断することができます。
逆に、エラーが発生した場合にはこの「stat=」の右辺が「Data format error」や「User unknown」のように直接的にエラーの要因を示すメッセージが記録されるようになります。


Ⅲ.PostFix配送成功の場合

最後にPostfixです。Postfixは他の二つと相違しまして、メールサーバーのユーザが電子メールの宛先に<testuser@send.domain.com>を指定して、メールを送信した場合のログとなります。
メール送信成功のログは以下のようになります。

Jul 5 17:52:50 mfgw1 postfix/smtps/smtpd[3362]: connect from hostname.domain.com[192.168.201.35]

Jul 5 17:52:51 mfgw1 postfix/smtps/smtpd[3362]: 07BC615C032: client=hostname.domain.com[192.168.201.35], sasl_method=LOGIN, sasl_username=t1user

Jul 5 17:52:51 mfgw1 postfix/cleanup[3365]: 07BC615C032: message-id=<000XXXXXXXXXXXXXXXXXXXXXXXXXXX$@send.domain.com>

Jul 5 17:52:51 mfgw1 postfix/qmgr[10852]: 07BC615C032: from=<t1user@send.domain.com>, size=961, nrcpt=1 (queue active)

Jul 5 17:52:52 mfgw1 postfix/smtp[3366]: 07BC615C032: to=<testuser@gmoacademy.com>, relay=host.gmoacademy.com [XX.XXX.XX.XX]:25, delay=1.6, delays=0.3/0/0.73/0.58, dsn=2.0.0, status=sent (250 2.0.0 OK 1467708772 67uq1t0043dLKTM017uqYP.255 - gsmtp)

Jul 5 17:52:52 mfgw1 postfix/qmgr[10852]: 07BC615C032: removed

Jul 5 17:52:53 mfgw1 postfix/smtps/smtpd[3362]: disconnect from hostname.domain.com[192.168.201.35]

行目で「connect from」で始まる部分に、メールサーバーに接続してきた社内PCのホスト名とIPアドレスが記録されます。これがインターネット上であればグローバルIPとグローバルのDNSで名前解決した結果のホスト名が記録されることになります。

行目でメールサーバーのユーザ「t1user」がメールの送信を開始したことが記録されています。メッセージにある「07BC615C032」に注目です。このメールの送信に関するログエントリにはおしなべて「07BC615C032」というIDが記述されています。

行目と行目で、メールの送信準備のためにキュー(他のサーバーへ送信するための処理待ち)に入ったことが記録されています。「queue active」と表記されています。

行目で実際に送信した相手のメールサーバーへ無事メールが届いた、という趣旨の記述がされています。この行にあるように「status=sent」となっていて「status=sent (250 2.0.0 OK」と表記されることになります。エラーの場合にはこの部分が「status=deferred」となりエラーの要因となっているエラーメッセージが続けて表記されます。

このメールは正常に処理が完了しているので、六行目では「07BC615C032: removed」と記録され、相手先メールサーバーにメールの引き渡しが完了したメールを自サーバー内から削除しています。
最終的に送信を完了し終えたメールサーバーとメールクライアント(PC)との接続が切断され、メールの送信が完了したことが七行目のように記録されます。


Ⅳ.ログの記述は違いが大きい

ここまでで、比較的歴史の長い有名なMTAが記録する主要なメール送信のログを解説してきましたが、同じメールサーバーのメール送信ログなのに、表記や表現方法が違うことはお分かりいただけたでしょうか?
同じメールサーバーでもこれだけ違ってくると、qmailなら分かるのですがPostfixは全然分かりません、ということもあるかもしれませんね。
※ただしPostfixはsendmailとの高い互換性が評判のメールサーバープログラムなので、ログの記述には多少似通った点が見受けられます。

このように正常な状態のログを知っていることで、異常が発生した時に正常時のログと見比べて、どの部分に記録されたメッセージの違いがあるか、そのメッセージは何を意味しているのか、を解決の糸口にトラブルシューティングすることで、やみくもに調査するよりも効率的に問題の絞り込みができるようになります。

ぜひ、お使いのメールサーバーのログをご覧になって、正常時にどのようなメッセージが出力されるのかを一度確認してみるのをお勧めします。

simplemail-bna

この記事を書いた人

木下肇

東京/神奈川を中心に、都内中堅企業ではシステム部門の一員として部内インフラ業務に、別の小規模企業ではインフラ全般について管理業務の委託を受けるフリーエンジニア。オンプレミスの企業内インフラからクラウド環境のサーバ/ネットワークまで、OS守備範囲はWindowsからLinuxまで、障害の診断や修復/修理であればソフトからハードまで、幅広い守備範囲で日々お客様の業務を遂行しています。
お仕事のご相談はコチラ⇒http://www.treedown.net/

GMOクラウドアカデミーYouTubeチャンネルはこちらから

アカデミー用バナー

メルマガ会員募集中!

アカデミーの最新情報や会員限定のお得な情報をお届けします。

メルマガ登録はこちら