2012年3月 7日

[postfix-jp: 4075] Re:1台目の relayhost が 4xx を帰す時

荻野です。お世話になっております。

今回問題が発生したホストは数千人のユーザがおり、おいそれと実験できない
ため、別のサーバでとりあえず relayhost のみ設定した状態で検証したところ、
問題は再現せず、即座に次のサーバにフォールバックが発生しました。

したがって、relayhost に MX を指定した場合にフォールバックしないという
挙動は少なくとも Postfix の固定された仕様というわけではなさそうです。

検証用に、おなじ RHEL 5.8 + postfix-2.3.3-2.3.el5_6 のサーバを準備。た
だ、DMZ 上に用意できなかったので IPv6 環境がありませんでした。今回の問
題とは関係ないと思いたいですが。

このサーバの main.cf で relayhost=mxtest.example.jp を指定。
このサーバの master.cf で smtp unix - - n - - smtp -v と詳細ログを指定。

mxtest.example.jp には、本来の mx.example.jp. の優先サーバ mx1 の代わり
に、検証用 relayhost を指定。

mx.example.jp. IN MX 10 mx1.example.jp.
mx.example.jp. IN MX 20 mx2.example.jp.

mxtest.example.jp. IN MX 10 maia1.sv.example.jp.
mxtest.example.jp. IN MX 20 mx2.example.jp.

maia1.sv.example.jp では、

relay_domains = example.jp
smtpd_delay_reject = no
smtpd_sender_restrictions = hash:$config_directory/client_mailfrom

として client_mailfrom では

451 4.7.1 Service unavailable - try again later

を返すように設定。

この状態で、まったく問題なくフォールバックしてしまい、delay=0.11 で配送
されてしまいました。


とりあえず、仕様ではなさそうだという見当が付きましたので、
・設定の問題
・メールの流量の問題
などを詰めていくしかなさそうです。

流量の問題は、

smtp_connection_cache_destinations = mxtest.example.jp.

が関係するかもと思って設定してみましたが、結果は同じでした。


引き続き、なにかヒント等ありましたらご示唆いただければ幸いです。


フォールバックするときの smtp -v のログを載せておきます:

