Soukaku's HENA-CHOKO Blog

  • Home
  • Computer
  • Network
  • なんで、そこでRSETを2発送るのかが理解出来ないんだが…

なんで、そこでRSETを2発送るのかが理解出来ないんだが…

ココ何日か、客先のメールサーバでログを見ていて、ちょっと気になるのがあった。

下は、postfixのログから、一部切り出したものなのだけど…。

May  2 10:32:11 imx01 postfix/smtpd[18313]: connect from unknown[172.16.101.131]
May  2 10:32:11 imx01 postfix/smtpd[18313]: 8F698D34C0F: client=unknown[172.16.101.131]
May  2 10:32:11 imx01 postfix/smtpd[18313]: C6B0DD34C0F: client=unknown[172.16.101.131]
May  2 10:32:11 imx01 postfix/cleanup[21110]: C6B0DD34C0F: message-id=<A9B8C2FDF47D4D8F88751F407F10D0DD@WHIRO03PC>
May  2 10:32:11 imx01 postfix/qmgr[13432]: C6B0DD34C0F: from=<hoge@mail.example.com>, size=1579, nrcpt=1 (queue active)
May  2 10:32:12 imx01 postfix/smtpd[18313]: disconnect from unknown[172.16.101.131]
May  2 10:32:12 imx01 postfix/smtp[20978]: C6B0DD34C0F: to=<fuga@mail.example.com>, relay=10.10.10.25[10.10.10.25]:25, delay=0.22, delays=0.08/0/0.06/0.08, dsn=2.0.0, status=sent (250 Ok: queued as EA2F33DA41)
May  2 10:32:12 imx01 postfix/qmgr[13432]: C6B0DD34C0F: removed

一見普通に見えるけど、キューID ”8F698D34C0F”に相当する送信ログが見当たらないのですよ。勿論、キューIDでログに対するgrepを実行した上で、「無い」って言うことなんですけどね。
別にWARNINGやERRORというメッセージも出てないし、メールの送信が出来ないというわけでもないのだけど、ナニカガオカシイ。

フツーにとっているログだけではよくわからないし、ある程度こういう形でログが残るクライアントも特定出来る状況だったので、

debug_peer_list = 172.16.101.131

を/etc/potfix/main.cfに追加して、postfixをリロード。
これで、設定したクライアント"172.16.101.131"からの接続があれば、そのときのSMTPセッションの詳細がログに出るので、待つこと数時間…。


待望の"172.16.101.131"からの接続があったので、ログから"172.16.101.131"を含むものを抜き出して、よく見てみたら…。
"HELO"送って、"MAIL FROM:"、"RCPT TO:"ときて、14時32分38秒の最後の4行のところ、何故かクライアント側から"RSET"コマンドが2回発行されてる…。orz

