2014/10/15 (水)

2014-10-15:postfix メール配送トラブル

いきなりメールが送れなくなって苦労。
自分の送信したメールが、

To: undisclosed-recipients:;
From: kajiwataru@youreducation.jp
X-Amavis-Alert: BAD HEADER SECTION, MIME error: error: unexpected end of header
Message-Id: <20141014124554.D355A151C082@wineroses.org>
Date: Tue, 14 Oct 2014 21:45:54 +0900 (JST)

みたいなヘッダ、そして本文なし。
Amavis が警告出してるなぁ。
サーバのログを見に行くと、

Oct 14 21:45:54 postfix/smtpd[1403]: connect from localhost[127.0.0.1]
Oct 14 21:45:54 postfix/smtpd[1403]: 9648B151C06D: client=localhost[127.0.0.1]
Oct 14 21:45:54 postfix/cleanup[1406]: 9648B151C06D: message-id=<m38uki6cqb.wl%kajiwataru@youreducation.jp>
Oct 14 21:45:54 postfix/qmgr[2145]: 9648B151C06D: from=<kajiwataru@youreducation.jp>, size=879, nrcpt=2 (queue active)
Oct 14 21:45:54 postfix/smtpd[1403]: disconnect from localhost[127.0.0.1]
Oct 14 21:45:54 postfix/pipe[1407]: 9648B151C06D: to=<kajiwataru@gmail.com>, relay=filter, delay=0.27, delays=0.14/0/0/0.13, dsn=2.0.0, status=sent (delivered via filter service)
Oct 14 21:45:54 postfix/qmgr[2145]: 9648B151C06D: removed
Oct 14 21:45:54 postfix/pickup[32657]: D355A151C082: uid=115 from=<kajiwataru@youreducation.jp>
Oct 14 21:45:54 postfix/cleanup[1406]: D355A151C082: message-id=<20141014124554.D355A151C082@wineroses.org>
Oct 14 21:45:54 postfix/qmgr[2145]: D355A151C082: from=<kajiwataru@youreducation.jp>, size=295, nrcpt=2 (queue active)
Oct 14 21:45:54 postfix/smtpd[1414]: connect from localhost[127.0.0.1]
Oct 14 21:45:54 postfix/smtpd[1414]: E8DBD151C06D: client=localhost[127.0.0.1]
Oct 14 21:45:54 postfix/cleanup[1406]: E8DBD151C06D: message-id=<20141014124554.D355A151C082@wineroses.org>
Oct 14 21:45:54 postfix/smtpd[1414]: disconnect from localhost[127.0.0.1]
Oct 14 21:45:54 postfix/qmgr[2145]: E8DBD151C06D: from=<kajiwataru@youreducation.jp>, size=724, nrcpt=2 (queue active)
Oct 14 21:45:54 amavis[17082]: (17082-19) Passed BAD-HEADER, <kajiwataru@youreducation.jp> -> <kajiwataru@gmail.com>, quarantine: J/badh-Jfg4DY9oumy3, Message-ID: <20141014124554.D355A151C082@wineroses.org>, mail_id: Jfg4DY9oumy3, Hits: -, size: 295, queued_as: E8DBD151C06D, 82 ms
Oct 14 21:45:54 postfix/smtp[1413]: D355A151C082: to=<kajiwataru@gmail.com>, relay=localhost[127.0.0.1]:10024, delay=0.22, delays=0.13/0/0/0.08, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=17082-19, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as E8DBD151C06D)
Oct 14 21:45:54 postfix/qmgr[2145]: D355A151C082: removed
Oct 14 21:45:58 postfix/smtp[1413]: E8DBD151C06D: to=<kajiwataru@gmail.com>, relay=gmail-smtp-in.l.google.com[74.125.25.26]:25, delay=3.3, delays=0/0.01/1.3/2, dsn=2.0.0, status=sent (250 2.0.0 OK 1413290758 a5si12788834pdi.224 - gsmtp)
Oct 14 21:45:58 postfix/qmgr[2145]: E8DBD151C06D: removed

たしかに、Amavis が「Passed BAD-HEADER」言ってる(上のログの16行目)。

ちょっとググって /etc/amavis/conf.d/ 以下を編集したりするも効果がない。
ええいメンドクサイと sudo /etc/init.d/amavis stop して、postfix の main.cf からフィルターを除いてみた。

