2018-08-03

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

発端

2015年の暑い夏の日。僕のデスクの電話が鳴った。僕が客先常駐して保守している社内システム「マハーカーラ」の主担当からだった。

「今マハーカーラに商品データを入れてたんだけどね？『次へ』ボタンを押したらログイン画面に戻されて、入力中のデータが消えちゃったの！一括登録しようとして30件分入力してたのよ？データ復元して欲しいんだけど！面倒臭いのよこの入力！商品名入れてから次の画面に行ってカテゴリ選んで、確認画面で確定ボタン押さないと確定できないんだから！」

主担当は、これまでの入力作業が水の泡になるのではないかという焦りからか、電話口でまくしたてた。残念ながら、「マハーカーラ」は優秀な Web システムではない。フォームに入力している最中の情報などキャッシュされているはずないだろう。僕は残酷な現実を伝えなくてはならなかった。

「申し訳ありません。確定前のデータは DB には保存されておりませんで、ブラウザのキャッシュにも残りませんので、もう一度入力していただくしか…」

「ええーーーどうにもなんないのぉ〜？大体なんでログアウトさせられちゃったの？…あ、ちょっと待って、今周りで同じ作業してるメンバもみんな画面遷移したらログイン画面に戻されたって…。M さんも？K さんもログアウトされちゃったの？ちょっと何これ…」

「えっ、周りの人もですか？！同時に…！？」

複数のユーザが同時にログアウトさせられ、ログイン画面に戻っただと…？マハーカーラの AP サーバが落ちたか…？いや、サーバが落ちたなら「ログイン画面に戻される」のではなく、システムエラー画面が表示されるはずだ。ログイン画面が表示されたということは、AP サーバはフリーズしたりシャットダウンしたりはしていないようだ。

「お手数ですが、再ログインはできますか？もしかしたらサーバが落ちているかもしれないので、確認させていただきたくて…」

「ログインはできたわよ。てことはサーバは落ちてないわよね？あー商品入力画面になんにも残ってないーー打ち直しなの〜？あなた保守してるならちゃんとしてよねぇ〜？」

僕はマハーカーラの保守担当だ。しかし、マハーカーラは僕や僕のいる会社が開発したシステムではない。マハーカーラは2005年に ReallyPoorCompany という別のベンダが開発して保守していたもので、それを2012年に僕の会社が引き継いで保守していたのだ。僕は2013年に入社したから、当初引き継いでいた先輩社員から保守業務を引き継いだだけで、僕が関係しているところはほとんどないシステムだ。入社してから僕が機能追加や改修案件に携わった部分はあるものの、僕が書いたコードは全体の1割にも満たないし、今回問題が起こっていた「商品入力」画面に関する機能には一切改修を入れていない。

とはいえ、今は僕が保守しているのだ。監督責任は僕にある。まずは AP サーバのシステムログを見てみて、何があったか調べてみよう。

「分かりました。現段階では原因が分かりませんので、本番サーバのシステムログを確認してきます。すぐに本番端末作業室への入室申請を作成致します」

本番サーバにアクセスするまでの三千里

常駐先の会社は制度に厳しいお堅い会社で、本番稼動しているサーバを操作するには、専用のネットワークに接続されている「本番端末作業室」にあるクライアント PC からしかリモートアクセスできなかった。開発者が自分のデスクから本番端末に SSH 接続して、本番データを抜き取って名簿業者に売りつけたりできないようにしてあったのだ。

しかし、この「本番端末作業室」に入るには、「入室申請書」を書く必要があった。「入室申請書」と呼んでいるが、申請書は3つあって、「開発者入室申請書」と「本番端末アクセス申請書」と「本番データ閲覧・移送申請書」の3つがセットだった。「開発者入室申請書」は、誰が何時から何時まで「本番端末作業室」に入るかを申請するモノで、「本番端末アクセス申請書」は本番端末作業室から SSH 接続する、本番サーバの IP アドレスを申請するモノ、「本番データ閲覧・移送申請書」は、本番サーバにアクセスしてその中のデータを見たり、サーバログファイルなんかを開発者のデスクに持ち帰ったりする時の申請書だ。

毎回この3つの申請書を印刷して紙に手書きし、ベンダ側 (つまり僕の会社) の PM がハンコを押し、さらに顧客側のシステム部担当のハンコをもらい、ハンコが揃った申請書を本番端末作業室の受付窓口に提出すると、30分後に本番端末作業室への入室許可が電子メールで送られてくる、という流れだった。バカバカしい。

そんなワケで、「社内システムの利用者が一斉にはじき出された」という比較的緊急事態であるにも関わらず、本番端末作業室に入室できたのは電話をもらってから1時間半後だった。

アプリログを見てみる

