自動化が「成功」と嘘をつくとき｜終了コードが当てにならない話

自動化が「成功」と嘘をつくとき｜終了コードが当てにならない話 定期実行と通知

自動化を毎日動かしていると、こういう状態がいちばん危険です。

処理は失敗しているのに、機械は「成功」と記録している。

結論から書きます。スクリプトの途中に |（パイプ）や tee を挟むと、中で何が失敗しても全体の結果は「成功」になります。 直し方は1行、set -o pipefail を足すだけです。

「動いていない」は、まだ気づけます。日付が古いままだからです。「成功と書いてあるのに中身が失敗」は、探しに行かない限り一生見つかりません。

なぜ「成功」と記録されるのか

プログラムは終わるときに終了コードという数字を返します。0が成功、0以外が失敗です。launchd（macOSの定期実行の仕組み）は、この数字だけを見て「うまくいったかどうか」を覚えています。

問題は、パイプでつないだときの決まりごとです。

パイプでつないだ一連の処理の終了コードは、いちばん右のコマンドの終了コードになります。

つまりこう書くと、

集計.py | tee 記録.log

返ってくるのは tee の結果です。tee は「受け取った文字をファイルにも画面にも出す」だけの道具なので、中身がエラーメッセージだろうが、受け取って書き出せた時点で成功（0）を返します。

左の集計が途中で落ちていても、右の tee は仕事を果たしています。だから全体は0。launchdには「正常終了」と記録されます。

自分のMacで1分で確かめる

ターミナルにそのまま貼って動かせます。何も壊しません。

zsh -c 'sh -c "exit 9" | tee /dev/null >/dev/null; echo "pipefailなし → $?"'
zsh -c 'set -o pipefail; sh -c "exit 9" | tee /dev/null >/dev/null; echo "pipefailあり → $?"'

exit 9 は「失敗しました」とはっきり言っている処理です。それでも1行目は 0、2行目は 9 と出ます。同じ失敗が、書き方ひとつで成功にも失敗にも見えるということです。

set -e を書いてあるから大丈夫、ではない

set -e は「失敗したらそこで止まる」という指定で、安全策としてよく紹介されます。ところがこれ、パイプの途中の失敗では止まりません。

理由は同じです。set -e が見るのは「その行の終了コード」で、パイプの行の終了コードは右端のものだからです。左で落ちても行としては0、よって止まらない。

set -e と set -o pipefail は、セットで初めて意味を持ちます。 片方だけだと、守れていると思い込んだ穴が残ります。

私のスクリプトは、先頭を必ずこの2行から始めるようにしています。

set -eu
set -o pipefail
  • -e … 失敗したらそこで止まる
  • -u … 中身が空の変数を使ったら止まる（打ち間違いの検出）
  • pipefail … パイプの途中の失敗も、全体の失敗として扱う

うちで実際にこの形になっている場所

記事を1本書かせるスクリプト（~/scripts/media/1本作る.sh）は、AIの出力を画面とログの両方に流すためにこう書いています。

"$CLAUDE" -p ... < /dev/null 2>&1 | tee "$LOG"

これは tee で受けている典型例です。 ここで pipefail が無ければ、AIが途中で力尽きても、予算上限で打ち切られても、全部「成功」で記録されます。翌朝ログには何も出ず、記事だけが増えていない。

別に動かしている旅行メディア側の毎日の運転スクリプトは、さらに危うい形をしています。処理全体を { } でくくって、まとめてログに流しているからです。

{
  echo "毎日運転を開始: $(date '+%Y-%m-%d %H:%M:%S')"
  記事を作る
  ...
  if [ -z "$NEW" ]; then
    echo "新しい記事の管理データを特定できませんでした"
    exit 1
  fi
  ...
} 2>&1 | tee "$LOG"

ここには注意点が2つあります。

  1. くくった中の exit 1 は、外まで届きません。 パイプにつないだ { } は別プロセスとして動くので、exit 1 はその中を抜けるだけです。
  2. その「中の失敗」を外に伝える唯一の道が pipefail です。

つまり、自分で「ここで止めろ」と書いた exit 1 ですら、pipefail が無ければ無視されます。 私はこの2本とも、先頭に set -o pipefail を入れてあります。

もうひとつの嘘：「最後まで来た＝成功」

パイプだけが原因ではありません。結果を見ずに次へ進んでしまう書き方も、同じ嘘をつきます。

正直に書きますが、うちの経理の月次スクリプトには、まだこの形が残っています。

python predict.py > "$OUT" 2>&1
# ここで結果を確かめていない
...
echo "[$(date '+%Y-%m-%d %H:%M')] 着地予想を保存・Slack投稿しました" >> 実行ログ.txt

2>&1 は「エラーメッセージも同じファイルに入れる」という意味です。便利なのですが、計算が失敗すると、エラーメッセージそのものが「結果ファイル」として保存されます。 そして次の行がそれをSlackに流し、最後の行が実行ログに「保存・投稿しました」と書いて、終了コード0で終わります。

