mixi engineer blog

*** 引っ越しました。最新の情報はこちら → https://medium.com/mixi-developers *** ミクシィ・グループで、実際に開発に携わっているエンジニア達が執筆している公式ブログです。様々なサービスの開発や運用を行っていく際に得た技術情報から採用情報まで、有益な情報を幅広く取り扱っています。

Padrino (WAF) の仕様変更にともなって発生した障害の原因を追いかけた話

はじめまして、豊川と申します。所属はCS部門専属の開発グループで、通称CS開発といいます。CSとは顧客満足 (Customer Satisfaction) のことを指します。
業界でもCS部門に専属の開発チームがあるのは珍しいかもしれません。専属の開発チームがあるとCSスタッフからの依頼や要望、プロダクトのアップデートに素早く対応できるので、サポート品質の向上やサービスの健全化に貢献できるという特長があります。
CS開発の業務は、ヘルプやお問い合わせフォームの改修から、決して表舞台に出ることのない社内向けCS管理ツールの開発保守やアクセスログの解析、さらにはクライアントアプリの改修やちょっとした業務補助スクリプトの開発まで多岐に渡ります。
本稿では、CS管理ツールで使用しているPadrinoの仕様変更にともなって発生した障害において、調査から解決に至るまでのお話をしたいと思います。

jp.padrinorb.com

ログインできない

障害が発生したのはPadrinoのアップグレードを含むバージョンアップメンテナンスが行われた直後でした。ログインしようとするとCSRFチェックに引っかかってしまいました。
いったんCSRFチェックをオフにして原因を調べることにしました。ところがチェックをオフにしても依然としてログインできないのです。
アプリケーションでログインセッションを参照するとnilになっており、Change Logを見直してもそれらしい変更を見つけることができませんでした。

Cookieの確認

アプリケーションでセッションがnilになっていることから、まずCookieがサーバに到達しているか確認することにしました。
下図はクライアントからCS管理ツールまでのHTTPリクエストの流れです。

f:id:mixi_engineers:20150616164318p:plain:w360

クライアント-LB間はHTTPSで、LB-アプリケーションサーバ間はHTTPになっています。
アプリケーションでダンプしたHTTPリクエストヘッダにはHTTP_COOKIEがセットされており、Cookieがサーバに到達していました。
問題はクライアントや経路ではなくアプリケーションのようです。

Cookieのデコード

次に、Cookieに保存されているセッションデータが正しくセットされているか、デコードして確認することにしました。
Padrinoでは下記のように設定した場合、セッションストアはRack::Session::Cookieが使われます。

enable :sessions

Rack::Session::Cookieのデータはドキュメントにもありますとおり、Marshal.dumpされたRuby HashオブジェクトがBase64エンコードされたものとなっています。
HTTP_COOKIEはこれにキーとデータ改ざんを防ぐためのメッセージダイジェストが付加された下記の形になっています。

rack.session=data--digest

ですので、Cookieの内容は下記のようにしてデコードすることができます。

Marshal.load data.unpack("m").first

デコードの結果、しかしながら、セッションデータは正しくセットされていることがわかりました。

HTTP通信の確認

サーバへCookieが届いていること、セッションが正しくセットされていることを確認し、原因の見当がつかなくなってしまいました。
そこでログイン時のクライアント−サーバ間のHTTP通信を見てみることにしました。
HTTPリクエスト・レスポンスの内容はブラウザの機能を使って見ることができます。例えばGoogle ChromeですとURL欄に下記のように入力します。

chrome://net-internals/#events

ログイン時のHTTPリクエスト・レスポンスの内容は下図のようになっていました。

f:id:mixi_engineers:20150605110313p:plain:w480

クライアントはログイン情報をPOSTし、認証されると認証が必要なページにリダイレクトされます。
ところがリダイレクト先で未認証とみなされ、再度ログイン画面にリダイレクトされていました。
つまり、認証されたにもかかわらずセッションがnilになっていたのです。

ソースを読む

セッションが読み出される過程のどこでnilになっているのか追跡することにしました。ライブラリを順に読んでいく地道な作業です。
するとリクエスト処理中でrack-protectionからRack::Session::Abstaract::SessionHash#clearが呼ばれてセッションが破棄されていました。
https://github.com/rack/rack/blob/1.5.3/lib/rack/session/abstract/id.rb#L78

リバースプロキシとIP Spoofing

rack-protectionで引っかかっていることを報告したところ、社内のエンジニアから、LB経由なのでHTTP_X_FORWARDED_FORヘッダが付加されIP Spoofingとみなされているのではないかというアドバイスをもらいました。Spoofingとはなりすましの意です。
そこで、LB経由のリクエストとアプリケーションサーバ直接のリクエストを比較してみることにしました。
すると下図のように、LB経由のリクエストではLBによってリクエストヘッダにクライアントのIPアドレスのみのHTTP_X_FORWARDED_FORが付加され、リバースプロキシによってHTTP_X_REAL_IPのIPアドレスはClientのものからLBのものへ書き換えられていました。

f:id:mixi_engineers:20150616164319p:plain:w480

Rack::Protection::IPSpoofingではHTTP_X_FORWARDED_FORが存在する場合、HTTP_X_REAL_IPHTTP_X_FORWARDED_FORに含まれるかチェックしています。
HTTP_X_FORWARDED_FORにLBのIPアドレスが含まれていなかったためチェックに引っかかり、セッションが破棄されていたのです。まさにアドバイス通りでした。
https://github.com/sinatra/rack-protection/blob/v1.5.3/lib/rack/protection/ip_spoofing.rb#L14-20

IP Spoofingチェックが有効になった原因と解決策

残る疑問は、どうして突然IP Spoofingチェックが有効になったかということです。
Padrinoのアップグレード差分を注意深く読んでいくと、rack-protectionのデフォルト値がv0.10.7では無効になっていたのに対しv0.11.1では有効になっています。
https://github.com/padrino/padrino-framework/compare/0.10.7...0.11.1#diff-1a0066278440da0ea73a0c5146a97c21L178

-        set :protection, false
+        set :protection, true

つまり、Padrinoのバージョンアップにともなってrack-protectionがデフォルトで有効となり、IP Spoofingを含むチェックが有効になっていたのでした。
解決策としてはリバースプロキシでHTTP_X_FORWARDED_FORヘッダにLBのIPアドレスを追加するのが良いのですが、IPアドレスでアクセス制限を設けていることもあり、当時はIP Spoofingチェックを無効化することで対処しました。無効化するモジュールは下記のように指定します。

+        set :protection, :except => [:ip_spoofing, :path_traversal]

おわりに

Padrinoの仕様変更にともなって発生したログイン障害の調査内容と原因についてお話ししました。文章にするとあっけないですが、実際には調査と解決に丸2日間を費やすという大変な内容でした。
障害調査においては原因となりうる可能性を1つ1つ排除していくこと、そのために普段からWebの基盤技術について理解を深めておくことが重要です。
いつでも対処できるように備えておきたいですね。

お詫びと訂正

問題の本質ではないためELBはLBという表記に訂正しました。
HTTP_X_REAL_IPのセットはELBによるものではないため図を含めて訂正しました。