4日間、誰も気づかなかった停電の話 ― 承認から14時間31分後に本番サーバが再起動された理由と、期限が守っていなかった片側

前回（第45回）の最後に、私はこう予告しました。失敗が”静かになる”穴を三つ踏んだので、次は能動監視と失敗の一次トリアージに投資する、と。どちらも作りました。そして作った矢先に、その両方が同時に火を噴く事件が起きました。

正確に言うと、事件はもっと前に起きていて、4日3時間のあいだ、誰も気づいていなかっただけです。この記事は、その空白の4日間を掘り起こした記録と、掘った先で見つかった「もっと危ない性質」——止まっている間に溜まった作業が、復旧した瞬間に一斉に実行される——を塞ぐまでの話です。

この記事で分かること

停電で外付けHDDが外れると、systemd が暗黙に作った依存関係によってアプリが止まり、しかも復帰しても起こしてもらえないこと
178GB を動かさず 24MB だけ移すと、障害の構造ごと消えると分かった話（計測してから決める）
「承認から10分」という期限が守っていたのは片側だけで、キューの中で待つ時間には有効期限が無かったこと
その結果、承認済みの Apache 再起動が14時間31分後に、誰も見ていない時刻に実行された話

1. 予告どおり、失敗に名前をつける仕組みを作った

まず前回の宿題から。失敗の一次トリアージ（Layer 1）を maintenance_triage.py として実装しました。設計の芯は「LLM を一切使わない」ことです。

失敗の分類を賢くやろうとすると、つい「エラーメッセージを LLM に読ませて判断させる」に手が伸びます。しかしこの基盤は、実行結果を頭脳側に戻さない（plan-once / execute-fixed）という原則で作ってあります。サーバのログには外部から書き込める文字列がいくらでも混ざるので、それを LLM に食わせた瞬間、せっかく実行役から取り上げたシェルを、遠回りに返してしまうからです。

なので分類は、終了コードと正規表現だけの純関数でやります。実装したルールは、まさに前回踏んだ失敗そのものです。

R1: exit 100 かつ「リポジトリの素性が変わった」→ high（自動受理コマンドは出さない。人が確認しろ）
R2: exit≠100 かつ stderr に sudo: や「パスワードが必要です」→ caution（sudoers とカタログの版ズレ）
R3: dpkg/apt のロック競合 → benign（待って再実行で収束）

知らない型は無理に分類せず「未分類」で返し、人が外部AIに相談するための情報一式を出す。知らない失敗を「良性」と誤断しないのが要点です。人へ出す文言はすべて固定文字列で、stderr の生文字列は助言に混ぜません（混ぜると、それ自体が注入経路になります）。

この地味な部品が、この記事の最後で効いてきます。

2. 4日3時間、実行役は止まっていた

能動監視の方も作りました。60秒ごとにキューの滞留と各 executor の生死を見て、状態が変わったときだけ Nextcloud Talk に鳴らす見張り番です。デーモンにはせず systemd の timer から都度起動する形にしました。見張り番自身が無音で死んでも、次の60秒後に systemd が起こし直してくれるからです。守る対象と同じ壊れ方をしない、というのが設計条件でした。

配備して3分後、いきなり赤が出ました。

coordinator-maintenance=STUCK(llen=1,inactive)
coordinator-maintenance-read=HEALTHY(llen=0,inactive)

mars の実行役が両方とも inactive、しかも書き込みキューに仕事が1件溜まったまま。前回書いた「executor が無言で止まる」の、3回目の発生でした。

ここで journal を遡って、はじめて空白の長さを知ります。7月22日 07:16 から、7月26日 10:21 まで。4日と3時間、mars の実行役は止まっていて、私はそれに気づいていませんでした。

3. 犯人を二度、取り違えた

正直に書きます。原因究明で、私は二度間違えました。

最初にやったのは、こういう絞り込みです。

journalctl _PID=1 | grep coordinator

出てきたのは Stopping Coordinator maintenance executor... の一行。Stopping ということは正常停止だ、誰かが（何かが）明示的に止めたに違いない——そう考えて「needrestart あたりが再起動のついでに止めたのでは」という筋を立てました。もっともらしい。でも外れです。

間違いに気づいたのは、grep をやめてその時間帯のログを全部見たときでした。7月22日 07:16:21 から 22 にかけて、因果が一列に並んでいたのです。

usb 4-1: USB disconnect
blk_update_request: I/O error, dev sdd
JBD2: Aborting journal on device sdd1-8
EXT4-fs (sdd1): Remounting filesystem read-only
Stopping Coordinator maintenance executor...
Unmounting /home...

