システムテストがFailをしたときの対処法

長い前置き

皆さんリリース前の最終試験ってなんて呼んでるでしょうか。

システムテスト、シナリオテスト、ステージングテストなど色々あると思います。

うちの会社ではシナリオテストって呼ぶことが多いんですが、個人的には「システム全体として正しく動いているか」を図りたいのでシステムテストという表現がしっくり来ています。

そんなわけで本日もシステムテストがしっかりFailしてくれたのでちょちょっと手直ししたんですが、原因特定と解決までの流れをざっくりと。

ああ、そういやUT回し直してねぇ。。。やべぇ。。。。

テストの種別を確認する

いろんな分類の仕方があるんですが、ざっくり分けて機能テストと非機能テストがあります。

今回は機能テストの話です。

アウトプットをみて現象を確認する

テストがFailしたからには何らかのアウトプットが正しくないという判断を下したわけです。

今回の案件はこんなかんじ。

対象：バッチ
入力：外部API上のデータ（テストにはサンドボックス環境を使用）
期待値：正常に処理されて終了
実際：エラーを出力して終了

正常に終わったかどうかはログに吐き出されます。本番運用ではZabbixでログを監視しています。ちょっとダサい。。。

というわけでログが最初の手がかりです。

ログを読もう

ログは大事。超大事。今回みたいにログ内容を確認するテストでなくてもログはちゃんと確認しましょう。
そしてログに大事な情報が記録されていないことに一通りブチギレてください。

今回ログには以下のエラー情報が記録されていました。

・エラーメッセージ：例外をハンドルしたよ！
・例外クラス名：名前忘れたけどDBMSが投げてる重複キー例外
・例外メッセージ：Insertしようとしてるレコードのキーは既にあるで！
・例外コールスタック

というわけで直接原因がわかりました。なんて優秀なログなんだ！（自画自賛）
何らかの原因でInsertしようとしているレコードと既に登録されている内容が衝突した感じです。

更にコールスタックのおかげで発生箇所も特定されました。
システムデータの更新を担うUpdateTaskというクラスのrunメソッドで落ちています。

さらにログには以下の情報も記録してありました。なんて優秀なログなんだ！（二回目）

・runメソッド実行の際にセットされていた入力情報

あと事前にテスト実行前のデータベースの状態のスナップショットも事前に記録されていました。

おかげさまで以下の情報が揃いました。

・問題発生箇所（メソッドレベルで）
・問題発生時の入力情報
・問題発生時の事前内部状態
・問題発生時の事後内部状態
・問題発生時の出力（今回は例外出力）

上記の組み合わせがおかしいことが判断できたのでこのメソッド処理内で問題が起きていると仮説を立てて調査の深堀りです。

ココまで来るとUTのスコープなのでこのメソッドのテストを追加してTDDに戻るのが正道・・・・なのですが、めんどくさかったので手抜きしてます。

例外ブチ込んで絞り込み

テスト再走行コストが低かったので以下のちょっと過激なやり方で処理中の変数覗き見しました。

1. 疑わしき場所の後で変数のダンプを例外として投げるコードを追加
2. 再実行して例外メッセージをメモ
3. 疑わしき場所の前で変数のダンプを例外として投げるコードを追加
4. 再実行して例外メッセージをメモ
5. メモ突き合わせて以上がなければあたりをつけなおして1に戻る

結果処理の順番が一部おかしいところがあったのを発見したので修正してコミットを積みました。

まとめ

ログがちゃんとしていればログメッセージだけで結構真に迫れます。

クラスレベルで入出力＆状態変化を確認できればUTに差し戻して深堀りすればいいと思います。

プリントデバッグは手抜きだけどちゃちゃっと変数の中身盗聴できて楽なので使いがち。