こんにちは、ナル(@naru_1walk)です。
気づけば１ヶ月更新してなかった・・・。
さて、最近仕事でとあるプログラムを改修した際に不具合が発生してしまい調査を行ったのですが、その調査に３日かかってしまいました。
振り返りと今後への対応も含めてまとめていこうと思います。
そもそもどんな不具合か
一応どんな不具合だったのかを環境を含めて簡単に説明します。
環境
- Windows Server
- ASP.net
- SQL Server
不具合内容
データ登録を行う際に以下のエラーメッセージが出力される場合がある。
IDENTITY_INSERTがOFFに設定されている場合、テーブル 'AAA'のID列に明示的な値を挿入できません。
System.Data.SqlClient.SqlExceptionに値を挿入しようとすると例外が発生します。エラーメッセージの内容は理解できます。が出ているエラーメッセージがいまいち不可解。
というのも今回の改修ではDBの設定に関わる改修を行なっていない(はず)。DBの設定が問題なのであれば現行のプログラムで発生しないのはおかしい。
後もっというと今回の改修は一覧表示に対して改修を行なってデータ登録機能は改修していないのに何故？？？
エラー原因と対処
まあ結論から言えば自分の改修ミスでした。
このシステムではDataSetを用いてDBへの登録、更新を行なっています。
よくよく見ると実はDataSetは一覧表示でもDB登録時と同じ名称のものを作成していました。
今回の改修で一覧表示時にデータを取得する際取得する項目を増やしたのですが、DataSetの名称をそのままにしていました。
どうやらその影響で自動採番の設定がDataSet側でうまく引き継ぐことができず、DBに登録しに行く際にエラーが発生していたと言うわけです。
なぜ時間がかかったのか
エラー原因と対処内容だけ見てみたら「そこまで複雑じゃなくてただのポカではないか」と思う方がいるかもしれません。
実際自分はそう思っています。
なのに何故調査に３日もかかってしまったのでしょうか。
再現性が低く見つけるのに時間がかかった
実はこのエラー、起きる場合と起きない場合の切り分けが非常に困難でした。
- テスターからは特定作業の時に動かないとあるが、動く場合がある。
- 同じプログラムで同じ動作をしても動く場合と動かない場合がある。
- 動かなかったプログラムが時間経過で動くようになる。
などです。このようなことが起きてしまったため、「タイミングの関係で稀に起きているものなのではないか」とさえ思ってしまいました。
その後、様々な動作確認を行なった結果、以下のことが判明。
- 一度エラーが起きるとログアウトしたりブラウザを立ち上げても一回目で正常に動く場合がずっと動く、動かない場合はずっと動かない
- プログラムが格納されているフォルダに関係ないファイルを配置したら今まで動いていたものが動かなくなった
そこからシステム起動時に一時ファイルが作成されているであろうこと、その一時ファイルはログインログアウトやブラウザ終了では消えないと仮定し、
プログラム入替→ログイン処理→特定の動作→エラーが起きること
で再現性を確認することが出来ました。
エラーメッセージに注目しすぎた
エラーメッセージを見るとデータを登録するときにエラーが発生しているからだろうと考えました。
IDENTITY_INSERTがOFFに設定されている場合、テーブル 'AAA'のID列に明示的な値を挿入できません。
System.Data.SqlClient.SqlExceptionに値を挿入しようとすると例外が発生します。が、今回の改修では画面登録処理は触っていないにも関わらず発生しています。
そのため、既存のシステムでも発生するものと仮定した上でどう直せばいいかと考えてしまったところがあります。
これは再現性が難しかったため、別方向で対処しようと考えましたがちょっと明後日の方向に考えてましたね。
開発環境による影響の切り分けが遅れた
実はこのシステムは前任者から引き継いだものですが、資料として残されていた開発環境を構築したところ動作できませんでした。
どうも前回の改修から連携しているサーバのDBのバージョンが更新されたことにより動かなくなってしまったようです。
そのため、開発時は一時的にVisual Studioのバージョンを上げてデバッグを行いました。
ビルド時は資料に残った環境で行うことで現行のものと動かせると判断したからです。
結果、エラーが発生したときにビルドした環境でブレークポイントによるデバッグ確認ができず、開発環境が正しいかどうかの判断をするのが遅れてしまいました。
今後への戒め
状況再現の認識を改める
これまではログイン後に操作を行うことで再現ができると認識していました。
が今回の例ではログイン後にエラーが発生しない動作を一度行うとそれ以降はエラーが発生しなくなるようになりました。(再ログインやブラウザを開き直しても同様の動きとなります)
そのため、今後再現性を確認する際はプログラムの入替も加味した上で再現が行えるかを確認します。
前バージョンからリビジョン単位で調査していく
今回、以下の調査を行ったことで原因の特定に一歩進んだ感じがしました。
- 前バージョンでのプログラムを今回作成した開発環境でビルドして動作すること
- 前バージョンでのプログラムから１リビジョン単位で更新していき動作すること
- 最新バージョンから動作しているリビジョンのファイルのみを入れ替えて動作すること
今回の例では以前までのプログラムではエラーが発生しないことを確認できていました。
そのため、前バージョンでのプログラムを今回の開発環境でビルドし、動作可能かを確認しました。
この確認により、開発環境に問題がないことの切り分けを行うことが出来ました。
次に前バージョンのプログラムから１リビジョン改修を進めたものでビルドし、動作可能かを確認しました。
この確認では動作を確認することが出来なかったため、１リビジョン改修を進めた中のファイル単位で問題があることを確定しました。
プログラムのデバッグでエラー原因が特定できない場合は、このように確認することでファイル単位で切り分けることが出来ます。
ファイル単位で切り分けを行うことで注視する箇所を限定することができ、結果原因の特定につながります。
不安なときはメモをする
このブログを書いていて思い出しましたが、今回不具合が発生した箇所は自分が改修していた際に疑問に思ったことを思い出しました。
その時は、
「このままで問題ないか不安があるが、問題があればテスト時にわかるだろう」
と思って改修した記憶があります。
実際、一覧表示や単体テスト時は問題は発生しなかったのですが、運用テスト時にエラーが発生したわけです。
今回の例ではこの不安を放置した上で改修したことも問題ですが、このなんとなく大丈夫かという直感を残しておけばもう少し不具合原因の特定が早かったかなと思いました。
システムエンジニアとしては理論的な考えも重要ですがそれと同じくらい直感も重要だと感じました。
頭を柔らかくする
一番はこれかもしれません。
このプログラムでエラーが発生した時、データ登録機能は改修していない→今回自分が行った改修で悪いところはないという前提で進めていた気がします。
初期調査でまずその切り分けを行い、調査箇所を特定するのであれば問題ないかもしれませんが、調査に行き詰まったのならその前提は取っ払い一つ一つ原因を確認するしかありません。
とりあえず行き詰まったらこれまでやってきた結果をまとめて一度頭をリセットしましょう。
まとめ
今回の対処は色々応えました・・・。
自分が改修した不具合に3日かけたこともそうですし、2日目の途中までほとんど原因を突き止めることができなかったので割と精神的にもきます。
ふとした気づきから原因を特定することが出来ましたが、今後調査を行う際は今回の教訓も含め一歩ずつやっていくことが結果的に近道だと痛感しました。