ようやく本番端末室に入り、マハーカーラの AP サーバに SSH 接続した。本番サーバのユーザ名は admin、パスワードは admin だ。セキュリティが甘すぎると思うのだが、前のベンダが納品した状態を勝手に変えてはならぬというお達しで、そのままにしている。

AP サーバに接続し、プロセスを確認してみたが、Tomcat は元気に動いている。DB サーバとの接続も問題なさそうだ。Struts をベースに、前ベンダの社名を冠したオレオレフレームワークを使って作られた Java アプリケーションも、Tomcat 上でちゃんと稼動していた。とりあえず復旧？はできているようだ。

次はアプリが出力する動作ログを見てみよう。動作ログのファイルは、日付ローテーションで生成されており、2005年の初回稼動時からのログが全て溜まっている。本番サーバのデータを勝手に消すことは許されていないため、全てのログファイルを溜めているのだが、このログファイルたちだけで 80GB を超えており、貧弱な AP サーバの HDD 容量を切迫している。この膨大なログファイルを10年以上残しておく価値はあるのか、それはまた別の話。

マハーカーラの主担当からヒステリックな電話を受け取った時刻の直前には、以下のような動作ログが出力されていた。

2015-08-01 14:21:39.401 [545215] MainMenuAction Start
2015-08-01 14:21:39.405 [545215] TABLE_USER_NEWS SELECT Start
2015-08-01 14:21:39.409 [545215] TABLE_USER_NEWS SELECT End
2015-08-01 14:21:39.842 [545215] MainMenuAction End
2015-08-01 14:22:04.213 [489513] ProductRegisterAction Start
2015-08-01 14:22:05.207 [545215] ProductRegisterAction Start
2015-08-01 14:22:05 572 [489513] ProductRegisterAction End
2015-08-01 14:22:05.609 [545215] ProductRegisterAction End
2015-08-01 14:24:27.511 [391342] MainMenuAction Start
2015-08-01 14:24:35.525 [391342] TABLE_USER_NEWS SELECT Start
2015-08-01 14:24:35.529 [391342] TABLE_USER_NEWS SELECT End
2015-08-01 14:24:36.213 [391342] MainMenuAction End
2015-08-01 14:26:09.534 [545215] ProductCategoryRegisterAction Start

アプリの動作ログは、日付・操作しているログインユーザの ID・動作している Java クラス名、という順番で出力されている。上から順に見ていこう。

2015-08-01 14:21:39.401 [545215] MainMenuAction Start
2015-08-01 14:21:39.405 [545215] TABLE_USER_NEWS SELECT Start
2015-08-01 14:21:39.409 [545215] TABLE_USER_NEWS SELECT End
2015-08-01 14:21:39.842 [545215] MainMenuAction End

ユーザ ID 545215 とは、電話をかけてきたシステム主担当のことだ。MVC でいう C、Controller にあたる MainMenuAction クラスで処理が行われている。コレはログイン直後に開かれる、メインメニュー画面を表示するための Action クラスだ。MainMenuAction が動作し、DB にある TABLE_USER_NEWS という名前のテーブルに SELECT 文を投げ、何やら処理している。メインメニュー画面にそのログインユーザに向けた新着メッセージを表示しているので、そのための処理だろう。最後に MainMenuAction End と表示されているので、システム主担当は14時21分39秒に、正しくログインし、正常にメインメニュー画面が表示された、と思われる。

ちなみに、このシステム、ログイン画面を表示した時の ShowLoginAction と、ログイン認証処理を行う LoginAction はログに記録されない。ログイン前だと、当然ユーザ情報は分からないので、ログを出力していない、ということみたいだ。だから、ログとしては LoginAction で認証ができ、ユーザが特定できた後の MainMenuAction が叩かれたところから出力されているのだ。

さて、その次からの行を抜粋しよう。

2015-08-01 14:22:04.213 [489513] ProductRegisterAction Start
2015-08-01 14:22:05.207 [545215] ProductRegisterAction Start
2015-08-01 14:22:05 572 [489513] ProductRegisterAction End
2015-08-01 14:22:05.609 [545215] ProductRegisterAction End

先にログインしていて、別作業を行っていたユーザ ID 489513 のログが登場する。この人は、システム主担当の同僚のオバサンだ。主に商品の発注業務を行うためにマハーカーラを利用している。このオバサンが ProductRegisterAction、つまり「商品登録」画面を初期表示するための Action クラスを叩いている (英語の品詞が無茶苦茶で瀕死しそうだ)。マハーカーラのメニューリストから「商品登録」のリンクを押した、という動作ログだろう。

これとほとんど同タイミングで、ユーザ ID 545215、つまり主担当が、同じ「商品登録」画面に遷移しようとしたようだ。ほぼ同時に、同じ Java クラスを実行している、ということになる。

もしかして、二人のユーザがリクエストした ProductRegisterAction クラスのインスタンスが同一で、この Action における処理がバッティングしてしまったのだろうか？

