AWS CLIで詰まったら、何はともあれ --debug

はじめに

こんにちは、ぐっさんです。

これはAWS CLIで何か困ったら、まずデバッグしましょう！というお話です。

最近AWS CLIでロールを引き受ける(AssumeRole)際、MFAコードを入力しても以下のエラーで弾かれ続ける、という事象に遭遇しました。

$ aws s3 ls --profile role-with-mfa
Enter MFA code for test-user:

An error occurred (AccessDenied) when calling the AssumeRole operation: 
MultiFactorAuthentication failed, unable to validate MFA code.  
Please verify your MFA serial number is valid and associated with this user.

上記のコマンドに--debugオプションを付けて実際のAPIリクエストの中身を確認したところ、すぐに原因が判明しました。
ちなみに、ログが大量に出力されるので標準エラー出力をテキストに吐くことをおすすめします。

aws s3 ls --profile role-with-mfa --debug 2> result.txt

出力されたログの中での特定箇所

'body': {'Action': 'AssumeRole', ..., 'SerialNumber': 'test-user', ..., 'TokenCode': '123456'}

SerialNumberに、本来指定すべきMFAデバイスのフルARN(arn:aws:iam::xxxxxxxxxxxx:mfa/test-user)とは異なる値(test-user)が渡っていました。~/.aws/configのmfa_serialに、正しいARN形式ではない値が設定されていたことが原因でした。

この原因特定自体はAIを使用したログ解析によって一瞬で終わります。大量のデバッグ出力を自分の目で1行ずつ追わなくても良い時代になりました。実務でのログ解析は、可能な範囲でAIを活用しましょう。

ここから先は、--debugの中身そのものをもう少し深掘りしてみた話です。
内部構造に興味がある方だけ、引き続きお付き合いください。
せっかくなので、今回のMFAの件に限らず、AWS CLIの--debugは「実際どこを見れば良いか」という観点で整理してみます。

そもそもbotocoreとは

デバッグを行うと、ログの中にbotocore.credentialsやbotocore.authといった名前が繰り返し出てきます。このbotocoreは、AWS CLIの内部で使われているPython製の低レベルライブラリです。

似た名前のものにboto3(Python向けAWS SDK)があります。botocoreは、このboto3(ライブラリ)とAWS CLI(コマンドラインツール)が共通の土台として使っている基盤ライブラリです。
boto3とAWS CLIは、どちらもbotocoreを直接利用しているという点で「親子」ではなく「兄弟」のような関係にあり、ほとんど似たことができますがAWS CLIはboto3を経由しているわけではありません。

ざっくりイメージにすると、こんな関係です。

https://github.com/boto/botocore

これが分かると、ログに出てくるbotocore.xxxという表記が「AWS CLIの中核処理そのもの」だと理解できるようになります。

そもそも1行1行の構造はどうなっているか

具体的なブロックの話に入る前に、ログ1行の構造自体を確認しておきます。例えばこんな行があります。

2026-07-23 10:19:17,661 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: assume-role

これはPython標準のloggingモジュールの出力形式で、タイムスタンプ - スレッド名 - ロガー名 - ログレベル - メッセージという5要素で構成されています。

タイムスタンプの活用例として、今回のログでもS3呼び出しの署名処理直前から、実際にSTS(AssumeRole)側の処理が始まるまでの行を見ると、こうなっていました。

2026-07-23 17:16:36,197 - MainThread - botocore.hooks - DEBUG - Event before-sign.s3.ListBuckets: calling handler ...
2026-07-23 17:16:40,700 - MainThread - botocore.hooks - DEBUG - Event choose-service-name: calling handler ...

17:16:36,197から17:16:40,700まで、約4.5秒の間が空いています。この間に(標準エラー出力には残らない)MFAコード入力のプロンプトが表示され、実際にコードを入力するまでの時間がここに現れています。こうした処理間の間隔も、タイムスタンプを追うことで確認できます。

