logは、障害だけではなくモジュールの動作も示してくれるわけで。ってご存じだったかな。
何を言いたいかというと、maillog一つ取ってみてもsmtpプロトコルのように詳細な手順をlogがはき出してくれる。とても便利だったりする。ここでは、日頃何気なく使っているメールのsmtpプロトコルのセッション確立からデータ配送までをlogと比較しながら説明していきたい。
１．メール配送の構造
以下、図１はbbb.jpドメインのユーザ（def@bbb.jp）がaaa.jpドメインのユーザ（abc@aaa.jp）宛へメールを配送する構造を示している。
■ MUA（Mail User Agent）は、メールクライアントを指す。POP3やIMAPプロトコルでメッセージを読んだり出来る。OutLookやOutLookExpressやBecky!などがそうである。
■ MRA（Mail Retrieval Agent）は、MUAがメッセージを取り出す操作を可能にする部分である。つまり、POP3やIMAPプロトコルでMUAと通信する部分である。
■ MailSpoolは、早い話メールボックスだ。送られてきたメールを一時的に保管する場所である。
■ MDA（Mail Delivery Agent）は、MTAが受け取ったメッセージをユーザ毎に分別してmail spoolへ格納する役割をする。
■ MTA（Mail Transfer Agent）は、メッセージの配送を行う部分だ。基本的には、メールを送信したり受信したりする。メールサーバの骨格はここになる。インターネット上でsmtpプロトコルを使ってお互いのサーバでデリバリーするのはこの部分である。
■ DNSが書いてあるのは、メールを配送する場合、MXレコードの問い合わせ等が発生するからである。DNS無しにはメール配送は語れない。
２．smtpプロトコルの手順の詳細
３．maillogの内容とsmtpプロトコルの手順との比較
１）メールlogで見るメール配送の為のセッション確立からメール送信までの様子
Aug 2 12:59:00 ns postfix/smtpd[9550]: connect from mail.bbb.jp[xxx.xxx.xxx.xxx]
Aug 2 12:59:04 ns postfix/smtpd[9550]: 28B89200BD: client=mail.bbb.jp[xxx.xxx.xxx.xxx]
Aug 2 12:59:04 ns postfix/cleanup[9553]: 28B89200BD: message-id=<20060802131206.EB87.DEF@bbb.jp>
Aug 2 12:59:04 ns postfix/smtpd[9550]: disconnect from mail.bbb.jp[xxx.xxx.xxx.xxx]
Aug 2 12:59:04 ns postfix/qmgr[2125]: 28B89200BD: from=<def@bbb.jp>, size=1219, nrcpt=1 (queue active)
Aug 2 12:59:04 ns postfix/smtpd[9557]: connect from localhost.localdomain[127.0.0.1]
Aug 2 12:59:04 ns postfix/smtpd[9557]: 51589202F8: client=localhost.localdomain[127.0.0.1]
Aug 2 12:59:04 ns postfix/cleanup[9553]: 51589202F8: message-id=<20060802131206.EB87.DEF@bbb.jp>
Aug 2 12:59:04 ns postfix/qmgr[2125]: 51589202F8: from=<def@bbb.jp>, size=1695, nrcpt=1 (queue active)
Aug 2 12:59:04 ns postfix/smtpd[9557]: disconnect from localhost.localdomain[127.0.0.1]
Aug 2 12:59:04 ns amavis[27759]: (27759-09) Passed CLEAN, [xxx.xxx.xxx.xxx] <def@bbb.jp> -> <abc@aaa.jp>, Message-ID: <20060802131206.EB87.DEF@bbb.jp>, mail_id: 18FJHAqk3-yu, Hits: 0., queued_as: 51589202F8, 201 ms
Aug 2 12:59:04 ns bogofilter[9561]: X-Bogosity: Unsure, spamicity=0.520000, version=1.0.2
Aug 2 12:59:04 ns postfix/smtp[9554]: 28B89200BD: to=<abc@aaa.jp>, relay=127.0.0.1[127.0.0.1], delay=4, status=sent (250 2.6.0 Ok, id=27759-09, from MTA([127.0.0.1]:10025): 250 Ok: queued as 51589202F8)
Aug 2 12:59:04 ns postfix/qmgr[2125]: 28B89200BD: removed
Aug 2 12:59:04 ns postfix/local[9558]: 51589202F8: to=<abc@aaa.jp>, relay=local, delay=0, status=sent (delivered to command: /usr/bin/procmail -m /etc/postfix/procmailrc)
Aug 2 12:59:04 ns postfix/qmgr[2125]: 51589202F8: removed
図３ smtp.aaa.jpサーバmaillogの中身
２）２項の図２の内容と上の図３の内容を比較して説明
○の番号は、図２の○番号に対応。
■ 接続確立
Aug 2 12:59:00 ns postfix/smtpd[9550]: connect from mail.bbb.jp[xxx.xxx.xxx.xxx]
① まずは接続要求を相手に投げる。
② smtp.aaa.jpから接続受理、220 サービスが準備出来ました。
■ エンベロープ情報送受信
Aug 2 12:59:04 ns postfix/smtpd[9550]: 28B89200BD: client=mail.bbb.jp[xxx.xxx.xxx.xxx]
③ HELO smtpセッション開始。
④ smtp.aaa.jpは 250 ok（了解）。
エンベロープ情報に入力。
⑤ Mail Fromは、 def@bbb.jpだよ。
⑥ 250 ok（了解）。
⑦ RcptToは、abc@aaa.jpだよ。
⑧ 250 ok（了解）。
■ ヘッダー情報及び本文送信、セッション終了
Aug 2 12:59:04 ns postfix/cleanup[9553]: 28B89200BD: message-id=<20060802131206.EB87.DEF@bbb.jp>
Aug 2 12:59:04 ns postfix/smtpd[9550]: disconnect from mail.bbb.jp[xxx.xxx.xxx.xxx]
Aug 2 12:59:04 ns postfix/qmgr[2125]: 28B89200BD: from=<def@bbb.jp>, size=1219, nrcpt=1 (queue active)
Aug 2 12:59:04 ns postfix/smtpd[9557]: connect from localhost.localdomain[127.0.0.1]
Aug 2 12:59:04 ns postfix/smtpd[9557]: 51589202F8: client=localhost.localdomain[127.0.0.1]
Aug 2 12:59:04 ns postfix/cleanup[9553]: 51589202F8: message-id=<20060802131206.EB87.DEF@bbb.jp>
Aug 2 12:59:04 ns postfix/qmgr[2125]: 51589202F8: from=<def@bbb.jp>, size=1695, nrcpt=1 (queue active)
Aug 2 12:59:04 ns postfix/smtpd[9557]: disconnect from localhost.localdomain[127.0.0.1]
Aug 2 12:59:04 ns amavis[27759]: (27759-09) Passed CLEAN, [xxx.xxx.xxx.xxx] <def@bbb.jp> -> <abc@aaa.jp>, Message-ID: <20060802131206.EB87.DEF@bbb.jp>, mail_id: 18FJHAqk3-yu, Hits: 0., queued_as: 51589202F8, 201 ms
Aug 2 12:59:04 ns bogofilter[9561]: X-Bogosity: Unsure, spamicity=0.520000, version=1.0.2
Aug 2 12:59:04 ns postfix/smtp[9554]: 28B89200BD: to=<abc@aaa.jp>, relay=127.0.0.1[127.0.0.1], delay=4, status=sent (250 2.6.0 Ok, id=27759-09, from MTA([127.0.0.1]:10025): 250 Ok: queued as 51589202F8)
Aug 2 12:59:04 ns postfix/qmgr[2125]: 28B89200BD: removedここ迄のlogでは、実際にはamavisdを使ってウィルスチェックをするためポートフォワードをしているため、いったん以下のようにsmtpセッションを終了している。
Aug 2 12:59:04 ns postfix/smtpd[9557]: disconnect from localhost.localdomain[127.0.0.1]
⑨ メールヘッダー送信。
⑩ メールの内容を送信してください。メールのデータの終わりの「.」ドットが来るまで待ちます。
⑪ メールの内容の送信。
⑫ 「.」ドットを送信。
⑬ 250 ok（了解）。
⑭ セッション終了要求。
⑮ セッション終了チャネル開放。
Aug 2 12:59:04 ns amavis[27759]: (27759-09) Passed CLEAN, [xxx.xxx.xxx.xxx] <def@bbb.jp> -> <abc@aaa.jp>, Message-ID: <20060802131206.EB87.DEF@bbb.jp>, mail_id: 18FJHAqk3-yu, Hits: 0., queued_as: 51589202F8, 201 ms
Aug 2 12:59:04 ns bogofilter[9561]: X-Bogosity: Unsure, spamicity=0.520000, version=1.0.2
Aug 2 12:59:04 ns postfix/smtp[9554]: 28B89200BD: to=<abc@aaa.jp>, relay=127.0.0.1[127.0.0.1], delay=4, status=sent (250 2.6.0 Ok, id=27759-09, from MTA([127.0.0.1]:10025): 250 Ok: queued as 51589202F8)ここの部分に関しては、ウィルスチェックとベイジリアン型スパムチェッカーが動いているので、このようなlogとなっているので、実際にはsmtpセッションとは無関係。
４．データを各フェーズ（層）毎にカプセル化して送ることを忘れずに
SMTPプロトコル（手順）は解ったけど、メール本文とかヘッダーはカプセル化されて送受信してることを忘れてはならない。ここで、基本に戻ってOSI基本参照モデルを思い出して、図３のような絵を描いてみた。
SMTPメッセージは、最終的に赤の四角で囲まれたMACフレームが生成され送信される、受信側では、MACフレームが各フェーズに分解されて各フェーズにより元のデータに復元される。
以上
コメント