技術者らしく、たまには技術ネタでブログを書こうw
というわけで、最近弊社サービスの開発中で実際に踏んだバグがなかなか面白かったので、分析と解決までの経緯を振り返りも兼ねてこちらにもまとめておきます。
バグの解析って、苦しいけどけっこう好きなんですよね。いろいろと仮説を立てて推理したりする過程がゲームみたいで楽しいというか。
まあ、ネタ的に技術者にしかわかってもらえないでしょうが、知ったことじゃありません、はい。
というわけでいってみよー。
事象：お問い合わせフォームが消える！？
弊社サービスのコラボ(http://www.collabo.in/)のWebページを見るとわかりますが、画面の右側にお問い合わせフォームの見出しタブが常に表示されていて、クリックされるとにゅにゅーっと伸びる仕組みになっています。
| ω・`）チラ ←なんか、これに似ている気がする。 |
ところがあるとき、このお問い合わせフォームのタブが画面のロード完了と同時に、みるみるFadeOutしてついには消えてしまう、という問題が発生。
| ω・`） |
| ・`） |
| )彡ｻｯ |
↑こんな感じ。左右逆だけど。
開発環境ではそんな問題が出てなかったのに、本番環境(Heroku)ではそうなるってのは、一体、どういう了見だ！？
というか、こういうバグがあったときこそのお問い合わせフォームだろう！
お問い合わせフォームが消えてどうする！ 恥ずかしがり屋さんか、君は！
※ちなみに、本来はステージング環境で摘出するべきだったんですが、バグがあまりに内向的な子だったんで気づくのが遅れました。ホントにすみません。
仮説１：Sprocketsが悪い？
コラボはRails3で実装しています。
で、開発環境(development)と本番環境(production)でJavaScriptの挙動が違う、となるとまずAssetsまわりの設定または処理に何らかの問題があるのでは、と最初は考えました。
特にdevelopmentではバラバラにJSファイルを読み込んでいたのを、productionではSprocketsがそれらをひとつのJSファイルに結合、かつ圧縮・難読化してくれるので、その過程で挙動が変わる何かが起こったのではないか、と疑ったわけです。
Chromeの開発者ツールで該当個所のHTMLを確認すると、属性として「style="display: none;"」が勝手に追加されているのがわかりました。これは、JQueryの.hide()が呼び出された場合と同じです。
作戦１：Chrome開発者ツールでイベントを捕捉
探し出すべき犯人は、HTMLに勝手にstyle="display: none;"を追加した何らかのコードです。
そこで、DOMの属性が変更された際のイベント("DOMAttrModified")をキャプチャー、スタックトレースを遡ればそのコードにたどり着けると考えました。
これはChromeの開発者ツールを使えば簡単にできます。
ただ厄介なのが、事象発生のタイミングが画面のロード時の一回限りなので、あらかじめブレークポイントを仕込んでおくことが難しいということ。
そこでJSファイルの先頭に、
debugger;
の一文を仕込んでおくことにしました。
こうしておけばこのコードを読み込んだ時点で開発者ツールが起動するので、楽々とブレークポイントを仕込むことができます。
その後、コード実行を再開させれば見事、犯人が網にかかる、ってわけ。事件解決、めでたしめでたし。
この時点で、私の頭の中では西武警察のエンディングテーマが流れ始めていたんですが、世の中というもの、そう甘くはないようです。
実際にやってみたところ、どうも「debugger;」が読み込まれて開発者ツールが起動し、JavaScriptのコード実行が停止されるまでに若干のタイムラグがあるらしく、その間にある程度のコードは実行されてしまうようなんですよね。
なので、開発者ツールがようやく起動したと思ってDOM属性を確認しても、あわれ、すでに「style="display: none;"」が追加された後。
このバグ、言うなれば、すさまじいスピードで壁に落書きをして、人が来る前に逃げ去るような奴です。
どんなに急いで駆けつけても、残されているのはただ落書きだけ、犯人の姿は影も見えず。えーい、おのれ。
仮説２：他のJavaScriptが悪い？
それにしても「debugger;」を仕込んでいるのに、それより先のコードが実行されてしまう、などということがあってよいのかしらん。
それより他に読み込んでいるFacebookやTwitterとかのJSが悪さをしている可能性が高いかも、などと考え始めたのがこの辺りから。
※しかし・・・思考経路を振り変えてみると、自分以外の誰かが悪いはず、という思い込みがアリアリだな、自分w。
この仮説を検証するのは簡単で、HTMLから自社開発のJSファイルの読み込みを削除し、かつ、他のJSファイルはそのままの状態で、同じ問題が発生するかどうかを確かめればいいわけです。
で、やってみました。・・・すると、バグ事象も消えた！
つまり、TwitterもFacebookも悪くないんです。疑ったりして、ホントごめんなさい。
ともあれこれで、バグは自社開発のソースの中に潜んでいる、ということだけはハッキリしたわけです。
まずは一歩前進。
作戦２：開発環境で条件を揃えてみる
さて、Chromeの開発者ツールでのデバッグが頓挫したため、次の作戦を考える必要が出てきました。
で、考えたのは「開発環境でバグを再現してみよう」作戦。まさに王道。
バグを再現しようとする過程で原因がわかることも多いですからね。
そこで、
${RAILS_ROOT}/config/environments/development.rb
を次のように修正して、development環境でもproduction環境と同じJSファイルをSprocketsに生成してもらおうと考えました。
諸事情により、"rails server -e production"だとローカルでは起動しないので。
-
- [修正前]
# Do not compress assets config.assets.compress = false # Expands the lines which load the assets config.assets.debug = true
-
- [修正後]
# Disable Rails's static asset server (Apache or nginx will already do this) #config.serve_static_assets = false config.serve_static_assets = true # Compress JavaScripts and CSS config.assets.compress = true # Don't fallback to assets pipeline if a precompiled asset is missed config.assets.compile = false # Generate digests for assets URLs config.assets.digest = true
基本的にproductionの設定ファイルから該当する個所をコピペしただけですが、serve_static_assetsだけはtrueにしておかないと、RailsがJSファイルを返却してくれなくなるので注意が必要です。
あと、あらかじめ"rake assets:precompile"を叩いて、JSファイルを結合しておくことも忘れずに。
これで、本番環境と同じJSファイルが生成されて、開発環境でも同じバグ事象が発生するはず・・・と思ってやってみると、バグ再現せず。
なぜ！？
仮説３：生成されるJSファイルが開発環境と本番環境でちがう？
ここで、そもそも開発環境と本番環境で、Sprocketsがまるで異なったJSファイルを生成しているのでは、という疑惑が急浮上してきました。
そこで本番環境のJSファイルと、作戦２で生成した開発環境のJSファイルを比較したところ、ありましたよ、犯人の姿が。
$ diff application-96518f0f.js application-994c381a.js | head 2c2 < * jQuery JavaScript Library v1.9.0 --- > * jQuery JavaScript Library v1.8.3 8c8 < * Copyright 2005, 2012 jQuery Foundation, Inc. and other contributors --- > * Copyright 2012 jQuery Foundation and other contributors 12c12 < * Date: 2013-1-14
application-96518f0f.jsが本番環境のもの、application-994c381a.jsが開発環境のものです。
見ればわかる通り、JQueryのバージョンが1.8.3から1.9.0へと変更されています。
見つけた、犯人！
=> 直接原因：JQueryのバージョン違い
なぜなぜ分析１：なぜJQueryのバージョンが違うのか？
しかし、捜査はここで終わりではありません。
なぜなら、JQueryのバージョンがどうして違っているのか、まだ理由がわかっていないからです。
Railsの場合、JQueryのバージョンはjquery-railsというgemのバージョンに紐づいているので、JQueryのバージョンが違うということはこのgemバージョンが開発環境と本番環境で違う、ということになります。
実際にHerokuにデプロイした時のログと、開発環境のGemfile.lockに記述されているjquery-railsのバージョンを比べると次のように違っていました。
開発環境：v2.1.4
本番環境：v2.2.0
しかし、これはおかしな話なんです。
そもそも、こういったgemのバージョンを含めた管理のために、Rails3ではbunlderというものを使っているのですから。
各gemのバージョンをFixするためにbundlerが自動で生成してくれるのが、Gemfile.lockというファイル。
こいつさえgitのリポジトリに含めておきさえすれば、Heroku側で"bundle install"された時にもbundlerがGemfile.lockを読み取って、本番環境でも開発環境と同じバージョンのgemが使用されるはずでした。
しかし、実際にはバージョンが違っているわけです。つまり、さらなる原因追跡が必要です。
=>第二の問題：Gemfile.lockによるgemのバージョン指定が無効になっている
なぜなぜ分析２：なぜGemfile.lockで指定されたバージョンのgemがHerokuで使用されないのか？
なんでだよ、Heroku。
ちゃんとGemfile.lockをリポジトリに入れて、pushしているよ。なのに、なんで無視するのさ！
などと、思わず心の中で突っ込みを入れながらも、Herokuのドキュメントをあたってみたところ、見つけたのがこちら。
すぐに目を引いたのが、この文章。
This ensures that all gems specified in Gemfile, together with their dependencies, are available for your application. Running bundle install also generates a Gemfile.lock file, which should be added to your git repository. Gemfile.lock ensures that your deployed versions of gems on Heroku match the version installed locally on your development machine.
ふむふむ、そうだよね。そのはずだ。
しかし、そのすぐ下に書いてある文章で思わず硬直。
If the platforms section of your Gemfile contains Windows entries, such as mswin or mingw, then the Gemfile.lock file will be ignored.
な、なんだってー！！
そして実際にコミットされたGemfile.lockを確認したところ、まさにドンピシャ。
PLATFORMS ruby x86-mingw32
"x86-mingw32"ってあるじゃん、おい！
あー、思い出したわー。
弊社サービスの開発当初は私、自宅のWindowsで作業しとったんですよ。その頃は事務所も無かったので・・・。
でー、VirtualBoxとかで動作確認するのが遅くて嫌だったので、RubyInstallerでWindows側にRubyを入れて動かしていたんですよね。
でも、そのうちgemの一部がWindows非対応だったり、いろいろ面倒くさいことが多くなってきたのでVirtualBox上で開発したり、現在愛用のMac Book Airで開発したりするようになったわけです。
この時の負の遺産が、まさかこんなところで現れるとはねー。
つまりは
「開発環境はデプロイ先の環境と合わせろや、このボケがっ！！」
ってことですねー。
まー、基本ですよねー・・・。
スンマセンしたっ！！。
まとめ
というわけで、今回のバグについてまとめてみます。
まず、バグの真の原因は、次の通り。
・Gemfile.lockのPLATFORMセクションにWindows指定のエントリが記載されていたため、バージョン不整合を引き起こしていた。
対して、得た教訓は次の通り。
・開発環境はデプロイ環境と極力、合わせること。
※当たり前。本当は開発環境もLinuxにするべきかも知れないけど、Macも一応FreeBSD系ということで許容範囲かな、と思ってる。
それくらいのさじ加減はあってもいい。
・Herokuのデプロイした時のログをちゃんと確認すること。
※といっても、いちいち目視確認なんかやってられないので、bundle installの時のログとGemfile.lockとの突き合わせ確認を自動化したいところ。
とまあ、サービス的にはあんまりヤバくないけど、解析したらばそれなりに奥深い、という技術者のブログにはお誂え向きのバグでしたねー。
もちろん本当にやばいバグだったら、こんなとこに書きませんけどねw
ココまで読んだ物好きなあなたも、きっと様々なバグと出会ってきたのでしょうw
何かしらご参考のなったとしたら、嬉しい限りです。
プログラムの数だけ、バグとの出会いがある。さて、次はどんな出会いが待っているのでしょう・・・
そんな出会い、全然うれしくないけどなっ！！
