AWS CLIでDEBUGレベルのログを出力する

AWS CLIでDEBUGレベルのログを出力する方法の備忘録です。

はじめに

AWS CLIをDEBUGモードで実行したくなったので、やり方の備忘録メモを残します。

AWS CLIでDEBUGレベルのログを出力する

やり方

--debugオプションを付けるだけで、DEBUGレベルのログを出力することができます。

この--debugオプションはaws cliのグローバルオプションなので、どのAWSコマンドでも使用可能です。

AWSユーザーガイドによると、

• 認証情報の検証
• パラメータのパース
• AWSに送信するリクエストの構成
• AWSに送信されたリクエストの内容
• レスポンスの生データ
• フォーマットされた出力

などの詳細が見れるとのこと。

実行例

では、実際にデバッグモードでawsコマンドを実行してみます。

aws sts get-caller-identityコマンドを--debugオプション付きで実行し、どんな情報が見れるのかを眺めてみます。

--debugオプションなしで実行した場合の出力例：

$ aws sts get-caller-identity
{
    "UserId": "AIDAXXXX",
    "Account": "123456789012",
    "Arn": "arn:aws:iam::123456789012:user/test"
}

--debugオプションありで実行した場合の出力例：

$ aws sts get-caller-identity --debug
2024-12-09 07:28:46,829 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/2.11.2 Python/3.11.2 Darwin/23.0.0 exe/x86_64
2024-12-09 07:28:46,829 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['sts', 'get-caller-identity', '--debug']
2024-12-09 07:28:46,846 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_s3 at 0x10dd29580>
2024-12-09 07:28:46,846 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_ddb at 0x10db5aac0>
2024-12-09 07:28:46,846 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method BasicCommand.add_command of <class 'awscli.customizations.configure.configure.ConfigureCommand'>>
2024-12-09 07:28:46,846 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function change_name at 0x10d570a40>
2024-12-09 07:28:46,846 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function change_name at 0x10d572020>
2024-12-09 07:28:46,846 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function alias_opsworks_cm at 0x10dd2ba60>
2024-12-09 07:28:46,846 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_history_commands at 0x10dbad4e0>
2024-12-09 07:28:46,846 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method BasicCommand.add_command of <class 'awscli.customizations.devcommands.CLIDevCommand'>>
2024-12-09 07:28:46,846 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <function add_waiters at 0x10dd2b920>
2024-12-09 07:28:46,846 - MainThread - botocore.hooks - DEBUG - Event building-command-table.main: calling handler <bound method AliasSubCommandInjector.on_building_command_table of <awscli.alias.AliasSubCommandInjector object at 0x10dde3a10>>
2024-12-09 07:28:46,846 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/awscli/data/cli.json
2024-12-09 07:28:46,847 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_types at 0x10dc62ca0>
2024-12-09 07:28:46,847 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function no_sign_request at 0x10dc62fc0>
2024-12-09 07:28:46,847 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_verify_ssl at 0x10dc62f20>
2024-12-09 07:28:46,847 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_cli_read_timeout at 0x10dc63100>
2024-12-09 07:28:46,847 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <function resolve_cli_connect_timeout at 0x10dc63060>
2024-12-09 07:28:46,847 - MainThread - botocore.hooks - DEBUG - Event top-level-args-parsed: calling handler <built-in method update of dict object at 0x10dde0d00>
2024-12-09 07:28:46,848 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/2.11.2 Python/3.11.2 Darwin/23.0.0 exe/x86_64 prompt/off
2024-12-09 07:28:46,848 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['sts', 'get-caller-identity', '--debug']
2024-12-09 07:28:46,848 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_timestamp_parser at 0x10dd29ee0>
2024-12-09 07:28:46,848 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function register_uri_param_handler at 0x10d324400>
2024-12-09 07:28:46,848 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_binary_formatter at 0x10ddacea0>
2024-12-09 07:28:46,848 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function no_pager_handler at 0x10d2f4b80>
2024-12-09 07:28:46,848 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_assume_role_provider_cache at 0x10d349d00>
2024-12-09 07:28:46,855 - MainThread - botocore.utils - DEBUG - IMDS ENDPOINT: http://169.254.169.254/
2024-12-09 07:28:46,858 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function attach_history_handler at 0x10db95da0>
2024-12-09 07:28:46,858 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_json_file_cache at 0x10db4ed40>
2024-12-09 07:28:46,866 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/awscli/botocore/data/sts/2011-06-15/service-2.json
2024-12-09 07:28:46,867 - MainThread - botocore.hooks - DEBUG - Event building-command-table.sts: calling handler <function add_waiters at 0x10dd2b920>
2024-12-09 07:28:46,874 - MainThread - botocore.hooks - DEBUG - Event building-command-table.sts: calling handler <bound method AliasSubCommandInjector.on_building_command_table of <awscli.alias.AliasSubCommandInjector object at 0x10dde3a10>>
2024-12-09 07:28:46,874 - MainThread - awscli.clidriver - DEBUG - OrderedDict()
2024-12-09 07:28:46,874 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.sts.get-caller-identity: calling handler <function add_streaming_output_arg at 0x10dd2a3e0>
2024-12-09 07:28:46,875 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.sts.get-caller-identity: calling handler <function add_cli_input_json at 0x10d34a660>
2024-12-09 07:28:46,875 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.sts.get-caller-identity: calling handler <function add_cli_input_yaml at 0x10d34a700>
2024-12-09 07:28:46,875 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.sts.get-caller-identity: calling handler <function unify_paging_params at 0x10db5b100>
2024-12-09 07:28:46,882 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/awscli/botocore/data/sts/2011-06-15/paginators-1.json
2024-12-09 07:28:46,882 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.sts.get-caller-identity: calling handler <function add_generate_skeleton at 0x10dc614e0>
2024-12-09 07:28:46,882 - MainThread - botocore.hooks - DEBUG - Event before-building-argument-table-parser.sts.get-caller-identity: calling handler <bound method OverrideRequiredArgsArgument.override_required_args of <awscli.customizations.cliinput.CliInputJSONArgument object at 0x10de4f250>>
2024-12-09 07:28:46,882 - MainThread - botocore.hooks - DEBUG - Event before-building-argument-table-parser.sts.get-caller-identity: calling handler <bound method OverrideRequiredArgsArgument.override_required_args of <awscli.customizations.cliinput.CliInputYAMLArgument object at 0x10ce2d050>>
2024-12-09 07:28:46,882 - MainThread - botocore.hooks - DEBUG - Event before-building-argument-table-parser.sts.get-caller-identity: calling handler <bound method GenerateCliSkeletonArgument.override_required_args of <awscli.customizations.generatecliskeleton.GenerateCliSkeletonArgument object at 0x10de4fe50>>
2024-12-09 07:28:46,882 - MainThread - botocore.hooks - DEBUG - Event building-command-table.sts_get-caller-identity: calling handler <function add_waiters at 0x10dd2b920>
2024-12-09 07:28:46,882 - MainThread - botocore.hooks - DEBUG - Event building-command-table.sts_get-caller-identity: calling handler <bound method AliasSubCommandInjector.on_building_command_table of <awscli.alias.AliasSubCommandInjector object at 0x10dde3a10>>
2024-12-09 07:28:46,883 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.sts.get-caller-identity.cli-input-json: calling handler <awscli.paramfile.URIArgumentHandler object at 0x10d0a97d0>
2024-12-09 07:28:46,883 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.sts.get-caller-identity.cli-input-yaml: calling handler <awscli.paramfile.URIArgumentHandler object at 0x10d0a97d0>
2024-12-09 07:28:46,883 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.sts.get-caller-identity.generate-cli-skeleton: calling handler <awscli.paramfile.URIArgumentHandler object at 0x10d0a97d0>
2024-12-09 07:28:46,883 - MainThread - botocore.hooks - DEBUG - Event calling-command.sts.get-caller-identity: calling handler <bound method CliInputArgument.add_to_call_parameters of <awscli.customizations.cliinput.CliInputJSONArgument object at 0x10de4f250>>
2024-12-09 07:28:46,883 - MainThread - botocore.hooks - DEBUG - Event calling-command.sts.get-caller-identity: calling handler <bound method CliInputArgument.add_to_call_parameters of <awscli.customizations.cliinput.CliInputYAMLArgument object at 0x10ce2d050>>
2024-12-09 07:28:46,883 - MainThread - botocore.hooks - DEBUG - Event calling-command.sts.get-caller-identity: calling handler <bound method GenerateCliSkeletonArgument.generate_skeleton of <awscli.customizations.generatecliskeleton.GenerateCliSkeletonArgument object at 0x10de4fe50>>
2024-12-09 07:28:46,883 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: env
2024-12-09 07:28:46,883 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: assume-role
2024-12-09 07:28:46,883 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: assume-role-with-web-identity
2024-12-09 07:28:46,883 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: sso
2024-12-09 07:28:46,883 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: shared-credentials-file
2024-12-09 07:28:46,883 - MainThread - botocore.credentials - INFO - Found credentials in shared credentials file: ~/.aws/credentials
2024-12-09 07:28:46,884 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/awscli/botocore/data/endpoints.json
2024-12-09 07:28:46,890 - MainThread - botocore.hooks - DEBUG - Event choose-service-name: calling handler <function handle_service_name_alias at 0x10c0471a0>
2024-12-09 07:28:46,898 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/awscli/botocore/data/sts/2011-06-15/endpoint-rule-set-1.json
2024-12-09 07:28:46,898 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/aws-cli/awscli/botocore/data/partitions.json
2024-12-09 07:28:46,898 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.sts: calling handler <function add_generate_presigned_url at 0x10bf97920>
2024-12-09 07:28:46,915 - MainThread - botocore.endpoint - DEBUG - Setting sts timeout as (60, 60)
2024-12-09 07:28:46,916 - MainThread - botocore.regions - DEBUG - Calling endpoint provider with parameters: {'Region': 'ap-northeast-1', 'UseDualStack': False, 'UseFIPS': False, 'UseGlobalEndpoint': False}
2024-12-09 07:28:46,916 - MainThread - botocore.regions - DEBUG - Endpoint provider result: https://sts.ap-northeast-1.amazonaws.com
2024-12-09 07:28:46,916 - MainThread - botocore.hooks - DEBUG - Event provide-client-params.sts.GetCallerIdentity: calling handler <function base64_decode_input_blobs at 0x10ddacf40>
2024-12-09 07:28:46,916 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.sts.GetCallerIdentity: calling handler <function generate_idempotent_uuid at 0x10c065440>
2024-12-09 07:28:46,916 - MainThread - botocore.hooks - DEBUG - Event before-call.sts.GetCallerIdentity: calling handler <function inject_api_version_header_if_needed at 0x10c066f20>
2024-12-09 07:28:46,916 - MainThread - botocore.endpoint - DEBUG - Making request for OperationModel(name=GetCallerIdentity) with params: {'url_path': '/', 'query_string': '', 'method': 'POST', 'headers': {'Content-Type': 'application/x-www-form-urlencoded; charset=utf-8', 'User-Agent': 'aws-cli/2.11.2 Python/3.11.2 Darwin/23.0.0 exe/x86_64 prompt/off command/sts.get-caller-identity'}, 'body': {'Action': 'GetCallerIdentity', 'Version': '2011-06-15'}, 'url': 'https://sts.ap-northeast-1.amazonaws.com/', 'context': {'client_region': 'ap-northeast-1', 'client_config': <botocore.config.Config object at 0x10e27bd50>, 'has_streaming_input': False, 'auth_type': None}}
2024-12-09 07:28:46,916 - MainThread - botocore.hooks - DEBUG - Event request-created.sts.GetCallerIdentity: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x10de42a90>>
2024-12-09 07:28:46,916 - MainThread - botocore.hooks - DEBUG - Event choose-signer.sts.GetCallerIdentity: calling handler <function set_operation_specific_signer at 0x10c065300>
2024-12-09 07:28:46,917 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth.
2024-12-09 07:28:46,917 - MainThread - botocore.auth - DEBUG - CanonicalRequest:
POST
/

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

