経路探索で多発したコネクションエラーとの出会いと別れ

この記事は、「JapanTaxi Advent Calendar 2018」の17日目です。

はじめに

JapanTaxiアプリのサーバサイドでは、地図関連からタクシー配車に関わるやりとりまで、さまざまな内外のサービス連携をAPI接続を通しておこなっています。

今回は、アプリ上で空車のタクシー表示や目安料金算出などに使っている経路探索関連の外部APIを、コストと精度の観点から内部APIに段階的に置き換える中で多発した「コネクションエラー」との出会いから別れまでの話をしたいと思います。

内部APIへの置き換えの概要

内部APIへの置き換えにあたり、アプリからの1リクエストに対して、サーバサイドでは複数の並列APIリクエストをおこなう必要が出ました。

これまでよりもサーバ内部からのコネクション数が増えることは想定されており、アプリからのリクエストをユーザーIDで8分割し、1/8ずつ段階的に切り替えていく手法をとることにしました。

Faradayが返す、コネクションエラーとの出会い

今回の置き換えでは、JapanTaxiアプリのサーバサイド（Rails）にてRubyライブラリのFaradayを使ってAPIリクエストをおこなっています。

connection = Faraday.new(url: host) do |faraday|
  faraday.response :json
  faraday.adapter Faraday.default_adapter
end

response = connection.get(path, params, headers) do |request|
  request.options.timeout = 4
end

上記のような実装で、リクエストのうち半分くらいを切り替えたタイミングから「Faraday::ConnectionFailed execution expired」なるコネクションエラーが散見されるようになりました。

呼び先の内部APIのパフォーマンスについては、切り替えを進める中で応答速度含めて問題のないレベルまで引き上げてもらっており、呼び元の問題である可能性が高い状況です。

また、CPUやメモリ使用量の全体的な増加に合わせて、順次サーバのスケールアウトはおこなっており、原因が見えないままこれ以上やみくもにスケールアウトするのははばかられます。

接続確立前のタイムアウト値をいじってみる

調べたところ、「Faraday::ConnectionFailed execution expired」はAPIとの接続が確立される前のエラーであり、タイムアウト値（秒）を個別に変更できることがわかりました。

段階的に、接続確立までのタイムアウト値を長くしてみます。

response = connection.get(path, params, headers) do |request|
  request.options.timeout = 4
  request.options.open_timeout = 4 # ここの値を調整
end

結論としては、エラー数にはっきりとした改善は見られませんでした。また、仮に改善されていても、タイムアウトまで4秒を超えてしまうとユーザー観点でも問題があります。

リトライ処理を入れてみる

そもそもリクエスト数が多いため、多少エラーが出るのはやむなしな可能性もあり、リトライ処理を追加することにします。

connection = Faraday.new(url: host) do |faraday|
  faraday.request :retry,
    max: 2,
    interval: 1,
    exceptions: [Faraday::Error::ConnectionFailed]
  faraday.response :json
  faraday.adapter Faraday.default_adapter
end

response = connection.get(path, params, headers) do |request|
  request.options.timeout = 4
end

これにより、一定数エラーを減らすことができたものの、リクエストの切り替え割合を増やすと、再び「Faraday::ConnectionFailed execution expired」は姿を表しました。

エラーをローカルで再現させる

この進め方では、今回根本的な解決が臨めなそうということで、ローカルで事象を再現させて、解決を目指していくことにします。

def execute(request, parallel)
  start_time = Time.current
  Parallel.each(0..request, in_process: parallel) do |index|
    p "- request: #{index}"
    route_finder # 経路探索処理
    sleep 0.1
  end
ensure
  p "-- #{Time.current - start_time} sec"
end

上記のような検証メソッドを用意し、1000回4並列くらいで処理実行すると、いつでも「Faraday::ConnectionFailed execution expired」と再会できるようになりました。

他の原因を探る旅へ