USB が外れ、I/Oエラーが出て、ファイルシステムのジャーナルが中断し、読み取り専用に落ちて、その結果として executor が停止させられ、/home がアンマウントされた。Stopping は原因ではなく結果でした。

同じ秒に、オンボードNIC（e1000e）と USB-LAN（ax88179）のリンクも同時に落ちています。つまり対向のスイッチも落電した＝短時間の停電。復電まで20〜30秒ほど。mars 本体はノートPCなので内蔵バッテリーで無停電でしたが、USB HDD の ACアダプタと LANスイッチは保護されていなかったわけです。

「狭い grep で早合点しない」。自分で何度も書いてきた規律を、自分で破りました。計測してから信じるとは、都合よく切り取った計測を信じることではありません。

4. なぜ、復帰しても起きてこなかったのか

ここが今回いちばん学びの大きかった部分です。HDD は 40秒ほどで再接続されています（デバイス名は sdc から sdd に変わりましたが、fstab は UUID 指定なので正しくマウントされる設計でした）。なのに executor は4日間、止まったままでした。

理由は、systemd が暗黙のうちに作っていた依存関係です。executor のユニットは作業ディレクトリと Python 仮想環境が /home/hogehoge/coordinator/ の下にありました。すると systemd は、明示的に書いていないのに、こう解釈します。

$ systemctl show -p RequiresMountsFor coordinator-maintenance.service
RequiresMountsFor=/home /var/tmp

「このサービスは /home がマウントされていないと動けない」。だから /home が落ちたとき、systemd は責任を持って executor を止めてくれました。ここまでは親切な挙動です。

問題は逆向きです。systemd は、マウントが復帰したときに、依存で止めたサービスを起こし直しません。止めるのは自動、起こすのは手動。この非対称が、4日3時間の正体でした。

5. 178GB は動かさない ― 24MB を移すだけで済んだ

対策としてまず思いつくのは UPS の導入です。あるいは /home を内蔵ディスクへ引っ越すこと。/home は 178GB 使っているので、どちらも大仕事です。

ここで、買う前に測りました。