Mar 7 10:47:52 testsrv postfix/smtp[21533]: deliver_request_get: file active/0441022804D
Mar 7 10:47:52 testsrv postfix/smtp[21533]: deliver_message: from root@xxxxx
Mar 7 10:47:52 testsrv postfix/smtp[21533]: smtp_parse_destination: mxtest.example.jp smtp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: connecting to mxtest.example.jp port 25
Mar 7 10:47:52 testsrv postfix/smtp[21533]: dns_query: mxtest.example.jp (MX): OK
Mar 7 10:47:52 testsrv postfix/smtp[21533]: dns_get_answer: type MX for mxtest.example.jp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: dns_get_answer: type MX for mxtest.example.jp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: smtp_addr_one: host maia1.sv.example.jp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: lookup maia1.sv.example.jp type A flags 128
Mar 7 10:47:52 testsrv postfix/smtp[21533]: dns_query: maia1.sv.example.jp (A): OK
Mar 7 10:47:52 testsrv postfix/smtp[21533]: dns_get_answer: type A for maia1.sv.example.jp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: smtp_addr_one: host mx2.example.jp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: lookup mx2.example.jp type A flags 128
Mar 7 10:47:52 testsrv postfix/smtp[21533]: dns_query: mx2.example.jp (A): OK
Mar 7 10:47:52 testsrv postfix/smtp[21533]: dns_get_answer: type A for mx2.example.jp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: begin mxtest.example.jp address list
Mar 7 10:47:52 testsrv postfix/smtp[21533]: pref 10 host maia1.sv.example.jp/192.168.127.15
Mar 7 10:47:52 testsrv postfix/smtp[21533]: pref 20 host mx2.example.jp/192.168.120.16
Mar 7 10:47:52 testsrv postfix/smtp[21533]: end mxtest.example.jp address list
Mar 7 10:47:52 testsrv postfix/smtp[21533]: smtp_find_self: not found
Mar 7 10:47:52 testsrv postfix/smtp[21533]: smtp_connect_addr: trying: maia1.sv.example.jp[192.168.127.15] port 25...
Mar 7 10:47:52 testsrv postfix/smtp[21533]: global TLS level: none
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 220 maia1.sv.example.jp ESMTP Postfix (Ubuntu)
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > maia1.sv.example.jp[192.168.127.15]: EHLO testsrv.example.jp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 250-maia1.sv.example.jp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 250-PIPELINING
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 250-SIZE 51200000
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 250-VRFY
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 250-ETRN
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 250-STARTTLS
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 250-ENHANCEDSTATUSCODES
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 250-8BITMIME
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 250 DSN
Mar 7 10:47:52 testsrv postfix/smtp[21533]: server features: 0x901f size 51200000
Mar 7 10:47:52 testsrv postfix/smtp[21533]: Using ESMTP PIPELINING, TCP send buffer size is 4096
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > maia1.sv.example.jp[192.168.127.15]: MAIL FROM:<root@xxxxx> SIZE=367
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > maia1.sv.example.jp[192.168.127.15]: RCPT TO:<dest@xxxxx> ORCPT=rfc822;dest@xxxxx
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > maia1.sv.example.jp[192.168.127.15]: DATA
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 451 4.7.1 <root@xxxxx>: Sender address rejected: Service unavailable - try again
Mar 7 10:47:52 testsrv postfix/smtp[21533]: 0441022804D: host maia1.sv.example.jp[192.168.127.15] said: 451 4.7.1 <root@xxxxx>: Sender address rejected: Service unavailable - try again later (in reply to MAIL FROM command)
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 503 5.5.1 Error: need MAIL command
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 503 5.5.1 Error: need RCPT command
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > maia1.sv.example.jp[192.168.127.15]: RSET
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > maia1.sv.example.jp[192.168.127.15]: QUIT
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < maia1.sv.example.jp[192.168.127.15]: 250 2.0.0 Ok
Mar 7 10:47:52 testsrv postfix/smtp[21533]: name_mask: resource
Mar 7 10:47:52 testsrv postfix/smtp[21533]: name_mask: software
Mar 7 10:47:52 testsrv postfix/smtp[21533]: smtp_connect_addr: trying: mx2.example.jp[192.168.120.16] port 25...
Mar 7 10:47:52 testsrv postfix/smtp[21533]: global TLS level: none
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 220 mx2.example.jp ESMTP Postfix
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > mx2.example.jp[192.168.120.16]: EHLO testsrv.example.jp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250-mx2.example.jp
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250-PIPELINING
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250-SIZE 26214400
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250-VRFY
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250-ETRN
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250-ENHANCEDSTATUSCODES
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250-8BITMIME
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250 DSN
Mar 7 10:47:52 testsrv postfix/smtp[21533]: server features: 0x800f size 26214400
Mar 7 10:47:52 testsrv postfix/smtp[21533]: Using ESMTP PIPELINING, TCP send buffer size is 4096
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > mx2.example.jp[192.168.120.16]: MAIL FROM:<root@xxxxx> SIZE=367
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > mx2.example.jp[192.168.120.16]: RCPT TO:<dest@xxxxx> ORCPT=rfc822;dest@xxxxx
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > mx2.example.jp[192.168.120.16]: DATA
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250 2.1.0 Ok
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250 2.1.5 Ok
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 354 End data with <CR><LF>.<CR><LF>
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > mx2.example.jp[192.168.120.16]: .
Mar 7 10:47:52 testsrv postfix/smtp[21533]: > mx2.example.jp[192.168.120.16]: QUIT
Mar 7 10:47:52 testsrv postfix/smtp[21533]: < mx2.example.jp[192.168.120.16]: 250 2.0.0 Ok: queued as 14D085205A
Mar 7 10:47:52 testsrv postfix/smtp[21533]: 0441022804D: to=<dest@xxxxx>, relay=mx2.example.jp[192.168.120.16]:25, delay=0.11, delays=0.07/0.01/0.02/0.02, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 14D085205A)
Mar 7 10:47:52 testsrv postfix/smtp[21533]: name_mask: resource
Mar 7 10:47:52 testsrv postfix/smtp[21533]: name_mask: software
Mar 7 10:47:52 testsrv postfix/smtp[21533]: deliver_request_final: send: "" 0
Mar 7 10:47:52 testsrv postfix/smtp[21533]: send attr status =
Mar 7 10:47:52 testsrv postfix/smtp[21533]: send attr diag_type =
Mar 7 10:47:52 testsrv postfix/smtp[21533]: send attr diag_text =
Mar 7 10:47:52 testsrv postfix/smtp[21533]: send attr mta_type =
Mar 7 10:47:52 testsrv postfix/smtp[21533]: send attr mta_mname =
Mar 7 10:47:52 testsrv postfix/smtp[21533]: send attr action =
Mar 7 10:47:52 testsrv postfix/smtp[21533]: send attr reason =
Mar 7 10:47:52 testsrv postfix/smtp[21533]: send attr status = 0
Mar 7 10:47:52 testsrv postfix/qmgr[21518]: 0441022804D: removed
Mar 7 10:47:52 testsrv postfix/smtp[21533]: master_notify: status 1
Mar 7 10:47:52 testsrv postfix/smtp[21533]: connection closed


--
荻野 充 (おぎの みつる) ... 「萩(はぎ)」にあらず
Key fingerprint = 7F26 5414 1805 F31B 1617 10B7 C117 07AE 1691 9BD1

_______________________________________________
Postfix-jp-list mailing list
Postfix-jp-list@xxxxx
http://lists.sourceforge.jp/mailman/listinfo/postfix-jp-list


投稿者 xml-rpc : 2012年3月 7日 15:33
役に立ちました?:
過去のフィードバック 平均:(0) 総合:(0) 投票回数:(0)
本記事へのTrackback: http://hoop.euqset.org/blog/mt-tb2006.cgi/109002
トラックバック
コメント
コメントする




画像の中に見える文字を入力してください。