FreeBSD 13.4 のメールログに、複数のエラーが発生していました。
確認してみると、複数あるFreeBSDサーバーのうち、特定のサーバーからデイリーレポートを受信できないというものでした。
メールを受信するサーバーには、
sm-mta[12660]: STARTTLS: read error=timeout sm-mta[12660]: 5297Sm2o012660: collect: premature EOM: Operation timed out with pc1.lifewithunix.jp sm-mta[12660]: 5297Sm2o012660: SYSERR(root): collect: relay=pc1.lifewithunix.jp, from=<>, info=I/O error sm-mta[12660]: 5297Sm2o012660: from=<>, size=48474, class=0, nrcpts=1, proto=ESMTPS, daemon=IPv4, relay=pc1.lifewithunix.jp
という行が残っていて、送信側には、
sm-mta[1043]: STARTTLS=client, relay=tokyo.lifewithunix.jp., version=TLSv1.3, verify=FAIL, cipher=TLS_AES_256_GCM_SHA384, bits=256/256 sm-mta[1043]: STARTTLS: read error=syscall error (-1), errno=60, get_error=error:00000000:lib(0):func(0):reason(0), retry=1, ssl_err=5 sm-mta[1043]: 528NQlcT068435: to=root@tokyo.lifewithunix.jp, delay=09:24:19, xdelay=00:01:20, mailer=esmtp, pri=1930109, relay=tokyo.lifewithunix.jp. [116.58.172.107], dsn=4.4.2, stat=Deferred: Operation timed out with tokyo.lifewithunix.jp. sm-mta[1043]: 528JCBuQ068112: to=root@tokyo.lifewithunix.jp, ctladdr=<root@pc1.lifewithunix.jp> (0/0), delay=13:40:15, xdelay=00:00:00, mailer=esmtp, pri=2739085, relay=tokyo.lifewithunix.jp., dsn=4.4.2, stat=Deferred: Operation timed out with tokyo.lifewithunix.jp.
という行が残っています。
これらのサーバー間でメールのやり取りができないかというと、そうではなく、今日、電子メールのエラーに気付くまでは正常に通信できていて、今日も手動でテストメールを送ると問題なく送受信できる。
毎晩自動で送信されるデイリーレポートが昨晩だけスプールに溜まったままで、出てゆかないだけ。
こういう場合は、通常、両メールサーバーで sendmail を再起動すれば復旧するんですが、今回は復旧しない。
エラーが起きているメール受信サーバーは1台で、送信サーバーは2台。
受信側の問題のような気もするけど設定変更は行っていないし、送信できないサーバーは2台あるものの、4台はいつも通り問題なくデイリーレポートを送られている。
なぜ？何が起きている？
sendmail -q -v で強制再送する時のやり取りが見えるので確認してみたのが以下。
ステータス 354 が返ってきたあたりで、止まって、タイムアウトとなる。
<中略>
250-ENHANCEDSTATUSCODES
250-PIPELINING
250-8BITMIME
250-SIZE
250-DSN
250-ETRN
250-STARTTLS
250-DELIVERBY
250 HELP
>>> STARTTLS
220 2.0.0 Ready to start TLS
>>> EHLO pc1.lifewithunix.jp
250-tokyo.lifewithunix.jp Hello pc1.lifewithunix.jp [192.168.1.xx], pleased to meet you
250-ENHANCEDSTATUSCODES
250-PIPELINING
250-8BITMIME
250-SIZE
250-DSN
250-ETRN
250-DELIVERBY
250 HELP
>>> MAIL From:<> SIZE=101110
250 2.1.0 <>... Sender ok
>>> RCPT To:<nobody@tokyo.lifewithunix.jp>
>>> DATA
250 2.1.5 <nobody@tokyo.lifewithunix.jp>... Recipient ok
354 End data with <CR><LF>.<CR><LF>
putbody: write error: Broken pipe
timeout writing message to tokyo.lifewithunix.jp.: Broken pipe
そもそも MAIL From:<> となるあたりでおかしい。これはエラーメールを返却する時の内容。普通のイントラネットメールを送る時に出てくるはずがないもの。
送信しようとするメールのヘッダーが壊れて生成されたとしか思えない。しかし原因がわからない。
再送する手段が何か残っているのかもしれないけど、不達メールの中身は日ごとのステータスレポートなので、目を通して問題が無かったら捨てるだけのもの。そのためにこれ以上時間を掛けても仕方がないので、spool に溜まっているファイルに直接目を通したあと、削除することにしました。
この後も、同様の現象が起きるなら、検討する必要がありますが、起こらないなら今回のトラブルは無視しようと思います。
翌朝、デイリーレポートを確認してみたところ、スプールに不達メールが貯まっていたホストからも無事にレポートを送信できていたことが確認できました。つまり、障害からは復旧済み。
しかし、なぜ、こういう現象が起きたのかが不可解。
でも一つだけ心当たりがあります。
デイリーレポートは午前3時に自動起動して、HDDスキャンを始めますが、その他のバッチジョブがデイリーレポート同様バックグランドで動いています。pkg の更新関係。
偶然、pkg 更新が掛かっていたパッケージにライブラリやコマンド更新関係のものが含まれていたら、レポート作成にエラーが発生するかも。
さすがにそこまでは面倒見切れないし、デイリーレポートが一通届かなくても害はありません。そして、脆弱性があるまま放置されていても、翌日同じレポートが届くわけだから、デイリーレポートが不達メールになることはあまり気にしなくていいのかも。外部から届くメールが毎回不達になるんだったら困りますけどね。