先週、死活監視のダッシュボードに🔴（停止）が3件並びました。夜間バッチ、メンテナンス処理、ニュース収集——朝いちばんに見た画面がこれでした。慌てて中身を確認すると、3件とも実体は正常に動いていました。原因はジョブ自体ではなく、数日前に入れた共通ロガーの小さな変更でした。
この記事は「cronやlaunchdの死活監視が誤検知する」「ログファイルが更新されない」と検索してたどり着いた方への実例です。結論から言うと、ログの更新時刻だけでジョブの生死を判定する設計は、ログの出力方式を変えただけで簡単に壊れます。私のmacOS環境では31個の定時ジョブをlaunchdで動かしており、各ジョブのログファイルのmtime(最終更新時刻)を見て、想定間隔より古ければ「停止」と判定する仕組みで死活監視をしています。
2日後の朝、正常に動いていた3つのジョブが「停止」と表示された
事の発端は、複数のジョブが共有しているロガーの初期化処理を棚卸ししたことでした。ターミナルなどのtty環境以外では標準出力へのログ出力をやめる、という変更を入れました。ログはファイルにも書いているので、標準出力を止めても実害はないと考えていました。
見落としていたのは、launchdのStandardOutPathにそのログファイルを指定しているジョブがあったことです。launchdはジョブの標準出力を指定ファイルへリダイレクトする仕組みで、多くのジョブがこの経路でログを残していました。標準出力へのログ出力を止めた結果、StandardOutPathの書き込み先だったファイルが更新されなくなりました。ジョブ自体は変更前とまったく同じように動いていたのに、ログだけが止まったのです。
変更から2日後の朝、死活監視が夜間バッチ・メンテナンス処理・ニュース収集の3ジョブを「停止」と判定しました。ログを見る前にジョブの実行結果を直接調べたところ、3件とも処理は完走していました。止まっていたのはジョブではなく、ログの更新だけでした。
放置していたら、翌朝には別の4ジョブも同じ理由で誤検知していた
厄介だったのは、この3件が偶然ではなく構造的な問題だったことです。共通ロガーを使うジョブは他にも複数あり、実行間隔がそれぞれ違うため、影響の出るタイミングがずれて現れていただけでした。棚卸しをせず放置していたら、翌朝には別の4ジョブが同じ理由で「停止」と誤判定される状態でした。3件で気づけたのは、むしろ運が良かった方だと思います。
ログの更新時刻は「生きている証拠」ではなく代理指標にすぎない
この一件で改めて認識したのは、ログの更新時刻はジョブが生きていることの直接の証拠ではなく、代理指標にすぎないという点です。代理指標は本体(ジョブの実行)と切り離されることがあります。今回は、ロガーという監視の外側にある部品を変更したことで、代理指標だけが本体から切り離されました。
代理指標が本体から外れる方向は2つあります。1つは、ジョブは生きているのにログが更新されない誤検知です。これが続くと、監視の通知は「まず疑う対象」から「まず無視する対象」に変わっていきます。オオカミ少年になった通知は、次に本物の停止が起きたときも見過ごされかねません。もう1つは逆に、ジョブは死んでいるのにログだけは更新され続ける見逃しです。こちらは通知そのものが上がらないため、気づくきっかけがなくなります。
直したのは、監視側のログ解決方法とロガーの出力先の2箇所
対処は2段階で行いました。まず監視側です。log_pathの設定をglobパターンに対応させ、マッチしたファイルのうちmtimeが最新の1件を監視対象として解決するようにしました。
import glob
import os
def resolve_log_path(pattern: str) -> str | None:
matches = glob.glob(pattern)
if not matches:
return None
return max(matches, key=os.path.getmtime)
次に、共通ロガーを使う8ジョブについて、監視対象をStandardOutPathではなく、日付付きのファイルハンドラ出力(*_????-??-??.logのような形式)へ向け直しました。ロガー側はもともとローテーション付きのファイル出力を持っていたので、監視対象をそちらに合わせるだけで済みました。全31ジョブでドライラン判定を実行し、🟢(正常)を確認しています。通知済みだった3件は、翌朝の自動実行でログが更新され、復旧扱いとして通知台帳から自動的に外れました。
そうは言っても、ログの中身を都度見ていれば気づけたのでは
反論としてありそうなのが「ログを毎回読んでいれば、更新が止まったことにもっと早く気づけたのでは」というものです。実際、夜間バッチのログを目視で確認する習慣は以前からありました。ただし目視確認は、気になったジョブを1日に数回、部分的にのぞく運用です。31個すべてのログを毎回突き合わせているわけではありません。ログのmtimeを機械的に判定する死活監視をわざわざ作ったのは、その目視の抜けを埋めるためでした。
今回のように監視の入力そのものが壊れているケースでは、目視を増やすことは根本的な対策になりません。目視は「見た人が気づいた分だけ」しか効きませんが、機械判定は「見なくても気づく」ためのものです。優先すべきは、目視を増やすことではなく、監視が読みに行く場所と、実際にジョブが書き込む場所を一致させ続けることだと考えています。
実際には起きなかった、もう一つの誤検知パターン
同じ週、別の変更をしていて、逆方向の落とし穴にも気づきました。15分ごとに動くポーリングジョブを新しく追加したときのことです。このジョブは条件を満たしたときだけ処理を行う設計で、何もしないことこそが正常な状態です。
このスクリプトを最初に書いたとき、既存の低頻度ジョブ(1日2回実行)と同じ内部ログファイルに書き込む実装にしていました。もしこのまま進めていたら、ポーリング側の「何もしなかった」というログが15分おきに書かれ続けるため、ログのmtimeは常に新しい状態になります。低頻度ジョブの方が本当に死んでいても、監視は永久に🟢を返し続けたはずです。誤検知どころか、監視そのものが意味を失う見逃しのパターンでした。
これは実際に誤検知した事例ではなく、実装中に気づいて先に潰した予防策です。対処はシンプルで、ポーリング側の内部ログを共有せず、launchdのStandardOutPathを専用ファイルに分離し、そちらを監視対象にしました。低頻度ジョブと高頻度ジョブが同じログを共有する構成は、見た目には自然でも、監視の観点では別ファイルに分けるべきだと学びました。
監視は、監視対象を変えたときに一緒に見直す対象
ここまでの2件に共通しているのは、監視のロジック自体には触れていないという点です。壊れたのはいつも、監視が読みに行く入力の側でした。ロガーの共通処理を変えることは、監視の入力を変えることと同じ意味を持ちます。これは監視を作った時点では見えにくく、監視対象や周辺の実装を変更するたびに、監視側の前提が今も成り立っているかを確認する必要があると考えるようになりました。
似た話として、ログの二重出力にも注意が必要です。スクリプト内部の書き込みとlaunchdのStandardOutPathが同じファイルを指していると、死活監視だけでなく、人がログを目視で確認するときにも読み違いが起きます。ローテーションの無いログは、気づかないうちに肥大化することもあります。私の環境でも、あるログが48MB・61万行まで積み上がり、クラウド同期のAPI制限に引っかかったことがありました。ログまわりの設定は、一度作って終わりにできる場所ではないというのが実感です。
この一件のあと、変えたのは仕組みだけではありません。共通処理を触るときのレビュー観点に「この変更で監視の入力(ログの書き込み先・出力形式)が変わらないか」を1項目足しました。ロガーの変更とダッシュボードの設定は、コード上はまったく別の場所にあります。関連しているように見えないからこそ、意識して結び付けておかないと見落とします。
まとめ：ログの更新時刻を信じすぎない
ログの更新時刻でジョブの生死を判定する設計は、手軽で導入しやすい一方、ログの出力経路が変わるだけで前提が崩れます。今回直したのは2箇所です。監視側はlog_pathをglob対応にしてローテーションログの最新ファイルを解決できるようにし、ロガー側は監視対象と実際の出力先を一致させました。加えて、「何もしないのが正常」なジョブは既存のログに相乗りさせず、専用の出力先を持たせるようにしています。
最後に、同じようにログのmtimeでジョブの死活を判定している方は、直近でロガーやログ出力の実装を変えていないか一度振り返ってみてください。監視は、監視対象が変わった瞬間に静かに壊れることがあります。
私は現役EMとして、1on1やチーム運営の仕組み化について書いています。1on1管理のNotionテンプレート(無料Lite版)を公開中です → 試してみる。X: @anikuma_tech
コメント