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

前回までのあらすじ

…

どうすれば MASTER_USER_BK テーブルのデータが消えるか？

もう一度、MASTER_USER_BK テーブルを 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) { /* 当然のようにエラーは握り潰す */ }
  }
}

このメソッドの呼び出し元は以下の2箇所のみ。

【1】ログインボタンを押下時、当該ユーザ ID の過去データを削除し、新たなログイン日付のレコードを INSERT する、ログイン時の定型処理。

// これから実行される Action クラスが LoginAction である場合に処理を行う
if("LoginAction".equals(currentActionClassName)) {
  try {
    MasterUserBkService masterUserBkService = new MasterUserBkService();
    
    // リクエストから "userId" パラメータを取得して、それを引数に MSTER_USER_BK テーブルに DELETE クエリを投げている
    masterUserBkService.delete(request.getParameter("userId"));
    
    // 同様に "userId" パラメータを利用し、現在日時を LOGIN_DATE カラムに設定し、INSERT を行う
    masterUserBkService.insert(request.getParameter("userId"));
  } catch(Exception e) { }
}

この呼び方で、先程の MasterUserBkService#delete() メソッドからは、以下のような SQL が生成される。

DELETE FROM MASTER_USER_BK WHERE USER_ID = '999999';

【2】8時40分から8時50分 (始業時間直後) にログインボタンを押した最初のユーザが、前日分のデータを削除する。通称「人力日次バッチ」。

// 始業時間直後かつ、この時間帯に初めてログインしようとしたユーザの場合
if(isBetweenStartTime(currentTime) && isFirstUser()) {
  try {
    MasterUserBkService masterUserBkService = new MasterUserBkService();
    // currentTime が8桁の String
    masterUserBkService.delete(currentTime);
  } catch(Exception e) { }
}

この呼び方で、先程の MasterUserBkService#delete() メソッドからは、以下のような SQL が生成される。

DELETE FROM MASTER_USER_BK WHERE LOGIN_DATE < '20150711';

いずれにしても意味不明なコードで、なぜセッションを利用せず DB で「ログインしているか否か」を管理しようとしているのか分からないし、毎日定期実行したい処理はバッチにしろと思うが、とりあえずこういうコードだったのだ。

この2つの呼び出し方のどちらかが誤作動して、MASTER_USER_BK テーブルからログイン中のユーザの情報まで DELETE してしまったとしたら、ログイン中のユーザは、画面遷移時に必ず行われる「不正アクセスチェック処理」によって、ログイン画面に戻されることになる。

// 画面遷移時に必ず動作する共通処理
try {
  MasterUserBkService masterUserBkService = new MasterUserBkService();
  // ログイン処理後、セッションに格納されている "userId" パラメータを引数に利用し、存在チェックを行う
  masterUserBkService.select(session.getParameter("userId"));
}
catch(SQLException e) {
  // SELECT できなかった場合は、ログインしていないユーザがリクエストしてきたもの = 不正アクセスと見なし、ログイン画面にリダイレクトする
  return redirectToLogin();
}

こんな雰囲気のコードがあったワケだ。

観測の時間だ

そろそろ推測を止めよう。ココまでは、強烈な臭いを発するコードを並べて、アレが臭いコレが臭いと言っているだけで、そもそもこれらのコードが本当に元凶なのかどうかはまだ分からないのだ。

だから、推測を止めて、実際に観測することにした。

システム主担当を呼び出し、ReallyPoorCompanyFramework.jar の中にデバッグログを出力するコードを仕込ませてもらえないか説得した。原因特定ができたら元の JAR ファイルに戻すことを条件に、なんとか承知いただけた。

本番 DB サーバから引っこ抜いてきた ReallyPoorCompanyFramework.zip の中身を利用し、上に掲載したコードの前後あちこちに、デバッグログを出力する行を追加した。コレで、アプリログファイルに、実行された SQL や、リクエストパラメータの内容などが出力できるようになった。この JAR ファイルをマハーカーラの Java プロジェクトに取り込み、Mahakala.war を生成した。