この構造が分かっていると、大量のログの中から目的の情報に素早くたどり着けるようになります。

--debugの出力、実際どこを見るべきか

--debugを付けると大量のログが出力されますが、実際にトラブルシュートで意味を持つのは主に以下の5ブロックです。

① 認証情報の解決順序

Looking for credentials via: assume-role
Looking for credentials via: assume-role-with-web-identity
Looking for credentials via: sso
Looking for credentials via: shared-credentials-file
Looking for credentials via: login
Looking for credentials via: custom-process

botocoreがどの順番で認証情報を探しているかが分かります(静的なアクセスキーを使う場合は、この後にFound credentials in shared credentials fileのような成功ログが続くこともあります)。これはコマンド実行のたびに1回行われる処理なので、S3呼び出しであろうとAssumeRoleであろうと共通です。意図しない認証方式(例えば設定したつもりのないSSOセッションが優先されている等)が使われていないかの確認に使えます。

② エンドポイント解決結果

S3への通信でも、実際どのURLへ解決されたかがログに出ています。

Calling endpoint provider with parameters: {'Region': 'ap-northeast-1', 'UseFIPS': False, 'UseDualStack': False, ...}
Endpoint provider result: https://s3.ap-northeast-1.amazonaws.com

実際にどのURLへ通信しようとしているかが確定した瞬間のログです。VPCエンドポイントを使っている場合など、意図した宛先に向いているかをここで確認できます。認証系のAPI(STSなど)に限らず、S3やEC2などどのサービス呼び出しでも同様に出力されます。

③ リクエストパラメータそのもの

こちらもS3呼び出し側の例です。

Making request for OperationModel(name=ListBuckets) with params: {'url_path': '/', 'query_string': {}, 'method': 'GET', ...}

署名される「前」の生のリクエスト内容です。設定ファイルの値やCLI引数が実際どう解釈され、何がAPIに渡っているかが丸見えになります。

今回はこのS3呼び出しの後、認証情報を取得するために内部的にAssumeRoleが呼ばれ、そちらのリクエストパラメータも同じ形式でログに出ていました。

Making request for OperationModel(name=AssumeRole) with params: {'body': {'Action': 'AssumeRole', 'Version': '2011-06-15', 'SerialNumber': 'test-user', 'RoleArn': 'arn:aws:iam::xxxxxxxxxxxx:role/test-user', 'RoleSessionName': 'botocore-session-xxxxxxxxxx', 'TokenCode': '123456'}, ...}

今回の原因(SerialNumberの値が異なっていた)は、まさにこのAssumeRole側のログで発見しました。呼び出しているAPIが何であれ、「実際に何が送信されているか」を生の値で確認できるのがこのブロックの強みです。

④ 署名プロセス

AWSにAPIリクエストを送る時、AWS側は「本当にこのアクセスキーの持ち主からのリクエストか」「途中で内容が改ざんされていないか」を確認したいのですが、シークレットアクセスキーそのものを毎回ネットワークに流すのは危険です。

ざっくり説明ですがここでいう「署名」は、日常の意味での サイン というより、秘密の鍵を持っている人にしか押せない"ハンコ"のようなものだとイメージすると分かりやすいです。
リクエストの中身を要約したものに、秘密の鍵でこのハンコを押し、リクエスト本体はそのままに、ハンコの跡(署名)を追加情報として一緒に送ります(SigV4という仕組みです)。
AWS側も同じ秘密の鍵を知っているので、同じ場所に同じハンコを押してみて、届いたハンコの跡と一致するか照合するだけで本人確認ができます。
この計算過程も、--debugではそのまま出力されます。

CanonicalRequest:
POST
/

content-type:application/x-www-form-urlencoded; charset=utf-8
host:sts.ap-northeast-1.amazonaws.com
x-amz-date:20260723T081640Z

content-type;host;x-amz-date
c6c3c209...(SHA256ハッシュ)

