ProLogue ～最下級戦士の推理～

FILE.1　同時刻の StopInstances

👨「…おかしい。」
👨「EC2 インスタンスは確かに停止した。」
👨「動作は完璧だ。」
👨「だが…。」

（CloudTrail のイベント履歴に並ぶ、2 つのStopInstances…。）

👨「何故、StopInstancesが 2 つ記録されている…？」
👨「あれれ～？」
👨「おかしいぞ〜？？」

FILE.2　実害なきトリック

👨「インスタンスは正常に停止。実害は無い。普通ならここで見過ごす。」
👨「だが…。」
👨「この違和感、見逃すわけにはいかない…！」
👨「真実はいつも 1 つ…。」
👨「なら、この 2 件にも必ず『カラクリ』があるはずだ…！」

FILE.3　3 つの証拠

👨「requestID‐‐‐ 別物。」
👨「eventID‐‐‐ 別物。」
👨「つまり、『表示上のダブり』という線は消えた。」
👨「コイツは確かに… 2 回呼ばれている……!？」
👨「userIdentityのarnは一致。」
👨「invokedByは、どちらもevents.amazonaws.com…。」
👨「呼び出し元は、同一人物（プリンシパル）。」
👨「そして…accessKeyIdも一致…だ…と…！？」
👨「これで決まりだ！」
👨「犯行は『別々の仕掛け』じゃない！」
👨「たった 1 回の実行の中で、2 回StopInstancesが呼ばれている…！」

FILE.4　真犯人

👨「犯人は…お前だ！」
👨「AWS-StopEC2Instance ‐‐‐ ！！」
💻「…いつから気づいていた？！」（AWS-StopEC2Instance）
👨「最初からさ。
👨「お前のmainStepsは2段構え。」
👨「まず、stopInstancesで普通に止め、続くforceStopInstancesで強制停止のダメ押し。」
👨「だから、StopInstancesは 2 回記録された…。」
👨「それが、トリックの正体だ！」
💻「…フッ。」
💻「だが言っておくが、実害は無いぞ。」
💻「冪等な処理だからな。」
👨「ああ。」
👨「だから、余計に性格（タチ）が悪いのさ。」
👨「『気持ち悪いだけ』で放置されがちなこのトリック…。」
👨「だが、俺は見過ごせなかった。」

Epilogue 〜最下級戦士、真実に辿り着く〜

真実はいつも 1 つ。

というわけで、この記事ではこの「2回事件」の推理過程を、証拠とともに追っていきます。

事件の概要

EC2 インスタンスを定時で自動停止していた。
停止は正常に動作している。（実害は無い。）
ある日、CloudTrail のイベント履歴を見たら StopInstances が同時刻・同一インスタンスIDで2件記録されていた

停止はできている。実害もない。だが StopInstances が2つ並んでいる。この違和感の正体を突き止める。

3 つの仮説

「2 件ある！」と言っても、考えられる筋書きは複数あります。

（01）表示上の重複。（同じ 1 回の呼び出しが 2 行見えているだけ。）
（02）リトライによる重複。（呼び出し元がレスポンスを取りこぼして再送。）
（03）そもそも 2 系統の仕組みが 2 重に動いている。

どれが真犯人か。
イベントレコードという『証拠』を突き合わせて、1 つずつ潰していきます。

推理① 〜 requestID / eventID の謎〜

まず 2 件の requestID と eventID を比較。

どちらも別物だった。

表示上の重複ではなく、本当に StopInstances API が 2 回呼ばれている。

これで仮説①『表示上の重複』は消えました。
コイツは確かに 2 回呼ばれている。

推理② 〜呼び出し元は誰だ〜

次に『誰が呼んだのか？』を確認

userIdentity.arn … 2 件とも一致。
invokedBy … 2 件とも events.amazonaws.com だった。

呼び出し元（プリンシパル）は同一

