→ 午後5時 要請

まんもす日記でリークされてましたが、仕事納めで呑んでる最中にいきなり呼び出されて緊急対応要請。

→ 午後6時 電話で現状把握

「サービス開始まで3営業日」という切羽詰ってる状況らしいが、知らされた状況は、Apache 1.3 + JRun 4 + MS SQL Server という構成のシステムで、「どの画面でもある確率で 500 Internal Server Error と表示される」ということだけ。とりあえず電話してみる。

「JRunのログになんか出てると思うんですけど」「あぁ、出てます。なんか、atなんとかっていうのがたくさん」「総合運転試験工程での障害とのことですが、以前では出てませんでしたか」「実は結合試験工程でも出てました。発生頻度が低かったんですが、ここにきて頻発するようになったんです。」「とりあえずエラーログと環境設定ファイルをこちらに送ってください。」

→ 午後7時 現場で、事象の把握

そうこうしているうちに、別ルートからの連絡で、現場に駆けつけることで話がついてしまった。30分後に、総合運転試験を行っている、お客様のマシンルームに駆けつける。早速、事象解析を開始。

事象は、[1] ブラウザに 500 Internal Server Error と出る、[2] エラーログに IllealStateExceptionが出ている、の二つ。エラーログをみて、事象2をひき起こしているJSPを二つ抽出。あろうことか、JSP なのにresponse.getOutputStream() して out.write() して out.close() してる。ここまで確認した段階で、別の解析チームから「get.jspのout.close()がおかしいと思います。」との連絡が入る。は? 別の解析チームってなによ。いつから分析してるの、と聞けば、今日の朝からだという。こっちは事象確認から始めて1時間ちょっと。「もうひとつ同じ問題を抱えているファイルがあるよ。」といったら、「は、確認してみます」だって。がんばれ解析チーム。

→ 午後9時 開発拠点へ移動

現象を把握して、動作ログとエラーログを取得して、その解析チームのいる開発拠点へ移動。プロジェクトリーダー等を交え、現状を報告する。頭数が多くて、話が発散しがち。ホワイトボードを使って、その場をコントロールし、考えうる対策を7つほど提示。平行してできる作業を分担する。

→ 午後11時 再現を試みる

ここから再現手順の確認に入る。試験担当者に聞いても手順ははっきりしないということなので、apacheのアクセスログをみてユーザのクリックを追いかける。あああ、common log formatだ。combined log format に変えて、JRunの標準出力をファイルにリダイレクトしておいて、テスト担当者にもういちど再現させてもらう。なかなか再現しない。

平行して、取得しておいたお客様環境のアクセスログをみて、原因となるJSPを踏むルートを確認する。おなじルートをたどってみても、get.jspを踏んでくれない。

テストチームに再現をしてもらうことをあきらめ、棚上げにしていたテストを再開してもらう。get.jspを踏みはじめたようなので、combined log format をきっちりみてみる。log を get.jspでgrepしてみたら、ある特定のuser agentからのリクエストのみであるという興味深い事実を発見。apacheのログを追いかけて再現手順を確認し、そのブラウザをつかってその手順を試してみたら、みごとに get.jspを踏んで、事象[2]IllegalStateExceptionが再現した。100%の再現手順を確立。この時点で午前3時半。JSPを修正し、事象[2]を回避できることを確認。今日の作業内容と明日の計画をまとめて、いったん家に帰る。自宅で90分ほど睡眠をとる。

→ 午前11時 事象[1]と事象[2]との関連を探る。

最初に言われた事象が、事象[1]「いろいろな画面で 500 Internal Server Errorが出る」ということだったので、お客様環境で、事象[2] IllegalStateExceptionとの関係をさぐる。

実はこの get.jspを踏むリクエストってのは、ブラウザにロードされたappletが出しているものだったので、事象[2] IllegalStateException自体はブラウザの表示に影響を与えない。さらに、「別フレームのファイルロードが終了していなかったらリロードする」とかいう変なJavaScriptのせいで、例外画面を覆い隠すような動作をしていることがあった。どちらにしろ、事象[2]が出たら事象[1]が発生し、そのあとしばらく事象[1]が出るようだ。

→ 午後12時半 事象[2]の対策を打つ

午前3時に確立しておいた対策を施し、事象[2]が収束することを確認。と同時に、事象[1]も収束することを確認した。とりあえず一段落。

→ 午後3時 開発拠点へ移動

事前に「どうにかなりました。これからそちらに向かいます。」と電話連絡していたせいか、開発拠点についたら、プロジェクトリーダーは寿司を用意していやがった。事象[2]IllegalStateExceptionを解決したら、同時に事象[1] 500 Internal Server Error も収束したことを報告し、開発チームをあつめて技術的な解説をして、ものすごく納得される。このあと、簡単な報告書をまとめて、オレのマネージャーに報告。帰ったのは午後5時。