Murga

個人的に言いたいコト・主張・気持ち。

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

前回までのあらすじ

  • 社内システム「マハーカーラ」を利用中、不定期に強制ログアウトさせられる不具合が発生する
  • 原因は、ある利用者が見つけた「ログインボタンを連打するとマハーカーラの動作が速くなる」という「裏技」によるモノだった
  • しかし、ログインボタンの連打と、ログインユーザがログアウトさせられることの関係性が見つけられない
  • マハーカーラの開発ベンダが残した ReallyPoorCompanyFramework.jar に隠蔽されている処理が怪しい…

JAR ファイルをデコンパイルしたかった

マハーカーラのソースコード中に怪しい点が見当たらないとなると、残るはマハーカーラのシステムをラップしている ReallyPoorCompanyFramework.jar の中身に疑いがかけられる。

しかし、この JAR ファイルはマハーカーラの Java プロジェクトに埋め込まれた状態で引き継がれており、元のソースコードがなかったようなのだ。当時の引き継ぎ担当、何やってんだ…。

JAR ファイルからソースコードを取得する方法がないか調べると、JD-GUI なる「デコンパイル」を行うツールが見つかった。なるほどデコンパイルとな。便利なツールもあるんだなぁ。しかし問題があり、このお客さんの会社は、ベンダはインターネットに接続できず、ツールをダウンロード・インストールすることは許可されていなかった。確かに、本番サーバを開発者のデスクから触れたらセキュリティリスクがあるし、それと同様で、開発者が好きにインターネットに接続できちゃうと、色んなウイルスを落としてくることは必至だし、自由にツールを入れさせたら悪いことをするに決まっているからね。僕のような悪知恵の働くエンジニアはきっと悪さをするはずだからね。信用しなくて正解だよ。

システム主担当の中では、プログラム的な原因は分からないものの、ログインボタンの連打をしていた部署には一喝したし、もうほとんど再発していないことから、「終わった問題」と見られていたこともあり、「調査のためにデコンパイラをインストールさせてください」と申請しづらかった。「大体デコンパイラって何なの?」「コンパイル済みの JAR ファイルからソースコードを抽出・復元するツールのことですよ」「何ぃ!?そんな危険なことができるツールを入れさせるワケにはいかん!ウイルスだろ!」と突き返されることが明らかだった。

ReallyPoorCompanyFramework を掘り起こす

そんな時、当初 ReallyPoorCompany 社からマハーカーラを引き継いだ先輩社員が、こんな一言を発した。

「あれ? ReallyPoorCompanyFramework のソースって見たことある気がするんだけど…」

あー、はいはい、月報の提出が毎月遅れる、忘れっぽい先輩のことだから、どうせマハーカーラの LoginAction のコードでも思い出して、それを JAR ファイルの中身のコードだと勘違いしているんでしょう。そんな中途半端な記憶ならキッパリ忘れてしまって、代わりに来月の月報提出日をしっかり覚えておいたらいいのに。

「確か本番サーバの中にあったんだよね」

「もう少し詳しく思い出せます?」

コイツは何か知っているようだった。

「確かねぇ、引き継いだ直後ぐらいに本番サーバの中身を見てた時に見たんだよねぇ。本番作業の度に作業フォルダを作るじゃない?『20140711_障害対応リリース作業』なんて名前でさ、そのときリリースする WAR ファイルを置いたりするじゃん?あの作業フォルダの中で、JAR ファイルをビルドする前のコードが置いてあったんだよね」

「いつ頃の作業フォルダか思い出せます?」

「いやぁ〜分かんないなぁ〜…」

ならば、と、本番稼動している AP サーバに接続して (もちろん忌々しい申請フローを回した上で!)、歴代の作業フォルダを見てみた。マハーカーラがリリースされた2005年の最初の作業フォルダは、「20050329_本番作業」というフォルダ名だった。コイツが本番サーバなんだから「本番作業」に決まっているだろう。他にも「パッチ作業」とか「修正対応」とか、中身が分からないフォルダ名が続く。目視確認を諦めた僕は、ReallyPoorCompanyFramework という文字列を含むファイルがないか grep した。