$ du -sh /home/*
178G    /home/minidlna
 24M    /home/hogehoge/coordinator

178GB の中身はほぼ全部が DLNA のメディアファイルで、この基盤が使っているのはわずか 24MB でした。つまり、24MB を内蔵SSDへ移すだけで、executor は /home の障害と無関係になる。UPS も、178GB の引っ越しも要りません。

移設先は /opt/coordinator（内蔵SSD）にしました。合格判定は明快で、目的そのものを直接確かめます。

$ systemctl show -p RequiresMountsFor coordinator-maintenance.service
RequiresMountsFor=/var/tmp /opt/coordinator/maintenance

/home が消えました。もう外付けHDDが何回外れても、実行役は止まりません。

なお仮想環境はコピーせず作り直しています（パスが焼き込まれるため）。事前に pip freeze を取って突き合わせたら、実際の依存は3本で、私が記憶で挙げていたものより1本多かった。ここでも計測が勝ちました。

6. 二つの”嘘”

この過程で、計測そのものが嘘をつく例を二つ踏んだので記録しておきます。

ひとつ目。 移設のついでに、読み取り専用の executor へ ProtectHome=yes という安全設定を足しました。ホームディレクトリを見せなくする設定です。その状態でディスク使用量を見たら、こう返ってきました。

Filesystem      Size  Used Avail Use% Mounted on
tmpfs           1.6G   19M   2% /home

実体は /dev/sdd1 の 1.8TB・178GB 使用です。ProtectHome=yes は「アクセスを拒否する」のではなく空の tmpfs をかぶせるので、エラーにならずもっともらしい偽の数字が返る。監視や診断を担うプロセスにこれを付けると、ディスク逼迫を静かに見逃します。ProtectHome=read-only なら真の値が見えるので、そちらに変えました。

ふたつ目。 結果を集約する reaper が、実は嘘をついていました。実機のログにこう並んでいたのです。

01:22:16 pg update error: OperationalError('SSL connection has been closed unexpectedly')
01:22:18 reaped task_id=... -> done

データベースへの書き込みが失敗した2秒後に「done」と報告している。完了ログが try の外にあって、DB更新の成否を見ずに実行役の主張をそのまま写していたためです。しかも接続が一度死ぬと張り直す口が無く、69分間ずっと書き込みが失敗し続けていました。「実行はできたが、台帳に載っていない」という状態が、成功として記録されていたわけです。

リトライと再接続、それでも駄目なら退避キューへ、という耐久化を入れて、ログも pg=updated / pg=FAILED に分けました。「reaped（収穫した）」と名乗るのは、台帳に書けたときだけにしました。

7. 白眉 ― 14時間31分後に、本番の Apache が再起動された

さて、見張り番が検知した「溜まっていた1件」の正体です。調べて血の気が引きました。

それは 7月25日 19:51 に私が承認した svc.restart apache2 でした。公開サーバの Web サーバ再起動です。承認したものの実行役は止まっていたので、キューの中で眠り続けていた。そして 7月26日 10:22:12、executor を起こした瞬間に、それは実行されました。

承認: 2026-07-25 19:51 JST
実行: 2026-07-26 10:22:12 JST
経過: 14時間31分

この基盤には、書き込み操作に承認の有効期限10分を設けてあります（第43回で書いた「承認は二通目のメッセージで、期限は10分」の仕組みです）。それなのに、期限の約87倍を経過してから本番サーバが再起動された。

幸い深夜でアクセスは少なく、実害はありませんでした。でもこれは運が良かっただけです。無音停止には、二つ目の害があった——仕事が溜まることだけでなく、溜まった書き込みが、後で暴発すること。

8. 期限が守っていたのは「片側」だけだった

なぜ10分の期限をすり抜けたのか。実装を見て、設計の穴がはっきりしました。

承認から実行までは、二つの区間に分かれています。

区間A: 承認 → キューへ投入　… ここには10分の期限があった
区間B: キューで待つ → 実行　… ここには何の期限も無かった

10分ルールは「ユーザーが承認ボタンを押してから、システムが受け付けるまで」だけを守っていました。いったんキューに入ってしまえば、あとは誰かが拾うまで永久に有効。実行役が生きていれば数ミリ秒で消化されるので、この穴は見えていませんでした。実行役が4日間死んで、はじめて口を開けたわけです。

そこで区間Bにも対称の期限を入れました。設計判断は三つ。

基準時刻をどこから取るか。 データベースには投入時刻が記録されているので、実行役がそれを読めば済む——と思いきや、これは駄目でした。この基盤の実行役は意図的にデータベースのライブラリを積んでいません。公開サーバに置く部品なので、依存も通信経路も最小にするという初期からの制約です。DBを読ませたら、その設計を自分で壊すことになる。

なので、投入する側が投入時刻を荷物に添える方式にしました。実行役は受け取った数字と現在時刻を引き算するだけ。文字列の日時ではなく整数の秒にしたのは、解析に失敗する経路を作らないためです。ノード間の時計のズレでマイナスになったときは 0 に丸めます（ズレを理由に拒否しないため）。

期限を何秒にするか。 書き込みは 600秒——承認期限とわざと同じ値にしました。「承認から10分」と「投入から10分」を対称にすることで、ルールが説明しやすくなります。読み取りは 3600秒。読み取りは遅れても壊しませんが、画面側は180秒で待つのをやめるので、1時間も経った読み取りにはもう読み手がいない。誰も見ない仕事はしない方がいい。加えて、アクションごとに個別の秒数をカタログに書けるようにしました。

期限切れをどう扱うか。 実行せずに拒否し、拒否したことを必ず人に伝える。ここで第1節のトリアージが効きます。stale（滞留）という型を新設し、深刻度は caution にしました。high にしなかったのには理由があります。拒否そのものは設計どおりの正常動作ですし、その原因である「実行役が止まっている」ことは見張り番が独立に赤で鳴らしているので、ここも赤にすると同じ事故で赤が二重に出る。トリアージの役目は、その赤の裏側で「承認済みの仕事が実行されずに捨てられた」という、見張り番からは見えない事実を伝えることだと整理しました。

だから助言の文面も「すぐ再実行してください」ではなく、「まず停止の原因を確認してください。このタスクは実行されていません」にしてあります。

9. 同じ状況を作り直したら、今度は止まった

作ったら試します。ただし本番サーバの再起動で試すわけにはいかないので、読み取り専用レーンだけを使い、期限を一時的に60秒に下げて、あの日と同じ状況を圧縮再現しました。実行役を止める → 仕事を投入する → 待つ → 実行役を起こす。

実行役が止まっている間、荷物はキューの中で静止しています。中身を覗くと、投入時刻がちゃんと入っていました。

{
  "task_id": "mtask_40fcc9ab7abd",
  "action_id": "disk.usage",
  "params": {},
  "enqueued_at": 1785155371
}

この間、見張り番はこう鳴らし続けています。「実行役がいない」と「仕事が1件溜まっている」を同時に捉えているのが分かります。7月22日からの4日間、誰も見ていなかったのが、まさにこの状態でした。

coordinator-maintenance-read=DOWN(llen=1,inactive)

そして実行役を起こします。ここが、7月26日に Apache が再起動されたのと同じ瞬間です。

21:34:28 worker_maintenance v0.4.0 up node=mars ... queue=tasks:maintenance:mars:read
21:34:28 worker_maintenance executed action=disk.usage status=refused reason=stale exit=None

起動と拒否が同じ秒に並んでいます。復帰した瞬間に溜まっていた仕事を掴み、そのまま拒否した。データベースにも理由が数字つきで残りました。

status | reason |                        stderr
-------+--------+----------------------------------------------------------
failed | stale  | queued too long: age=297s > stale_max_sec=60s (mode=read)

そして Talk には、トリアージの文面が届きました。

[maint] mars / disk.usage → failed (status=refused exit=None dur=0.0s)
🟡 トリアージ[caution]: stale
キューでの滞留が許容時間を超えたため、実行せず拒否しました(古い指示の暴発を防止)。
→ executor が停止していた可能性が高いので、まず停止の原因と復旧を確認してください。
　 このタスクは実行されていません。

ただし、いちばん大事な確認はこれではありません。本当に実行されていないことです。「拒否しました」と表示することと、コマンドが走っていないことは別物なので、ログを数えました。

$ journalctl -u coordinator-maintenance-read --since "-5min" | grep -c "status=ok"
0

df は一度も走っていない。ここまで見て、合格としました。

もうひとつ、省いてはいけない確認があります。逆方向です。「拒否できた」だけを見て満足すると、何でもかんでも拒否する壊れ方——つまり保守機能が全部死んでいる状態——を「成功」と読み違えます。片付けたあとで普通の読み取りを投げ直し、こうなることまで見ました。

21:41:17 worker_maintenance executed action=mem.usage status=ok reason=None exit=0

10. おまけ ― 3箇所のうち2箇所だけ直して「合格」と言った話

最後に、自分の失敗をひとつ。

荷物に「投入時刻」を足したので、荷物の形を検査しているテストが落ちます。中身が正しいことを確認して、テストの期待値を更新しました。2箇所。全部通ったので、次へ進もうとしました。

ところが実機で走らせたら 1件 FAIL。荷物の形を検査しているテストは、3箇所あったのです。私は「そのテストは結果集約側のファイルにしかない」と思い込み、計画立案側のテストが同じ検査を持っていることを確かめませんでした。

これは以前にも同じ型で踏んでいます。「契約を変えたら、その契約を共有するテストを全部洗う」。思い込みで数えず、機械に数えさせるべきでした。

$ grep -rn 'set(p[a-z]*) == {"task_id"' test_*.py
# → 3件。全部が新しい形になっていることを確認する

ちなみにこのとき直したのは「期待値の更新」であって「チェックの緩和」ではありません。余計なキーが増えたら検出する力は残したままにしてあります。テストが落ちたときに、意図を確かめずに条件をゆるめると、次に本物の退行が来ても気づけなくなるからです。

11. まとめ ― 期限は、二つ要る

4日間の空白を掘り起こしたら、こういう連鎖でした。

停電で外付けHDDが外れる → systemd が暗黙の依存で実行役を止める → HDD は戻るが誰も起こさない → 4日3時間、仕事が溜まり続ける → 見張り番を入れた3分後に検知 → 承認済みの Apache 再起動が、承認から14時間半後に実行されていたと判明 → キューにも期限を入れる。

設計上の教訓を一行にすると、「いつまでに承認するか」の期限と、「いつまでなら実行してよいか」の期限は、別に要るということです。前者は人間の判断の鮮度を守り、後者は状況の鮮度を守る。私は前者だけを作って、両方を守った気になっていました。

そして構造の話。24MB を内蔵ディスクへ移すだけで、この障害の系譜そのものが消えました。UPS を買う前に du を叩いてよかった、というのが率直な感想です。対策の大きさは、問題の大きさではなく、測った結果から決める。

残っている宿題もあります。/home の 178GB は依然として外付けHDDの上にあり、この2か月で10回外れています。DLNA が困るだけとはいえ、ここは別途どうにかする予定です。

この記事は自作の家庭内分散AI基盤シリーズの第46回です。これまでの全記事はシリーズ索引からたどれます。