StringToSign:
AWS4-HMAC-SHA256
20260723T081640Z
20260723/ap-northeast-1/sts/aws4_request
16e1f7f0...(SHA256ハッシュ)

Signature:
6b3fea29...(HMAC-SHA256の結果)

3つの要素はそれぞれこんな意味です。

• CanonicalRequest: HTTPリクエスト(メソッド・パス・ヘッダー・署名対象ヘッダー一覧・ボディ)を「決まった書き方」に整形したもの。同じリクエストでもヘッダーの順番などに自由度があるため、クライアント側とAWS側で必ず同じ形に揃えてから比較できるようにする。最後の行(c6c3c209...)は、リクエストボディ自体をSHA256でハッシュ化した値(ハッシュ化ペイロード)
• StringToSign: CanonicalRequest全体(上記6要素をまとめたもの)をもう一段SHA256でハッシュ化した値**(16e1f7f0...)に、リクエスト時刻(x-amz-date)や対象リージョン・サービス名を組み合わせた文字列。「いつ・どのリージョンの・どのサービス宛の、このリクエスト」という情報が詰め込まれている
• Signature: シークレットアクセスキーから段階的に導出した鍵を使って、StringToSignをHMAC-SHA256で署名した最終結果。これが実際にAWSへ送られる「証拠」になる

AWS側は、送られてきたアクセスキーIDから同じシークレットキーを引いてきて同じ計算をし、送られてきたSignatureと一致するか照合します。一致すれば認証OK、x-amz-dateから一定時間(前後15分程度)経ちすぎていれば拒否されます。

普段はここまで見る機会は少ないブロックですが、AWSのAPI呼び出し全般で共通の仕組みなので、サービスを問わず確認できます。

⑤ 実際のHTTPレスポンス

"POST / HTTP/1.1" 403 384
Response body:
b'<ErrorResponse xmlns="https://sts.amazonaws.com/doc/2011-06-15/">
  <Error>
    <Type>Sender</Type>
    <Code>AccessDenied</Code>
    <Message>MultiFactorAuthentication failed, unable to validate MFA code.  Please verify your MFA serial number is valid and associated with this user.</Message>
  </Error>
  <RequestId>xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx</RequestId>
</ErrorResponse>'

AWS側が実際に返してきた生のレスポンスです。CLIが整形してプロンプトに表示するエラーメッセージの「元ネタ」がこれです。

こうして見ると、①〜⑤はいずれもAssumeRoleやMFAに限った話ではなく、S3・EC2などどのAWS CLIコマンドのトラブルシュートにもそのまま使える見方だと分かります。

こんなエラーの時はここを見る、簡易tips

余談: 昔はエラー文字列でgrepしたり正常系ログとの突き合わせをしていたな・・・

CLIのログに限らず、その他アプリケーション等のログの切り分けは以前は単純にエラーとなっている文字列でgrepをかけたり、「正常に動く環境のログ」と「うまくいかない環境のログ」を並べて地道に差分を追う、というのをよくやっていました。
デバッグ系のログは情報量が多く、慣れていないと見るべき箇所を見つけるだけでも一苦労です。

今はAIに渡せば一瞬で終わる作業ですが、構造を理解した上で自分の目で追ってみると、ログの中に地味に発見があって面白いものだなとなんだか懐かしさを感じました。

まとめ

原因特定が目的なら、--debugのログをAIに読ませるのが一番早いです。今回もそうでした。
とはいえ--debugの中身を読み解けるようになると、それはそれで面白いものです。
実質的に意味を持つのは「認証情報解決」「エンドポイント解決」「リクエストパラメータ」「署名プロセス」「レスポンス」の5点で、ログ1行の構造(タイムスタンプ・スレッド名・ロガー名・ログレベル)が分かっていると、grepするキーワードの目星もつけやすくなります。

なかみを見るのは楽しいですね！
ありがとうございました。

参考

• AWS CLI のエラーのトラブルシューティング
• botocore (GitHub)
• Signature Version 4 signing process - AWS General Reference