カイワレの大冒険 Third

技術的なことや他愛もないことをたまに書いてます

定期実行スクリプトの綺麗なロギング3選

オリンピックの流れに乗れてない@masudaKです。

職業柄かちょくちょくスクリプトを書くことはあるのですが、やはり色々自分で書いたり人のを見たりしてるうちに、この実行履歴綺麗だなーと思うことが多々あります。

今回は、そう思える対象のなかでも、「定期実行スクリプト」の「出力」を扱ってみたいと思います。

「定期実行スクリプト」というのは、バッチ処理だったり、何か必要に応じて叩かれるスクリプトで、具体的にはバックアップとか集計とか、一日に最低一回は叩かれるようなスクリプトです。cronやJenkinsで叩かれるような類ですかね。そのようなスクリプトの「出力」について書いてみたいと思います。

出力は標準出力であれば、tailfコマンドだったり、Jenkinsのビルドのコンソール出力で見られるようなもの。ロギングされてるのであれば、それと同様に追えるようなものとします。

以下に書くのはあくまで今の僕の個人的な見解で、一年後変わってるかもしれないし、もっといい方法があるかもしれないので、ご指摘・コメントは是非。

1. ログの冒頭

まずはログの冒頭から。出だしなのですごーく大事でございます。すごく重要なので、いつ、どのスクリプトが、どのようにして叩かれたかが分かるようにするのがいいかなと思います。
例えばこんな感じ。

[2012/08/12_04:02:04] --------------------------------------------------------------
[2012/08/12_04:02:05] /usr/local/bin/test_script.sh is started.
[2012/08/12_04:02:08] --------------------------------------------------------------

何時に実行されているかを明確にするのと、記号を使って見やすくしておきます。記号はハイフンでも、イコールでもシャープでも一貫していれば、何でもよいでしょう。

ログファイルも実行ごとに違うファイルを作成するならファイルのパスが変わるので区別しやすいですが、1日に1ファイルとかの場合は、区切りをすぐ分かるようにしておきましょう。

日付を記録しておけばgrepできたりするので大きな問題にならないかもしれませんが、最初の実行と次の実行の区切りがわかりづらいのは困りものですので。

もう少し情報を加えるとするなら、

User:    test_user
Options: /usr/local/bin/test_script.sh -g B

こんな感じで実行ユーザやオプションも書いておくとなおよいでしょう。
bashだったら、

declare -x NOW='$( date '+%Y/%m/%d_%H:%M:%S' )'

function logger()
{
    [[ "$#" -ne 1 ]] && echo "${FUNCNAME} 'an argment insufficiency'" && return 1
    local _msg="${1}"
    eval 'echo "[${NOW}] ${_msg}"' 2>&1 | tee -a "${LOG_FILE}"
}

としておけば使い回しもできるでしょう。 Pythonだと、
Python標準ライブライリを使い倒す(logging編) - HDEラボ
みたいに標準ライブラリでできるので、loggingモジュール使えばよいでしょう。

LLやフレームワークはこういうのが整っているので楽ですよね。

2. 今何が行われているかを記録する

冒頭に必要な情報を記録しましたが、それだけだとやはり不十分でしょう。次に、今何が実行されているかわからないとどこまで進んでいるのか分からないということになってしまいます。

たとえば、

    umount_dir "${TARGET_DIR}"

という関数があったとして、対象ディレクトリをumountする関数があったとします。んで、その関数のなかではディレクトリの有無を確認して、あればumountするとする。

ざっくりですが、こんな感じ。

function unmount_dir()
{
    [[ "$#" -ne 1 ]] && echo "${FUNCNAME} 'an argment insufficiency'" && return 1
    local _target_dir="${1}"

    is_exist_dir "${_target_dir}"

    eval 'umount "${_target_dir}"'

    local _cmd_exit_status=$?
    if [ "${_cmd_exit_status}" -eq 0 ]; then
        logger "Success: unmounted directory. [target: ${_target_dir}]"
        return 0
    else
        err_msg "Error: cannot unmount directory!!! [target: ${_target_dir}]"
        return 1
    fi
}

これで、umount_dirを呼ぶわけですが、重要なのは、その実行前にもちゃんと「こういうことをこれから行います」と出力しておくことです。

logger "------------"
logger "Unmount ${TARGET_DIR} is started."
logger "------------"
umount_dir "${TARGET_DIR}"

一例ですが、こんな感じ。

対象の関数では、成功しようが失敗しようが、こうなりましたと出力をしてくれるので、結果は出力されてすぐ分かるのですが、今何されているか分からないと、どこまで進んでいるか分からないことになります。

よくありますが、umountできないディレクトリってあったりして、そこで止まってるのに、この関数は実行され続けている。そういうときにJenkinsのコンソール出力見てもどこで止まっているかわからないとか、ログ直接見てもどこまで進んでいるか分からないとか、そういうケースが起きかねません。

そういうケースではないにしても、実行時間が長いような関数でも同じケースになるでしょう。でかいディレクトリをコピーとか転送とか時間かかりますからね(途中経過をverboseで出せて、情報量も適度であればよいかもしれません)。

作っているのが自分で、自分しかそこを管理せず、そのスクリプト失敗しようが自分しか面倒みないならよいのかもしれませんが、半年後の自分が見て分からないとか、引き継いだけど後任の人が分からないとか色々あり得るので。

3. ロギングするもの

最後は、何を出力するのかを。僕なんかはスクリプト書いてると、面倒だったり、デバッグ用に自分で分かるものをどんどん出力したりしてしまいます。そうすると、今何が行われていて、何がどうなったか一切わからなくなったりしてしまいます。

なので、そのスクリプトのログを見る人は何をするときにログを見るのか、コマンド・関数実行前とあとでどう変わったのかが分かるようにロギングしましょう。

たいていログを追うときというのは、障害対応だったり、問題があったときなので、そのときにここは成功していて、ここは何が原因で失敗したなというように綺麗に出せるようにするのが一番いいと思います。
(ただ、言語によっては放っておくと、スタックトレースを山ほど出してくれる場合もあるので、ハンドリング頑張るしかないかなぁと)

終わりに

スクリプトなんて、半年ぐらい前のを見ると、いつも後悔の念に晒されて、なんでこんな風に書いたんだろうととか思うのが常なので、多分ここに書いてあることも半年後にはもっと違うことになってるかもしれません。

ただ、プロジェクトに関わる以上、自分以外の人が見るケースも増えるでしょうし、やっておいて損はないでしょう。言語によって変わるようなものでもないでしょうし。もちろん出力する以前に、例外をちゃんと拾えていないとか、スパゲッティになってるとか、そういうことをまず整えるのが重要かとは思いますが、出力されるものもまた重要ですので。

ということで、自戒の意味も込めて、書いてみました。 頑張らんとですな。