To: undisclosed-recipients:;
From: kajiwataru@youreducation.jp
Message-Id: <20141014131942.08E9F151C086@wineroses.org>
Date: Tue, 14 Oct 2014 22:19:41 +0900 (JST)

うわっ、変わらねぇ。。。
サーバのログはというと、

Oct 14 22:19:41 postfix/smtpd[2863]: connect from localhost[127.0.0.1]
Oct 14 22:19:41 postfix/smtpd[2863]: 8118B151C06D: client=localhost[127.0.0.1]
Oct 14 22:19:41 postfix/cleanup[2867]: 8118B151C06D: message-id=<m338aq6b61.wl%kajiwataru@youreducation.jp>
Oct 14 22:19:41 postfix/qmgr[2846]: 8118B151C06D: from=<kajiwataru@youreducation.jp>, size=883, nrcpt=2 (queue active)
Oct 14 22:19:41 postfix/smtpd[2863]: disconnect from localhost[127.0.0.1]
Oct 14 22:19:42 postfix/pickup[2845]: 08E9F151C086: uid=115 from=<kajiwataru@youreducation.jp>
Oct 14 22:19:42 postfix/pipe[2868]: 8118B151C06D: to=<kajiwataru@gmail.com>, relay=filter, delay=0.53, delays=0.43/0/0/0.1, dsn=2.0.0, status=sent (delivered via filter service)
Oct 14 22:19:42 postfix/qmgr[2846]: 8118B151C06D: removed
Oct 14 22:19:42 postfix/cleanup[2867]: 08E9F151C086: message-id=<20141014131942.08E9F151C086@wineroses.org>
Oct 14 22:19:42 postfix/qmgr[2846]: 08E9F151C086: from=<kajiwataru@youreducation.jp>, size=295, nrcpt=2 (queue active)
Oct 14 22:19:43 postfix/smtp[2847]: 08E9F151C086: to=<kajiwataru@gmail.com>, relay=gmail-smtp-in.l.google.com[74.125.25.26]:25, delay=1.6, delays=0.16/0/0.92/0.57, dsn=2.0.0, status=sent (250 2.0.0 OK 1413292783 jd12si13009371pbd.10 - gsmtp)
Oct 14 22:19:44 postfix/qmgr[2846]: 08E9F151C086: removed

Amavis まわりが抜けただけか。
よくよく見るに、メールを受けた postfix が Message-ID を youreducation.jp のものから、wineroses.org に書き換えた上で転送してて、でもその時点で size=295 と小さいので(10行目。最初は4行目の size=883)、削られまくったヘンなヘッダになってる?

悪いのは postfix そのもののよう。
けど、そもそもここの転送ってどこで指定されてるんだ?
/etc/postfix/main.cf ともろもろ格闘するも、なかなか解決せず。

。。。が、/etc/postfix/master.cf をディストリビューションのデフォルトに差し替えたらいきなり解決した。

Oct 15 10:49:19 postfix/smtpd[24904]: connect from localhost[127.0.0.1]
Oct 15 10:49:19 postfix/smtpd[24904]: 0E0D2151C085: client=localhost[127.0.0.1]
Oct 15 10:49:19 postfix/cleanup[24907]: 0E0D2151C085: message-id=<m34mv6xftv.wl%kajiwataru@youreducation.jp>
Oct 15 10:49:19 postfix/qmgr[24530]: 0E0D2151C085: from=<kajiwataru@youreducation.jp>, size=939, nrcpt=2 (queue active)
Oct 15 10:49:19 postfix/smtpd[24904]: disconnect from localhost[127.0.0.1]
Oct 15 10:49:23 postfix/smtp[24909]: 0E0D2151C085: to=<kajiwataru@gmail.com>, relay=gmail-smtp-in.l.google.com[74.125.129.26]:25, delay=4.4, delays=0.09/0/0.54/3.8, dsn=2.0.0, status=sent (250 2.0.0 OK 1413337763 s9si14486573pdm.59 - gsmtp)
Oct 15 10:49:23 postfix/qmgr[24530]: 0E0D2151C085: removed

うーん、master.cf にヘンな記述をしちゃってたのか。
とりあえずは解決をみた(メールが送れるようになった)ので、深い追究は別の機会に。
一応、参照ドキュメントとしては↓んあるのかな

Postfix キューに入った後のコンテンツフィルタ
http://www.postfix-jp.info/trans-2.1/jhtml/FILTER_README.html

comment