とある社内業務システムで起こったバグの話 2

前回のあらすじ

…

不定期な粛清

3枚の申請書を2時間かけて用意すると入室できる、忌々しい「本番端末作業室」から戻った僕は、入力中のデータを全て失って茫然自失する主担当に電話した。

「本番サーバの稼動状況を見てきましたが、アプリケーションの動作に異常は見られませんでした。システムログにもアプリログにもエラーの類は出力されておらず、強制的にログアウトさせられた原因は分かりませんでした」

「えー分かんないのぉ？あんたが見てるシステムでしょ？なんとか調べてよ」

「申し訳ありません。現段階では分かりませんで…。引き続き調査は致します」

しかし、それ以降も原因が特定できなかった。数日間何も起こらない日もあれば、日に何回も「強制ログアウト粛清」が行われる時もあった。その度にマハーカーラの利用者たちは、作業中のデータが消滅したことに怒り狂い、僕はその怒りの声を電話で聞き、本番端末室への入室申請書をしたためてサーバのログを見てみるのだが、アプリログにこれといったエラーもなければ、異常な CPU 使用率になっているような形跡もみられない。原因らしい原因が見つからず、全く不定期に問題が起こっていたのだ。

この不具合は数ヶ月間謎のままだった。前のベンダからシステムを引き継いだ当時の社員はまだ在籍していたので、その先輩社員にヒアリングしたり、マハーカーラの開発言語である Java に詳しい BP のベテランおじさんに思い当たることがないか聞いてみたりしたが、どれも当たらなかった。

主担当を含めたマハーカーラの利用者たちは、次第に粛清を回避する術を身に着けた。「商品登録」画面にはフォームにデータを直接入力するのではなく、「CSV ファイルから商品データをインポート」する機能も搭載されており、コレでも一括登録処理ができるのだ。主担当は元々、メールで送られてきた Excel ファイルを見ながらマハーカーラにデータ入力していたので、Excel ファイルの列を少し組み替えて、CSV 形式で保存し直してマハーカーラにインポートすることで、Web 画面上での作業を最小限に減らした。

他の利用者たちも、フォームに入力する情報は Submit する前に「メモ帳」に控えておき、Submit ボタンによって画面遷移した時にログイン画面に戻されても、入力していた情報を失わないように工夫し始めた。

「時々意図しないタイミングでログアウトさせられてしまう」という以外にシステム上の問題はなかったので、利用者たちは「運用で回避」することで被害を最小限に食い留め、次第に粛清の動きにも慣れていったようだった。システム主担当と行う「マハーカーラ保守定例会」でも、最初の頃はブチ切れていたものの、1ヶ月もすれば「また落ちちゃったわよ〜」とヘラヘラするようになった。

保守ベンダとしてマハーカーラを保守する担当の僕としては、原因が分からないまま調べるのを止めることもできないし、したくない。主担当はこの不具合に慣れて見逃してくれるようになってきたものの、定例会議資料に毎度「原因調査中」と書かれた不具合が残っているのは印象が悪かった。

原因は依然として分からない。万策尽きかけた、その頃だった。

特定のユーザがログインするとき

最初に不具合が報告されてから数ヶ月。「今日は粛清が頻発しているようだから、いっちょログを見てみるか〜」と思い、(本番端末室入室申請書を書いて担当者に押印してもらって受付窓口に提出して申請受理メールを受け取って本番端末室に入室し本番サーバに SSH 接続して) サーバログを見てみると、ある法則に気が付いた。

特定の、数人のユーザの誰かがログインすると、その直後から「強制ログアウト運動」が発生している。

特定のユーザとは、前回の記事に出てきた、支払業務を担当するユーザ ID 391342 や、その人の付近のデスクで仕事をしている数名の利用者だった。これは座席表を見て確認した。

コレまで不具合が発生する度に集計してきた数十のログを見てみると、その内の8割以上の確率で、391342 かその関係者が直前にログインしていることに気付いた。

これは何かおかしい。彼らがログインのタイミングに何かやっているに違いない。

システム主担当にこの事実を告げると、主担当の方から 391342 氏に話を聞いてもらえることになった。そして驚くべき事実が発覚する。

一部で広まっていた「裏技」

数日後、システム主担当が興奮した様子で電話をかけてきた。

「あれから支払担当の E さん (ID 391342 氏のこと) に話聞いたのよ。そしたら『マハーカーラの動作が遅い時に、ログイン画面のログインボタンを連打するとモタつきが解消するからログインボタンを連打してる』って言ってたのよ！一体何が起こっているの？！」

ログインボタンを……連打……？

「マハーカーラってもう古いシステムだから、AP サーバもスペック低いじゃない？確かに利用者が増える月末は画面遷移が遅くなったりすることはあったんだけど、なんか『動作が快適になる裏技だ』って、支払担当チームの中で見つけたみたいなのよ…！」

「ログインボタンを連打すると何が起こるのかは分からないけど、きっとそれのせいで私達がログアウトさせられてるのよ！だから E さんにはログインボタンの連打止めてって言ってきたわ！」

…ワケが分からなかった。ログインボタンを連打するとレスポンスが速くなるって？誰かがログインボタンを連打すると、他にログインしている人たちがログアウトさせられる？にわかには信じがたい話だった。

しかし、どうやら本当に、ログインボタンを連打することが、他の人をログアウトさせる問題に繋がっていたようだ。支払担当チームに「連打禁止令」が通達されてから、強制ログアウトはほぼ発生しなくなった。システム主担当は大いに喜び、「E さんたちがワケ分かんない裏技見つけなければよかったのよ！」と息巻いていた。

