実例に見る、バグの原因を見つけるアイデア : catch 句の中で例外が発生している

何かバグが起きた時、どうしてそれが起こっているのかすぐには特定できない場合がある。

今回は、僕が実際に遭遇した「一見しただけでは特定しにくかったバグ」を紹介することで、似たようなバグに出会った時の参考にしていただければと思う。

サンプルコード

僕が実際に遭遇したバグとサンプルコードを紹介する。JavaScript で書いているが、Java など似たような構文の言語でも同様だろう。

// 呼び出し元の関数
function main() {
  logger.trace('main() 開始');
  try {
    logger.trace('main() 実処理呼び出し');
    const result = exec();
    logger.trace('main() 呼び出し終了・結果 = [' + result + ']');
    return result;
  }
  catch(error) {
    logger.error('main() 例外を検知・異常終了');
    process.exit(1);
  }
}

// 実処理
function exec() {
  logger.trace('exec() 開始');
  try {
    // ユーザ情報を取得するような処理 (ココはサンプルのためテキトーに)
    const userId = myStorage.getData('userData').id;
    logger.trace('exec() ユーザ ID 取得成功 = [' + userId + ']');
    return userId;
  }
  catch(error) {
    // myStorage がスローする例外には詳細情報が含まれているのでその内容を出力する
    logger.error('exec() 例外を検知', error.details.statusCode);
    // 例外発生時は空値を返す実装とする
    return '';
  }
}

こんなコードがあったとして。

main() 関数を実行すると、内部で exec() 関数が呼び出され、正常に動けば以下のようにログが出力される。

2019-01-01 00:00:00 [TRACE] main() 開始
2019-01-01 00:00:01 [TRACE] main() 実処理呼び出し
2019-01-01 00:00:02 [TRACE] exec() 開始
2019-01-01 00:00:10 [TRACE] exec() ユーザ ID 取得成功 = [U0011]
2019-01-01 00:00:11 [TRACE] main() 呼び出し終了・結果 = [U0011]

大抵はこのように正常系が動作するのだが、ある時コレが上手く動かなくなったとする。大本のエラーは myStorage.getData() 関数で発生するので、以下のようなログが出力されることを期待していた。

2019-01-01 00:00:00 [TRACE] main() 開始
2019-01-01 00:00:01 [TRACE] main() 実処理呼び出し
2019-01-01 00:00:02 [TRACE] exec() 開始
2019-01-01 00:00:10 [ERROR] exec() 例外を検知 500
2019-01-01 00:00:11 [TRACE] main() 呼び出し終了・結果 = []

exec() 関数内の catch 句が例外をキャッチし、エラーコードをログ出力した上で、空の文字列を返却する。main() 関数から見るとエラーは握り潰されているので、正常な結果ということで、空の文字列を受け取って終了するはずだたｔ.

が、実際は次のようなログが出力された。

2019-01-01 00:00:00 [TRACE] main() 開始
2019-01-01 00:00:01 [TRACE] main() 実処理呼び出し
2019-01-01 00:00:02 [TRACE] exec() 開始
2019-01-01 00:00:12 [ERROR] main() 例外を検知・異常終了

今回は「一見しただけでは見つけにくかったバグを紹介する」と前置きして、順に説明しているので、原因になりそうなコード行がもうお分かりかと思う。

しかし、いきなりこのログの並びだけを見ると、「exec() 関数は try / catch で囲んでいるのに、どうして catch 句をすり抜けて main() 関数に戻ってるの？！」と思うワケだ。また実際のコードはもっと処理 (行数) が多いので、何が起こっているのか余計に分かりにくくなるのだ。

catch 句の中で例外が発生している

さて、このような奇妙なログの並び方をする理由は、exec() 関数の catch 句内にある、以下のコードが原因だ。