しかし、見当たらない。先輩が消したのか?

…いや、待て、いくら忘れっぽい先輩でも、それはなかろう。あの人はファイルの存在は覚えていたけど、ファイルの在処は忘れているんだ。ということは、AP サーバではない場所でファイルを見たのかも知れない。

思い付いたのは、マハーカーラの DB サーバだった。マハーカーラは、Tomcat が動作する AP サーバと、Oracle DB が動作する DB サーバの2台が連携して動作していた。すぐさま DB サーバにアクセスする申請書を作ってやんややんやして、DB サーバの方にある作業フォルダを grep してみた。

ビンゴ。2007年の何かの対応のときに、なぜか DB サーバ側に WAR ファイルを持ち込んでいた。そしてそれと一緒に、ReallyPoorCompanyFramework.zip があり、解凍されたらしき ReallyPoorCompanyFramework ディレクトリがあり、中には .java ファイルが転がっていて、これらをコンパイルしたと思われる ReallyPoorCompanyFramework.jar ファイルも見つかった。

これらのファイルを個人の開発端末に持ち帰り、中身を検証してみたところ、確かにこの .zip を解凍したものが ReallyPoorCompanyFramework ディレクトリで、コイツから生成したのが、作業ディレクトリに置かれていた JAR ファイルだった。そしてこの JAR ファイルは、現在稼動しているマハーカーラが WAR ファイルに同梱している ReallyPoorCompanyFramework.jar と、全く同じモノであることが分かった。つまり、本番 DB サーバから掘り起こしたこの ReallyPoorCompanyFramework.zip の中にあるソースコードが、現在稼動しているマハーカーラに影響を与えているコードと一致するワケだ。

早速、ソースコードを見てみた。

LoginAction 用の特別な処理

ReallyPoorCompanyFramework.zip の中にある ReallyPoorCompanyBaseAction クラス (マハーカーラの全ての Action クラスが継承する親クラス) から、何やらかんやらコードを辿って調べてみると、こんなコードを見つけた。このコードは、各 Action クラスが実処理を開始する直前に、必ず呼び出されるコードとして実装されていた。

if("LoginAction".equals(currentActionClassName)) {
  try {
    MasterUserBkService masterUserBkService = new MasterUserBkService();
    masterUserBkService.delete(request.getParameter("userId"));
    masterUserBkService.insert(request.getParameter("userId"));
  }
  catch(Exception e) {
  }
}

コメントが一切ないコードなので、解説を付けよう。

// これから実行される Action クラスが LoginAction である場合に処理を行う
if("LoginAction".equals(currentActionClassName)) {
  try {
    // 「MasterUserBkService」は、マハーカーラのコードによく見られる命名規則で、
    // MASTER_USER_BK という名前の、マスタテーブルに対して DB 操作を行うためのサービスクラスのことだ
    MasterUserBkService masterUserBkService = new MasterUserBkService();
    
    // リクエストから "userId" パラメータを取得して、それを引数に MSTER_USER_BK テーブルに DELETE クエリを投げている
    masterUserBkService.delete(request.getParameter("userId"));
    
    // 同様に、MSTER_USER_BK テーブルに "userId" パラメータを INSERT しているようだ
    masterUserBkService.insert(request.getParameter("userId"));
  }
  catch(Exception e) {
    // 悪名高き Pokemon Exception Handling だ!
  }
}

なんと、各 Action クラスが継承する、その大元である親クラスの方で、「その子クラスが特定の○○クラスだった場合のみ行う処理」を書いていたのだ。今回は LoginAction、つまりログインボタン押下時に実行される Action クラスだった時に、LoginAction クラスに書いたコードの手前に、以上の処理を行っていたのだった。

さらに、MASTER_USER_BK という名前のマスタテーブルに対し、DELETEINSERT を実施していることも分かった。引数にはリクエストから "userId" パラメータを渡していて、どうやらこのマスタテーブルに対し、ユーザ ID 情報を登録しているようなのだ。

