概要

CloudFormationのトラブルシュートでは、CloudFormationスタックの情報を確認することで、エラーになったAPI呼出しやエラーメッセージまでは確認できる。その次の調査ステップとしては…

CloudTrailに記録される「イベント履歴」を確認 すると、API呼出しの受け取ったパラメータや返した結果がわかる。
CloudTrailイベント履歴画面では、「リクエストID」「発信元IPアドレス」などを表示対象に追加 してこのフィールドを見ていくと、エラーになったAPI呼出しや関連API呼出しを探しやすい。

結果的にはつまらないテンプレート記述ミスだったけど、CloudTrailイベント履歴を調べて解消したトラブルシュートがあったので、顛末をまとめておく。

状況

CloudFormationでAWS Backupボールト（AWS::Backup::BackupVaultリソース）のデプロイが失敗した。まずCloudFormationスタック画面で、以下を確認した。

スタックの作成または更新の実行結果を確認する。表示されるスタックステータスコードがROLLBACK_COMPLETE。CREATE_COMPLETEかUPDATE_COMPLETE以外なので、おそらくなにかしらのエラーが起きている。
スタックの「テンプレート」タブや「パラメータ」タブで、指定値が想定通りか確認する。正しいテンプレートとパラメータを指定できている。
スタックの「スタック情報」タブの「状況の理由」を確認する。エラーメッセージは以下だった。

Resource handler returned message: "Invalid Key provided by the user. %s (Service: Backup, Status Code: 400, Request ID: abc1d2e3-a1bc-1ab2-1234-12345ab6cd7e)" (RequestToken: a1234bc5-1a23-1234-1234-123456789a01, HandlerErrorCode: InvalidRequest)

スタックの「イベント」タブを確認する。エラーメッセージを出力したAPI呼出しは CreateBackupVault だった。

エラーメッセージが「Invalid Key provided」だから、パラメータとして渡されたバックアップボールトの暗号化キーの値が不適切だったのだと思う。でもわからないことが二つある。

「暗号化キーとして渡された値」はなんだったのか？
どう不適切だったのか？例えば以下のような可能性を思いついたけど、どれなのか（あるいはそれ以外なのか）？
- 同じスタック内で作成しているはずの暗号化キーが、作成できていない。
- 暗号化キーに設定しているアクセス制御が適切じゃなくて、AWS Backupサービスから利用できない。
- 暗号化キーの指定がうまくいっていない。

結局のところ、パラメータが何だったのかを確かめたい。

API呼出しのパラメータをCloudTailで確認する。

基本的に、クラウドコンピューティングではすべての操作はAPIの呼出しで行われる。AWSでは、API呼出しとその結果は、CloudTrailイベント履歴で見ることができる。ただ多数のイベントが記録されているので、まずは上のエラーを起こしたCloudFormationからのAPI呼出しを探すことにする。

APIはユニークなリクエストIDを持っている。上の「状況の理由」に「Request ID: abc1d2e3-a1bc-1ab2-1234-12345ab6cd7e」とあるので、これを探せばいい。
CloudTrailイベント履歴では、初期はリクエストIDが表示されていない。「表示をカスタマイズする」の手順で、リクエストIDを表示対象に追加する。
「状況の理由」にあったID abc1d2e3-a1bc-1ab2-1234-12345ab6cd7eを探す。ブラウザのページ内検索を使うと簡単。

CloudTrailレコードの内容には、以下が含まれている。

API呼出し時に渡した引数（requestParameters）
APIからのレスポンス（responseElements）

requestParametersは、以下のように記録されていた。

{
    "eventVersion": "1.09",
    (略)
    "eventSource": "backup.amazonaws.com",
    "eventName": "CreateBackupVault",
    "awsRegion": "ap-northeast-1",
    "sourceIPAddress": "cloudformation.amazonaws.com",
    "userAgent": "cloudformation.amazonaws.com",
    "errorCode": "InvalidParameterValueException",
    "errorMessage": "Invalid Key provided by the user. %s",
    "requestParameters": {
        "backupVaultName": "my-backup-vault",
        "backupVaultTags": "HIDDEN_DUE_TO_SECURITY_REASONS",
        "encryptionKeyArn": "9z8yxw7u-987z-98zy-z987-9z87y65x4321",
        "creatorRequestId": "a0000aa0-0a00-0000-4025-000000000a00"
    },
    (略)
}

errorCodeやerrorMessageもCloudFormationスタックのイベントに記録されていたやつなので、このレコードで間違いなさそうだ。そしてrequestParametersにencryptionKeyArnが記録されている。これがパラメータとして渡された暗号化キーのIDで、次の調査対象だ。

"encryptionKeyArn": "9z8yxw7u-987z-98zy-z987-9z87y65x4321",

API呼出しの結果をCloudTailで確認する。

