一週間ぐらいデバッグ作業に悩まされた話

デバッグ作業に苦しんでいるプログラマー

パッと見、簡単な不具合だと思って修正に手を付けたところ1週間近く悩まされてしまったので、何が問題であったかを振り返るためにも文章でまとめておきたいと思います。

問題の背景

開発しているシステムのデータベースをクリーンアップする夜間バッチプログラムがあり、そのバッチが「外部キー制約で削除できないデータがある」アラートを報告して異常終了しました。
この「外部キー制約のため削除できない」データを期待通り削除できるようにするのが今回の修正で目指したところです。

修正の第一段階

最初の調査は、AzureのApplication Insight上に出力されたログからの調査になりました。
ログにはデータベースが吐き出しているエラーメッセージが記録されていましたが、スタックトレースはAzureのコレクションのトレースしか残っておらず、スタックトレースから問題個所を探すことはできませんでした。
ただ、データベースが吐き出しているログに多対多でデータを管理しているテーブルの名称があったので、そこから該当箇所を絞り込むことができました。

このログの情報から、今回の問題が発生するより以前に追加した、(ブログ記事に関連するブログ記事をぶら下げるような)多対多のデータ構造の削除でエラーになっていることがわかりました。
コードを見ると、多対多の関係を考慮した削除ができておらず、ここが問題個所であることが明白でしたので、データ同士の関係性を考慮して削除するように修正を行いました。

具体的には、A対Bの多対多関係になっているデータについて、B側からA側を参照しているデータを削除し、続いてA側からB側を参照しているデータを削除することで、EFCoreが自動生成してくれている中間テーブルのデータを孤立させ、EFCore自身が孤立したデータを削除データとしてマークして削除処理が実行されるというロジックを組み込みました。

修正確認時に生じた問題

ここまでは順調に生きましたが、修正後に動作を確認しようとすると、同じエラーでコケてしまいます。
ここで他のログを調査しなかったのが最大の問題点でした。
エラーが同じであったことから、当初アタリを付けた該当箇所にまだ問題が潜んでいると思い込み、ログをしかけたり、ロジックを再点検したり、ロジックを組み直したり、とにかく手を動かす方向で修正を試みてしまったために、真の問題解決までに時間を要してしまったのです。

何が起こっていたか

実は、該当箇所の後続処理でも同じテーブルに対する似たような削除処理を行っており、そちらでもデータ同士の関係が考慮されていなかったためにエラーが生じていました。
つまり、修正作業の発端になったアラートに対応する部分は修正できたものの、同じアラートを挙げる箇所がもう一カ所あったという事になります。

どのようにすれば、素早く解決できたのだろうか?

「手を動かさずにログをじっくり読む」「仮説をもって検証するために手を動かす」これに尽きると思いました。
ログを読まずに問題個所を決めてかかってしまったり、仮説を持たずに場当たり的にコードを直してしまったり、こういう所に時間を要した原因があったんだろうなと反省しきりです。

今回学んだことを糧にしながら仕事に励みたいと思います。