MASTER_USER_BK というマスタテーブルが本番 DB に存在することは把握していたが、他にも BK と名の付くテーブルは数多く存在し、そのどれもが DB パッチ作業時のバックアップとして作られた、テーブルのコピーの残骸だったのだ。しかしこの MASTER_USER_BK テーブルは、「BK (バックアップ)」と名付けておきながらそうしたバックアップ用のテーブルではなく、「MASTER (マスタ)」と名付けておきながらログインのたびに頻繁に DELETE や INSERT を行う、バリバリ使われているテーブルだったのだ。

MASTER_USER_BK テーブルのフィールドを見てみると、USER_ID (ユーザ ID)、NUM (何かの連番)、LOGIN_DATE (ログイン日時の情報) というフィールドが定義されていた。つまり、そのユーザがログインした日時を記録していたようである。

コードを見ていると、さらにエグいモノが見つかった。MasterUserBkService#delete() メソッドは別の箇所でも使用されていて、8時40分から8時50分の間に最初にログインをしようとしてきたユーザがいた時のみ、前日以前の LOGIN_DATE のレコードを全て削除するという作りになっていた。

8時40分というのは、マハーカーラを利用するお客さんの会社の始業時間のことだ。つまり、始業時間から10分以内にマハーカーラにログインした人がいたら、その人に日次バッチのトリガーとなってもらい、「前日分までの MASTER_USER_BK テーブルのデータ」を全て削除していたのだ。

ログインユーザの ID を何故保存していたのかというと、各ページに遷移するタイミングで動作する共通処理の中で、そのリクエストが「ログインしているユーザによるリクエストかどうか」を確認するために使っていたようだった。つまり、MASTER_USER_BK に今日日付の LOGIN_DATE が登録されていない USER_ID からのリクエストで Action が動いたら、それは不正なアクセスだと判断して、ログイン画面に飛ばす作りになっていたのである。だから例えば、午前0時、日付をまたいだ時にマハーカーラを利用していたユーザがいたら、そのユーザは一度ログアウト扱いになってしまう、ということだ。日付をまたぐまで残業してマハーカーラを使う人が少なかったか、残業で疲弊していて、0時前後にマハーカーラからログアウトさせられたことに注意が向いていなかったか、理由は分からないが、そうした残業時間の長い人からの問合せはこれまでなかったので、気付かなかった。

MASTER_USER_BK テーブルの更新タイミング

段々混乱してきた。MASTER_USER_BK テーブルとは何であり、いつデータが登録され、いつ削除されるのか、もう一度まとめてみよう。

  1. MASTER_USER_BK テーブルは、ログインした日時とユーザ ID が記録されている。
  2. ログインボタンを押した時に、MASTER_USER_BK テーブルに登録されている自分のユーザ ID のデータを DELETE している。自分の過去のログイン情報のレコードを消すためだ。
  3. 同じくログインボタンを押した時に、MASTER_USER_BK テーブルに自分のユーザ ID とログイン日時を登録している。連番はこのタイミングで雑に採番していて、特に使っていないようだった。
  4. ログインしたユーザが画面遷移を行う度に、MASTER_USER_BK テーブルを SELECT し、そのユーザが今日ログインしていることを確認する。これにより不正アクセスを見極めるつもりだったようで、MASTER_USER_BK テーブルからそのユーザの今日日付のログイン情報が見つからない場合はログイン画面にリダイレクトしている。要するにこれが「画面遷移時にログイン画面に戻された」動きを引き起こす処理だったワケだ。
  5. 始業時間直後に最初にログインしてきたユーザには、MASTER_USER_BK テーブルに溜まった前日分までの全てのデータを DELETE させる。「人力日次バッチ」と呼べなくもない仕組みだ。

全体的には、MASTER_USER_BK テーブルはその日1日分のログインユーザの情報さえ残してあればよく、同一ユーザが複数回ログインした履歴や、前日までのログイン履歴の情報は残したくないがために、DELETE 処理を呼んでいたようである。

