Node.js で書かれたアプリがメール送信に失敗します。使用しているライブラリは nodemailer です。こんな感じのログが出ます。

Nov  2 19:55:00 myapp[545]: Error: Can not use IPv4 addresses with current network
Nov  2 19:55:00 myapp[545]:    at GetAddrInfoReqWrap.callback (/path/to/myapp/node_modules/nodemailer/lib/shared/index.js:217:35)
Nov  2 19:55:00 myapp[545]:    at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:91:8) {
Nov  2 19:55:00 myapp[545]:  code: 'EDNS',
Nov  2 19:55:00 myapp[545]:  command: 'CONN'
Nov  2 19:55:00 myapp[545]: }

IPv4 のアドレスが使えないとのことですが、メールサーバ(localhost)は DNS でちゃんと 127.0.0.1 が引けますし、同じコードをコマンドラインからテスト実行すると送信されます。

この障害、あちこちで報告されているのですが、解決に至っていないようです。その対策を紹介します。

原因の推定

状況を挙げていくと、段々見えてきます。4つ目はかなり重要なポイントです。

  1. IPv6 を有効にした環境で発生する(私の環境では、以前はメール送れていたのですが、IPv6 有効化後に発生しました)。
  2. ログインして、コマンドラインからテストコードを実行すると、正常にメールを送信できる。
  3. サービスは systemd で自動起動する設定にしている。
  4. 障害が発生しているサービスを再起動すると、メールが送信できるようになる。

systemd で自動起動した時の環境と、再起動した時の環境が違うので、同じコードでも障害が再現しないのです。別のサービス(dnsmasq)でも類似の障害を経験しました。原因は、ネットワークの初期化が終わるのを待たずにサービスを起動しているためと考えられます。正直なところ、ループバック(lo)の起動に時間がかかるというのは、盲点でした。

解決策

myapp.service (各自、問題が起きているサービス)に After=network-online.target を追加し、ネットワークが起動し切る(IP アドレスの取得が完了する)までサービスの起動を待たせましょう。

以下のように、[Unit] セクションの中に書きます。

[Unit]
Description=My Great Application
After=network-online.target

[Service]
ExecStart=/path/to/myapp/index.js
...

環境によっては、NetworkManager-wait-online.servicemask されていることがあります。この場合は、network-online.target が正しく動作しませんので、unmask しておきましょう。

# systemctl unmask NetworkManager-wait-online
# systemctl start NetworkManager-wait-online
# systemctl enable NetworkManager-wait-online

NetworkManager-wait-online.servicemask しておくという謎 tips は、未設定の NIC がある場合に、IP アドレスを DHCP で取得できず、タイムアウトするまで起動が待たされるのを避けるためのようです。unmask したら起動が遅くなった場合は、未設定の NIC があると思われます。オフラインにしておきましょう。

おわりに

本稿では、nodemailer がメール送信に失敗する障害と、その対策について紹介しました。本番環境でないと再現しない類いの障害で、原因がプラットフォーム側にあって、意外な盲点が関係しているなど、あちこちで指摘されている割に解決していないのも納得でした。この手の話は、解決した後からもう一度見直すと、すべてが腑に落ちたりもしますが、当初は原因の追及が難しく、的外れな試行を繰り返しがちです。

私も解決には時間がかかった(影響がほぼなかったので放置していた)のですが、きっかけは、OpenSSL の緊急セキュリティパッチを急遽当てて、サービスを再起動したら、メールが届くようになったことです。上記のログの日付がそれを物語っていますね。障害対応は観察眼が問われると、改めて認識しました。