はじめに
以前、Python スクリプトを daemon 化して、Azure VM の Schedule Event をポーリングしました。
今回は、そのスクリプトを実装した後のテストをしてみる、そして Scheduled Event で検知される値がどのように変化するのか、という内容です。
実装編の投稿はこちら
目次
Scheduled Event のテスト方法
そもそもの Scheduled Event については、実装編で記載したため省略します。そちらを参照ください。
まずは Scheduled Event で検知される以下のイベントをどうテストするか、というところです。
- freeze: VM の一時停止
- reboot: VM の再起動
- redeploy: ホストの移動
- preempt: スポット VM の削除
- terminate: VM の削除
と言っても非常に簡単で、Azure ポータルから VM の停止、再起動を実行すれば、それが Scheduled Event として検知されます。
現状メンテナンスを疑似的に起こすことはできませんし、削除だと繰り返しテストするのが面倒なので、これが一番簡単です。
Azure ポータル以外にも、API やコマンドでの実施も OK です。これについては、Docs 上にも記載があります。
ということで、Azure ポータルから VM を再起動し、挙動と出力されたログの内容を確認します。
テスト 1 : 予定時刻まで放置してみる
最初は、素直にポータルから再起動をして、待機時間いっぱいまで放置してみました。
先に全体の流れをまとめると、こんな感じでした。
同じ矢印の時間帯は、Scheduled Event から同じ結果が返っている、と解釈してください。
つまりは、以下の 4 種類のレスポンスがありました。
- ログ 1 : 再起動実行以前からイベント検知開始まで
- ログ 2 : イベント検知開始から、イベント開始まで
- ログ 3 : イベント開始から、ログ出力停止 (再起動) まで
- ログ 4 : ログ出力再開以降
これらを順に以下に紹介します。
ログ 1 : 再起動実行以前からイベント検知開始まで
ポータルで再起動を教えてから、イベントとして検知されるまで、つまりは何もイベントがない平常時のレスポンスです。
この時は以下のような結果が返ります。
当然、イベントは空っぽです。
{
"DocumentIncarnation": 4,
"Events": []
}
ログ 2 : イベント検知開始から、イベント開始まで
イベントが検知されはじめ、実行時間まで待機している状態 (EventStatus が Scheduled 状態) のレスポンスです。
{
"DocumentIncarnation": 5,
"Events": [
{
"EventId": "6B951C83-99B4-4551-8A5E-CB0BA9A6F82B",
"EventStatus": "Scheduled",
"EventType": "Reboot",
"ResourceType": "VirtualMachine",
"Resources": [
"IMDS-East1"
],
"NotBefore": "Wed, 07 Sep 2022 05:51:15 GMT",
"Description": "Virtual machine is going to be restarted as requested by authorized user.",
"EventSource": "User",
"DurationInSeconds": -1
}
]
}
イベントが 1 件検知されており、イベントの実行者がユーザーであることや、Reboot であること、対象がどのマシンかなどがわかります。 (実際のメンテナンスだった場合には、EventSource が Platform になります)
NotBefore がイベント実行を待機できる最大の時間です。これよりも長く待機することはできず、この時間になるとイベントが実行されます。
DocumentIncarnation はレスポンスに変化があるたびに値が +1 されるため、先ほどと異なる値になっています。
Azure ポータルで実施した再起動は、NotBefore の時間まで保留になります。
ちなみに、このときポータルでは再起動が終わるまでずっとぐるぐるしてます。
ログ 3 : イベント開始から、ログ出力停止 (再起動) まで
NotBefore の時間まで待機した結果のイベント開始から、再起動の実行によりログの出力が停止される直前までのレスポンスです。
{
"DocumentIncarnation": 6,
"Events": [
{
"EventId": "6B951C83-99B4-4551-8A5E-CB0BA9A6F82B",
"EventStatus": "Started",
"EventType": "Reboot",
"ResourceType": "VirtualMachine",
"Resources": [
"IMDS-East1"
],
"NotBefore": "",
"Description": "Virtual machine is going to be restarted as requested by authorized user.",
"EventSource": "User",
"DurationInSeconds": -1
}
]
}
DocumentIncarnation 以外で先ほどと異なるのは、EventStatus が Started になっていること、NotBefore が空欄になっていることです。
イベントの開始時刻になると即実行ではなく、一旦上記のようなイベント実行状態になったあと、開始されるようです。
この後は再起動が行われるため、一時的にログの出力が停止します。
ログ 4 : ログ出力再開以降
再起動から復帰し、ログ出力が再開された以降のレスポンスです。
{
"DocumentIncarnation": 7,
"Events": []
}
再起動により検知していたイベントは完了したため、再びイベントなしに戻っています。
例によってイベントの変化の度に、DocumentIncarnation は変化しています。
Scheduled Event で検知しても放置しておくと、イベントなし ⇒ イベント検知 ⇒ イベント開始 ⇒ イベントなし、となることがわかりました。
テスト 2 : 待機中に自分でイベント開始を要求してみる
Scheduled Event が有効な場合、所定の時間までイベントの実行が保留になりますが必ずその時間まで待つ必要はなく、自分で開始を要求することができます。
待機中に準備が整ったので早く済ませたいから開始を要求、というようなイメージでしょうか。
ということで 2 つ目は、再起動の待機中に自分で開始を要求してみたら何か変わるのか？を確認してみます。
こちらも先に全体の流れをまとめると、こんな感じでした。
今回は以下の 3 種類のレスポンスがありました。
- ログ 1 : 再起動実行以前からイベント検知開始まで
- ログ 2 : イベント検知開始から、イベントの開始要求、ログ出力停止 (再起動) まで
- ログ 3 : ログ出力再開以降
これらを順に以下に紹介します。
ログ 1 : 再起動実行以前からイベント検知開始まで
これについては、1 つ目のテストと変わりはありません。
イベントを検知する前なので、空っぽの状態です。
{
"DocumentIncarnation": 7,
"Events": []
}
ログ 2 : イベント検知開始から、イベントの開始要求、ログ出力停止 (再起動) まで
イベントの検知も、1 つ目と同様です。
ただ、何で DocumentIncarnation が +2 されてるのかよくわからない…
{
"DocumentIncarnation": 9,
"Events": [
{
"EventId": "B7D02EBD-FB9F-430B-B3B6-1845EF2D5328",
"EventStatus": "Scheduled",
"EventType": "Reboot",
"ResourceType": "VirtualMachine",
"Resources": [
"IMDS-East1"
],
"NotBefore": "Wed, 07 Sep 2022 06:32:35 GMT",
"Description": "Virtual machine is going to be restarted as requested by authorized user.",
"EventSource": "User",
"DurationInSeconds": -1
}
]
}
ここで、今回は NotBefore まで待たずに、自分でイベントの開始を要求します。
方法は、メタデータ サービスに対して、イベント ID を添えて POST します。
このテストでは、以下のコマンドを実行しました。
curl -H Metadata:true -X POST -d '{"StartRequests": [{"EventId": "B7D02EBD-FB9F-430B-B3B6-1845EF2D5328"}]}' http://169.254.169.254/metadata/scheduledevents?api-version=2020-07-01
ここで、1 つ目と同じように EventStatus が Started になってから再起動かなーと思っていたのですが、違いました。
先ほどのレスポンスに特に変化がないまま、再起動に入りログの出力が停止しました。
そういうもの…？
ログ 3 : ログ出力再開以降
再起動から復帰し、ログ出力が再開された以降のレスポンスです。
これも 1 つ目のときと変わりません。
ただ、ここでも DocumentIncarnation が +2 されています。
変化の度に +1 ずつされていくはずなのでもしかしたら、ログ出力にできなかったけど一瞬だけ Status が Started のレスポンス (DocumentIncarnation: 10) があったのかもしれません。
{
"DocumentIncarnation": 11,
"Events": []
}
確認できたログからは イベントなし ⇒ イベント検知 (イベント開始要求) ⇒ イベントなし という変化をしましたが、実際は放置したときと同じように Started のタイミングがあるけれど、毎秒のポーリングでは検知できなかった、という可能性も考えられます。
ということで、若干の謎が残るところではありますが、今回のやり方でテストしたところ、このような結果になりました。
終わりに
今回は Scheduled Event の検知をテストしてみました。
ポーリングを実装する場合には、検知した (Status: Scheduled の) 段階でイベント ログに残すとか、備えるための処理をしてからイベントの開始を要求、という感じになるのかなと思います。
そのため開始した後の Started 状態はあまり気にすることはないように思いますが、こんな動作なんだなーと把握する際の参考になればいいかなと！
