Murga

個人的に言いたいコト・主張・気持ち。

実例に見る、バグの原因を見つけるアイデア: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() 関数から見るとエラーは握り潰されているので、正常な結果ということで、空の文字列を受け取って終了するはずだたt.

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

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 で囲まれている部分なので、errorObjdetails プロパティがなかろうと、convertValues() 関数で問題が起ころうと、呼び出し元では例外が発生しない。代わりに「ログ出力に失敗」という用意しておいたエラーログが出ることになるが、コレを検知したらロギング処理をコード修正していけば良いだろう。

まとめ

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

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

ライト、ついてますか―問題発見の人間学

ライト、ついてますか―問題発見の人間学

エンジニアらしい Excel にしたかった

ニホンノエスイーは Excel を表計算ソフトとしてではなく、方眼紙として使用するのはよく知られた事情。モロにニホンノエスイーだった前職から転職した今も、方眼紙を作らされることはよくある。

現職ではご意見番の長老が幅を利かせていて、とにかく Excel で全ての資料を作らせてくる。彼が作らせる資料は、

  • 人間が目視で確認するための表であり、
  • 人間が目視でデータを比較しやすく、
  • 紙印刷して使いやすい

ことを目指しており、ひどくアナログなのだ。

要は「上の人間はこまけぇこたぁ分からん、パッと見で要旨が分かるようにせい」ということで、その視点は不要だとは思わない。上司に説明するための資料であれば、ペライチで言わんとすることが表現されている方が良いのは、まだ分かる。

でも今回作っているのは、開発者と運用担当が相互に用いる、細かなサーバ設定やソフトのパラメータを記すための資料なのだ。そもそも Excel なんかで作る必要はなく、設定情報を YAML や JSON なんかで出力させて diff とった方が良いのは明らかなのだが、Excel で作るにしても、

  • EXACT 関数で前回の値と比較するとか、
  • 条件付き書式で空欄や明らかな不正値を検出するとか、
  • データのインポートや表の整形などをマクロで実装しておく

とかして、Excel の機能を最大限使って、人間が目視でじっくりチェックせずとも異常が炙り出せるファイルを作った方が、運用しやすいし、間違いが減らせるだろう。

もちろん、人間が目で読むこともあるし、加筆修正は人間がするものだが、こうした機械によるダブルチェック機構も用意しておくことで、より人的ミスを防ぐ仕組みづくりができると思う。


ただ、仮にそのようなチェック関数やマクロを仕込んだ Excel ブックを作ったとしても、更新する人間が Excel の仕様を知らなかったり、そのブックにどのような関数が仕込まれているかを把握せずに手を加えてしまうと、途端にそのブックは壊されてしまう。

他人が作った Excel ブックを「壊す」人は、Excel を知った気になっていて、いくら丁寧に更新手順を書いていても正確には読めず、自己流のやり方で作業して、条件付き書式を壊してみたり、罫線を崩してみたり、チェック用の関数を消してみたり、行参照をズラしてみたりしてくる。

できるなら

  • 条件付き書式を使わない
  • 各行や各列に計算用セルが必要になる作り方にしない
  • 実線と点線を組み合わせるような複雑な罫線の使い方はしない (全部単純な実線で十分)

というような対策で、ブックを壊されても被害が少なくなる作りにしたいが、データの比較をしたいとか、集計したいとかなると、なかなか厳しい。

ならばと書式や数式を正しい状態に復元するような自己修復するブックのマクロを書こうと思うと、それこそ膨大なコストがかかるので、技術的には可能だとしても、そのような Excel は作り込まずに諦めてしまう。

こうして、デキる人は Excel に対する (というより Excel のリテラシが低い連中に対する) わだかまりを深めていき、Excel を方眼紙としてしか見ていないエンジニアごっこをしている連中はいつまでも同じ手作業を繰り返しては悦に入っていて成長しない状況が続くのだ。

「エンジニアたるもの、関数やマクロを使いこなして、全てを自動化しようではないか」と思っていたが、もう諦めた。

そういうゴリゴリに計算するような Excel は一人で作って持っておけばいいや。そんで、対外的にはバカどもに見せるバカ用の Excel を作って回すことにしよう。同じような資料を2つ作ることになるが、自分だけは楽に、間違いなく運用できる Excel を使うとしよう。

Excel 最強の教科書[完全版]――すぐに使えて、一生役立つ「成果を生み出す」超エクセル仕事術

Excel 最強の教科書[完全版]――すぐに使えて、一生役立つ「成果を生み出す」超エクセル仕事術