Padrino (WAF) の仕様変更にともなって発生した障害の原因を追いかけた話
はじめまして、豊川と申します。所属はCS部門専属の開発グループで、通称CS開発といいます。CSとは顧客満足 (Customer Satisfaction) のことを指します。
業界でもCS部門に専属の開発チームがあるのは珍しいかもしれません。専属の開発チームがあるとCSスタッフからの依頼や要望、プロダクトのアップデートに素早く対応できるので、サポート品質の向上やサービスの健全化に貢献できるという特長があります。
CS開発の業務は、ヘルプやお問い合わせフォームの改修から、決して表舞台に出ることのない社内向けCS管理ツールの開発保守やアクセスログの解析、さらにはクライアントアプリの改修やちょっとした業務補助スクリプトの開発まで多岐に渡ります。
本稿では、CS管理ツールで使用しているPadrinoの仕様変更にともなって発生した障害において、調査から解決に至るまでのお話をしたいと思います。
ログインできない
障害が発生したのはPadrinoのアップグレードを含むバージョンアップメンテナンスが行われた直後でした。ログインしようとするとCSRFチェックに引っかかってしまいました。
いったんCSRFチェックをオフにして原因を調べることにしました。ところがチェックをオフにしても依然としてログインできないのです。
アプリケーションでログインセッションを参照するとnil
になっており、Change Logを見直してもそれらしい変更を見つけることができませんでした。
Cookieの確認
アプリケーションでセッションがnil
になっていることから、まずCookieがサーバに到達しているか確認することにしました。
下図はクライアントからCS管理ツールまでのHTTPリクエストの流れです。
クライアント-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リクエスト・レスポンスの内容は下図のようになっていました。
クライアントはログイン情報を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のものへ書き換えられていました。
Rack::Protection::IPSpoofing
ではHTTP_X_FORWARDED_FOR
が存在する場合、HTTP_X_REAL_IP
がHTTP_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によるものではないため図を含めて訂正しました。