shakapacker-dev-server の5秒遅延の謎

はじめに

私は現在 Shakapacker を使ってアプリケーションを開発しています。ある時、まれに JS ファイルを取得するのに5秒ほどかかることに気づきました。当然、ビルドで遅くなることもありますし、低頻度なので最初は気にしていなかったのですが、遅延する時はいつも5秒以上かかるのです。一度気になり出すと気味が悪く、なんとか解決しようと調べてみました。

ちょっとした謎解き感覚で読んでもらえたらと思います。

調査

Shakapacker の標準的なセットアップをした場合、下記の経路でリクエストが解決されます。

ブラウザ → Rails サーバー → dev-server

どこに問題があるのか色々なアプローチで調査しました。調査のプロセスを飛ばして解決策が知りたい場合は、次のセクションまで読み飛ばしてもらって大丈夫です。

ビルドに問題はないか？

dev-server のログを確認してみると、ビルドの痕跡はありませんでした。よって JS ファイルをビルドするのに時間がかかっているわけではないようです。

GC は発生してないか？

常に発生するわけではないので GC が発生しているのではないかと疑いましたが、rails サーバーや dev-server が動いているメモリには余裕があります。何より遅延する時は必ず5秒以上かかるという奇妙な性質があるため、この可能性は除外しました。

コネクション不足ではないか？

JS ファイルを大量にダウンロードしているのでコネクションが不足している可能性があると考えました。そこで Rails サーバー(puma)の最大コネクション数を増やして実験しました。しかし結果は変わりませんでした。

プロキシの名前解決でIPv6が使われてないか？

Rails サーバーから dev-server にプロキシする際に、IPv6 が使われてしまうが dev-server が IPv6 で待ち受けてないためにリクエストが無視されてしまうケースがあるそうです。

IPv6 でのアクセスで5秒待ってタイムアウト
IPv4 でアクセスをリトライし JS が取得されて応答

上記の順序で動作しているとしたら、現象とも噛み合うように感じました。しかし下記のコマンドで調査してみたところ、どうも IPv4 のみが使われているようです。

# localhost を使う場合
Socket.getaddrinfo("localhost", 3035)
# IPv6 が含まれているので想定した問題が起こりうる
# => [["AF_INET6", 3035, "::1", "::1", 10, 1, 6], ["AF_INET6", 3035, "::1", "::1", 10, 2, 17], ["AF_INET6", 3035, "::1", "::1", 10, 3, 0], ["AF_INET", 3035, "127.0.0.1", "127.0.0.1", 2, 1, 6], ["AF_INET", 3035, "127.0.0.1", "127.0.0.1", 2, 2, 17], ["AF_INET", 3035, "127.0.0.1", "127.0.0.1", 2, 3, 0]]

# dev-server を使う場合
Socket.getaddrinfo("dev-server", 3035)
# IPv6 が含まれてないので、問題は起きないはず
# => [["AF_INET", 3035, "192.168.97.3", "192.168.97.3", 2, 1, 6], ["AF_INET", 3035, "192.168.97.3", "192.168.97.3", 2, 2, 17], ["AF_INET", 3035, "192.168.97.3", "192.168.97.3", 2, 3, 0]]

よってこの可能性も除外しました。

プロキシを経由しないとどうなるか？

最後に、Rails を経由せずに、ブラウザから dev-server (ポート3035) へ直接 JS ファイルをダウンロードする実験をしました。この方法では100回試して5秒の遅延問題は発生しません。どうやら原因は Rails サーバーから dev-server へプロキシしている部分にあるようです。

原因

調査によってプロキシ経由でのみ、まれに5秒の遅延が発生することがわかりました。この「プロキシ越しでの5秒遅延」は、Node.js の Keep-Alive タイムアウトが原因であるケースが多いようです。

dev-server に使われている Node.js の HTTP サーバーは、デフォルトで keepAliveTimeout が 5000ms（5秒）に設定されています。Rails（プロキシ）側がコネクションを再利用しようとしたタイミングと、Node.js 側が5秒経過でコネクションを切断しようとしたタイミングが運悪く衝突すると、通信がハングアップしてしまい、ピッタリ5秒の遅延として現れる、というメカニズムのようです。

対策

根本的なプロキシの設定を見直すよりも、「そもそもローカル開発環境ではアセットへのリクエストをプロキシさせない」のが手っ取り早くて確実です。config/environments/development.rb に以下の設定を追加し、アセットへのリクエストを強制的に dev-server へ直接向けるようにしました。

# /packs/ を含むアセットへのリクエストのみ、強制的にdev-serverへ向ける
config.action_controller.asset_host = proc do |source|
  'http://localhost:3035' if source.include?('/packs/')
end

また、ブラウザから見ると Rails サーバー（例: 3000番）と dev-server（3035番）でポートが異なるため、Content Security Policy (CSP) 違反でブロックされてしまいます。これを回避するため、config/initializers/content_security_policy.rb に下記を追加します。

if Rails.env.development?
  policy.script_src :self, :unsafe_eval, :unsafe_inline, :https, "http://localhost:3035"
  policy.style_src :self, :unsafe_inline, :https, "http://localhost:3035"
  policy.connect_src :self, :https, "http://localhost:3035", "ws://localhost:3035"
end

この方法で5秒遅延問題はようやく解決しました。

おわりに

Shakapacker の5秒遅延問題いかがだったでしょうか。おそらくチームの開発者全員が「なんとなく遅い時があるな」とモヤモヤを感じていたと思います。なかなか思ったように調査が進まずに苦しかったですが、最終的には解決できてよかったです。こうした引っ掛かりを無くしていくことが開発体験をよくしていくことだと思うので、今後も注意を向けていきたいと思います。