【SREチーム ブログリレー2回目】
お疲れ様です。エンジニアリンググループ、コアSREの山本です。
前回ブログリレー1回目の記事で大量メール送信のために基本設定について書かせていただきました。
今回はそれを受けて構築したサーバで実際に発生したいくつかの問題、その問題への対処といったものを書かせてください。
エムスリーのメール送信で発生した問題とその対策
実際にここ一年あたりの間に発生した問題とその問題への対応を記述していきたいと思います。postfixを利用して送信していますので設定はpostfixに依存します。
特定のメールサーバからの突然のメール拒否
エムスリーからのメールが突然に某大手企業の運営するメールサービスから拒否され始めました。
とはいえ、後で考えるとその前兆は存在しており途中までは配信遅延(deferred)で済んでいました。この遅延の場合には再送によって最終的には送信に成功いたしますのですぐには発覚しませんでした。
ある日から拒否が始まり会員様からの連絡を受けてようやく発覚です。メールが到達せずにバウンスメールとなってしまい、その結果としてメール不達判定がなされてしまったことで会員様はメールアドレスの再確認が必要となった、ということです。その会員様の所持しているメールアドレスのドメインが特定のものでした。
どうしてもメール拒否の基準は各社ごとに異なりますし、それ自体に対して手を出すことはできません。
調査を進めたところ、拒否されているのは全てのIPではなく特定のIPでしかありませんでした。とりあえず次の対策を進めました。
- 拒否されたIPを持つメールサーバについては他の正常に送信されるメールサーバにrelayしてから送信
- 正常なメールサーバが拒否されては困るので送信を絞る
- 最終的には新たなIPを確保して上記の異常状態を解除
ちょっと変則的ですが特定ドメイン(ここでは example.com と example.net ということにしています)についてrelayを一時的に変更しました。
/etc/postfix/transport に以下を追加
example.com smtp:[正しく送信できるメールサーバのみが入ったFQDN] example.net smtp:[正しく送信できるメールサーバのみが入ったFQDN]
このIPについてメールから外すこともできたのですが、元々大量のメールを送信していることから他のサーバへの負荷の偏りを懸念して苦し紛れの策をとった形です。(事故も起きそうなのでお勧めするわけではありません。)
正常なサーバについては送信速度を絞りました。
/etc/postfix/master.cf
smtp-denied-domains unix - - n - 1 smtp
-o smtp_destination_concurrency_limit=1
上記わかりにくいですが、 上の行の 1というところがプロセス数にあたります。ここの数字がmaxprocなのですが送信制限によく効きました。下の smtp_destination_concurrency_limit=1 は受信ドメインごとの並列配送数ですが、大きくは意味がなかったかも知れません。
メールの翌日までの滞留
我々のメール送信は早期到達が必要なものもあります。しかし、メールがいつになっても捌けずに深夜どころか翌日に送信される事態が発生しました。
これは上の問題の対処で発生した送信制限によって引き起こされてしまったものです。
単純に送信速度を絞ったのに処理されるメールの量が増えたことで送信が終わらなかったという問題で非常にお恥ずかしいです。滞留の監視が甘かったことで徐々にqueueにメールが溜まってしまい、最終的には前日夜のメールを翌日まで配送を続けていたのです。
特定ドメインについて送信速度を絞ったのはよいとしても、送信可能なサーバ数が減っていることもあってさらに遅くなってしまったのでした。 次の対処を取りました。
- 恐る恐る送信速度を上昇させる
- 用意していた新IPのサーバも利用してチョロチョロと流し始める
最終的にメールをさばくことができ、流入数よりも送信速度の方が上回ったのでなんとか解決しました。
この時新たな監視を入れることとなりましたがそれは後述します。
TLS問題
最近のメールサーバはTLSを利用して送信可能です。 postfixの場合は次の設定を入れておきます。
/etc/postfix/main.cf
smtpd_tls_security_level = may
これは相手サーバがTLSに対応していればTLSを使ってくれるというオプションであり、これでほぼ問題はありません。 しかし、ある時から特定の相手に全くメールが届かなくなるという問題が発生しました。
エムスリーではTLS 1.0と1.1の撲滅運動を実施しており、かなり駆逐がなされていたのですが、残念ながらpostfixサーバで撲滅できていなかった、というのがこの原因でした。
まだ古いメールサーバが存在していたことが原因です。 そのため、「メール送信でも意識を高く保ってTLS 1.2以上のみ許可している相手」には届かなくなっていたのでした。
これは根本的にはTLS 1.2に対応しろということになるのですが、すぐに対応はできなかったために一旦これもリレーによってTLS 1.2に対応しているサーバを経由させるということとなりました。
/etc/postfix/transport に以下を追加
example.com smtp:[TLS 1.2対応したメールサーバのFQDN] example.net smtp:[TLS 1.2対応したメールサーバのFQDN]
このような特殊な設定が好ましいとはとても思えないので、古いサーバを破棄するという方向となりました。
メールがどうしても迷惑メール扱いされるという苦情
ある日「エムスリーから来るメールが先日から迷惑メールに分類されてしまう」という連絡を受けました。 迷惑メール扱いということは、大量送信かなと思い調査とヒアリングを進めましたが、これに関しては大量送信とはまた別の問題でした。
正しく設定しているはずのSPFの判定で失敗しているということが判明しました。
エムスリーとしては envelope-fromに test@m3.com のようなエムスリーのアドレスを設定しています。
しかし、エムスリー→A社メール→B社メールと転送が進んだ際に、B社メールで受信した側からすれば送信元IPはA社サーバです。
これは我々としては回避しようがありません。 このようなことが起きることを防ぐために、転送元のサーバではenvelope-fromを書き換えてから転送するという技術(SRSと呼ばれる)を採用することがありますが、どうやら今回の件ではA社サーバにおいてSRSの設定を切ってしまった模様です。
さらに、転送の際には To: は確実に変化します。それにも関わらずDKIMのヘッダをそのまま転送してくることによってDKIMも失敗していました。
いくつかのメールサービスで確認したのですが、転送については次の3つの場合があるようでした。
- 何もしない(つまり今回の問題)
- 独自にDKIMで再署名する(つまり、m3.com の署名を破棄して自分で署名)
- DKIMではなくARCで再署名する(つまり、m3.com の署名を破棄して自分で署名)
いずれにしても、SPFもDKIMもメール転送に弱いという問題があり、この辺りで苦労するかも知れません。
postfixのメール処理とステータス
postfixのメール送信ログには次のような status が存在します。
- sent (送信成功)
- deferred (一時的に相手側から拒否されている、時間を置いてから再送すべくキューに格納)
- クォータ超えで一時的に拒否された
- 流量の多さから相手から一時的に拒否された
- 相手サーバへの接続がタイムアウトした
- bounced (相手サーバから拒否された、相手先が存在しなかったその他で、バウンスメールを送信者に返す)
- クォータ超えで拒否された
- 流量の多さから拒否された
- スパムサーバと判断されて拒否された
- メールアカウントが存在しなかった
- そもそも接続先のメールサーバが存在しなかった
- expired (再送をしても最終的に特定の時間
bounce_queue_lifetimeに送信できなかったので、バウンスメールを送信者に返す)
ここで全てがsentとなればもちろんありがたいのですが色々な理由で他の問題が発生します。
最終的にメールが到達しなかったと判断できるのは bounced と expired です。bounced も expired ももちろん問題なのですが、メルマガを送信していて気づくのは「メールボックスのクォータ超え」のようなものについてもこの数に入ってしまうものがある(それも大量に)というところです。
従って絶対量ももちろん大事ですが、変化量に気づいた方がよいとわかりました。問題視せねばならない変化というのは「いきなりexpired が10倍に増えた」とかです。これは例えば「何度再送してもうちからのメールを受け付けないメールサービスが登場した」ということを示唆するので大きな問題です。
メールログの監視
さて、メールのログやstatusを見るのはよいとしても、メール送信を実施する側の社員はメールサーバにログインする権限を持っておりません。postfixを使う際には例えばpostfix-exporterを使ってダッシュボードを作ることはできるのですがもう少し細かな情報を見たい時、あるいは分かりやすくメールの破棄数や破棄率だけ見たい、アラートをあげたいということで別のシステムを作成しております。
それほど難しい仕組みではありませんが、メールサーバから /var/log/maillog の情報を送り続けています。図では省略していますがtd-agentにおいてメールアドレスに関してはハッシュ化しているため、個人情報は送られないようになっています。それ以外でもいくつかの処理を実施しており、例えば同じメッセージに対する処理は取りまとめられるようになっています。
kibanaの側ではクエリを簡単に発行して直近のメール処理について確認してもらっています。Redashの側ではもう少し長期の傾向を見るために次のような情報を可視化しています。
- 日別メール破棄率グラフ(status=expired/status=sent)
- 日別メールバウンス率グラフ(status=bounced/status=sent)
- 日別メール破棄数グラフ(status=expiredの数)
- 日別メール一時的遅延率グラフ(status=deferred/status=sent)
- queue滞留率(4時間滞留しているメールの数・12時間滞留しているメールの数/これはdelayのフィールドから取得可能)
- ドメイン別の遅延率/数テーブル(遅延率・遅延数)
上記がダッシュボードです。これによってexpiredや bouncedの変化に気づきます。
同時に一定の指標を上回ったときにslackに通知を投げるようにしました。これによって問題が起きた翌朝には判明します。
なお、この中でqueue滞留率は、前述したトラブルである「翌日までメールを送り続けていた問題」を受けて作成しました。 以下に以前のグラフを貼りますが、つまりこの日は4時間遅れが2.87%もあるという異常事態であったことがわかります。
まとめ
エムスリーでのメール送信の苦労の一端を示してみました。相手側サーバの拒否とその対処、メールログの監視と可視化による早期発見といった話がメール運用において何かお役に立てれば良いなと思います。あるいは既に書きましたが「こんなのやだから、マネージドなサービスにする！」という判断の一助になったかもしれません。
実は現在もまだメールとは戦っており、未解決の問題があります。 「俺たちの戦いはこれからだ！」ということでこの果てしなく遠いメール坂を登り続けていきたいと思います。
We are Hiring!
エムスリーではSREエンジニアを絶賛募集中です！（なお、メールとの戦いはごく一部ですので、果てしなく遠いメール坂を登ることはほぼないと思います！）
もちろんSREに限らず各種エンジニア大歓迎です。 メールに限らず少しでもエムスリーのエンジニアに興味を持っていただいた方は是非下記からご連絡ください！
