三週間ぶんの実行記録を、日付順にまとめて読み返しておりました。どの日も緑でした。失敗の行が一つもありません。
喜ばしい並びのはずでした。ところが同じ検査を手元で素のまま呼んでみますと、違反が三件そのまま残っていたのです。手が止まりました。
検査そのものは正しく動いておりました。壊れていたのは、検査を呼び出している行の形のほうでした。ログを読みやすくしようとして足した | head -5 の一本が、失敗を持ち帰らなくしていたのです。
検査は、通ることではなく落ちることを先に確かめてから、無人に任せます。 その日以来、この一文を作業の前に置くようにしております。
緑だったのは、落ちられなくなっていたからでした
無人実行の記録は、たいてい「終了コードが 0 か否か」で色が決まります。ですから検査の中身がどれだけ厳密でも、呼び出し側が 0 を返してしまえば、記録の上では成功として積み上がっていきます。
厄介なのは、この壊れ方が出力を残すことです。ログには違反の行がきちんと書かれておりました。ただ、誰も落ちていないログを開いて読み返さないだけでした。無音で終わる不具合よりも、饒舌なまま気づかれない不具合のほうが、私には見つけにくかったのです。
私は個人開発で四つの技術サイトと二つの WordPress サイトを回しており、毎日の検査は Cowork のスケジュールに任せております。人が見ていない前提で組んだ仕組みだからこそ、「落ちる能力」そのものを疑う視点が抜けておりました。
終了コードが消える三つの経路
手元で一つずつ潰していきますと、消える場所は三つに絞れました。いずれも本番運用のスクリプトで自然に生まれる形で、書いている最中に手が止まる種類の落とし穴ではありません。
経路1 — パイプの右端が結果を上書きします
シェルはパイプラインの終了コードとして、いちばん右のコマンドの結果を返します。head も tee も、左側が何を返そうと自分は 0 で終わります。ログを整形する意図しかない一本が、判定そのものを差し替えてしまうのです。
経路2 — 関数内の local 宣言が代入結果を隠します
local out=$(cmd) と書きますと、$? に入るのは cmd の結果ではなく local 組み込みコマンドの結果になります。宣言は成功しますから、常に 0 です。関数へまとめた瞬間に生まれるので、動作を変えていないつもりの整理が原因になります。
経路3 — フォールバックの || が失敗を終わらせます
cmd || echo "failed" は「失敗したら知らせる」つもりの書き方ですが、echo が成功した時点で行全体は 0 になります。set -e を敷いていても、この行では止まりません。
どれも読みやすさや親切心から足したものでした。壊す意図のない一文字が、検査を無力にしていたのだと気づいたときは、しばらく言葉が出ませんでした。
手元で測った、書き方ごとの終了コード
推測で直しますと、また別の場所で同じことをします。ですから、わざと失敗する検査を一つ用意して、呼び出しの形だけを変えながら終了コードを記録しました。
# gate.py — 常に違反を報告して 1 で終わる、測定用のダミー検査
import sys
print("VIOLATION: 3 files failed", file=sys.stderr)
print("detail line 1")
print("detail line 2")
sys.exit(1)
これを Bash 5.1 から呼び分けた結果です。
| 呼び出しの書き方 | 終了コード | 無人運用での意味 |
python3 gate.py | 1 | 失敗が伝わります |
python3 gate.py 2>&1 | head -5 | 0 | 失敗が消えます |
python3 gate.py 2>&1 | tee run.log | 0 | 失敗が消えます |
set -o pipefail を敷いたうえで | tee run.log | 1 | 失敗が伝わります |
| tee run.log のあと ${PIPESTATUS[0]} を読む | 1 | 失敗が伝わります |
local out=$(python3 gate.py) | 0 | 失敗が消えます |
local out; out=$(python3 gate.py) | 1 | 失敗が伝わります |
python3 gate.py || echo "gate failed" | 0 | set -e でも止まりません |
事前の予想と逆だったのは、tee の行です。ログを残すための書き方であって出力を変えるつもりはありませんでしたから、終了コードにも触らないだろうと思い込んでおりました。tee はパイプラインの右端にいる、というただそれだけの理由で、左の失敗を上書きしていたのです。
local の一行が、関数の失敗を飲み込みます
三つのうち、いちばん見つけにくかったのが local でした。関数にまとめて読みやすくした結果として現れますので、リファクタリングの副作用として静かに入り込みます。
# 失敗が消える書き方
run_gate_bad() {
local out=$(python3 gate.py 2>&1) # $? は local の結果(常に 0)
return $?
}
run_gate_bad; echo "exit=$?" # → exit=0
# 失敗が伝わる書き方(宣言と代入を分けます)
run_gate_good() {
local out
out=$(python3 gate.py 2>&1) # $? は python3 の結果
return $?
}
run_gate_good; echo "exit=$?" # → exit=1
対処は、宣言と代入を二行に分けるだけです。shellcheck は SC2155 としてこの形を指摘してくれますので、検査スクリプトを書いた日に一度通しておくことを推奨します。私は検査を足すときだけ shellcheck を走らせる習慣にしております。すべてのシェルスクリプトに掛けようとして続かなかった経験があり、対象を絞ったほうが結局は長持ちするのかもしれません。
set -e を敷いても救われない場所
set -euo pipefail を先頭に置けば安心、と考えていた時期がありました。実際には、set -e が効かない文脈がいくつも残ります。
( set -e; python3 gate.py >/dev/null 2>&1; echo "ここには来ません" )
# → サブシェルは exit=1 で終わります(正しい挙動)
( set -e; python3 gate.py >/dev/null 2>&1 || echo "gate failed"; echo "ここに到達しました" )
# → "gate failed" と "ここに到達しました" の両方が出て、exit=0
|| の右側を書いた瞬間に、その行は「失敗を扱い終えた行」として扱われます。if の条件部や && の左辺でも同じです。つまり set -e は、失敗を握っていない行だけを守ってくれる仕組みなのだと理解し直しました。
握るならば、握ったあとで自分で落とす必要があります。
if ! python3 gate.py >/dev/null 2>&1; then
echo "gate failed" >&2
exit 1 # 握ったなら、自分で落とします
fi
毒入りサンプルを常設して、落ちることを毎回確かめます
原因が分かったあとも、私はしばらく落ち着きませんでした。三つの経路を潰したところで、次に足す一行がまた同じことをするかもしれないからです。
そこで考え方を変えました。検査が正しいかを人が読んで確かめるのではなく、検査が落ちられることを機械に毎回確かめさせるという方向です。
必要なものは二つだけでした。既知の違反を含む「毒入りサンプル」と、確実に通る「正常サンプル」です。この二つを固定で置いておき、検査を本番のファイルに向ける前に、必ずこの二つへ向けます。毒入りで落ちなければ、その日の検査結果はすべて無効として扱います。
# fixtures/bad.txt … 既知の違反を1つだけ含む固定ファイル
# fixtures/good.txt … 確実に通る固定ファイル
サンプルは意図的に最小にしております。中身を増やすと、検査の仕様が変わったときにサンプル側の保守が要りますし、「毒入りが落ちない理由」を切り分ける手間も増えるからです。
検査を検査する、40行ほどのハーネス
実際に常設しているものを、汎用の形に直して置いておきます。検査コマンドと二つのサンプルを受け取り、期待どおりの終了コードが返るかだけを見ます。
#!/usr/bin/env bash
# check_the_checker.sh — 検査そのものが「落ちられる」ことを確かめます
# 使い方: ./check_the_checker.sh <検査コマンド> <毒入りサンプル> <正常サンプル>
set -uo pipefail # -e は敢えて外します(自前で終了コードを判定するため)
GATE=${1:?検査コマンドを指定してください}
BAD=${2:?毒入りサンプルを指定してください}
GOOD=${3:?正常サンプルを指定してください}
fail=0
# 出力は捨てて、終了コードだけを取り出します。
# パイプを挟まないことが要点で、ここに head や tee を足すと測定側が壊れます。
run() {
"$GATE" "$1" >/dev/null 2>&1
echo $?
}
bad_code=$(run "$BAD")
good_code=$(run "$GOOD")
if [ "$bad_code" -eq 0 ]; then
echo "NG: 既知の違反サンプルで検査が落ちませんでした (exit=$bad_code)" >&2
fail=1
else
echo "OK: 違反サンプルで exit=$bad_code"
fi
if [ "$good_code" -ne 0 ]; then
echo "NG: 正常サンプルで検査が落ちました (exit=$good_code)" >&2
fail=1
else
echo "OK: 正常サンプルで exit=$good_code"
fi
exit "$fail"
健全な検査に向けますと、次のように通ります。
OK: 違反サンプルで exit=1
OK: 正常サンプルで exit=0
harness exit=0
そして、冒頭と同じ壊れ方をした検査に向けた場合です。ログを読みやすくするつもりで head を挟んだ、あの形を再現しました。
#!/usr/bin/env bash
# 壊れた検査の再現(ログ整形のつもりで head を足した版)
grep 'FORBIDDEN' "$1" | head -1
exit $? # head の終了コードを返してしまいます
NG: 既知の違反サンプルで検査が落ちませんでした (exit=0)
OK: 正常サンプルで exit=0
harness exit=1
三週間かけても気づけなかったものが、二つのサンプルで一発で出ました。私自身、この結果を見たときに肩の荷が下りた気持ちになりました。検査を疑うより先に検査対象を疑っていた自分の順序が、そもそも逆だったのだと感じています。
ハーネスを組み込む位置にも一つだけ癖があります。検査の直前ではなく、その日いちばん最初に走らせることです。検査の直前に置きますと、ハーネス自身の呼び出しが同じ壊れ方をしたときに共倒れになります。日の初めに単独で走らせ、落ちたらその日の自動処理を進めない、という順にしております。
いま引いている線引き
三つだけ決めております。
検査を呼ぶ行にはパイプを置かない、というのが一つめです。ログが読みにくくなるぶんは、検査側が自分で整形して出力すればよいのだと考え直しました。どうしてもパイプで受けたいときは set -o pipefail か ${PIPESTATUS[0]} を必ず添えます。
二つめは、失敗を || で握ったら、その場で自分で exit 1 する、というものです。握って何もしないことを、私は「握りつぶし」と呼んで避けるようにしております。
三つめが、毒入りサンプルの常設です。検査を新しく足した日には、まず毒入りを食べさせて、赤くなることを見てから本番へ向けます。
無人で回す仕組みは、失敗を報せてくれる限りにおいて手放せます。逆に言えば、報せる能力を失った瞬間に、その仕組みは動いているふりをしているだけの何かになります。同じ性質の見落としは定期実行の回数そのものにも起こりますので、以前に書いた無音で半分になっていた定期実行と、欠落を捕まえる突き合わせや、存在チェックが通っても書けない — 無人実行の前提を能力プローブで測るも併せてご覧いただけますと、輪郭がつかみやすいかと思います。
まずは、いま無人で走らせている検査を一つ選んで、既知の違反を含むファイルを一つだけ食べさせてみてください。赤くならなければ、その検査が積み上げてきた緑は、今日から数え直すことになります。私もそこから始めました。
長くなりましたが、最後までお読みくださりありがとうございました。