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

[Mitsuru Ogino <ogino@xxxxxxxxxx>]

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

今回問題が発生したホストは数千人のユーザがおり、おいそれと実験できない
ため、別のサーバでとりあえず 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@testsrv.example.jp
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@testsrv.example.jp> SIZE=367
Mar  7 10:47:52 testsrv postfix/smtp[21533]: > maia1.sv.example.jp[192.168.127.15]: RCPT TO:<dest@example.jp> ORCPT=rfc822;dest@example.jp
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@testsrv.example.jp>: 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@testsrv.example.jp>: 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@testsrv.example.jp> SIZE=367
Mar  7 10:47:52 testsrv postfix/smtp[21533]: > mx2.example.jp[192.168.120.16]: RCPT TO:<dest@example.jp> ORCPT=rfc822;dest@example.jp
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@example.jp>, 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@xxxxxxxxxxxxxxxxxxxx
http://lists.sourceforge.jp/mailman/listinfo/postfix-jp-list