引き算したらバッチが死んでいた話

引き算したらバッチが死んでいた話:

こんにちは yoichi22 です。ある日深夜のオフィスにて夜間メンテナンスの間に待ち時間が出来たので、数日前にリカバリしたバッチサーバーのログを眺めていると、起動しては処理本体を実行せず即座に終了してを繰り返していることに気づきぞっとしました。冗長構成のバッチサーバーの待機系だったので幸い外部影響はありませんでしたが、エラー発生時に飛ぶはずのメール通知が機能していない状況でした。もし稼働系の障害まで気付かないままだったら悲しき事態になってたこの事象、何故起こったのでしょうか。

crontab からの通知

対象のバッチは crontab で実行制御しています。crontab からバッチが実行されると、失敗しようが成功しようが、標準出力もしくは標準エラー出力に何か書き込まれていると、バッチ終了時にメールで通知がされます。

普通のコマンドは失敗するとエラーメッセージを標準エラーに出力するので、バッチ内でエラー出力を捨てなければメールが通知されていたはずです。エラーメッセージは例えば

$ ls file > /dev/null 
ls: cannot access 'file': No such file or directory

といった感じに問題の内容を含んでいるので、どういう問題が起きているのか、どう対処したらいいかのヒントを与えてくれます。

しかし今回のケースではバッチ自体は失敗していたものの、cron経由でのメール通知はありませんでした。

バッチ内のエラー通知

問題になったバッチでは、バッチ自体の処理としてもエラー通知をする仕組みが入っていました。

#!/bin/bash 
 
start=$(date +%s) 
MAILTO=foo@example.com 
 
function notify_and_exit() { 
    end=$(date +%s) 
    elapsed=$(expr $end - $start) 
    /usr/sbin/sendmail -t << EOF 
To: $MAILTO 
Subject: batch failed (elapsed ${elapsed} sec) 
 
$2 
EOF 
    exit $1 
}

このようにユーティリティ関数を定義したスクリプト util.sh をインポートし、エラー発生時に呼び出すように記述しておくことでエラーメールが送信されます。今回の場合、notify_and_exitを呼び出す直前に別途ログファイルに記録する処理がありそちらには出力されていたものの、エラーメールは送信されていませんでした。

調査

ログファイルに残っていた記録から、バッチの多重起動を抑止するためのファイルが残存していたためにエラー終了するパスに入っていることはすぐにわかり、手元の環境でも再現できたのですが、何故エラーメールが送信されなかったのかが一瞬ではわからなかったので調べました。

バッチの要点を抜き出すと以下のようなものです：

#!/bin/bash 
 
set -e 
 
. util.sh 
 
if [ -f "batch.lock" ]; then 
    echo “lock file exists" 
    notify_and_exit 2 "error occurred" 
fi 
 
echo "success"

再現させてみましょう。

$ touch batch.lock 
$ bash batch.sh 
lock file exists 
$ echo $? 
1

エラーが再現しています。そして指定したエラーコード2ではなく、1が返却されています。デバッグのため -x オプションをつけてトレースしてみましょう。

$ bash -x batch.sh 
+ set -e 
+ . util.sh 
+++ date +%s 
++ start=1540814067 
++ MAILTO=foo@example.com 
+ '[' -f batch.lock ']' 
+ echo 'lock file exists' 
lock file exists 
+ notify_and_exit 2 'error occurred' 
++ date +%s 
+ end=1540814067 
++ expr 1540814067 - 1540814067 
+ elapsed=0

expr の引数を評価した結果が 0 になっています。 expr のマニュアルを見ると書いてあるのですが、このように評価結果が 0 になると expr は黙って 1 を返します（一方で表現が不正な場合は 2 を返します）。これが set -e の効果によりエラーと判定されて、エラー終了していたというのが不具合の原因でした。

修正は、expr を使わずにシェル算術式 elapsed=$(($end - $start))を使うという対処をしました。

まとめ

エラーが起きてるのに通知ができていないという不具合についてふりかえりました。まとめると

• expr の戻り値には注意。 set -e と組み合わせるとわかりにくい動作を招く
• 異常系の処理の中でさらに異常が起きると辛い

ということです。エラーを見逃すよりは異常時に冗長な通知が来たほうがマシなので、crontab で || echo fail としておき、黙って失敗した場合にもエラーメールを飛ぶようにしておけばよかったのかもしれません。

オリジナルのエンクロージャ: