カテゴリー: 自動化の運用

この記事では、自動化処理のログに「対象なし」とだけ書いていたために、3日間まったく処理できていない状態に気づけなかった実例と、そこから変えた3つのログ設計を書きます。エラーが出ない故障をどう可視化するかの話です。

「対象なし」と書いていたら、故障が見えなくなった

自動化した処理のログで、処理対象が0件だったときに『対象なし』とだけ出力していました。文字としては間違っていません。実際に対象は0件です。

ところが、これで3日連続で1件も処理できていない状態に、画面から気づけませんでした。「対象なし」は正常な日にも出る文字列なので、それが3日続いていても異常として目に入ってこないのです。

原因：ボタンは押せるが、状態が変わっていなかった

原因は、操作先の外部サービスのUI変更でした。ボタンは押せる状態にあり、クリック自体は成功します。しかしその後、状態が変わっていませんでした。

この手の失敗はエラーを出しません。クリックが例外を投げるわけではないので、ログ上は最後まで走って正常終了したように見えます。つまり、

• 例外なし
• ログは最後まで出ている
• 「対象なし」と書いてある

という三点が揃うと、外から見て健康な自動化と区別がつきません。ここが一番怖い部分でした。

対策1：0件でも必ず数字で書く

まず、0件のときに文章で逃げるのをやめました。件数を必ず数字として出します。

解除 0件 / 保護 41件

数字で書くと、0という値が記録として残ります。「対象なし」は文字なので比較も集計もできませんが、0件は他の日の数字と並べられます。0が3日並んでいれば、それは並べた時点で異常として見えます。文章にすると消えてしまう情報が、数字にすると残るという違いです。

ポイントは「異常だったから数字を出す」のではなく、「正常でも常に同じ形式で数字を出す」ことです。形式が揃っていないと、そもそも並べられません。

対策2：押せた≠変わった、を確認する

2つ目は、操作した後に状態が変わったかどうかを確認することです。今回の故障は、まさに「押せたこと」を成功の判定に使っていたために見逃しました。

ボタンが押せることと、対象の状態が変わることは別の事象です。押せたのは手前の話で、目的は状態の変化です。だから操作の後にもう一度状態を読み、変わっているかを見る。変わっていなければ、押せていても失敗として扱う。

ここを分けておかないと、外部サービスのUIが変わったときに「操作は通っているのに何も起きない」という状態が、そのまま正常終了として記録されてしまいます。

対策3：手動実行も、cronと同じ経路で通す

3つ目は運用側の話です。手動で動かしたいときも、cronやタスクと同じ経路、つまりログに残る形で実行するようにしました。

直接叩くと記録が残りません。記録が残らない実行が混ざると、集計したグラフが嘘をつきます。実際には動かしていた日が「動いていない日」として並び、逆に手動で処理してしまった件数がどこにも計上されない、といったズレが出ます。故障の判断材料として使うつもりのログなら、抜け道を作ってはいけないと考えるようになりました。

まだ分かっていないこと

今回は外部サービスのUI変更が原因でしたが、UIが変わることを事前に検知する方法は持っていません。次のUI変更でまた壊れる可能性は残っています。今できているのは「壊れたときに、それを数字として見えるようにする」ところまでで、壊れないようにする手立てはありません。ここは正直に、分かっていない部分です。

まとめ

• 0件のときに「対象なし」とだけ書くと、正常な日と区別できず、3日連続の停止に気づけなかった
• 原因は外部サービスのUI変更で、ボタンは押せるが状態が変わらない状態だった
• エラーが出ないため、ログ上は正常終了に見えていた
• 0件でも数字で書く（例：解除 0件 / 保護 41件）。数字なら並べて比較できる
• 操作後に状態が変わったかを確認する。押せた≠変わった
• 手動実行もcronやタスクと同じ経路でログに残す。直接叩くとグラフが嘘をつく
• UI変更そのものを事前に検知する方法は、まだ持っていない

この記事で分かること

Windowsタスクスケジューラで定期実行を回していて、私が実際につまずいた点をまとめます。戻り値267009・267014の意味、PowerShellのSet-ScheduledTaskでハマったTaskPathの指定、そして「戻り値0なのに何も処理されていなかった」件の話です。カタログ的な説明ではなく、運用して初めて分かったことだけを書きます。

