Deferred後のメールが消えてしまうと思われる現象について

概要

Postfixのログを精査していたところ、deferredとなったメールが再送処理の後に
消失していると思われるケースがありました。
原因や対策を調べても見当がつかないため、何かヒントをご教示頂ければと思います。

調査の経緯

1．配信結果の集計を行ったところ、最終的な結果（Status）がないメールを発見
2．キューIDを元に追跡したところ、以下の状態であった
　(1)キュー作成（queue active）
　(2)Deferred発生
　(3)再度キューに投入（queue active）
　以降なしのつぶて
3.DeferredキューやActiveキューには何も残っていない

実際のログ（アドレスは改変しています）

Jun 22 16:23:14 ip-10-0-1-1 postfix-test/smtpd[27507]: 2DB112803FC3: client=unknown[10.0.0.100]
Jun 22 16:23:14 ip-10-0-1-1 postfix-test/cleanup[27607]: 2DB112803FC3: message-id=<>
Jun 22 16:23:14 ip-10-0-1-1 opendkim[21546]: 2DB112803FC3: DKIM-Signature field added (s=example, d=example.com)
Jun 22 16:23:14 ip-10-0-1-1 postfix-test/qmgr[24349]: 2DB112803FC3: from=<info@example.com>, size=5357, nrcpt=1 (queue active)
Jun 22 16:23:19 ip-10-0-1-1 postfix-test/smtp[27595]: 2DB112803FC3: host host.example.net[192.168.0.1] said: 451 Temporarily unavailable -- please try later (in reply to RCPT TO command)
Jun 22 16:23:24 ip-10-0-1-1 postfix-test/smtp[27595]: 2DB112803FC3: to=<hoge@example.org>, relay=mail.example.net[192.168.0.1]:25, delay=11, delays=0.13/0/5.4/5, dsn=4.0.0, status=deferred (host mail.example.net[192.168.0.1] said: 451 Temporarily unavailable -- please try later (in reply to RCPT TO command))
Jun 22 16:33:09 ip-10-0-1-1 postfix-test/qmgr[24349]: 2DB112803FC3: from=<info@example.com>, size=5357, nrcpt=1 (queue active)

補足情報

消失したと思われるメールはDeferredとなったメールの5％程度で、残りのメールは再送を何度か繰り返した後に
送信完了または配送不能で処理されています。1日のメール処理件数は1万件ほどです。

行動規範の内容に同意します

回答2件

ベストアンサー

下記のどちらかではないでしょうか

再送プロセスがハングしており、ログに出力されずプロセスも残っている

ps などでハングしているプロセスがあるか確認してください。

maillogに出力されていないだけで実は処理されている

rsyslog の単位時間あたりの1プロセスの出力制限に引っかかっている可能性があります。
$SystemLogRateLimitInterval 0 を rsyslog.conf の適切な場所に追加し、rsyslog を再起動してください。

投稿2018/06/29 07:50

scsi

総合スコア2840

回答へのコメント

k.yoshida

2018/06/29 09:32 編集

ご教示ありがとうございます。 > 1.再送プロセスがハングしており、ログに出力されずプロセスも残っている既に時間が経過しているため、当時と状況が変わっている可能性がありますが、現状プロセスには問題なさそうです。ハングしたプロセスもありませんでした。また、当時もメモリ使用状況やCPU使用率に十分余裕がある状況でしたのでプロセスは問題なかったと推測しています。 > 2.maillogに出力されていないだけで実は処理されている /var/log/messagesを確認したところ、以下のログが記録されていました。 `Jun 22 16:27:29 ip-10-0-1-1 journal: Suppressed 115 messages from /system.slice/postfix.service` ご推察された通り、rsyslogの制限に引っかかって保存されなかったようです。 $SystemLogRateLimitInterval 0を追加して経過観察致します。ありがとうございます。