いつもどおり時間をかけて忌々しい入室申請を行い、中の JAR ファイルを書き換えたバージョンの Mahakala.war をデプロイした。そして翌日、始業前の少し早い時間に出社し、誰の迷惑にもならない時間帯にマハーカーラを開き、僕が「ログイン」ボタンを連打してみた。

ログインボタンを10回ほどカチカチカチカチっと連続クリックすると、メインメニュー画面に遷移するまで8秒ほど待たされる (いつもなら2・3秒だ)。どうも妙な動きをしている。しかし、始業時間前なので、8:40〜8:50 に発動する「人力日次バッチ」の処理には該当しないはずだ。

始業時間を待ち、本番サーバのログを確認してみた。

デバッグログによって発覚した衝撃の事実

アプリログには、以下のように出力されていた。[DEBUG] と書かれている行が、自分が追加で仕込んだデバッグログだ。

# 分かりやすくするため、連打によって10数回分出力されていたログイン処理のうち、最後の3回分を掲載
2015-09-14 08:28:34.255 [DEBUG] LoginAction 開始
2015-09-14 08:28:34.257 [DEBUG] ログイン認証成功 [614290]  # ← コレは僕のユーザ ID だ
2015-09-14 08:28:34.268 [DEBUG] MASTER_USER_BK テーブルから USER_ID を条件に削除 : DELETE FROM MASTER_USER_BK WHERE USER_ID = '614290';
2015-09-14 08:28:34.268 [DEBUG] LoginAction 開始
2015-09-14 08:28:34.268 [DEBUG] MASTER_USER_BK テーブルに INSERT
2015-09-14 08:28:34.270 [DEBUG] LoginAction 開始
2015-09-14 08:28:34.271 [DEBUG] ログイン認証成功 [614290]
2015-09-14 08:28:34.271 [DEBUG] ログイン認証成功 []  # ← ！？
2015-09-14 08:28:34.284 [DEBUG] MASTER_USER_BK テーブルから USER_ID を条件に削除 : DELETE FROM MASTER_USER_BK WHERE USER_ID = '614290';
2015-09-14 08:28:34.284 [DEBUG] MASTER_USER_BK テーブルから USER_ID を条件に削除 : DELETE FROM MASTER_USER_BK;  # ← ！？
2015-09-14 08:28:34.891 [DEBUG] MASTER_USER_BK テーブルに INSERT
2015-09-14 08:28:34.908 [DEBUG] MASTER_USER_BK テーブルに INSERT
2015-09-14 08:28:35.434 [DEBUG] LoginAction 終了
2015-09-14 08:28:35.434 [DEBUG] LoginAction 終了
2015-09-14 08:28:35.434 [DEBUG] LoginAction 終了
2015-09-14 08:28:49.511 [614290] MainMenuAction Start
2015-09-14 08:28:55.525 [614290] TABLE_USER_NEWS SELECT Start
2015-09-14 08:28:56.529 [614290] TABLE_USER_NEWS SELECT End
2015-09-14 08:28:57.213 [614290] MainMenuAction End

ログインボタンを連打した時刻は、始業前の8時28分頃。ログインボタンを10回ほど連打したので、LoginAction 開始 というデバッグログがつらつらと並んだ。そしてこれらのリクエストがその数だけ並行して処理されているようなのだが、途中で凄いことが起こっている。

2015-09-14 08:28:34.271 [DEBUG] ログイン認証成功 []

2015-09-14 08:28:34.284 [DEBUG] MASTER_USER_BK テーブルから USER_ID を条件に削除 : DELETE FROM MASTER_USER_BK;

まず、ログイン認証が成功した時点で、ユーザ ID が上手く受け取れていない瞬間が発生している。あとでログイン認証機構を持つサーバ側のログを見ると、レスポンスデータは欠落していないようだったので、どうもマハーカーラ側がそのレスポンスデータを受け取った時に、上手くデータを保持できていなかったようだ。恐らくは同じ処理が並列実行されたことによる不具合か？この部分の挙動の詳細はこれ以上追いきれなかった。

