はじめに
GMOコネクトの永田です。
長く運用しているシステムで、Windows ServerのゴールデンAMIをSSM Automationで毎月作っています。WSUSからパッチを当てて、その状態でAMIを焼く、というよくある構成です。ある月から、そのパッチ適用ステップが失敗するようになりました。しかもSSMのログには failed to run commands: exit status 1 としか出ず、再実行しても直りません。ログを何度見ても原因がどこにも書いていない、というのが出発点でした😇。
追いかけてみると、犯人は再起動後に再実行されたスクリプトの処理中に、Windows自身が勝手にかけた強制再起動で、それがSSMのログには一切残らない、という厄介なものでした(今回はたまたまWindows Updateのスキャン中に食らいましたが、スキャンに限った話ではありません)。パッチ適用スクリプトは複数回の再起動を想定して冪等(何度実行しても同じ結果になる作り)に書いてあったのに、それでもすり抜けられた、という話です。
この記事は、exit status 1しか出ないところから原因を確定し、再起動に耐えるように直すまでの記録です。
先にまとめ
- SSMのstdout/stderrで見えるのは
failed to run commands: exit status 1だけ。でもスクリプトは失敗判定していません(スクリプトが出すはずのFailed ...もイベントログも無い)。つまり、スクリプトの実行プロセスが外部要因で中断させられていました。 - パッチ適用スクリプトと
exit 3010は、もともと複数回の再起動を想定した冪等設計でした。「再起動が複数回必要」自体は問題ではありません。 - 真因は、制御再起動の起点にしている保留中再起動フラグが肝心なときに空振りし、その隙にTrustedInstaller(Windows Update本体)がフラグと無関係に強制再起動をかけて、再起動後に再実行されたスクリプト(run2)の処理を中断していたことでした(今回はスキャン中でしたが、run2で走る処理ならどこでも起こり得ます)。ここで注意したいのは、SSMログに出るのは「失敗した」という結果(
exit status 1)だけで、その原因=強制再起動が起きたこと自体は残らない点です。再起動の記録はWindowsのイベントログにしかありません。 - 解決は二段構えです。スクリプト側で保留再起動を先読みして逃がしつつ(best-effort)、取りこぼす分はAutomationステップの
maxAttemptsで中断を拾って再試行します。
| 見えた事象 | 実際に起きていたこと | 対策 |
|---|---|---|
run2が途中で途切れ exit status 1(今回は Start Scan... の後) |
フラグ空振り→run2の処理中(今回はスキャン)にTrustedInstallerが強制再起動→中断 | ステップの maxAttempts で中断を拾い再試行/スクリプトで保留再起動を先読み |
SSMログには失敗(exit status 1)は出るが「強制再起動」は出ない |
再起動②はSSM(exit 3010)起因でなくOS(TrustedInstaller)起因 |
Windowsイベントログ 1074/6005/6006/6008 で確認 |
| 保留フラグを事前に見ても防げない | run2開始時はどのフラグも未検知、run2の処理中に再起動 | 事前チェックはbest-effort、取りこぼしはステップ再試行で吸収 |
以下、順を追って書きます。
症状: SSMログは「exit status 1」しか教えてくれない
失敗はいつも同じパッチ適用ステップで、再実行しても直りません。SSMのRun Commandの出力を見ると、こうなっていました(レジストリ確認の出力などは省いています)。
(1回目の実行 = run1)
Start Scan for Windows Update...
Scan attempt 1/5: HResult=0x00000000, Count=3
Start Windows Update...
Apply attempt 1/5: HResult=0x00000000
Windows Update completed.
Request Restart computer. ← exit 3010(再起動要求)に正常到達
(再起動後の再実行 = run2)
Start Scan for Windows Update... ← ここで途切れている
--- stderr ---
failed to run commands: exit status 1
run1はスキャンで3件を検出し、適用も HResult=0x00000000(成功)で終わり、再起動要求(exit 3010)まで正常に到達しています。問題はその後、再起動して再実行されたrun2がスキャンの途中で消えていることです。
ここで最初の切り分けができます。この failed to run commands: exit status 1 はSSM Agentが出すメッセージで、スクリプト自身の失敗判定ではありません。スクリプトが失敗と判断したなら、Failed ... の出力やWindows Updateのイベントログをスクリプト側で残すように作ってあります。それらが一切無い。つまりrun2のプロセスが、自分で終了する前に外部要因で中断させられた、と読めます。
exit 3010の仕組みと、スクリプトが複数回の再起動を想定していること
前提を整理します。Run Commandには、スクリプトが exit 3010 で終了するとSSM Agentがノードを再起動し、再起動後にスクリプトを再実行する仕組みがあります(AWS公式の Handling reboots when running commands)。Windowsでインストーラが「再起動が必要」を示す終了コード 3010 を、そのままこの用途に使うかたちです。
そして、パッチ適用スクリプト側も保留中の再起動がある限り exit 3010 を繰り返すように書いてありました。1回のパッチ適用で再起動が複数回必要になっても、そのたびに再起動→再実行を回して最後まで進む、という想定です。無限ループを避けるため、再起動回数はファイルに記録して上限で止めます(スクリプトは再起動のたびに最初から実行し直され、変数が消えるためです)。
つまり「再起動が複数回必要」自体は織り込み済みで、冪等に作ってあります。それでも落ちました。理由は「回数」ではなく「再起動の起こされ方」でした。
SSMログに映らない「強制再起動」を、イベントログで捕まえる
SSMのログだけでは行き止まりなので、Windowsのシステムイベントログ(再起動の記録が残る 1074 / 6005 / 6006 / 6008)を取ってもらいました。すると、こういう並びでした。
01:08 イベントID 1074 Reboot initiated by SSM Agent ← exit 3010 による制御再起動①
01:17 (起動)→ run2 開始("Start Scan for Windows Update..." を出力)
01:18 イベントID 1074 TrustedInstaller.exe / 計画済みの再起動 ← Windows 自身の強制再起動②(run2 を中断)
①はスクリプトの exit 3010 を受けてSSM Agentが行った、想定どおりの再起動です。問題は②で、run2が動いている最中にTrustedInstaller(Windows Modules Installer、Windows Update本体)が独自に再起動をかけていました。これがrun2の処理(今回はスキャン)を中断させ、SSMから見ると exit status 1 になっていた、というのが真相です。
ポイントは、再起動②が起きたこと自体はSSMのログには現れないことです。SSMに出るのは「コマンドが失敗した」という結果(failed to run commands: exit status 1)だけで、「再起動が入ったから中断した」という理由までは出ません。SSM AgentはRun Commandが起こした再起動(①)しか把握しておらず、OSが自分の都合で行った再起動②はWindowsのイベントログにしか残らないからです。だからSSM側だけを見ていると、失敗は分かっても原因にたどり着けませんでした。
冪等なのに落ちた ──「保留フラグ検知→制御再起動」の盲点
ここが今回いちばん詰まったところです。
スクリプトは、再起動を制御された形で行うために、保留中の再起動があるかどうかを先に判定してから exit 3010 で逃がす設計でした。判定は、Windowsで「再起動保留」を示すことが多い次の3つを見ます。
-
CBS(コンポーネントベースサービシング):
HKLM:\SOFTWARE\Microsoft\Windows\CurrentVersion\Component Based Servicing\RebootPendingキーの有無 -
Windows Update:
HKLM:\SOFTWARE\Microsoft\Windows\CurrentVersion\WindowsUpdate\Auto Update\RebootRequiredキーの有無 -
ファイルリネーム待ち:
HKLM:\SYSTEM\CurrentControlSet\Control\Session ManagerのPendingFileRenameOperations値の有無
このいずれかが立っていれば「保留中の再起動あり」と判断します。
考え方はこうです。「run2の冒頭で保留フラグが立っていたら、スキャンをする前に exit 3010 で再起動して片付ける。立っていなければ、もう再起動は要らないのでスキャンに進む」。
ところが実際には、run2の冒頭ではCBS・WU・PendingFileRenameOperationsのどれも立っていませんでした(=検知が空振り)。だからスクリプトはそのまま処理を続け、その最中にTrustedInstallerがフラグとは無関係に強制再起動をかけた、という順序でした。今回はスクリプトが再実行後にまず行うのがスキャンだったのでスキャン中に食らいましたが、これは再起動後に再実行されるスクリプトの処理中ならどこでも起こり得ます(スキャン固有の問題ではありません)。
つまり「保留フラグを見て、立っていれば exit 3010 で制御的に再起動する」という戦略にはタイミングの盲点があります。Windows Updateの最終処理(finalize)に伴う再起動は、事前にフラグとして現れないまま実行されることがあり、事前チェックでは捕まえられないのです。冪等に作っても、この「フラグに現れない強制再起動」は防げませんでした。
再起動には2種類あります。
-
制御された再起動(スクリプトが
exit 3010を返す): SSM Agentが再起動して、同じスクリプトを再実行してくれる -
想定外の再起動(TrustedInstallerがフラグと無関係に行う強制再起動): run2を実行の途中で中断し、SSMから見ると
exit status 1
前者は仕組みに乗れますが、後者は事前検知では防ぎきれません。であれば、中断を「起きるもの」として受け止め、あとから拾い直すしかありません。そこで効くのがAutomationステップの再試行です。
中断は exit status 1、つまりステップの失敗として表面化します。だからAutomationのステップに maxAttempts を付ければ、SSMがステップごと再試行してくれます。追加の再起動がすべて終わって系が安定すれば、次の試行で通ります。しかも maxAttempts は失敗したときだけ発火し、制御された exit 3010(=再起動要求で、ステップは失敗扱いにならない)では消費されません。つまり「正常なときは1回で完了、本当に中断したときだけ再試行に回る」という都合のよい網になります。
恒久対応: スクリプト内 × ステップの二段構え
方針は「事前に読める再起動はスクリプトで制御して片付け、読めない想定外の再起動はステップ再試行で吸収する」の二段構えです。
1. スクリプト側: 保留再起動の先読み(best-effort)
スキャンに入る前と、適用の後に、先ほどの3キーで保留中の再起動を確認し、立っていれば exit 3010 で逃がします。事前に読める分はここで潰す、という素直な対策です。
2. Automationステップ側: 中断を拾って再試行する網
ここが今回の肝です。スクリプトの事前チェックで取りこぼす「run2の処理中に起きる強制再起動」は、ステップの maxAttempts で拾います。多段再起動で時間が延びるので timeoutSeconds も伸ばしておきます。
- name: runWindowsUpdate
action: 'aws:runCommand'
# run2(再起動後の再実行)の処理中にWindows自身が強制再起動し、中断されることがある。
# 中断は exit status 1 で表面化するため、ステップごと再試行して吸収する。
# ※ maxAttempts は失敗時のみ発火。正常な exit 3010(再起動要求)では消費されない。
maxAttempts: 5
timeoutSeconds: 5400
inputs:
DocumentName: "AWS-RunPowerShellScript"
InstanceIds: "{{ launchInstance.InstanceIds }}"
# parameters: ...
この二段構えにしてから、パッチ適用が安定して完走するようになりました。スクリプトだけ、あるいはステップの再試行だけでは足りず、「事前に読める分は制御して片付け、読めない分はあとから拾う」の両方が必要だった、というのが結論です。
(コラム)EC2 Image Builder なら防げたのか
ゴールデンAMI作成にはマネージドの EC2 Image Builder があり、AWSはこちらを推奨しています。ただ、実行エンジンのAWSTOE(AWS Task Orchestrator and Executor=Image Builderがインスタンス上でコンポーネントを実行するアプリケーション)も再起動の作法は今回と同じ exit 3010 ベースで、公式ドキュメントには「exit codeを伴わない再起動が起きるとビルドは失敗し得る(the build process may fail)」と明記されています。今回のTrustedInstallerの強制再起動はまさにこれなので、Image Builderでも同じように中断・失敗する可能性はあります。今回は実機検証していないので断定はできませんが、少なくとも「Image Builderにすれば自動で安全」とは言えなさそうです。新規なら運用をAWSに寄せられるImage Builderが有力な一方、冪等性+再試行という備えはどちらでも要る、というのが今の理解です。
まとめ
- SSMのログには
failed to run commands: exit status 1しか出ませんが、真因はexit 3010の再起動後に走ったrun2を、TrustedInstallerの強制再起動が中断していたことでした - パッチ適用スクリプトと
exit 3010は複数回の再起動を想定した冪等設計でした。落ちたのは回数ではなく、制御再起動の起点にした保留フラグ(CBS/WU/PendingFileRenameOperations)が空振りし、フラグに現れない強制再起動がrun2を中断したからです - SSMログに出るのは失敗の結果(
exit status 1)だけで、原因の強制再起動が起きたこと自体は残りません。再起動の記録はWindowsのイベントログ 1074/6005/6006/6008 にしかなく、SSM側だけ見ていると原因にたどり着けません - 解決は二段構えです。スクリプト側で保留再起動を先読みして逃がしつつ(best-effort)、取りこぼす強制再起動による中断はステップの
maxAttempts:5(+timeoutSeconds:5400)で拾って再試行します。maxAttemptsは制御されたexit 3010では消費されません
最後に、GMOコネクトではサービス開発支援や技術支援をはじめ、幅広い支援を行っておりますので、何かありましたらお気軽にお問合せください。