catch(error) {
  // myStorage がスローする例外には詳細情報が含まれているのでその内容を出力する
  logger.error('exec() 例外を検知', error.details.statusCode);

error オブジェクトの中には details というオブジェクト・プロパティがあり、その中に statusCode というプロパティがある、という前提で、このようにコーディングしていた。

しかし、myStorage.getData() 関数がスローした error オブジェクトが details オブジェクトを持っていなかった場合は、以下のような例外が発生する。

TypeError: Cannot read property 'statusCode' of undefined

catch 句の中で発生した例外は、呼び出し元に伝搬する。エラーログを出力するためのこの行で例外が発生した場合は、「exec() 例外を検知」というエラーログが出力されないまま、呼び出し元である main() 関数の catch 句が例外を拾い、突然「main() 例外を検知・異常終了」と出力されたように見える、というワケだ。

例外を捕捉するための catch 句の中で例外が発生している、という可能性は、最初はなかなか思い当たらないだろう。しかし、おかしな動きをしている時は、「ココでキャッチしているはずだから…」といった思い込みを捨て、catch 句の中に問題はないかと調べる癖を付けたい。

「ログ出力処理」そのものが悪影響を及ぼす

また、この例で厄介なのは、エラーの内容を把握するために仕込んだはずのログ出力処理自体に問題があって、エラーの詳細が表に現れなかったところだ。

「正常ログが出るはず」「異常ログが出るはず」と思っているのに、想定していたどちらのログも出なかった場合は、ログ出力処理部分に問題はないかをチェックするようにしたい。

ログ出力処理で例外を出さないようにする

ロギング処理は、システムの動作に影響を与えてはならない。パフォーマンスが明らかに低下するほど大量のログを出力したり、今回のようにログ出力処理が悪さをして、システム異常を引き起こしたりしてはならない。

catch 句の中では、ログ出力も含めて余計な操作や処理をしないようにしたい。どうしても何か処理する必要があるのであれば、極端な話、catch 句の中に try / catch を書いてでも、ログ出力による問題を引き起こさないようにしたいところだ。

function exec() {
  logger.trace('exec() 開始');
  try {
    const userId = myStorage.getData('userData').id;
    logger.trace('exec() ユーザ ID 取得成功 = [' + userId + ']');
    return userId;
  }
  catch(error) {
    logger.error('exec() 例外を検知', error);
    
    // 極端ではあるが同様の例外は防げる例
    try {
      logger.error('exec() 例外の詳細コード', error.details.statusCode);
    }
    catch(innerError) {
      logger.error('exec() 例外の詳細コードなし・未知のエラー');
    }
    
    return '';
  }
}

JavaScript の場合であれば、ログ出力したい値を直接ロガーに渡すのではなく、ログ出力したい値を返す「関数」を渡すようなラッパーを実装すれば、ロギングによる例外発生を防げるだろう。

// INFO ログを出力するロガーのラッパー関数
function infoLogWrap(fn) {
  try {
    const results = fn();  // 引数で受け取った関数を実行して値の配列を得る
    logger.info(...results);  // 配列を展開してログ出力する
  }
  catch(error) {
    logger.error('ログ出力に失敗', error);
  }
}

// ↓ 呼び出し元となるコード

// ログ出力したい値を配列で返す関数を作り、それをラッパー関数の引数に与える
infoLogWrap( () => [errorObj.details.statusCode, convertValues(myValues)] );

// 分かりやすく書くなら以下と同義
const myFn = () => {
  return [
    errorObj.details.statusCode,
    convertValues(myValues)
  ];
};
infoLogWrap(myFn);

infoLogWrap() 関数の呼び出し元は、関数を定義したまでで、まだ実行していない。実際に関数を実行して値を得るのは infoLogWrap() 関数の中、try / catch で囲まれている部分なので、errorObj に details プロパティがなかろうと、convertValues() 関数で問題が起ころうと、呼び出し元では例外が発生しない。代わりに「ログ出力に失敗」という用意しておいたエラーログが出ることになるが、コレを検知したらロギング処理をコード修正していけば良いだろう。

まとめ

• catch 句の中で例外が発生している可能性を疑う
• ロギングのための処理が例外を発生させている可能性を疑う

バグを見つける際の参考になれば。