Postfixのメールログを確認していると、
status=deferredという表示を見かけることがあります。
例えば、
postfix/smtp[12345]: ABC123DEF:
to=<user@example.com>,
relay=none,
delay=120,
status=deferred
(connect to mx.example.com[192.0.2.10]:25:
Connection timed out)のようなログです。
deferredという文字を見るとエラーの原因そのものに見えますが、実際には、
status=deferredは「メールを今すぐ配送できなかったため、後で再試行する状態」
を表しています。
そのため、Postfixのトラブル調査ではstatus=deferredだけを見るのではなく、なぜdeferredになったのか、その前後に記録されているメッセージを確認することが重要です。
この記事では、Postfixでstatus=deferredが発生したときのログの見方と、原因を切り分ける方法を紹介します。
status=deferredとは？
Postfixがメールを配送しようとしても、一時的な理由で配送できないことがあります。
例えば、
Postfix
↓
相手メールサーバーへ配送
↓
接続できない
↓
今は配送できない
↓
キューへ残す
↓
status=deferred
↓
後で再試行という流れです。
つまりdeferredは、
「配送を諦めてメールを削除した」
という意味ではありません。
メールは通常キューに残り、Postfixが後から再配送を試みます。
status=sentとの違い
正常に配送できた場合は、
status=sentと記録されます。
例えば、
status=sent (250 2.0.0 Ok: queued as XXXXX)などです。
大まかには、
status=sent
↓
配送成功
status=deferred
↓
今回は配送できなかった
↓
キューに残して再試行という違いがあります。
メール障害を調査するときは、まずsentなのかdeferredなのかを確認すると状況を把握しやすくなります。
deferredの後ろにある理由を見る
最も重要なのがここです。
例えば、
status=deferred
(connect to mx.example.com[192.0.2.10]:25:
Connection timed out)なら、注目するのは、
Connection timed outです。
つまり、
Postfix
↓
mx.example.com
↓
TCP/25で接続
↓
応答なし
↓
タイムアウト
↓
status=deferredとなっています。
この場合、deferredを直すのではなく、
「なぜ相手SMTPサーバーへ接続できないのか」
を調査します。
まずQueue IDを確認する
Postfixのログには、
ABC123DEFのようなQueue IDが表示されます。
例えば、
postfix/smtp[12345]: ABC123DEF:
to=<user@example.com>,
status=deferredなら、
ABC123DEFがQueue IDです。
このQueue IDを使って、
grep ABC123DEF /var/log/maillogのように検索します。
Ubuntu/Debian系などでは環境によって、
grep ABC123DEF /var/log/mail.logとなる場合もあります。
これによって、そのメールが、
いつ受け付けられた？
誰から？
誰宛？
どこへ配送しようとした？
なぜ失敗した？という流れを追いやすくなります。
mailqでも確認する
現在キューに残っているメールは、
mailqで確認できます。
または、
postqueue -pです。
例えば、
ABC123DEF 1234 Thu Sep 17 10:20:00
sender@example.jp
(connect to mx.example.com[192.0.2.10]:25:
Connection timed out)
user@example.comのように表示されます。
ここでもQueue IDと配送できない理由を確認します。
原因1：Connection timed out
比較的分かりやすいのが、
Connection timed outです。
例えば、
connect to mx.example.com[192.0.2.10]:25:
Connection timed outなら、相手のTCP/25へ接続しようとしたものの、時間内に接続できなかったことが分かります。
この場合は、
ネットワーク
Firewall
ルーティング
TCP/25の制限
相手メールサーバーなどを確認します。
例えば、
nc -vz mx.example.com 25などでTCP/25への接続を確認できます。
ただし、本番環境では組織のネットワーク構成やセキュリティポリシーも確認してください。
原因2：Connection refused
次に、
Connection refusedです。
これはタイムアウトとは少し意味が違います。
大まかには、
Connection timed out
↓
接続を試みたが応答がない
Connection refused
↓
接続先から拒否されたと考えると分かりやすいです。
例えば、
connect to mx.example.com[192.0.2.10]:25:
Connection refusedなら、
接続先SMTPサービス
ポート番号
Firewall
MXレコード
相手サーバーの状態などを確認します。
原因3：Host or domain name not found
次のようなメッセージが出ることもあります。
Host or domain name not foundこの場合はDNSを疑います。
例えば、
dig example.com MXまたは、
nslookup -type=MX example.comを実行します。
MXレコードが、
example.com.
MX 10 mx.example.com.なら、
dig mx.example.com Aなどで配送先ホストも名前解決できるか確認します。
つまり、
宛先ドメイン
↓
MX検索
↓
メールサーバー名
↓
A / AAAA検索
↓
IPアドレス
↓
SMTP接続のどこで失敗しているかを調べます。
原因4：Network is unreachable
ログに、
Network is unreachableと表示されることがあります。
この場合、
ルーティング
IPv4
IPv6
ネットワークインターフェース
デフォルトゲートウェイなどを確認します。
特に注意したいのがIPv6です。
例えば、
connect to mx.example.com[2001:db8::10]:25:
Network is unreachableなら、IPv6アドレスへ接続しようとしていることが分かります。
サーバーに正常なIPv6経路がない場合などに失敗する可能性があります。
ただし、その後IPv4へフォールバックして正常配送されている場合もあるため、この1行だけでメール配送全体が失敗しているとは判断しません。
原因5：Relay access denied
例えば、
Relay access deniedが表示される場合があります。
これは、
Postfix
↓
この送信元・宛先を
中継していい？
↓
許可されていない
↓
拒否というケースです。
この場合、
mynetworks
relayhost
smtpd_recipient_restrictions
SMTP認証など、Postfixのリレー設定を確認します。
ただし、安易にリレー許可範囲を広げるのは危険です。
設定を誤ると第三者から利用できるオープンリレーにつながる可能性があるため、原因を確認してから設定変更します。
原因6：SASL authentication failed
外部のSMTPサーバーをrelayhostとして使用している環境では、
SASL authentication failedなどが表示される場合があります。
この場合は、
SMTPユーザー名
パスワード
認証方式
relayhost設定
TLS設定などを確認します。
例えば、
Postfix
↓
外部SMTPへ接続
↓
SMTP AUTH
↓
認証失敗
↓
配送できないという状態です。
原因7：TLS関連のエラー
配送先によってはTLS関連のエラーが記録されることもあります。
例えば、
TLS
certificate
handshake
protocolなどを含むメッセージです。
この場合、
Postfixのバージョン
OpenSSL
TLS設定
証明書
相手SMTPサーバーとの対応プロトコルなどを確認します。
特に古いOSや古いPostfixを使用している場合は、相手側のセキュリティ要件変更によって、それまでできていた通信ができなくなるケースも考えられます。
特定のドメインだけdeferredになる場合
これは原因を絞る大きなヒントです。
例えば、
gmail.com sent
yahoo.co.jp deferred
outlook.com sent
example.jp sentなら、
Yahoo宛だけで発生している
という共通点があります。
この場合、
Postfix全体が壊れている可能性よりも、
特定配送先との通信
DNS
相手側の受信条件
送信元IPなどを重点的に調べられます。
逆に、
gmail.com deferred
yahoo.co.jp deferred
outlook.com deferred
example.jp deferredなら、Postfix側やネットワーク側に共通原因がある可能性が高くなります。
relay=も確認する
ログを見るときは、
relay=も重要です。
例えば、
relay=mx.example.com[192.0.2.10]:25なら、実際にそのメールをどこへ配送しようとしたのかが分かります。
一方、
relay=noneで名前解決エラーなどが記録されている場合は、SMTP接続以前の段階で止まっている可能性があります。
つまり、
宛先
↓
MX解決
↓
relay決定
↓
SMTP接続
↓
SMTP応答のどこまで進んでいるかを見ることができます。
delayも確認する
Postfixログには、
delay=が表示されます。
例えば、
delay=5と、
delay=86400では状況が大きく違います。
長時間キューに滞留しているメールなら、
一時的な失敗ではなく、問題が継続しているのではないか
と考える材料になります。
deferredだけを見るのではなく、
Queue ID
to=
relay=
delay=
status=
失敗理由をセットで確認すると状況を把握しやすくなります。
ログは1行だけで判断しない
Postfixのトラブル調査で特に重要です。
例えば、
status=deferredを見つけても、その1行だけでは判断しません。
Queue IDを使って、
grep ABC123DEF /var/log/maillogと検索すると、
メール受付
↓
cleanup
↓
queue
↓
配送先決定
↓
smtp
↓
deferredという流れを追える場合があります。
つまり、
エラー文字列ではなく、1通のメールをQueue IDで追跡する
という考え方です。
原因を修正したら再送する
例えばDNS設定に問題があり、修正したとします。
その後、
postqueue -fを実行すると、キューにあるメールの配送を再試行できます。
その後、
mailqを確認します。
さらにログで、
status=sentになったか確認します。
流れとしては、
status=deferred
↓
原因調査
↓
DNS等を修正
↓
postqueue -f
↓
再配送
↓
status=sentとなれば、原因修正後に配送できたことを確認できます。
原因を直さずpostqueue -fを繰り返さない
例えばTCP/25が遮断されたまま、
postqueue -fを何度実行しても、
再配送
↓
Connection timed out
↓
deferred
↓
再配送
↓
Connection timed outとなるだけです。
postqueue -fは修復コマンドではありません。
原因を修正したあと、再配送を試すために使用します。
status=deferredのメールを削除するべき？
基本的には、
deferredだから削除する
とは考えません。
一時的な障害なら、後で正常に配送される可能性があります。
削除する場合は、そのメールが不要であることを確認してから、
postsuper -d QUEUE_IDを使用します。
大量のメールを一括削除する操作は、正常な業務メールまで失う可能性があるため特に注意が必要です。
私ならこの順番で調べる
status=deferredを見つけた場合は、次の順番で確認します。
status=deferred
↓
Queue ID確認
↓
mailq確認
↓
Queue IDでログ検索
↓
失敗理由を確認
↓
┌───────────────┐
│ DNS？ │
│ Network？ │
│ TCP/25？ │
│ SMTP応答？ │
│ Relay？ │
│ SASL？ │
│ TLS？ │
└───────────────┘
↓
特定宛先だけ？
全宛先？
↓
原因を修正
↓
postqueue -f
↓
ログ確認
↓
status=sentこの方法なら、deferredという結果から徐々に原因を絞り込めます。
「メールが届かない」と「deferred」は同じではない
ここも重要です。
利用者から、
Gmailにメールが届かない
と言われても、必ずdeferredとは限りません。
例えば、
Postfix
↓
status=sent
↓
Gmail受信
↓
迷惑メールフォルダという可能性があります。
この場合、Postfix側では配送が完了しているため、
PTR
SPF
DKIM
DMARC
IP・ドメインレピュテーション
メール内容など、別の調査へ進みます。
したがって、
メールが届かない
↓
まずPostfixログ
↓
┌─────────────┐
│ deferred │ → 配送できていない
└─────────────┘
┌─────────────┐
│ sent │ → SMTP配送後を調査
└─────────────┘と分けて考えると分かりやすくなります。
まとめ
Postfixのログに、
status=deferredと表示されている場合、
メールをその時点では配送できず、キューに残して後で再試行する状態
と考えます。
重要なのはdeferredという文字そのものではありません。
例えば、
Connection timed out
Connection refused
Host or domain name not found
Network is unreachable
Relay access denied
SASL authentication failed
TLS関連エラーなど、なぜ配送できなかったのかを確認します。
調査するときは、
Queue ID
↓
ログ検索
↓
to=
↓
relay=
↓
delay=
↓
status=
↓
具体的な失敗理由という順番で追うと分かりやすくなります。
そして原因を修正したあと、
postqueue -fで再配送し、
status=sentになったことを確認します。
Postfixのトラブルでは、
「status=deferredを直す」のではなく、「deferredになった原因を直す」
という考え方が重要です。
Postfix関連記事
Postfixのメール配送トラブルについて、以下の記事でも解説しています。
コメント