朝、壁紙アプリ用のカテゴリ未設定の画像フォルダを何気なく開いて、手が止まりました。数が明らかに多いのです。
そのフォルダは、1日2回動く分類ジョブが毎回きれいに空にしてくれているはずでした。実行ログを遡っても、並んでいるのは成功の行ばかりです。エラーは1件もありません。
原因はジョブの中身ではありませんでした。1日2回動くはずのジョブが、実際には1回しか発火していなかったのです。しかも、その事実はどのログにも書かれていませんでした。
気づいたのは、ログではなく溜まった側からでした
指定していたのは 30 4,16 * * * という式でした。4時半と16時半の2回。カンマ区切りで複数のスロットを1つの式にまとめる、ごく普通の書き方です。
ところが実際に発火していたのは、朝の1回だけでした。夕方の枠は、静かに存在しないままだったのです。
厄介なのは、この状態が「壊れているように見えない」ことです。動いた回はきちんと最後まで走り、成功で終わっています。ジョブ自体はどこも壊れていません。壊れていたのは、動く回数のほうでした。
私が気づけたのは、監視の仕組みがあったからではなく、たまたま未処理フォルダを目視したからです。運用を仕組みで支えているつもりで、実際には自分の目に頼っていたわけです。ここは正直に書いておきたい部分でした。
「実行されなかった回」はログに現れません
冷静に考えれば当たり前なのですが、しばらく腑に落ちませんでした。
ログは「起きたこと」の記録です。実行されなかった回には、書き手がいません。ですから成功ログをいくら丁寧に眺めても、そこには欠落が写らないのです。
| 見ているもの | 検出できること | 見逃すこと |
| 実行ログの成功/失敗 | 走った回が途中で落ちたか | そもそも走らなかった回 |
| 最終実行時刻 | 完全に止まったこと | 2回のうち1回だけ動いている状態 |
| ジョブの実行時間 | 処理の重さの変化 | 1回あたりは正常なので変化なし |
| 期待スロットとの突き合わせ | 欠落した回の日時 | スロット定義そのものの誤り |
| 未処理件数の傾き | 供給に処理が追いついていない期間 | 供給側も同時に減っている場合 |
上の2行だけで運用していると、半分だけ動いている状態は無期限に続きます。私の場合、次の更新まで気づかないままでした。
式は正しく、式を読む側が同じとは限りませんでした
ここが、この件で一番学びになった部分です。
30 4,16 * * * は cron の文法として正しく、標準的な cron であれば1日2回発火します。式に誤りはありません。にもかかわらず、私が使っていたスケジューラでは片方しか動きませんでした。
つまり「式が正しいこと」と「式を解釈する側が仕様どおりに振る舞うこと」は別の話です。私はこの2つを暗黙に同じものとして扱っていました。ドキュメントに cron 形式と書いてあれば、cron の仕様どおりに動くと思い込んでいたわけです。
同じ落とし穴は、モバイルアプリの周辺にもいくつもあります。CI のスケジュール実行、ストア用アセットの定期生成、サーバー側の集計バッチ。どれも「cron 形式で書けます」とだけ書かれていて、複数スロットや秒フィールドの扱いまで明記されていないことは珍しくありません。
そして、この手の差異は書いた当日には現れません。翌日以降、静かに半分だけ動く形で現れます。
発火を実測する: 期待スロットと実行記録の突き合わせ
対策の一つ目は、ジョブ自身に発火を記録させて、期待している時刻と突き合わせることです。
やることは単純で、ジョブの先頭で台帳に1行追記するだけです。JSON Lines にしておくと、後から機械的に読めて扱いが楽になります。
// ジョブの先頭で1行追記する(成功・失敗に関係なく必ず書く)
import { appendFileSync } from "node:fs";
function stamp(processed = 0, status = "started") {
const now = new Date();
const jst = new Date(now.getTime() + 9 * 60 * 60 * 1000);
const row = {
date: jst.toISOString().slice(0, 10),
at: jst.toISOString().slice(11, 16), // "04:31"
processed,
status,
};
appendFileSync("ledger.jsonl", JSON.stringify(row) + "\n");
}
status を書いていますが、この仕組みの本体は status ではありません。行が存在するかどうかです。ジョブが落ちても行は残りますし、ジョブが起動しなければ行は生まれません。それが欲しかった情報でした。
突き合わせる側は次のようになります。
// ledger.mjs — 期待発火スロットと実行記録を突き合わせる
// 使い方: node ledger.mjs ledger.jsonl 2026-08-10 2026-08-23
import { readFileSync } from "node:fs";
const SLOTS = ["04:30", "16:30"]; // 1日に発火すべき時刻(JST)
const TOLERANCE_MIN = 20; // 遅延の許容幅
const toMin = (hhmm) => {
const [h, m] = hhmm.split(":").map(Number);
return h * 60 + m;
};
function loadLedger(path) {
const rows = [];
for (const line of readFileSync(path, "utf8").split("\n")) {
const s = line.trim();
if (!s) continue;
try {
const r = JSON.parse(s);
if (r.date && r.at) rows.push(r);
} catch {
// 壊れた行があっても集計を止めない(欠落検出のほうが優先)
}
}
return rows;
}
function eachDate(from, to) {
const out = [];
for (
let d = new Date(`${from}T00:00:00Z`);
d <= new Date(`${to}T00:00:00Z`);
d.setUTCDate(d.getUTCDate() + 1)
) {
out.push(d.toISOString().slice(0, 10));
}
return out;
}
export function audit(path, from, to) {
const rows = loadLedger(path);
const byDate = new Map();
for (const r of rows) {
if (!byDate.has(r.date)) byDate.set(r.date, []);
byDate.get(r.date).push(r);
}
const missing = [];
let expected = 0;
let matched = 0;
for (const date of eachDate(from, to)) {
const runs = byDate.get(date) ?? [];
for (const slot of SLOTS) {
expected += 1;
const hit = runs.find(
(r) => Math.abs(toMin(r.at) - toMin(slot)) <= TOLERANCE_MIN
);
if (hit) matched += 1;
else missing.push({ date, slot });
}
}
return { expected, matched, missing, coverage: matched / expected };
}
const [, , path, from, to] = process.argv;
const r = audit(path, from, to);
console.log(
`期待 ${r.expected} 回 / 実行 ${r.matched} 回 / 充足率 ${(r.coverage * 100).toFixed(1)}%`
);
console.log(
`欠落 ${r.missing.length} 回:`,
r.missing.slice(0, 5).map((m) => `${m.date} ${m.slot}`).join(", "),
r.missing.length > 5 ? "…" : ""
);
process.exitCode = r.missing.length === 0 ? 0 : 1;
事故のかたちをそのまま台帳に落として流すと、こう出ます(Node.js v22 での実行結果です)。
期待 28 回 / 実行 14 回 / 充足率 50.0%
欠落 14 回: 2026-08-10 16:30, 2026-08-11 16:30, 2026-08-12 16:30, 2026-08-13 16:30, 2026-08-14 16:30 …
exit=1
充足率 50.0%。数字で見ると身も蓋もありませんが、成功ログを14行眺めても決して出てこない数字です。
意図的に入れた実装上の判断が3つあります。
1つ目は、許容幅を20分取っていることです。スケジューラの発火は数分ずれます。厳密一致にすると、正常な回まで欠落として拾ってしまいます。
2つ目は、壊れた行を読み飛ばして集計を続けることです。台帳が1行壊れたせいで欠落検出そのものが止まるのは、本末転倒でした。
3つ目は、欠落があるときに終了コードを1にしていることです。この1行があるおかげで、既存の通知の仕組みにそのまま乗せられます。判定を人間が読む前提にすると、結局また見落とします。
台帳そのものの運用にも注意点があります。追記は1行を丸ごと書く形に固定して、複数のジョブが同じファイルへ同時に書き込む構成は避けました。行が途中で混ざるとパースが崩れます。ファイルが際限なく育つのも困りますので、月ごとにファイルを分け、突き合わせのときだけ連結する形で回避しています。
本番運用でこの台帳が壊れると、欠落検出まで一緒に失われます。監視の側が新しい単一障害点にならないよう、書き込みは最小限に留めておくのが安全でした。
二つ目の番兵: 滞留の傾きを見る
台帳の突き合わせだけでは足りない場面があります。スロット定義そのものを間違えていたら、期待と実行はきれいに一致してしまうからです。
そこで、処理の側ではなく結果の側からも見ます。未処理の件数が減っているかどうかです。
// backlog.mjs — 未処理キューが減っているかを見る
// 成功ログが並んでいても、供給に処理が追いついていなければ滞留は増え続ける
import { readFileSync } from "node:fs";
const WINDOW = 7; // 直近7点で傾きを見る
const SLOPE_LIMIT = 0; // 1日あたりの増加がこれを超えたら異常
function slope(ys) {
const n = ys.length;
const xs = ys.map((_, i) => i);
const mx = xs.reduce((a, b) => a + b, 0) / n;
const my = ys.reduce((a, b) => a + b, 0) / n;
let num = 0;
let den = 0;
for (let i = 0; i < n; i++) {
num += (xs[i] - mx) * (ys[i] - my);
den += (xs[i] - mx) ** 2;
}
return den === 0 ? 0 : num / den;
}
export function checkBacklog(points) {
const recent = points.slice(-WINDOW);
const s = slope(recent.map((p) => p.pending));
return {
from: recent[0],
to: recent.at(-1),
slopePerDay: Number(s.toFixed(2)),
healthy: s <= SLOPE_LIMIT,
daysToDouble: s > 0 ? Math.ceil(recent.at(-1).pending / s) : null,
};
}
const points = JSON.parse(readFileSync(process.argv[2], "utf8"));
const r = checkBacklog(points);
console.log(`${r.from.date} pending=${r.from.pending} → ${r.to.date} pending=${r.to.pending}`);
console.log(
`傾き ${r.slopePerDay} 件/日 / 判定 ${r.healthy ? "OK" : "滞留増加"}` +
(r.daysToDouble ? ` / このペースで倍増まで ${r.daysToDouble} 日` : "")
);
process.exitCode = r.healthy ? 0 : 1;
1枠しか動いていない期間(供給が1日96件、処理が1日48件)の滞留を流すと、こうなります。
2026-08-17 pending=210 → 2026-08-23 pending=498
傾き 48 件/日 / 判定 滞留増加 / このペースで倍増まで 11 日
exit=1
枠を分けて2回とも動くようにした後の滞留は、こうです。
2026-08-24 pending=498 → 2026-08-30 pending=258
傾き -40 件/日 / 判定 OK
exit=0
数値そのものより、傾きの符号を見ていることのほうが本質です。件数の絶対値に閾値を置くと、供給が増えた日に誤検知しますし、逆に静かな滞留は閾値の下でいくらでも育ちます。減っているか増えているかで見ると、その両方を避けられました。
余談ですが、daysToDouble の行は自分向けの目安として足しました。「異常です」とだけ言われても着手の優先度が決まりません。11日と言われると動きます。
直したのは式ではなく、枠の持たせ方でした
復旧そのものは拍子抜けするほど簡単でした。30 4,16 * * * を1つ持つのをやめて、30 4 * * * と 30 16 * * * の2つに分けただけです。
4,16 という書き方は、人間にとっては「1つのジョブが2回動く」という自然な表現です。けれど運用の単位としては、朝の回と夕方の回は別の実行です。片方が落ちたときに片方だけ再実行したいのも、実行時間を後からずらしたいのも、枠ごとの都合です。
1つの式にまとめると、その枠ごとの都合を表現する場所がなくなります。今回の発火漏れがなかったとしても、分けておくほうが運用しやすかったのだと思っています。
似た判断は、生成パイプラインの側でも何度かしてきました。生成した壁紙カタログのハッシュが毎回変わる問題を切り分けたときも、まとめて1回で済ませていた処理を段階に割って、どこで揺れているかを見えるようにしています。分けると手数は増えますが、後から一部だけ触れるようになります。
個人開発で、どこまで作るか
ここまで書いておいて何ですが、監視を作り込むのは楽しくありません。作っても機能が増えるわけでもなく、収益が上がるわけでもありません。
それでも今回の2本を残したのは、コストの見積もりが合ったからです。台帳の追記が数行、突き合わせが50行ほど、滞留の傾きが30行ほど。合計しても1時間かからない分量でした。対して、気づかないまま半分の処理量で走り続けた期間は二週間です。
逆に、作らないと決めたものもあります。ジョブごとの実行時間の分布を取ることと、通知をリッチにすることです。前者は今回の事故と無関係でしたし、後者は終了コードで足りていました。
個人的には、監視を増やすより先に、監視しなくても壊れにくい形へ寄せるほうが効くと感じています。枠を分けたのはその一手でした。それでも構成上まとめざるを得ない場合は、台帳の突き合わせを先に置いてから進めています。
判断の基準にしているのは、**「その仕組みは、今回の事故を検出できたか」**という問いです。検出できないものは、どれだけ立派でも今は要りません。壁紙カタログの重複を知覚ハッシュの閾値を実測して決めたときも、同じ問いで範囲を絞りました。
手を動かすなら、ここから
今日できることを1つだけ挙げるなら、複数スロットを1つの式にまとめているジョブを探して、翌日に発火数を数えることです。
台帳の1行追記を今日入れておけば、明日には答えが出ます。カンマ区切りが手元の環境で本当に2回発火しているのか、確かめないまま動かしているジョブは、案外あるかもしれません。
私自身、まだ全部を確かめきれてはいません。同じところで足を止めた方の手がかりになれば嬉しいです。お読みいただき、ありがとうございました。