こんにちは。フリーエンジニアの木下です。
メールサーバーの配送ログはトラブルシューティングに必要な情報の一つです。
もしこのメールログ、読めない、という場合には知識として知っておいたほうがいい要素です。
今回はよく使われる有名なMTAプログラム(Mail Transfer Agent または Message Transfer Agent)から、qmail、sendmail、postfixの三大MTAにおいて記録されるメール送信(配送)成功ログをもとに、どのようなログが記録されていればメールの送信が成功しているのか、を確認します。すべてが解説できるわけではありませんが正常動作ログが把握できていれば、これ以外の記述がログになされていることで正常動作外の処理が発生したということが分かるようになります。
メールサーバー管理者に任命されたばかりでログの読み方がよく分からない方や、なんとなくは分かっているけどしっかりとメールサーバーのログを読めるようになりたいという読者の方に役に立つよう、メールログをできるだけ分かりやすく解説しています。
- 連載『メールと添付ファイルについて学ぼう』のほかの記事はこちら
第1回:メール添付ファイルでユーザーが思っている4つのこと - 第2回:なぜ、複雑な電子メールのルールは形骸化するのか
- 第3回:メール添付ファイルで遭遇するトラブル一例
- 第4回:ファイル分割が使われなくなった理由は
- 第5回:インフラ管理知識:メールの流れを把握する
- 第6回:この記事
Ⅰ.qmail配送成功のログ例
以下は社内メールサーバーではqmailを利用していて自IPが192.168.10.5で上位メールサーバーのIP192.168.101.15にメールリレーが成功した場合のログです。
架空のアドレスtestuser@gmoacademy.comというアドレスにメールを送信した場合、と言うケースでのログを掲載しています。
②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/80④2016-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: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: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との高い互換性が評判のメールサーバープログラムなので、ログの記述には多少似通った点が見受けられます。
このように正常な状態のログを知っていることで、異常が発生した時に正常時のログと見比べて、どの部分に記録されたメッセージの違いがあるか、そのメッセージは何を意味しているのか、を解決の糸口にトラブルシューティングすることで、やみくもに調査するよりも効率的に問題の絞り込みができるようになります。
ぜひ、お使いのメールサーバーのログをご覧になって、正常時にどのようなメッセージが出力されるのかを一度確認してみるのをお勧めします。