いや、それは考えにくい。この Action クラスは「商品登録」画面を初期表示するためのモノで、特に商品情報を DB から SELECT するワケでもない。大体 Action クラスというのは Struts フレームワークが管理してくれていて、別々のユーザに対して同じインスタンスをシングルトンに使い回すような動作はしないはずだ。現に、複数ユーザが同タイミングで同じ Action クラスの処理を通り、動作ログが今回のように交互に出力されているような動きは数多く見てきた。今回だけたまたま Struts がインスタンス生成をケチって Action クラスを使い回した、とは考えにくい。

しかし、今回は問題が発生した直前の処理なので、ちょっと気になるところではある。

この部分の推測は一旦後回しにして、残りのログを見てみよう。

# 同時に「商品登録」画面に遷移した時のログ (再掲)
2015-08-01 14:22:05.609 [545215] ProductRegisterAction End

# 2分ほど間が開いている
2015-08-01 14:24:27.511 [391342] MainMenuAction Start
2015-08-01 14:24:35.525 [391342] TABLE_USER_NEWS SELECT Start
2015-08-01 14:24:35.529 [391342] TABLE_USER_NEWS SELECT End
2015-08-01 14:24:36.213 [391342] MainMenuAction End

# さらに2分ほど間が空いている
2015-08-01 14:26:09.534 [545215] ProductCategoryRegisterAction Start

「商品登録」画面への遷移がバッティング？したかもしれないログの後、2分ほど開いて、更に別のユーザ 391342 がログインしているようだ。今回はなぜか MainMenuAction の開始から終了までに9秒ほどかかっているようだが、この 391342 ユーザが新たにログインしてきたようだ。あとで聞いたところ、このユーザは「商品登録」機能は利用しておらず、「支払管理」機能を主に利用する、システム主担当とは別の部署の人であるようだった。

そこからさらに2分程あいて、545215、つまりシステム主担当が次の画面に遷移している。ProductCategoryRegisterAction は、「商品登録」画面の「次へ」ボタンを押し、「商品カテゴリ登録」画面に移動しようとした時に実行される Action だ。システム主担当が「商品登録」画面で30商品を一括入力し、ウィザード形式で進む次の画面、「商品カテゴリ登録」画面に移動しようとした、ということだ。

しかしこのアプリログ、ProductCategoryRegisterAction の Start は残っているが、End のログがない。つまり、システム主担当は「商品カテゴリ登録」画面に実際には遷移できておらず、画面を移動しようとした途中でなにかがあって、はじき出されてしまったようなのだ。

この後ろは数分間ログがなく、しばらくして多くのユーザが MainMenuAction を叩くログが並び始める。つまりこのタイミングが、「画面遷移時にログイン画面に戻される」という粛清が行われ、主担当が電話してきたタイミングだということになる。

もしもシステムエラーが発生すると、このログファイルにスタックトレースが出力されるのだが、今回はシステムエラーログが全くない。アプリログだけ見ると、アプリは一切クラッシュしていないように見えるのだ。

本番サーバで有用なログというとこのぐらいしかなく、プロセスの異常終了なども確認されなかった。このアプリログの中で気になること、推測できることといえば、以下ぐらいだろうか。

システム主担当と、同僚のオバサンが、ほぼ同時に、同じ画面にアクセスしたようである。
- Java クラスの同一インスタンスが使い回され、二人のユーザの作業が混じり、おかしな状況を生み出したかもしれない？
- しかし、この二人以外のユーザも強制ログアウトの被害に遭っていたようなので、この原因は考えにくい。
システム主担当が「商品登録」画面を開いている間に、別のユーザ 391342 がログインしている。
- この人のログイン時に何か問題があって、システムがクラッシュしたか？
- しかしそれらしいエラーログは出ておらず、詳しいことは分からない。
Tomcat サーバも、その上で稼動する Java アプリも、異常終了はしていない。つまり、「ログイン画面に戻される」ことになる処理は、どこかに実装されている、意図した動きである可能性がある。
- プロセスのフリーズやクラッシュであれば、エラーログやプロセスが再起動した時のログが出力されるはずだし、サーバ全体のシステムログにも記録されるはずだ。でもそれが一切なかった。
- 何らかの条件を満たすと、ログイン画面にリダイレクトされるような仕組みが埋め込まれている、いわば「想定内の挙動」である可能性がある。

僕はひとまず今回のアプリログを (「本番データ閲覧・移送申請書」に則って！) 自分の作業端末に持ち帰り、自席でもう少し調べてみることにした。

次回予告

原因不明の「強制ログアウト粛清」が不定期に発生する
不定期に作業中のデータが亡きものにされ怒り狂う主担当
強制ログアウトを引き起こす条件とは…

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