この時点で、SREと話す中では「ファイルディスクリプタ数の上限値に引っかかっているのでは？」という仮説が出ており、検証メソッドを用いてシステムまわりの値を見ていくことにしました。

詳細は割愛しますが、実際に普段アプリケーションが動いているのと同等のコンテナ上で、

プロセス数 lsof
通信数 ss -t
TCPコネクション数 netstat -t
ファイルディスクリプタ数 ls /proc/*/fd
メモリ使用量 free -tm

の値変化を見てみたものの、いずれも張り付きや上限値に近づいているクリティカルな数値は見つけられず。

コネクション確立の開始時点を疑ってみる

改めて、今回の問題の原点に立ち戻ることにしたのがこのタイミングです（冷静に考えると遅いような…）。

当初にopen_timeout値の変更を試していた際に以下の記事を参照しており、

Ruby の Net::HTTP のタイムアウトにハマって、結局 Timeout について調べることになった件

そもそもサーバーが障害等でネットワークがつながってない状態では、DNS の名前解決により、timeout が割り込めず、タイムアウト値を設定しても、その秒数で処理を終了させることが出来ない。

の記述が引っかかっていました。

名前解決がボトルネックになっている可能性

内部APIはIPアドレス固定ではないのですが、一時的にコンテナ上の/etc/hostsでドメインのIPアドレスを固定させ、名前解決をコンテナ内で完結させる形で検証をおこないます。

XXX.XXX.XXX.XXX route_finder.host

検証プログラムを実行したところ、2倍以上のパフォーマンスが出る結果に。根本的な原因に近づいた気がします。

ローカルで名前解決のみを実行してみる

検証プログラムを以下のように変更し、名前解決のみを実行させてみます。/etc/hostsはもとに戻している状態です。

def execute(request, parallel)
  start_time = Time.current
  Parallel.each(0..request, in_process: parallel) do |index|
    p "- request: #{index}"
    p Socket.getaddrinfo('route_finder.host', 433)
    sleep 0.1
  end
ensure
  p "-- #{Time.current - start_time} sec"
end

すると、秒間のリクエスト数250回目でぴたりと処理が止まり、4秒ほど経つとまた再開する挙動になることが判明。

これかもしれない。

根本原因はDNSによる名前解決時のレート制限

JapanTaxiでは、Azure、AWS、GCPと複数のクラウドベンダーを利用していますが、今回のサーバサイドはAzure上のDockerコンテナで動いていました。

検証からわかったこととして、

コンテナからの名前解決は内部DNS（≒AzureDNS）の利用となる
Linuxには標準でDNSキャッシュの仕組みがないため、毎回名前解決の問い合わせが走る
秒間リクエスト数が多いとFaradayのtimeout=4により4秒以上経つとタイムアウトして「Faraday::ConnectionFailed execution expired」が発生する

検証はSREメンバーと共有しながら進めており、この結果を受けてコンテナ上にdnsmasqを導入してもらうことに（DNSでの名前解決結果を1分キャッシュ）。

その後、改めて名前解決のみの検証プログラムを実行すると、秒間のリクエスト数250回目で止まることはなくなりました。

コネクションエラーとの別れ

dnsmasqを本番のコンテナに導入の上で、内部APIの置き換えを再開させたところ、「Faraday::ConnectionFailed execution expired」はほぼゼロに 🎉🎉🎉

実は、今回のAPI置き換え以前にも多少このエラーは発生しており、件数がそこまで多くないことと原因がわからず放置されていたようでしたが、今回の対応により駆逐することができています。

おわりに

New Relic上でのエラー一覧からも、「Faraday::ConnectionFailed execution expired」が消えたことで他のエラーが目立つ結果となり、システム安定化に向けた改善が進めやすい状態になりました。

大きく回り道した感もあるのですが、試行錯誤の末解決できたことで今回の出会いと別れは忘れがたいものになったと思っています。