JavaScriptとPHPで構築しているINTER-Mediatorで、分かりにくいバグに遭遇してしまったので、記録の意味も含めてここに書いておく。そもそも発端は、Ver.5.6-RC2を入れて動かしていたアプリケーションで、そろそろVer.5.7もリリース近いので、入れ替えるかと思って入れ替えたのが直接の原因なのだが、その瞬間にバグが顕在化したのならまだしも、ある程度時間が経過してから顕在化したので、根本的な原因を突き止めるのに非常に労力が消費されてしまった。
不具合が発生したのは、勤務先の業務システムで、スタッフ向けのページはかなり重たい動作のものある。全てのページで問題が出ないで、一部の「重たいと思われる」ページでのみで不具合が顕在化した。ここで、まず判断を狂わせることになる。システムは、サクラVPSで運用している。ここ数ヶ月、徐々にレスポンスが悪くなっている感じもあったので、プロバイダやネットワークをまずは疑ってしまった。不具合による結果は、ページを表示しようにもページ自体がフリーズしてしまうのである。ログインパネルはちゃんと出るが、正しいユーザ名とパスワードを入れると、フリーズする。これに気づいたのは2018年2月の上旬だ。
当然ながら、まずやることはデバッガでの確認だ。すると、以下のように、Statusが(Pending)となている。サーバーのログを追ったところ、Apache2はステータス200でデータを全部出し切っている。クライアント側で通信に入ったものの、一切のデータ受信ができない結果になっている。色々観察した結果、ページごとにPendingになるタイミングやこのページでの行番号は違うのもの、同一ページでは常に同じタイミングで発生した。ちなみに、Chromeだとこれが発生すると高い確率でそのタブを閉じることができず、他のタブは利用できる状態であるにも関わらず、Chromeの強制終了が必要になる。
今まで動いていたという気持ちがあると、当然ながら、アプリケーション側に問題はないとまずは考えてしまう。これも、後から考えれば間違いなのだが、エンジニアの皆さんはとりあえず人のせいにしてしまう気持ちはよく分かると思う。折しも、色々探すと、サクラのサポート情報で、「さくらのVPSで回線速度が遅くアクセスに時間がかかります。」というのがあった。ページのフリーズと、遅くなるのは違うのではあるが、こういう時には楽観的に物事を見てしまう。なんだ、原因分かっているんだと思いつつ、「さくらのVPSにおいて、不特定のVPS収容ホストとクライアント環境(プロバイダ等)の組み合わせにより、 さくらのVPSからのダウンロード方向の通信に遅延が発生する場合があります。」という記述をみて、ネットワークの問題があるということに意識がかなり振られてしまった。
当然ながら、ここにある対処をしたのだが、結果は同じだった。むしろ、どのページも遅くなったので、仮にうまくいっても恒常的な対処にはならない。しかしながら、「ネットワークに問題がある」というところで判断がスタックしてしまった。もし、ネットワークに問題があるとしたら、プロバイダを変えるか、職場のネットワーク内にサーバーを立てるしかない。GMOクラウドのVPSは無料で試せるので、ともかく移動して動かして見た。結果は同じだ。同じページで、同じようにフリーズする。GMOではネットワークの問題は解決しないとしたら、一度、自宅のサーバーにセットアップして、自宅内でアクセスするとどうなるかをチェックして見た。なんと、同じようにフリーズする。また、別の軽いページを改良している時にも、フリーズが発生した。つまり、「ネットワーク」「重いページ」はどうも原因ではないという結論になった。
しかし、なんでPendingになるのか？色々検索すると、Ajaxがデッドロックしたみたいな書き込みがあった。しかし、それへの回答でも、JavaScriptはユーザープログラムは絶対に並列的に動作しないで、処理を1つずつしかしないのだから、他の言語等で発生する問題が同じように発生する可能性は低いと書かれている。もっともだ。しかも、INTER-Mediatorのこのバージョンは、Ajaxを非同期では利用せず、同期通信しているため、フレームワーク内で複数の通信が発生することはない。なお、次のバージョンでは完全に非同期通信を行うようになる。
前述のChromeのデバッガを見ると、CSSの通信がPendingになっている唯一、並列的に通信が発生するとしたら、CSSのサーバーからの取得と、INTER-Mediatorのデータベースアクセスの通信が並列にはなりうる。ちなみに、CSS自体もサーバーで生成しているので、URLは.phpになっている。そこで、フレームワークをいじってCSSアクセスのlinkタグを突っ込まないようにして見た。それでも同じところでフリーズする。やはりこれも原因ではない。
ここで、根本的な原因が全くわからない状態になった。ネットワークでも通信でもないということで、フレームワークに問題があることはほぼ明白になった。そして、2017年9月のVer.5.6.1に戻して見たところ、問題なく動いた。これで、INTER-Mediator側に問題があることが確実となった。INTER-MediatorはGitHubのレポジトリにコードが残っている。そこで、どのコミットでバグが発生したかを突き止めることにした。大雑把に2分割をしながら、2018年1月のあるコミットであるところまで突き止めた。コードを見ても、明らかに通信ではない。通信に問題があるが、原因は通信でないということはさらに明白になった。
しかし、見当がつかない状態と、ここまで絞りきれても原因の特定まではできない。このコミットでファイルは4つ変更されているが、1つはメタデータで処理には関係ないので、そのうちの3つのどれかである。そこで、ファイルを1つずつ、前のコミットに戻すことで、INTER-Mediator-Calc.jsに問題があることが分かった。diffの結果はあれこれあるが、setUndefinedToAllValuesにメソッドしか変更していないので、問題はここにある。何れにしても、計算式の処理部分に問題があることが分かったのである。
ここで腹を括って、地道にステップ動作をさせて見たところ、ついに問題の根本が分かった。325〜335行のdoループが、ある条件の場合だけ、無限ループしている。つまり、ここのループ処理にバグがあったのだが、ポップアップメニューのタグ要素に計算式の結果を適用する場合だけ、無限ループし、その他のタグ要素の場合には無限ループにならず、間違えたコードだが正しい結果が得られているという状況になっていたのである。直したところ、えらく時間がかかるようになったので、処理を効率化して高速化する必要もあったものの、ともかく修正ができて、Pendingは出なくなった。原因追及から修正完了まで、1日かかってしまった。
結論は明らかだ。ページがフリーズしたら無限ループを疑えということになる。だが、なんで、こんな処理が入っているのかという点もあって、モデルをさらに改良してここで問題になったコードは取り除く予定ではあるものの、「動いている」つもりになっていたので、後回しになってしまっているのである。テストでクリアできないかということもあると思うが、ページ展開していないとテストのしようがない部分であり、単体テストではカバーできていなかった。現在、Seleniumベースでの統合テストを組み込んでいるところであり、そこで、計算式のテストページに、ポップアップメニューに計算式を仕込んだものも作っておいた。やはり、見つけにくいバグは、テストから漏れている箇所に存在するということだ。
なんとも当たり前なことの確認に、ひどく時間がかかってしまったのではあるが、自戒の意味も含めてブログに記録する。