2018-08-07

とある社内業務システムで起こったバグの話 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" パラメータを取得して、それを引数に MASTER_USER_BK テーブルに DELETE クエリを投げている
    masterUserBkService.delete(request.getParameter("userId"));
    
    // 同様に、MASTER_USER_BK テーブルに "userId" パラメータを INSERT しているようだ
    masterUserBkService.insert(request.getParameter("userId"));
  }
  catch(Exception e) {
    // 悪名高き Pokemon Exception Handling だ！
  }
}

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

さらに、MASTER_USER_BK という名前のマスタテーブルに対し、DELETE と INSERT を実施していることも分かった。引数にはリクエストから "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 テーブルとは何であり、いつデータが登録され、いつ削除されるのか、もう一度まとめてみよう。

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

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

いや〜しかし、MASTER や BK という紛らわしい名前もそうだし、「毎朝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 が生まれたとしたら？

# 「2015年7月11日」の始業時に削除すべきなのは、7月10日以前のデータなので、本来は「LOGIN_DATE < '20150711'」となるべきだが、
# もしもパラメータの日付が1日後にズレたとしたら、7月11日のデータも削除されることになる
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 のレコードをヒットさせて削除する方法は考えにくいのだ。

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

次回予告

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

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