GitHubがセッション処理でまれなレースコンディションをどのように発見し修正したか

3月8日、セキュリティ脆弱性のため GitHub.com の全ユーザーをログアウトさせた。

• 3月2日、あるユーザーがログインしたところ別のユーザーとして認証されたという報告が入った。ユーザーは直ちにログアウトしたが、この問題を報告し、ただちに調査に入った。数時間後、別のユーザーも似た問題を報告した。

• 初期調査の結果、あるユーザーのセッションが報告時点で2つの IP から共有されていたことを発見した。

• 最近のインフラ変更を調査した結果、直近でロードバランサーとルーティング側をアップグレードしており、その際に HTTP keepalives が変更されていたことを見つけ、関係があるように見えたが、さらに調べると無関係であることが判明した。

• それでもインフラを調査する過程で、誤ったセッションを受け取ったリクエストが正確に同じマシンとプロセスで処理されていたことが分かった。

• ログを調べた結果、レスポンスボディは正常で、Cookie だけが誤って送られていたことが分かり、同じプロセスで処理された別のユーザーの Cookie が誤って返されていた。報告されたケースの1つでは2つのリクエストが連続しており、もう1つでは2つのリクエストの間に別のリクエストが2つあった。

• ここから、同じ Ruby プロセスで処理されたリクエスト間で状態が漏えいしたという仮説を立て、これがどうして可能なのかを追究した。

• 最近の変更を見直した結果、性能向上のため、ユーザーに有効化されている機能を検査するロジックをリクエスト処理中に実行するのではなく、一定間隔で更新するバックグラウンドスレッドで処理するよう変更していたことが分かった。このスレッドセーフな動作に調査の焦点を当てた。

• GitHub.com のメインアプリケーションは Ruby on Rails であり、マルチスレッドで動作するように書かれていない多くのコンポーネントがある。

• アプリケーションではスレッドはすでに使われていたが、新しいバックグラウンドスレッドは例外処理ルーチンで予期しない挙動を生み出していた。

• バックグラウンドスレッドで例外が発生したとき、エラーログにはバックグラウンドスレッドと実行中のリクエストの情報が両方含まれていた。

• 当初は、無関係なリクエストのデータがバックグラウンドスレッド側のログに残るのは、内部レポーティングの問題による不一致にすぎないと考えていた。

• Rails はリクエストごとに新しいコントローラオブジェクトを生成して処理するため、安全だと考えていた。

• そのため、なぜこの問題が起きるのかは依然として明確ではなかった。

• Rails アプリケーションで Rack HTTP サーバとして使っている Unicorn が、リクエストごとに新しい独立した env オブジェクトを生成しないことを発見し、突破口が見え始めた。

• その代わりに Unicorn は、リクエストごとに Ruby のハッシュを割り当て、それをクリアして再利用していた。

• これによって、バックグラウンドスレッドのログはレポーティング上の不一致ではなく、リクエストデータが共有されていることを示していると分かった。

• このレースコンディションを開発環境で再現しようと試みた結果、この状況が発生するには匿名リクエストから始まる必要があることが分かった。

1. 匿名リクエスト（リクエスト #1）が来ると、例外レポートライブラリにコールバックが登録される。このコールバックには、Unicorn が提供する Rack のリクエスト環境オブジェクトにアクセスする Rails コントローラオブジェクトへの参照が含まれている。

2. バックグラウンドプロセスで例外が発生すると、報告のために完全なコンテキストがコピーされ、コールバックも含まれる。

3. メインスレッドで、新しいログイン済みリクエストが始まる（リクエスト #2）。

4. バックグラウンドスレッドで例外レポーティングがコンテキストコールバックを処理する。ユーザーセッション識別子を読み取ろうとするが存在しないため、リクエスト #1 の Rails コントローラを通じて認証システムに問い合わせる。Rack はすべてのリクエストで同じオブジェクトを使うため、そのコントローラはリクエスト #2 のセッション Cookie を見つける。

5. メインスレッドでリクエスト #2 が終了する。

6. 別のログイン済みリクエストが来る（リクエスト #3）。認証はすでに完了している。

7. バックグラウンドスレッドで、コントローラは Rack 環境内の Cookie jar にセッション Cookie を書き込んで認証を完了する。この時点では、それはリクエスト #3 用の Cookie jar である。

8. ユーザーはリクエスト #3 のレスポンスを受け取るが、Cookie jar にはリクエスト #2 のセッション Cookie が書き込まれているため、リクエスト #2 のユーザーとして認証される。

要するに、例外発生と同時にどのリクエスト処理がどの順番で起きるかがこの状況を生み出すと、あるレスポンスのセッションが直前のレスポンスのものに置き換わる。これは Cookie ヘッダでのみ発生し、HTML などのレスポンス自体はすべて本来認証されていたユーザー向けのデータである。

このバグは、こうした複雑な条件がすべてそろったときにだけ発生する。

• この問題を解決するため、新たに導入されたバックグラウンドスレッドを削除し、3月5日に本番環境へデプロイした。

• その後、環境共有が起きないよう Unicorn にパッチを作成し、3月8日にデプロイした。

• ログ分析の結果、この問題はまれにしか発生していなかったことが分かったが、潜在的な問題を解消するために全ユーザーのセッションを無効化した。

• 問題解決後、Unicorn メンテナと協力して、この修正をアップストリームにも適用した。

[kunggom]

並列処理は本当に複雑ですよね。私も週末の間、個人的な勉強のために最近作ったコードをCPUスレッド数ぶん並列実行してみようとして、かなり苦労しました。成功はしたものの、ちゃんとできているのか今でも少し不安です。