そして次に、MASTER_USER_BK テーブルへの DELETE 処理で発行される SQL が DELETE FROM MASTER_USER_BK; となっている瞬間があった。確かにこの SQL が発行されたら、MASTER_USER_BK テーブルの全レコードが削除され、コレによってマハーカーラのシステム上の認識は「今日はまだ誰もログインしていない状態」となるワケだ。その状態で、ログイン済みだったユーザが画面遷移によるリクエストを投げてくると、「誰だこのユーザ ID は！今日まだログインしていないじゃないか！ログイン画面に戻れい！」とリダイレクトされてしまう、というワケだ。

これが、今回の不具合が引き起こされた流れだったようだ。直接的な原因は、if 文の書き方がイケてなかった、という簡単な問題だったのだ。

WHERE 条件がない SQL が出来上がる仕組み

しかし、DELETE の SQL に、WHERE 句が設定されない条件なんてあり得るのか？僕はもう一度、MasterUserBkService#delete() メソッドのコードを見てみた。

// MASTER_USER_BK テーブルを CRUD 操作するエンティティクラス
class MasterUserBkService {
  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 + "'";
      }
      
      // SQL を実行する
      ReallyPoorCompanyDBUil.executeQuery(sql);
    }
    catch(Exception e) { /* 当然のようにエラーは握り潰す */ }
  }
}

今回は、引数の paramStr が空文字になっているようだったので、どちらの if 文にも合致しないまま、「SQL を実行する」のコード行に到達したのだろう。そうすると変数 sql の中身は "DELETE FROM MASTER_USER_BK " となっていて WHERE 条件が付かないので、今回と同じ、問題のある SQL が発行されることになる。

盲点だった。引数 paramStr は、大元はログイン認証結果やシステム時刻の取得結果を利用しているのだから、必ず6桁か8桁の文字列が入ってくるはずだろう、と決め付けていて、この if 文の作りを無視していた。しかし、「万が一、どういうワケか」paramStr が6桁でも8桁でもなかったら何が起こるか、もう少し考えるべきだった。

要するに、

if(paramStr.length() == 6) { }
if(paramStr.length() == 8) { }

コレでは paramStr.Length() が 6 でも 8 でもない場合は、どちらの if 文にも合致せず処理を続けてしまう。

せめて、

if(paramStr.length() == 6) { }
else { /* paramStr.length() が 8 の時の処理 */ }

のようにしておけば、必ず WHERE 条件付きの SQL しか生成されないことになる。

もっとちゃんとするなら、

if(paramStr.length() == 6) { }
else if(paramStr.length() == 8) { }
else { throw new Exception(); }

といった形で引数チェックをして、異常な引数の時に処理をしないのが良いだろう。もちろん、Exception は実際にはより適切なサブクラスで表現する。

この後、しばらくデバッグログを出力させたまま経過を見守った。すると、ログインボタン連打の「裏技」を見つけた支払担当の人たち以外でも、ログインボタンを2・3回連続でクリックしてしまったような人によって、強制ログアウトの粛清が引き起こされる場合があることが分かった。ログインボタンに対しても、最も基本的な対策である「ダブルサブミット防止」策を取る必要がある。滅茶苦茶簡単なやり方でいけば、以下のような作りにすれば防げる。

<button type="button" id="submit-btn" onclick="onSubmit()">ログイン</button>

// ログインボタンを押したかどうか判定するフラグ変数
var isClickedSubmitBtn = false;
function onSubmit() {
  // ログインボタンが押下済なら何もしない
  if(isClickedSubmitBtn) {
    return;
  }
  
  // ログインボタンを押したとしてフラグ変数をセットする
  isClickedSubmitBtn = true;
  // ボタンを非活性にし、ユーザが再度押下出来ないようにする
  document.getElementById('submit-btn').disabled = true;
  // ログイン処理
  myForm.submit();
}

サーバサイド (Struts) 側で、リクエストトークンをチェックしたりしても良いが、まずはフロントエンドでできる予防を。

問題解決

3日ほど様子を見て、調査結果をシステム主担当に報告した。元々かなり意味不明な実装なので、説明してもなかなか理解してもらえなかったが、ダブルサブミットを防止しつつ、WHERE 条件を持たない状態で DELETE SQL を実行しないように修正すれば、二度と同じ不具合を起こさないように直せる、と説明したところ、「ぜひ直してくれ！」と頼まれた。

