数万回に一度くらいの頻度で起きるエラーに対処しよう

パターンその１・ホスト名が勝手に入れ替わる

TwilioのTwiMLアプリケーションはTwilio側のサーバからのHTTPリクエストにTwiMLと呼ばれるXMLで応答して電話の挙動を制御する仕組みです。通話の遷移が発生するたびに通信が発生しますが、それだけではありません。例えばTwiMLにmp3などのオーディオファイルの再生命令を記述すると、その分のアクセスも発生します。

<?xml version="1.0" encoding="UTF-8"?>
<Response>
  <Play>/files/hello.mp3</Play>
</Response>

こんなXMLを返すと、このXMLを取得するためのアクセスと、それからhello.mp3を取得するためのアクセスの2つが発生します。簡便のため絶対パスで記述しましたが、実はここにはフルのURLを書いた方が安全です。なぜなら、例えばAWSのS3に設置したファイルとEC2インスタンスに設置したファイルの両方を扱うとして、こんなXMLを書くと…

<?xml version="1.0" encoding="UTF-8"?>
<Response>
  <Play>http://s3-ap-northeast-1.amazonaws.com/my-backet/hello.mp3</Play>
  <Play>/files/goodbye.mp3</Play>
</Response>

基本的にはちゃんと動きます。が、たまに、数万回に一度くらいの頻度で、どういうわけかこの goodbye.mp3 を取得しにTwilioがこのXMLのホストではなくXMLに記載があった s3-ap-northeast-1.amazonaws.com の方にアクセスしてしまい、当然のようにエラーになることがあります。テスト時に動いたからと油断してはいけません。

対処方法

Play のようにXMLの値に記述するURLがある場合は必ずパスではなくURLを書きましょう。attributeならパスで大丈夫といわれていますが、油断は禁物です。マニュアルの記述も今は完全にURLと明記するようになっているので、うっかり古いサンプルなどをコピペした人は注意しましょう。

またTwilio側からのアクセスが15秒でタイムアウトする設定になっているので、この問題を放置するとエラーになったらユーザーが15秒くらい放置されてしまうという問題にも悩まされます。

パターンその２・リクエストのバリデーションがエラーになる?

これは完全にこちらが悪かったという事例です。

電話の自動応答システムでは、重要な個人情報を扱うケースもあるかもしれません。そのため、リクエストの発信者がTwilio自身であるかどうか厳密にチェックしておくことが必要です。しかしTwilio自身がAWS上に構築されていることもあり、発信元URLをレンジで指定するのは実質的に不可能になっています。そこで、チェックのための２種類の仕組みがTwilioには用意されています。1つはエンタープライズ向けにリクエストを発信するIPアドレスを固定するサービスで、これには毎月数十万円の費用が発生します。流石に相当大きなビジネスでないと使えませんから、もう少し現実的な手段として、他にもリクエストヘッダの X-Twilio-Signature の値をチェックすることで検査が可能になっています。例えばRailsなら

validator = Twilio::Security::RequestValidator.new auth_token
signature = request.headers['X-Twilio-Signature']
unless validator.validate(request.url, request.request_parameters, signature)
  raise 'invalid request'
end

こんな感じで発信元をチェックすることができます（あとで書くけどこのままコピペしたら痛い目にあいますよ）。

が。

時々、数万回に一度くらいの頻度で、これがエラーになることがありました。

もし一致しない場合、発信元IPアドレスを逆引きしてTwilioからのアクセスかどうかチェックすれば、まあたまにだったらいいじゃないかと考えたのですが、以前は紹介されていた気がするもののもうTwilioからは公式に自分たちのIPアドレスの範囲は公表されておらず、AWSからのアクセスであれば攻撃者からのアクセスと区別する方法がありません。

対処方法

幸いにも、エラーを検知してログを調べたところ、このエラーが発生するのはどうやら特定のURLまたはPOSTリクエストのパラメータらしいことがわかりました。

<?xml version="1.0" encoding="UTF-8"?>
<Response>
  <Gather finishOnKey="#" action="/next_action" numDigits="1" timeout="5">
    <Play>https://example.com/voice.mp3</Play>
  </Gather>
  <Redirect>https://example.com/next_action/</Redirect>
</Response>

この時点で気づいた人はいるかな？ヒントは上のRailsのコードです。

このTwiMLはユーザーからの入力を待ちながらmp3ファイルを再生し、ボタンが押されたら次のフローに遷移して、もし入力がないかシャープを押した場合も同じく次のフローに遷移する、という動作をします。この際に、何も入力がないとこのエラーになるケースが見受けられました。 Digits が空だとリクエストパラメータに含まれないのに、含むものとしてハッシュを計算するバグでもあるのかなとあたりをつけて調べてみましたが、やっぱり再現しません。

それはそうです。だって、validationのコードが間違っているのですもの。もう一度見てみましょう。

unless validator.validate(request.url, request.request_parameters, signature)
  raise 'invalid request'
end

勘のいい方はお気づきでしょうが、Railsの request.url は後ろのスラッシュを自動的に外します。なので、Twilio側からは https://example.com/next_action/ にアクセスしているのに、Railsの request.url は https://example.com/next_action として処理しようとするので、ハッシュ値の計算が一致せずエラーとなってしまうのです。解決方法は request.url から request.original_url に変更するか、後ろにスラッシュを追加してリトライすることでしょうけれど、まあ後者はないですね。 orignial_url の場合、schemeやpathを環境変数で上書きできるようなので注意しましょう。