いや〜しかし、MASTERBK という紛らわしい名前もそうだし、「毎朝1名様に当たる人力日次バッチ」処理も、とにかく乱暴で無茶苦茶だ。横着しようとして面倒なことになっている。どういう設計をしたらこうなるんだろう?いや、アプリログは日付ローテで吐き続けているだけだし、設計なんてしてなかったんだろうな。

さて、これらの更新処理の中身をもう少し詳しく見ていこう。

MASTER_USER_BK テーブルを DELETE する SQL

上述のように、MASTER_USER_BK テーブルにはログインしたタイミングでのユーザ情報が INSERT される作りになっていて、これを放っておくと、MASTER_USER_BK テーブルは膨大なレコードを抱えることになる (要はログイン履歴テーブルの状態だ)。そこで、先程掲載したコードのように、ログイン処理時に MASTER_USER_BK テーブルから自分のユーザ ID に合致するレコードを一旦 DELETE し、その後で INSERT を実施している。

この DELETE 処理が怪しそうなので、MasterUserBkService#delete() の中身を見てみよう。

// MASTER_USER_BK テーブルを CRUD 操作するエンティティクラス
class MasterUserBkService {
  // delete() メソッドのみ抜粋して掲載
  public void delete(String paramStr) {
    try {
      // SQL 文の構築
      String sql = "DELETE FROM MASTER_USER_BK ";
      
      // 引数 paramStr が6文字だった場合、引数をユーザ ID と見なし、USER_ID との完全一致で絞り込む
      if(paramStr.length() == 6) {
        sql += "WHERE USER_ID = '" + paramStr + "'";
      }
      
      // 引数 paramStr が8文字だった場合、引数を日付情報 (yyyyMMdd) と見なし、ログイン日付が古いデータを絞り込む
      if(paramStr.length() == 8) {
        sql += "WHERE LOGIN_DATE < '" + paramStr + "'";
      }
      
      // オレオレフレームワークが持っている DB 実行ユーティリティクラスを利用して SQL を実行する
      ReallyPoorCompanyDBUil.executeQuery(sql);
    }
    catch(Exception e) { /* 当然のようにエラーは握り潰す */ }
  }
}

処理全体を乱暴に囲み、エラーを握り潰す try / catch にはもはや何も感じなくなった。

引数の文字列の長さに応じて、WHERE 句で絞り込むフィールドを振り分けるという恐ろしい実装になっている。

前述の更新タイミングの「2.」、ログイン時にそのユーザの古い情報を削除する場合は、1つ目の if 文を通り、SQL 文を構築する。ユーザ ID は必ず6桁なので、こういう if 文になっている。コレで USER_ID カラムを条件にして、

DELETE FROM MASTER_USER_BK WHERE USER_ID = '999999';

といった SQL が生成されるワケだ。

一方、前述の更新タイミングの「5.」、始業時間直後にログインしたユーザに日次バッチのような処理を行わせる時は、2つ目の if 文を通り、

DELETE FROM MASTER_USER_BK WHERE LOGIN_DATE < '20150711';

といった SQL を生成する。日付 (DATE) 型のカラムだが、Oracle DB の暗黙的な型変換を利用して比較していたようだ。

PreparedStatement を使わず引数を直接 SQL 文字列に組み込んでいるとか、スメルを感じる部分はあるものの、これならとりあえず意図したとおりに動きそうな気がする。

一旦このコードから頭を離して、「なぜログアウトさせられる人が生まれるか」を考え直そう。

「強制ログアウトされた」ではなく、「ログインしていない」とみなされている?

MASTER_USER_BK テーブルに、そのユーザ ID がその日にログインしたレコードがない場合に、不正アクセスと見なしてログイン画面にリダイレクトする」という動きが、ログイン画面にいきなり戻される「強制ログアウト」を引き起こしていたことは分かった。