Slackには何かが届く。ログには成功と書いてある。届いた中身がエラー文だと気づくのは、開いて読んだ人だけです。

直すならこうなります。

if ! ~/scripts/keiri/.venv/bin/python predict.py > "$OUT" 2>&1; then
  echo "[$(date '+%Y-%m-%d %H:%M')] ✖ 着地予想の計算に失敗" >> 実行ログ.txt
  exit 1
fi

if ! コマンド; then は「そのコマンドが失敗したら」という書き方です。 これだけで、成功と書く前に結果を確かめる形になります。

変数に入れるときも気をつける

結果を変数で受け取る書き方にも、同じ落とし穴があります。

# ⭕ これは大丈夫。$? はコマンドの結果になる
KEKKA=$(./投稿.sh --公開)
STATUS=$?

# ❌ これはだめ。$? は tail の結果になる
KEKKA=$(./投稿.sh --公開 | tail -1)
STATUS=$?

# ❌ これもだめ。local 自体の結果で上書きされる
local KEKKA=$(./投稿.sh --公開)

local（関数の中だけで使う変数の宣言）を付けると、終了コードは local の分になってしまいます。宣言と代入は分けて書きます。

local KEKKA
KEKKA=$(./投稿.sh --公開)

いま自分の自動化が安全か調べる

パイプでログを取っているのに pipefail を書いていないスクリプトを、まとめて洗い出せます。読むだけなので、実行しても何も変わりません。

grep -rl '| tee' ~/scripts --include='*.sh' | while read -r f; do
  grep -q 'pipefail' "$f" || echo "要注意: $f"
done

「要注意」と出たファイルが、失敗しても成功と記録される可能性のあるスクリプトです。先頭付近に set -o pipefail を1行足せば直ります。

1行足す前に、必ずコピーを取ってください。
cp ~/scripts/例.sh ~/scripts/例.sh.bak-$(date '+%Y%m%d-%H%M%S')

ひとつだけ副作用があります。pipefail を入れると、これまで黙って通っていた失敗が本当に止まるようになります。 特に grep は「1件も見つからなかった」だけで失敗を返すので、見つからなくて構わない場所では最後に || true を付けて「ここは失敗してよい」と明示します。

grep '合計' "$OUT" | tail -1 || true

終了コードだけを信用しない

ここまでで終了コードは正直になりますが、それでもまだ足りません。 終了コードが0でも、「やるべき仕事をしていない」ことはあり得るからです。

私は仕上げに、結果そのものを数えて確かめるようにしています。記事を書かせるスクリプトなら、実行の前後でファイルの数を比べます。

BEFORE=$(find "$記事の置き場" -maxdepth 1 -type f -name '*.html' | sort)
# ここで記事を書かせる
AFTER=$(find "$記事の置き場" -maxdepth 1 -type f -name '*.html' | sort)

NEW=$(comm -13 <(print -r -- "$BEFORE") <(print -r -- "$AFTER") | head -1)
if [ -z "$NEW" ]; then
  echo "記事が作られませんでした"
  exit 1
fi

「終了コードが0」ではなく「ファイルが1本増えた」を成功の定義にする。 これが実際にいちばん効きました。

公開のスクリプトも同じ考え方で、終了コードと出力の中身の両方を見ています。

KEKKA=$(./投稿.sh "$記事" --公開 --はい 2>&1)
STATUS=$?
if [ $STATUS -ne 0 ] || ! print -r -- "$KEKKA" | grep -q '✔'; then
  # 失敗として扱う
fi

終了コードが0でも、成功したときにしか出ないはずの印が出ていなければ失敗とみなします。二重に確かめるほうが、あとで悩む時間より安いです。

launchd側の設定でエラーの記録先を指定する方法は launchdが動かない・終了コード127の原因と対処 にまとめています。あちらは「0以外を見つける話」、この記事は「その0が嘘をついている話」です。

まとめ

  • パイプでつないだ処理の終了コードは、いちばん右のコマンドの結果になる
  • tee でログを取ると、中で失敗しても tee は成功するので全体は0（成功）になる
  • set -e だけでは守れない。 set -o pipefail とセットで書く
  • { } でくくってパイプに流すと、中の exit 1 は外に届かない。届かせるのも pipefail
  • 結果を確かめずに「成功」と記録しない。if ! コマンド; then で受ける
  • 変数に入れるときは local と代入を分ける。パイプを挟んだら $? は当てにならない
  • 仕上げは終了コードではなく、ファイルが増えたか・成功の印が出たかで判定する

自動化は、黙って止まるより笑顔で嘘をつくほうが厄介です。 まずは上の grep を1回流して、自分の ~/scripts に「要注意」が何本あるか見てみてください。1行足すだけで、記録が正直になります。

記録そのものの設計は 自動化が止まったときに気づくためのエラーログ設計 に書いています。次はそちらをどうぞ。

コメント

タイトルとURLをコピーしました