僕は不具合を修正した。WHERE 条件がない状態で DELETE SQL が実行されないようにするため、以下のような作りにした。

class MasterUserBkService {
  // delete() は例外をスローするようにした
  public void delete(String paramStr) throws SQLException, IllegalArgumentException {
    // SQL 文の構築
    String sql = "DELETE FROM MASTER_USER_BK WHERE ";
    // ↑ ココに WHERE まで書いておいて、コレ単体では不正な SQL になるようにしておいた
    
    if(paramStr.length() == 6) {
      // 引数 paramStr が6文字だった場合、引数をユーザ ID と見なし、USER_ID との完全一致で絞り込む
      sql += "USER_ID = '" + paramStr + "'";
    }  // ↓ else if で繋いだ
    else if(paramStr.length() == 8) {
      // 引数 paramStr が8文字だった場合、引数を日付情報 (yyyyMMdd) と見なし、ログイン日付が古いデータを絞り込む
      sql += "LOGIN_DATE < '" + paramStr + "'";
    }  // ↓ else で拾い上げるようにした
    else {
      // 引数 paramStr が意図しない状態だったら例外を投げる
      throw new IllegalArgumentException("引数 paramStr が異常です : [" + paramStr + "]");
    }
    
    // SQL を実行する
    ReallyPoorCompanyDBUil.executeQuery(sql);
  }
}

ダブルサブミットについては先程の JavaScript コードそのままの対応を入れた。リクエストトークンの設定は ReallyPoorFramework の都合上設定が難しかったので断念したが、本来はトークン設定しておくのが望ましい。そもそも PreparedStatement で書けよとかなんとかいわれそうだが、あんまり原型を留めない変更は現場の人間がコードレビューできなくて許可されないので諦める。悲しい。

平穏

当時の ReallyPoorCompany がどうしてこんなコードを生み出したのか、それはもう考えないことにした。考えても仕方がない。考えたところで何も成果がない、無駄なことだ。

いずれにしても、コレで「一斉ログアウト」という恐怖の事態は二度と発生しなくなった。1ヶ月ほどアプリログを監視していたが、ログインボタンのダブルサブミットも発生していなかったし、他人のログイン履歴まで削除してしまうような MASTER_USER_BK テーブルの DELETE 文も発行されていなかった。めでたしめでたしである。

数ヶ月に及んだ不具合追跡と修正がようやく解決した。

暑かった夏も、いつの間にかクリスマス直前だ。今日は早く帰ってクリスマス・イブの準備でもしようかな。デートに行く約束は取り付けたけど、ディナーはどこにしようかな。早く予約しないともうギリギリだからな…

…なんて考えていたその時、僕のデスクの電話が鳴った。電話機のディスプレイには「システムタントウ ヤマグチ」の文字。

受話器を持ち上げるなり、システム主担当の喚き声が漏れ聞こえてきた。

「ちょっと〜〜！！今期の売上データが全部0円になってるんだけどぉ〜〜〜！？」

(いいちこたぁちこ、おわり)

あとがき

くぅ〜疲れましたｗこれにて完結です！3万字以上も書いてしまいました！

この物語は完全なるフィクションであり、東京オリンピックの年に設立した老舗大手 SIer も、2000年代に顧客情報が流出した会社も、十数ベンダから無茶な引き継ぎをやった会社も、何も関係ありません。

ただ、バグというのは大抵こうした考慮不足、if 文の些細な構成ミスみたいなことから引き起こされるもので、無知によって生み出されたオレオレフレームワークやスパゲッティコードがそうしたバグの原因をとことん分かりにくくさせる。

こんなシステムの保守担当にはなりたくないものだが、もしもなってしまったら、上司に許可を求めることなく、独断でリファクタリングしていこう。技術力をもって先にやってしまって、「でもコッチの方が良いっしょ？」と思い知らせてやろう。マインドだけでなく、良いアクションを継続して見せていけば、周りもいつか説得できるはずだ。