しかし、なぜログインボタンを連打する人がいると、MASTER_USER_BK テーブルの関係ないユーザ ID のレコードまで削除されてしまうのだろうか。MASTER_USER_BK テーブルの DELETE 処理の時に何かが起こったとして、どういう状態になると、「ログインしていた人たちがログアウトさせられる」だろうか。

例えば、「5.」の、前日分のデータを DELETE する「人力日次バッチ処理」において、パラメータに取る日付が何らかの理由でズレて、今日日付のレコード (≒ 今ログインしている人たち) まで削除する SQL が生まれたとしたら?

# 「2015711日」の始業時に削除すべきなのは、710日以前のデータなので、本来は「LOGIN_DATE < '20150711'」となるべきだが、
# もしもパラメータの日付が1日後にズレたとしたら、711日のデータも削除されることになる
DELETE FROM MASTER_USER_BK WHERE LOGIN_DATE < '20150712';

ログイン処理が動作している時刻が始業時間直後、8時40分から8時50分の間かどうかを検証する際に参照しているのは、この Java プログラムが配置されている AP サーバのシステム時刻だ。つまり、何かの拍子にシステム時刻が翌日の8時45分にズレたら、なんでもない日中にログインしようとした人によって、「早朝の人力日次バッチ処理」が動作することになる。

この誤動作が起こったとして、MASTER_USER_BK テーブルのレコードが削除されると、前述の「4.」のタイミング、つまり画面遷移時に必ず走る「不正アクセスチェック」時に、MASTER_USER_BK テーブルからログインユーザの情報が取得できず、不正アクセスとみなされてログイン画面に戻されるという動きが起こりうるのだ。

しかし、システム時刻がズレることは考えにくい。事実、同じシステム時刻を参照して出力しているログファイルの方は、時分秒にズレがなく、正確に出力されていた。ということは、「人力日次バッチ」向けに呼び出された MasterUserBkService#delete() メソッドが誤作動したとは考えにくい。

全てのユーザを対象にログイン履歴を削除した?

MasterUserBkService#delete() の誤作動によって、ログイン中のユーザのレコードまで削除される他の方法というと、ログイン時に自身の過去のレコードを削除しようとしている箇所がおかしな動きをした可能性が考えられる。

つまり、

DELETE FROM MASTER_USER_BK WHERE USER_ID <> '999999';

もしこんな SQL が発行されたとしたら、USER_ID'999999' 以外のレコードが全て削除されることになる。

しかし、前述の Java コードを見ても、USER_ID の絞込条件は =、つまり完全一致でベタ書きされているので、複数のユーザ ID のレコードをヒットさせて削除する方法は考えにくいのだ。

…長くなってきた。今回はココマデ。

次回予告

  • 推測を止めて観測する
  • デバッグログから発覚した衝撃の事実

業務システム クラウド移行の定石

業務システム クラウド移行の定石

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

前回のあらすじ

  • 前ベンダの ReallyPoorCompany が開発し、僕の会社が保守業務を引き継いだ Web システム「マハーカーラ」
  • 作業中にいきなりログイン画面に戻される「強制ログアウト粛清」が、複数人の端末で同時に発生した
  • アプリログを見てもエラーは出力されていない・Tomcat などのプロセスも落ちていない
  • 僕は原因調査を進めることにした

不定期な粛清

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

この「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 が絡んでいることは明らかなのだが、これとログアウトさせられてしまう動き、つまり SessionTimeoutActionLogoutAction が絡むような動きは見つけられなかった。

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

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

次回予告

  • ReallyPoorCompanyFramework.jar の中身を探る
  • ログイン時に行われていた奇妙な処理とは…

Amazon Web Services 業務システム設計・移行ガイド (Informatics&IDEA)

Amazon Web Services 業務システム設計・移行ガイド (Informatics&IDEA)

  • 作者: 佐々木拓郎,林晋一郎,瀬戸島敏宏,宮川亮,金澤圭
  • 出版社/メーカー: SBクリエイティブ
  • 発売日: 2018/01/20
  • メディア: 単行本
  • この商品を含むブログを見る