誰かがきっと見てるから, もうあんたでいいから見ててよ, そうだよなだから「誰か」か
(クリープハイプ 二十九、三十)
そのへんのくだりに非常にグッとくる今日このごろです。
というわけで、Android 4.2.2の標準ブラウザ でHTTPリクエストが2回発行されて困った話を書きます。
ことの発端
とある案件のテストをしていて、
Android 4.2.2 の標準ブラウザ だけ登録出来ましぇ~ん。
というBTSが挙がってきたのがそれです。
調査
確認したところ、たしかに Android 4.2.2の標準ブラウザ だけ登録できません。
他のブラウザ(chromeとか)やiPhoneだと登録できました。
こんなとき信じられるのはログだけです。
どこまで処理が走って、どこで処理が止まっているのか調べます。
そんな感じでガンガンログを仕込んで調べたところcsrf用のtokenチェックでNGになっており登録処理が行われていないことがわかりました。
なぜ、この機種だけtokenチェックでエラーになるのか当初全くわからなかったのですがtokenを保持しているcookieと実際にPOSTされているtokenの値を比べたところ確かに違うわけです。
そこでエラーとなり登録処理が行われていなかったわけです。
サーバサイドはFuelPHPを使っており、tokenチェックは \Fuel\Core\Security::check_token() でバリデーションを行っていました。
仕組みをいちおう書くと、
- tokenチェック対象の画面にアクセスされた時にtokenを発行しcookieに保持しつつ、viewにセット
- 登録時とかにその値をPOST
- cookieに保持されている値とPOSTされたtokenの値を比較
- 一致していればOK、違っていればNG
というよくあるやつです。
今回はこの3.のところでNGとなっていたわけです。
(そもそもエラーメッセージを何も出していなかったのが原因特定させるのを遅らせた1つの要因だったのは秘密です)
原因
で、なんでtokenの値が違っていたのかというところですが、それが題目にあげたとおり画面を表示させたときに何故かHTTPリクエストが2回来ていたのが原因でした。
この不思議な現象を書くと、
- tokenチェック対象の画面にアクセスされた時にtokenを発行しCookieに保持しつつ、viewにセット
- 続いて何故か2回目のHTTPリクエストが起こりtokenが発行されCookieが上書きされる(謎の2回目)
- この値はviewにセットされない
- 登録時とかにその値をPOST
- POSTされるのは最初にviewへセットされたtokenの値
- Cookieに保持されている値とPOSTされたtokenの値を比較
- 一致していればOK、違っていればNG
- Cookieに保持されているtokenの値は謎の2回目のHTTPリクエスト時に発行された値
- POSTされる値は1回目に発行されたtokenの値
- なのでエラーとなる
という流れになります。信じられないウソのような話ですが本当の話です。
※ちなみにうちの長女(4歳)はカワウソに似ていると最近よく言われます
なぜHTTPリクエストが2回来ていたのか
じゃあなんでHTTPリクエストが2回来ていたのかなのですが、最初に結論を書くと
imgタグで存在しない画像(正確には空文字)を参照していた
というのが原因だったようです。
[highlight_markup]
[/highlight_markup]
みたいなのが初期値にセットされていた
- 最初のアクセス(1回目のHTTPリクエスト)
- viewの読み込み
- <img src=””> を読み込んでいる
- なぜかもう一度自身のURLに対して2回目のHTTPリクエスト
こんな動作がログを見る限り行われており今回のバグの起因となっていました。
当初これはjsかなんかが勝手にHTTPアクセスしているんだろうなぁという軽い目論見でいたのですが(この画面はjsでグリグリ実装されております)、
- viewでjsを呼んでいるところを削除 → 解決せず(2回HTTPリクエストが来る)
- viewの中身をすべて削除 → 1回しかHTTPリクエスト来ない
- ざわつき始める
- viewの中身を少しずつ修正
- 問題の箇所を発見
という流れで特定できました。
(特定できれば後は簡単な話でした)
この問題は
android 4.2 HTTPリクエスト 2回
でぐぐってみると結構同じ問題で困っている人も多く、以下の記事はまさにビンゴでした。
http://lealog.hateblo.jp/entry/2014/03/27/224121
これを見ると、この問題は4.2.2だけじゃないっぽいですね。。
結論
機種依存の不具合のようでしたorz…。
でも個人的には全く腑に落ちない。2回目のHTTPアクセスの結果がviewに反映されないところとか、う～む。謎い。
ただ、こういった問題もログをとことん仕込むとかviewの中身をちょっとずつ修正するとか地道な作業を根気よく続ければ今の時代原因は特定できるってわかったのがせめてもの救い。