※『プリンシパル』とは？　…　例えると、『誰が？』にあたる部分。

別々の仕組みが 2 重に動いている線も薄くなりました。

そして、 invokedBy が events.amazonaws.com ということは、EventBridge の Scheduler （新しい方）ではなく、スケジュールされたルール（レガシー） 経由で動いていたことが判明します。

推理③ 〜決定的証拠の accessKeyId 〜

ダメ押しで accessKeyId を比較。

2 件とも一致

これで確定。

「同一の実行セッションから 2 回呼ばれている。」

リトライでも二重起動でもなく、1 回の実行の中で 2 回 API が叩かれている。
犯行現場は、たった 1 つの実行の中にあった。

真犯人〜ターゲットの SSM Automation ドキュメント〜

レガシールールのターゲットを確認すると AWS-StopEC2Instance（SSM Automation ドキュメント）が 1 つだけ。
このドキュメントの定義を見にいくと、mainSteps が 2ステップ構成 になっていました。

ステップ	アクション	内容
`stopInstances`	`aws:changeInstanceState`	通常停止（`onFailure: Continue`）
`forceStopInstances`	`aws:changeInstanceState`	強制停止（`Force: true`）

つまり、『まず、普通に止める。　⇒　続けて、念の為、強制で止める。』という 2 段構え。

それぞれのステップが裏で StopInstances API を叩く為、CloudTrail に 2 件記録される。

これがトリックの正体でした。

裏取り〜 Automation の実行履歴〜

『Systems Manager＞Automation＞実行履歴』から該当の実行を開くと、

stopInstances … 開始 04:30:49 GMT ／ステータス成功
forceStopInstances … 開始 04:31:30 GMT ／ステータス成功

2 ステップが順番に実行され、どちらも成功。

推理は証拠と一致しました。

ハマりどころ

CloudTrailのイベント履歴は**ブラウザのタイムゾーン（JST）**で表示されるのに対し、Automation の実行履歴は GMT 表示。
04:30:49 GMT = 13:30:49 JST で、同じ出来事を別タイムゾーンで見ていただけ、という『第 2 のトリック』もありました。

ダメ押し〜 Start と Stop は非対称〜

念の為、 AWS-StartEC2Instance の実行履歴も開いてみると、こちらは startInstances の 1 ステップだけ。

停止：stopInstances + forceStopInstances の 2 段構え。
　　　⇒ StopInstances が 2 回記録される。
起動：startInstances の 1 段のみ。
　　　⇒ StartInstances は 1 回だけ。

『何故、【停止】だけ 2 回出るのか？？』の答えが、この非対称性に集約されていました。

【起動】には『強制起動でダメ押し』という保険ステップが不要なので 1 段で済む、という設計思想の違いです。

結論〜真実はいつも 1 つ〜

ルールは予定通り 1 回だけ発火している。（2 重【起動】ではない。）
AWS-StopEC2Instance が『【停止】　⇒　強制【停止】』の 2 段構えなので、StopInstances が 2 回記録されるのは仕様通り。
停止処理は冪等で実害ゼロ。
気持ち悪いだけなので、放置で問題無し。

気持ち悪さの正体は『【停止】＋念の為、強制【停止】』という 2 段構えドキュメントの素直な挙動でした。

『真実』はいつも 1 つ。

参考

ドキュメント定義の実体。
2ステップ構成が確認できる。
aws-StopEC2Instance.json（awslabs）
公式リファレンス
AWS-StopEC2Instance - Automation Runbook Reference
各ステップが使うアクションの仕様。
aws:changeInstanceState - AWS Systems Manager

補足

1 本目の GitHub リポジトリ（awslabs）はメンテ頻度が低い場合があります。
確実に『今動いているドキュメントの中身』を確認したいなら、Systems Manager〉ドキュメント〉AWS-StopEC2Instance の［コンテンツ］タブで現在の JSON 定義を見るのが確実です。