267009 はエラーではありません

タスクの「前回の実行結果」に見慣れない数値が出ると、まずエラーコードだと思ってしまいます。私も最初はそう思いました。しかし 267009 は SCHED_S_TASK_RUNNING で、「まだ実行中」という状態を表しています。エラーではありません。

267009 = SCHED_S_TASK_RUNNING（まだ実行中）

つまり、この値を「失敗」として扱う監視を組んでしまうと、正常に走っている最中のタスクを毎回アラートに上げることになります。私はここで一度、無駄な通知を自分で作ってしまいました。実行中を意味する値なので、確認したいのは「なぜ止まらないのか」であって「なぜ失敗したのか」ではありません。

267014 は「時間切れで殺された」状態

もう一つよく出るのが 267014 で、これは SCHED_S_TASK_TERMINATED です。実行時間の上限に達して強制終了された状態を指します。

267014 = SCHED_S_TASK_TERMINATED（実行時間の上限に達して強制終了）

ここで重要なのは、これが「スクリプトが失敗した」ことを意味していない点です。スクリプト側は普通に処理を続けていたのに、外側から打ち切られただけ、というケースがあり得ます。そのため、267014 を見たときに調べるべきはスクリプトのエラーログではなく、そもそもなぜ上限時間内に終わらなかったのかという方向になります。処理量が増えたのか、途中で待ちが発生しているのか、原因の切り分けはタスクスケジューラ側の情報だけでは分かりません。ここは実行するスクリプト自身にログを吐かせて追うしかありませんでした。

Set-ScheduledTask は TaskPath を指定しないと見つからない

PowerShell からタスクの設定を変更しようとして、素直に名前だけ指定しても対象が見つからない、ということがあります。原因は単純で、Set-ScheduledTask はタスクの置き場所（TaskPath）を指定しないと見つけられないためです。

GUI 上ではフォルダ構造が目に見えているので忘れがちですが、コマンドから触るときは「どのフォルダに置いたタスクなのか」を明示する必要があります。自動化の設定変更をスクリプト化するときは、ここを最初に確認しておくと余計な時間を使わずに済みます。

一番怖いのは「戻り値0」です

267009 や 267014 は、少なくとも目に見える異常です。運用していて本当に危なかったのは、戻り値が 0 のケースでした。

実行結果が 0 でも、処理件数が 0 件ということがあります。スクリプトは正常終了しているので、タスクスケジューラの画面上は何の問題もなく見えます。しかし実際には何も処理していません。戻り値だけを見て「動いている」と判断すると、この失敗に気づけません。

私は実際に、戻り値0のまま3日連続で処理件数が0だったことがありました。しかも気づいたのは3日経ってからです。理由ははっきりしていて、ログに件数を数字で書いていなかったからです。「処理を開始しました」「完了しました」とは書いていても、「何件処理したか」を数字で残していませんでした。ログを見ても正常に見えるので、疑うきっかけがなかったのです。

結局どこを見るべきか

• タスクスケジューラの戻り値は「タスクが動いたか」しか教えてくれません。「仕事をしたか」は教えてくれません
• だから、処理件数は必ず数字でログに書きます。0 件なら 0 件と書き残します
• 数字が残っていれば、「3日連続で0件」のような異常はログを並べた瞬間に見えます

なお、0件が続いていた根本原因の一般的なパターンについては、私が確認できた範囲を超えるので断定的なことは書きません。分かっているのは、ログに件数を数字で残していなかったせいで発見が3日遅れた、という事実だけです。

まとめ

• 267009 は SCHED_S_TASK_RUNNING で「まだ実行中」。エラーではないので、失敗として扱わないこと
• 267014 は SCHED_S_TASK_TERMINATED で、実行時間の上限に達して強制終了された状態。スクリプトの失敗とは限らない
• PowerShell の Set-ScheduledTask は TaskPath（タスクの置き場所）を指定しないと対象を見つけられない
• 実行結果0でも処理件数0のことがある。戻り値だけで「動いている」と判断すると失敗に気づけない
• 実際に戻り値0のまま3日連続で処理件数0だった。ログに件数を数字で書いていなかったのが気づけなかった原因
• 対策はシンプルで、処理件数を数字でログに残すこと