前に書いた記事 で、パイプが失敗を消す話をしました。処方として挙げたのは set -o pipefail です。
その処方を、自分のサイトのフロントマター検査に当てて、もう一度確かめ直しました。すると、効くはずの薬が、別の症状を起こす条件が見つかりました。
欠陥が 1 件もないリポジトリで、検査が赤になるのです。しかも、検査の中身は何も変えていません。変わったのは、出力の量だけでした。
パイプ越しの終了コードには、失敗を隠す向きと、成功を失敗に変える向きの 2 つの誤りがあります。 前者は有名ですが、後者は対象が増えた日に突然現れるので、気づきにくいと感じました。測った数字と、直した実行ラッパーの全文を残します。
検査スクリプトと、確かめた環境
対象は、個人開発で運営しているこのサイトの日本語記事 1,122 本の MDX です。フロントマターの level の綴り、slug のピリオド、highlights の未クォートのコロン。この 3 つを見ます。どれも、本番で 404 や 500 になる実害のある項目です。
最初に、検査スクリプトの全文です。
#!/usr/bin/env python3
"""MDX フロントマター検査。違反があれば 1 件ずつ出力し、終了コード 1 で終わる。
検査対象が 0 件のときは「何も見ていない緑」を避けるため、終了コード 2 で止める。"""
import re
import sys
import pathlib
LEVELS = { "beginner" , "intermediate" , "advanced" }
args = [a for a in sys.argv[ 1 :] if not a.startswith( "-" )]
verbose = "-v" in sys.argv
root = pathlib.Path(args[ 0 ])
files = sorted (root.rglob( "*.mdx" ))
if not files:
print ( f "NOFILES { root } " )
sys.exit( 2 )
bad = 0
for p in files:
text = p.read_text( encoding = "utf-8" )
m = re.match( r " ^ --- \n (. *? ) \n --- \n " , text, re.S)
if not m:
print ( f "NOFM { p } " )
bad += 1
continue
fm = m.group( 1 )
if verbose:
print ( f "OK { p } " )
lv = re.search( r ' ^ level: \s * " ? ([ a-z ] + ) " ? ' , fm, re.M)
if not lv or lv.group( 1 ) not in LEVELS :
print ( f "LEVEL { p } " )
bad += 1
sl = re.search( r ' ^ slug: \s * " ([ ^ " ] + ) "' , fm, re.M)
if sl and "." in sl.group( 1 ):
print ( f "SLUG { p } ( { sl.group( 1 ) } )" )
bad += 1
for h in re.findall( r ' ^ - ([ ^ " \n ][ ^ \n ] * : \s[ ^ \n ] * )$ ' , fm, re.M):
print ( f "COLON { p } ( { h[: 30 ] } )" )
bad += 1
print ( f "checked= { len (files) } violations= { bad } " )
sys.exit( 1 if bad else 0 )
終了コードは 3 種類です。違反があれば 1、対象のファイルが 1 本もなければ 2、問題なければ 0 です。
2 を足したのは、空のディレクトリを渡したときに「違反 0 件」で緑になってしまうからです。実際に空のディレクトリで走らせると、NOFILES と出て終了コード 2 で止まります。何も見ていない緑は、赤より危ないと考えています。
欠陥を 3 件入れて、五通りの呼び出しを比べました
実リポジトリは欠陥ゼロなので、そのままでは検査が赤になる場面を見られません。コピーしたディレクトリの 3 本に、わざと欠陥を入れました。level を intermediat に、slug の末尾に .v2 を、highlights の先頭に 手順: を足しています。
同じコピーに対して、呼び出し方だけを変えた結果が次の表です。
ここまでは、前の記事のとおりです。違反が 3 件あるのに tail -1 の末尾だけを見ると、緑が返ります。pipefail を付ければ 1 に戻ります。
私自身、これで一件落着だと思いました。そのまま pipefail を足した形を、別の呼び出しにも広げようとして、つまずきました。
pipefail が、通るはずの検査を赤にしました
検査が何を見たのか分かるように、ファイルごとに OK を 1 行ずつ出す -v を使います。その出力の先頭だけを確認したくて、head -1 に渡しました。欠陥のないリポジトリです。
( set -o pipefail ; python3 check_frontmatter.py corpus-clean -v | head -1 )
echo "rc= $? "
結果は終了コード 1 で、標準エラーには BrokenPipeError: [Errno 32] Broken pipe が出ていました。検査は成功しているのに、パイプ全体が失敗として報告されたわけです。
原因は、head -1 が 1 行読んだところで終わってしまうことでした。読み手がいなくなったパイプに Python が書き込もうとして、書き込みに失敗します。pipefail は、パイプの中のどれかが失敗した事実を、そのまま結果に載せます。
では、出力がどれくらいなら起きるのでしょうか。ファイルの本数を変えて、30 回ずつ数えました。欠陥は入れていません。
#!/usr/bin/env bash
# 出力量を変えながら、pipefail + head -1 が「正常な検査」を赤にする回数を数える。
# 事前に sweep/xN/ へ N 本の .mdx を置いておく(欠陥は入れない)。
for n in 100 103 104 106 300 1122 ; do
d = "sweep/x $n "
bytes = $( python3 check_frontmatter.py " $d " -v | wc -c )
red = 0
for i in $( seq 30 ); do
( set -o pipefail ; python3 check_frontmatter.py " $d " -v 2> /dev/null | head -1 > /dev/null ) || red = $(( red+1 ))
done
echo "files= $n output=${ bytes }B 赤= $red /30"
done
104 本の別の回は 30 回中 29 回(約 97%)でした。どちらにしても、ほぼ毎回赤になる水準です。
境目は、手元では 103 本と 104 本のあいだでした。Python の標準出力バッファは 8,192 B です。出力がそれを超えて複数回に分けて書かれるようになると、2 回目以降の書き込みが、先に終わった head に当たります。
検査の中身は 1 文字も変わっていないのに、対象が増えただけで、ある日を境に毎回赤になります。 出力の量でスイッチが入る誤検知は、検査そのものを疑っても原因に届きません。
境目の本数は、表示するパスの長さでも動きます。103 本の行が 0 回の日と 1 回の日があったとおり、境界付近は不安定です。手元の数字をそのまま基準にせず、「8 KB 前後に境目がある」という形で覚えておくのが安全だと思います。
同じことは grep -q でも起きました。grep -q は一致を見つけると読むのをやめるので、前段の検査が同じように書き込みに失敗します。300 本以上の出力では、40 回中 40 回が赤でした。
終了コードは 1 つに決まりません
赤になったときの値は、環境によって変わりました。
1、120、141 のどれが返っても、「検査が失敗した」とは読めません。読めるのは「パイプのどこかが非ゼロだった」までです。値の違いから原因を当てにいくのは、割に合わないと感じました。対処としては、パイプを使わない形に寄せるのが確実でした。
直した形は、ファイルに落としてから表示することでした
pipefail をやめるのではなく、判定にパイプを使わないことにしました。検査の出力をいったんファイルに書き、検査本体の終了コードを先に確定させてから、表示します。
#!/usr/bin/env bash
# 検査コマンドの出力を一度ファイルに落とし、終了コードを先に確定してから表示する。
# 使い方: run_gate.sh <ログ名> -- <コマンド...>
set -u
name = " $1 " ; shift ; [ " ${1 :- } " = "--" ] && shift
log = "${ GATE_LOG_DIR :- $HOME / . gate-logs }/${ name }.log"
mkdir -p "$( dirname " $log ")"
" $@ " > " $log " 2>&1
rc = $? # ← パイプを挟まないので、ここが検査本体の値そのもの
echo "[gate: $name ] rc= $rc lines=$( wc -l < " $log ")"
tail -n "${ GATE_TAIL :- 5 }" " $log " # 表示用の tail は終了コードに影響しない
exit " $rc "
仕組みは単純です。検査本体は、パイプの左側ではなく、ファイルへのリダイレクトで走ります。rc=$? が受け取る値は、検査の終了コードそのものです。表示に使う tail は、その後に別のコマンドとして走るだけです。
同じコピーと、同じ検査で確かめた結果です。
head -1 で 30 回中 30 回赤だった出力量でも、ラッパー越しなら 10 回とも 0 でした。
もうひとつ、1 行目に rc= を出すようにしています。呼び出し側が出力の末尾しか読まない場合でも、画面の頭に終了コードが残るようにするためです。末尾の tail が見せる行数は、環境変数で変えられます。
赤になれることを、カナリアで確かめます
終了コードの扱いを直しても、検査そのものが壊れていれば、緑は何も保証しません。前にフックが読み込まれているのに一度も動かなかった症状 を扱ったとき、「動いている」ことは「動いた痕跡」でしか確かめられないと実感しました。検査にも同じ考え方を当てはめます。
既知の不良を 1 件だけ置いたディレクトリに検査を走らせ、必ず非ゼロで返ることを確かめるスクリプトです。
#!/usr/bin/env bash
# 既知の不良 1 件を置き、検査が必ず赤になることを確かめる。赤にならなければ検査側が壊れている。
here = "$( cd "$( dirname " $0 ")" && pwd )"
./run_gate.sh canary -- python3 " $here /check_frontmatter.py" " $here /canary" > /dev/null
rc = $?
if [ " $rc " -eq 0 ]; then echo "CANARY BROKEN: 不良を置いたのに rc=0" ; exit 2 ; fi
echo "canary ok (rc= $rc )"
canary/bad.mdx には、level が不正で、slug にピリオドがあるファイルを 1 本だけ置いています。手元では canary ok (rc=1) と出て、ログには違反が 2 件記録されました。
このカナリアは、検査を足すたびに一緒に増やします。検査の正規表現を直したときに、何も検出しなくなる事故を、直した直後に気づけるからです。
落とし穴
ラッパーに set -e や pipefail を足さないでください。 rc=$? に届く前にスクリプトが終わり、1 行目の rc= が出なくなります。ラッパーは、検査の結果を受け取る側に徹するほうが安定しました。
ログは同じ名前で上書きされます。 同じ検査を並行して走らせるときは、名前に実行ごとの値を足してください。私は、読み違えを避けるために、並行で走らせる検査には別の名前を付けています。
標準エラーも同じファイルに混ぜています。 検査の診断メッセージが 1 本のログに集まるので、あとから読みやすくなります。一方で、標準出力だけを後段に渡したい用途には向きません。
終了コードを読み分けようとしないことです。 1、120、141 の違いに意味を探すより、パイプを使わない形に寄せたほうが、確かめる回数が減りました。
私の運用ルール
この検証から、次の 3 つを守ることにしました。個人的には、検査を足す前の最初の確認として推奨します。
検査の判定には、パイプを使いません。ファイルに落としてから rc=$? を取ります。表示にだけ tail を使います。
検査を足すときは、カナリアを 1 本一緒に置きます。「既知の不良で赤になる」ことを、検査と同じ場所に残します。
対象が 0 件の緑を許しません。見るものがなければ、終了コード 2 で止めます。
次に検査スクリプトを足すときは、まず存在しない欠陥を 1 件置いて、赤になるかを確かめてみてください。緑の数を増やすより先に、緑が信じられる状態にしておくほうが、結局は手間が少なくなります。
同じところでつまずく方が少しでも減れば幸いです。最後までお読みいただき、ありがとうございました。