content-type;host;x-amz-date
ab821ae955788b0e33ebd34c201234567890
2024-12-09 07:28:46,917 - MainThread - botocore.auth - DEBUG - StringToSign:
AWS4-HMAC-SHA256
20241208T222846Z
20241208/ap-northeast-1/sts/aws4_request
b2e9356b9b388ac58afe62ed0771234567890
2024-12-09 07:28:46,917 - MainThread - botocore.auth - DEBUG - Signature:
69b9646e8259eba6a76f1fe0d12345678
2024-12-09 07:28:46,917 - MainThread - botocore.endpoint - DEBUG - Sending http request: <AWSPreparedRequest stream_output=False, method=POST, url=https://sts.ap-northeast-1.amazonaws.com/, headers={'Content-Type': b'application/x-www-form-urlencoded; charset=utf-8', 'User-Agent': b'aws-cli/2.11.2 Python/3.11.2 Darwin/23.0.0 exe/x86_64 prompt/off command/sts.get-caller-identity', 'X-Amz-Date': b'20241208T222846Z', 'Authorization': b'AWS4-HMAC-SHA256 Credential=AKIA123456EXAMPLE/20241208/ap-northeast-1/sts/aws4_request, SignedHeaders=content-type;host;x-amz-date, Signature=69b9646e8259eba6a76f1f1234567890', 'Content-Length': '43'}>
2024-12-09 07:28:46,918 - MainThread - botocore.httpsession - DEBUG - Certificate path: /usr/local/aws-cli/awscli/botocore/cacert.pem
2024-12-09 07:28:46,918 - MainThread - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): sts.ap-northeast-1.amazonaws.com:443
2024-12-09 07:28:47,001 - MainThread - urllib3.connectionpool - DEBUG - https://sts.ap-northeast-1.amazonaws.com:443 "POST / HTTP/1.1" 200 401
2024-12-09 07:28:47,001 - MainThread - botocore.parsers - DEBUG - Response headers: {'x-amzn-RequestId': 'eb292a1e-69ab-439a-acf5-991e8deb148f', 'Content-Type': 'text/xml', 'Content-Length': '401', 'Date': 'Sun, 08 Dec 2024 22:28:46 GMT'}
2024-12-09 07:28:47,001 - MainThread - botocore.parsers - DEBUG - Response body:
b'<GetCallerIdentityResponse xmlns="https://sts.amazonaws.com/doc/2011-06-15/">\n  <GetCallerIdentityResult>\n    <Arn>arn:aws:iam::123456789012:user/test</Arn>\n    <UserId>AIDAXXXX</UserId>\n    <Account>123456789012</Account>\n  </GetCallerIdentityResult>\n  <ResponseMetadata>\n    <RequestId>eb292a1e-69ab-439a-acf5-991e8deb148f</RequestId>\n  </ResponseMetadata>\n</GetCallerIdentityResponse>\n'
2024-12-09 07:28:47,003 - MainThread - botocore.hooks - DEBUG - Event needs-retry.sts.GetCallerIdentity: calling handler <bound method RetryHandler.needs_retry of <botocore.retries.standard.RetryHandler object at 0x10e282010>>
2024-12-09 07:28:47,004 - MainThread - botocore.retries.standard - DEBUG - Not retrying request.
2024-12-09 07:28:47,004 - MainThread - botocore.hooks - DEBUG - Event after-call.sts.GetCallerIdentity: calling handler <bound method RetryQuotaChecker.release_retry_quota of <botocore.retries.standard.RetryQuotaChecker object at 0x10de16ad0>>
2024-12-09 07:28:47,004 - MainThread - awscli.formatter - DEBUG - RequestId: eb292a1e-69ab-439a-acf5-991e8deb148f
{
    "UserId": "AIDAXXXXX",
    "Account": "123456789012",
    "Arn": "arn:aws:iam::123456789012:user/test"
}

これらDEBUGログを読み解くことで、このaws sts get-caller-identityコマンドが実行している処理が見えてきます：

1. CLIの初期化/コマンド引数解析
2. フックの読み込み/コマンドテーブルや引数テーブルの構築
3. セッションの初期化
4. STSサービスデータの読み込み
5. 引数とコマンドの準備
6. 認証情報の取得
7. エンドポイントとクライアント設定
8. リクエストの作成と署名
9. HTTPSリクエストの送信
10. レスポンスの処理

不具合が出たときにはこのように--debugオプションを付けることで、どの部分の処理でどのようなエラーが出てるのか、切り分けがやり易くなります。

おわりに

AWS CLIもDEBUGモードで実行する方法と、その実行例の解読をしました。

余談ですが、aws cliは内部でbotocoreを利用してたんですね、これまで意識してませんでした。

以上、どなたかの参考になれば幸いです。

Follow @bioerrorlog

[関連記事]

www.bioerrorlog.work

参考

• Troubleshooting errors for the AWS CLI - AWS Command Line Interface
• aws — AWS CLI 2.22.12 Command Reference
• aws — AWS CLI 1.36.17 Command Reference