May  2 14:32:37 imx01 postfix/smtpd[15744]: connect from unknown[172.16.101.131]
May  2 14:32:37 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 127.0.0.1
May  2 14:32:37 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 10.0.0.0/8
May  2 14:32:37 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 172.16.0.0/12
May  2 14:32:37 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 220 imx01.mail.example.com ESMTP Postfix
May  2 14:32:37 imx01 postfix/smtpd[15744]: < unknown[172.16.101.131]: HELO WHIRO03PC
May  2 14:32:37 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 250 imx01.mail.example.com
May  2 14:32:37 imx01 postfix/smtpd[15744]: < unknown[172.16.101.131]: MAIL FROM: <hoge@mail.example.com>
May  2 14:32:37 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 250 2.1.0 Ok
May  2 14:32:38 imx01 postfix/smtpd[15744]: < unknown[172.16.101.131]: RCPT TO: <fuga@mail.example.com>
May  2 14:32:38 imx01 postfix/smtpd[15744]: permit_mynetworks: unknown 172.16.101.131
May  2 14:32:38 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 127.0.0.1
May  2 14:32:38 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 10.0.0.0/8
May  2 14:32:38 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 172.16.0.0/12
May  2 14:32:38 imx01 postfix/smtpd[15744]: permit_inet_interfaces: unknown 172.16.101.131
May  2 14:32:38 imx01 postfix/smtpd[15744]: 0221ED34C0F: client=unknown[172.16.101.131]
May  2 14:32:38 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 250 2.1.5 Ok
May  2 14:32:38 imx01 postfix/smtpd[15744]: < unknown[172.16.101.131]: RSET
May  2 14:32:38 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 250 2.0.0 Ok
May  2 14:32:38 imx01 postfix/smtpd[15744]: < unknown[172.16.101.131]: RSET
May  2 14:32:38 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 250 2.0.0 Ok
May  2 14:32:40 imx01 postfix/smtpd[15744]: < unknown[172.16.101.131]: MAIL FROM: <hoge@mail.example.com>
May  2 14:32:40 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 250 2.1.0 Ok
May  2 14:32:40 imx01 postfix/smtpd[15744]: < unknown[172.16.101.131]: RCPT TO: <fuga@mail.example.com>
May  2 14:32:40 imx01 postfix/smtpd[15744]: permit_mynetworks: unknown 172.16.101.131
May  2 14:32:40 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 127.0.0.1
May  2 14:32:40 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 10.0.0.0/8
May  2 14:32:40 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 172.16.0.0/12
May  2 14:32:40 imx01 postfix/smtpd[15744]: permit_inet_interfaces: unknown 172.16.101.131
May  2 14:32:40 imx01 postfix/smtpd[15744]: 5AD58D34C0F: client=unknown[172.16.101.131]
May  2 14:32:40 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 250 2.1.5 Ok
May  2 14:32:40 imx01 postfix/smtpd[15744]: < unknown[172.16.101.131]: DATA
May  2 14:32:40 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 354 End data with <CR><LF>.<CR><LF>
May  2 14:32:40 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 250 2.0.0 Ok: queued as 5AD58D34C0F
May  2 14:32:40 imx01 postfix/smtpd[15744]: < unknown[172.16.101.131]: QUIT
May  2 14:32:40 imx01 postfix/smtpd[15744]: > unknown[172.16.101.131]: 221 2.0.0 Bye
May  2 14:32:40 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 127.0.0.1
May  2 14:32:40 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 10.0.0.0/8
May  2 14:32:40 imx01 postfix/smtpd[15744]: match_hostaddr: 172.16.101.131 ~? 172.16.0.0/12
May  2 14:32:40 imx01 postfix/smtpd[15744]: disconnect from unknown[172.16.101.131]

折角張ったSMTPセッションを有効活用するために、"DATA"コマンドでメールデータを送った後に"RSET”でリセットして、また"MAIL FROM:"から始めるってのなら判らんでもないけど、データ送る前に"RSET”を投げるって、なんでだよ〜。（それも2発。）

すべてのSMTPセッションの詳細を見たわけではないのだけど、最初に挙げたログのようなパターンとなるSMTP接続を行うクライアントが他にもあることがわかっているので、おそらくはクライアント側で動いているMUAに依存して発生しているんじゃないかとは、推測してはいますけどね。
とりあえず、手持ちの環境で使えるWindows Live MailやOutLook 2003、ThunderBirdでは、再現できなかったので、お客様への聞き取りをしてみて、使っているMUAが判れば、再現試験やってとなるわけですが、さてさて。

ログには、”too many errors after RSET from unknown[172.16.101.131]"というのも残っていて、コッチはおそらく複数の宛先にメール送信しようとした時に、RSET 2回×宛先の数がしきい値を超えてるんだろうなぁ、と予想はしているんですが。
postfix側のどのパラメータいじれば極力出ないように出来るのかの当たりはつけてあるのだけど、出来ればMUA側の設定で回避したいなぁ。

トラックバック(0)

コメントする