次は、同じスタック内で作成しているはずの暗号化キーは作成できていたのか、そのキーは 9z8yxw7u-987z-98zy-z987-9z87y65x4321 なのか、この二点を確かめたい。ただし、スタック作成は失敗した後で自動的にロールバックされて、作成された（とすれば）キーも削除されている。なので、CloudTrailイベント履歴で前後のイベントを見ていく。

CloudTrailには同じAWSアカウント内で行われたすべてのAPI呼出しが時系列に記録されているので、関連するものだけを見ていきたい。上記のCloudTrailレコードのように、CloudFormationが行った操作は発信元IPアドレス（sourceIPAddress）がcloudformation.amazonaws.comになる。そこで以下を行う。

CloudTrailイベント履歴では、初期は発信元IPアドレスが表示されていない。「表示をカスタマイズする」の手順で、発信元IPアドレスを表示対象に追加する。
エラーになったCloudTrailレコードの直前の、発信元IPアドレスがcloudformation.amazonaws.comのものだけを見ていく。

エラーになったAPI呼出しのいくつか前に、キーの作成のCloudTrailレコードがあった。

{
    "eventVersion": "1.09",
    (略)
    "eventSource": "kms.amazonaws.com",
    "eventName": "CreateKey",
    "awsRegion": "ap-northeast-1",
    "sourceIPAddress": "cloudformation.amazonaws.com",
    (略)
    "responseElements": {
        "keyMetadata": {
            "aWSAccountId": "123456789012",
            "keyId": "9z8yxw7u-987z-98zy-z987-9z87y65x4321",
            "arn": "arn:aws:kms:ap-northeast-1:123456789012:key/9z8yxw7u-987z-98zy-z987-9z87y65x4321",
            "creationDate": "Aug 8, 2024, 2:48:55 PM",
            "enabled": true,
            "description": "Backup encription key for SYSTEMNAME-STAGE",
            "keyUsage": "ENCRYPT_DECRYPT",
            "keyState": "Enabled",
            "origin": "AWS_KMS",
            "keyManager": "CUSTOMER",
            "customerMasterKeySpec": "SYMMETRIC_DEFAULT",
            "keySpec": "SYMMETRIC_DEFAULT",
            "encryptionAlgorithms": [
                "SYMMETRIC_DEFAULT"
            ],
            "multiRegion": false
        }
    },
    (略)
}

エラーメッセージはないし、responseElementsにキーの情報が入ってきているので、キーの作成はできている。それから、キーのIDは 9z8yxw7u-987z-98zy-z987-9z87y65x4321 なので、生成されたキーをボールトの暗号化に使おうとしていることも間違いない。

オチとまとめ

ただここで、あれっと思う。バックアップボールトを作成したことがある人なら、暗号化キーはARNかエイリアス（デフォルトはaws/backup）を指定するのだったことを覚えているかもしれない。CloudFormationでも、このフィールドの名前はEncryptionKeyArnで、ARNを指定する。

上のキー作成時のresponseElementを見ると、以下のようになっている。

"keyId": "9z8yxw7u-987z-98zy-z987-9z87y65x4321",
"arn": "arn:aws:kms:ap-northeast-1:123456789012:key/9z8yxw7u-987z-98zy-z987-9z87y65x4321",

ARNじゃなく、キーIDの方がパラメータとして渡されている。実はこの引数の値に !Ref KMSキーを指定していた。AWSリソースの!RefはリソースのARNを返すことが多いけど、そうでないリソースも少なくない。AWS::KMS::Keyの戻り値の説明を読むと、これも!Refが返すのはキーIDで、ARNが必要なら!GetAtt KMSキー.arnのようにする。実際、この修正でデプロイが成功してしまって、ありがちな初心者ミスで恥ずかしかったというのが今回のオチ。

とは言え、CloudTrailでAPI呼出しのパラメータと返り値を確認することで、コードを見るまでもなく原因特定できて、あとは修正するだけの段階まで持っていけた一例ではあったと思う。どんなシステムも正しいと思うように作られてて、実際に一見正しそうにできていて、そこから「実はおかしい」ところを手探りで探るのはしばしば難しい。情報不足でシステム構成やコードを見始めるトラブルシュートは不自由だし非効率で仕方がない。

CloudFormation（開発者がよく使うツール）から離れて、CloudTrail（運用管理系ツール）に手を出すのはちょっと気後れするかもしれないけど、開発者でも「CloudTrailはインフラ屋の触るもの」なんて敬遠せず仲良くしていきましょう。

参考

CloudTrailイベント履歴で、sourceIPAddressがcloudformation.amazonaws.comのものを見ていく手法は、以下から。

CloudFormation で特定ユーザだけ Invalid request provided が発生するときの対処方法 | DevelopersIO