validator = Twilio::Security::RequestValidator.new auth_token
signature = request.headers['X-Twilio-Signature']
unless validator.validate(request.original_url, request.request_parameters, signature)
  raise 'invalid request'
end

Githubにも投稿しておきました…

パターンその3・あれ？リクエストが来ない

Twilioの管理画面のログに、時々、数万回に一度くらいの頻度で、こちらが5xxエラーとなってリクエストが完了しなかったというエラーが表示されることがあります。ところが、Webサーバのログを調べても、リバースプロキシのログを調べても、ロードバランサのログを調べても、VPCのログをひっくり返しても、どこをどう調べてもアクセスされた形跡がないことがあります。Twilioの管理画面に残るエラーコードは11200、界隈では呪いの数字として知られる恐ろしい番号です。特にコンテナサービスやherokuのように通常はそこまで細かくログにまでアクセスできない環境を利用している場合、どうしても必要な情報が揃わず、サポートとのやりとりも時間とともに有耶無耶になってしまうことも多いのですが、私たちのようにしつこいクライアントだと結構あれこれ追いかけていくので、議論の俎上に乗せることが出来るようになります。

実際、Twilioの年次イベントSignalに参加して本国のエンジニア達と話す機会を持つことができたので、こちらも情報を持ち寄って色々と議論してきたのですが、やはりソケットの作成に失敗してそのままエラーになっているケースがあるとのこと。

もう少し説明すると、Twilioのサーバ群からユーザのTwiMLアプリにhttp(s)でアクセスしてくるリクエスト（ユーザーエージェントはTwilioProxy）は、観測する限りではグローバルで管理されているアメリカ国内からのアクセスになります。このリクエストを発信するサーバ群は当然ながらオートスケーリングに対応しており、必要に応じて増減します。しかし、起動にはそれなりの時間がかかるため、急激なアクセス数の上昇に間に合わないことがありえます。ここで利用されているソケット通信のプログラムはOS側のTCPスタックが用意した機能を基本的には呼び出すだけなのですが、サーバには作成できるソケットには数の上限があり、通常はリソースとの兼ね合いを見ながら、個々のサーバではulimitで、サーバー群全体ではプログラムを実行するサーバの数で上限値を調整します。Twilioくらいの規模になると個々の対応は間に合うわけがないので必然的に台数での勝負になるわけですが、そのため急激なスパイクが発生した際に後手に回ることが往往にして起こり得ます。

Signalに参加して現場のエンジニアと話す機会を持つと、ぶっちゃけこれって実装はXXXXでしょ？とかいう質問にも割と気軽に答えてもらえるので、こちらとしても大変助かりました。プログラマは横の繋がりが大切なのは国を問わず真実ですね。

対処方法

正直なところ、こちら側で対処できることは大変少ないのは間違いありません。例えば、

<?xml version="1.0" encoding="UTF-8"?>
<Response>
  <Play>https://example.com/voice1.mp3</Play>
  <Play>https://example.com/voice2.mp3</Play>
  <Redirect>https://example.com/next_action</Redirect>
</Response>

こんなTwiMLを実行する際に、このTwiML自体をTwilioがこちら側のサーバから取得するのが失敗すれば復旧は可能です。 fallback のURLを指定して、直前のエラーが発生したURLのアクションを再実行すればいいからです。しかし、この中のmp3ファイルの１つの取得に失敗した場合はどうでしょう。この単純な例なら強引に復帰できなくもないですが、リアルワールドのIVRではよくあるような、他の Gather や Record といった動詞が混ざったTwiMLの場合は、再実行はできないかもしれません。またmp3ファイルが複数箇所で利用されている場合はURLを工夫しておかないとどの場面で使われたのかがわからないので復帰させることも出来ません。

とはいえ、Twilioのプロダクトマネージャの方とお話ししたところ、決して手を拱いているわけではないようで、近いうちにソケットの作成リトライ回数のオプションが利用可能になる予定とのこと。まあ実際にエラーが起きている環境で再実行して本当に解決になるのかどうかはさておき、対処療法としてはありだとは思います。流石に日本でのピークタイムを考慮したスケーリングのスケジュールを要望しても個別の対応は難しいとのことですが、サポートには投げるとのことなので実際に朝9:00のように日本のタイムゾーンでのピーク時のエラーは減少傾向にあります。というかどんどん減ってます。

もし根本的な解決を望む場合は、その前にご自身の完璧主義が果たして正当かつコスト見合いかどうかよく考えるべきだとも思いますが、それでもという場合には、あらゆるリクエストは失敗する可能性があり、 fallback URLで復旧させることを見越しながら全体を設計する他はありません。上のような例では同じMP3ファイルを使い回さず、場合によっては動的にTwiMLを生成してまでもエラーからの復帰が可能な仕組みを用意することになるでしょう。もちろん下手をすると無限ループでTwilioのサーバ群からリクエストを受け続ける羽目になることにもなりかねませんが、それは理想主義的な完全主義との素直なトレードオフです。

こんな風に、大規模なシステムをTwilioで運用すると、これまで見えてこなかった様々な問題に行き当たるようになったので、これを機会に情報を共有して次に続くみなさんのお役に立てれば何よりです。