だが、ちょっと待って欲しい。エンジニアとしては、「誰かがログインボタンを連打する操作」と、「ログインしている人たちが強制的にログアウトさせられてしまうこと」の繋がりを知りたいし、「ほぼ」発生しなくなった、と書いているとおり、強制ログアウトの問題は未だ 「たまに」は発生しているのである。これはもう少し調査してみないといけないだろう。

ログイン処理を辿る

これまで、マハーカーラのソースコードを見ていなかったワケではない。マハーカーラに「メインメニューの表示順序をお好みで変更できる機能」を追加したのは僕だし、マハーカーラに注文データを送りつけてくる連携システム側のリプレイスに合わせて、連携処理部分を書き直したこともある。強制ログアウトさせられる原因を調べるために、あちこちのソースコードを読み続けていた。それでも原因が掴めなかった。

前回軽く触れただけだったのでおさらいしておくが、マハーカーラのシステムは Apache Struts という Java フレームワークをベースにして作られている。要は Java サーブレットに JSP で構成された Web システムなのだが、それを扱いやすくしてくれるのが Struts だった。そしてマハーカーラの場合は、さらに Struts フレームワークをラップする形で、引き継ぎ元のベンダが作ったオレオレフレームワーク「ReallyPoorCompanyFramework」が組み込まれていた。

コイツは、Struts が提供する Action クラスを継承して ReallyPoorCompanyBaseAction クラスを作っていて、マハーカーラを動作させるためには Action クラスではなく ReallyPoorCompanyBaseAction を継承して実装しないといけないように縛りをかけていた。もし ReallyPoorCompanyBaseAction を使わず、純粋な Struts の Action クラスを作ろうとすると、リクエスト情報が届かず、レスポンス情報が送り返せない作りになっていた。

何のために ReallyPoorCompanyBaseAction が居るかというと、アプリログを自動出力させることが主目的だったようだ。Start や End と書かれたアプリログを、規定の書式でログファイルに出力するのを強制させるために、クラスの継承をしないといけない作りにしていたようだ。

この「ReallyPoorCompanyFramework」は、マハーカーラの Java プロジェクト中に JAR ファイルとして格納されており、この ReallyPoorCompanyFramework.jar をクラスパスに追加 (つまり、同梱) した状態で Mahakala.war をビルドしないといけない作りだった。僕が入社した時には、既に JAR ファイルにコンパイルされた状態の ReallyPoorCompanyFramework.jar しか見たことがなく、Java の経験もほぼなかったことから、当時の僕は「とにかく自社製のフレームワークが組み込まれているんだな」ぐらいにしか思っていなかった。

さて、そんなマハーカーラの、MVC でいうところの「C (Controller)」に当たる、各画面を表示するための Action クラスを見てみよう。

ログイン画面を表示する ShowLoginAction クラス (ネーミングセンス悪すぎるだろ…) は画面を表示するだけで何も処理していない。「ログイン」ボタンが押された時に処理する LoginAction クラスも、ユーザ認証処理しか行っていない。この「ユーザ認証処理」は、社員を管理する別システムの API を利用していて、ユーザ情報として存在チェックができていればログインできる、という仕組みだった。コレ以外の目立った処理は書かれていない。

ログアウトに関する処理はというと、「ログアウト」ボタンを押した時にセッション情報を破棄し、「ログイン」画面に戻る LogoutAction と、Tomcat サーバ側のセッション有効期限設定 (2時間に設定されていた) に合わせて処理をする SessionTimeoutAction しかなかった。SessionTimeoutAction は、ユーザが前の画面を開いてから、次の画面を開こうとするまでの間の時間をカウントしていて、その間が2時間以上開いていたら呼び出される仕組みになっていた。つまり、「商品登録」画面を開いてから、2時間そのページのままブラウザを放置し、それから「次へ」ボタンを押して画面遷移しようとしたりした時に、この SessionTimeoutAction に送られて、「あなたは無操作状態が2時間続いたのでセッションが切れちまった、だからログアウト扱いにしたよ」と通知するワケだ。

(実際のところ、Tomcat サーバに設定したセッション有効期限と同じ値を Java アプリケーションにも static final で書いておいて、自前で時間を計って、セッション期限切れっぽい処理をアプリの中でやらせる意味はよく分からなかった。でも、マハーカーラを開いて2時間無操作でいる人なんてほとんどいなかったから、あまり問題にもされていなかった)

問題が発覚してからしばらくの間は、この SessionTimeoutAction が悪さをしているのかな、と思っていた。でも、どういうパターンを考えても、「ログインボタンの連打」といった操作でこの Action クラスにたどり着き、不正な動きをさせる方法はなかったのである。

ログインボタンを連打した時に問題が起こるということは、ログイン認証を行う LoginAction が絡んでいることは明らかなのだが、これとログアウトさせられてしまう動き、つまり SessionTimeoutAction や LogoutAction が絡むような動きは見つけられなかった。

マハーカーラの Java プロジェクトに含まれるコードは全て見た。それでも原因箇所が特定できないとなると、「まだコードを見ていない箇所」はあと1つとなる。つまり、開発ベンダが残したオレオレフレームワーク、ReallyPoorCompanyFramework.jar の中身である。しかし、このフレームワークはコンパイル済みの JAR ファイルしか残されておらず、ソースコードがないのだ。

果たして、どうやって ReallyPoorCompanyFramework.jar のソースコードを見ようか…。

次回予告

→ とある社内業務システムで起こったバグの話 3