awscli >= 1.11.108 fails to resolve DNS name for DNS-compatible buckets

[tuukkamustonen]

With something like:

aws --debug s3 cp s3://some_bucket/file.zip .

With awscli-1.11.108 + botocore-1.5.71, it hangs to:

2017-07-05 13:47:11,464 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTPS connection (1): s3.amazonaws.com

With awscli-1.11.107 + botocore-1.5.70, it succeeds because:

2017-07-05 13:48:17,209 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTPS connection (1): some_bucket.s3.amazonaws.com

1.11.107 also has this:

2017-07-05 13:48:17,208 - MainThread - botocore.utils - DEBUG - Checking for DNS compatible bucket for: https://s3.amazonaws.com/some_bucket/file.zip
2017-07-05 13:48:17,208 - MainThread - botocore.utils - DEBUG - URI updated to: https://some_bucket.s3.amazonaws.com/file.zip

But these logging lines are missing in 1.11.108.

[JordonPhillips]

That was around the time we switched the default signature version to sigv4. With that signature version we do not use host style addressing by default. You can change this by setting the s3 addressing style: aws configure set s3.addressing_style virtual (more details here).

[tuukkamustonen]

Alright, I wasn't aware of that, thanks for the pointer.

I don't have my AWS account at hand now, but we are using S3 VPC endpoint and I think the problem was that path-based addressing style doesn't get resolved to the endpoint. I need to read the docs.

In any case, I don't know what is your versioning scheme, but I think this was a (breaking) change rather than a fix or new feature - shouldn't you have indicated that via a version bump, or at least made a note about the change in the changelog?

[JordonPhillips]

It shouldn't be a breaking change, s3 should be able to resolve your bucket regardless of the addressing style since it supports both. I would need more clear steps to reproduce to see what the issue is. If s3 is failing to resolve dns then that's a much bigger issue.

I am seeing a similar behavior where we also have an S3 VPC endpoint and I can no longer copy files to my EC2 instance. However I can do it if I specify our proxy which defeats the purpose of why we put in the S3 VPC endpoint

We did attempt setting aws configure set s3.addressing_style virtual and noticed that the request fails with a generic "An error occurred (400) when calling the HeadObject operation: Bad Request". However this exact same request works on the older version of the AWS cli.

[fgimian]

I can also confirm this issue on our end. Similarly, we are using a VPC Endpoint to connect to S3 on instances which don't have direct internet access.

This update was a breaking change for us and resulted in our CI Docker image builds failing.

Similarly to @pantocrator27, I have the same problem after using the suggested configuration of aws configure set s3.addressing_style virtual

fatal error: An error occurred (400) when calling the HeadObject operation: Bad Request

I'll be reverting to awscli-1.11.107 for now, which is the last version that worked for us.

Any help would be greatly appreciated folks!
Fotis

[fgimian]

Please find full debug output below (I have replaced our bucket name for privacy):

root@a01609ff484c:/# aws --debug s3 cp s3://mybucket/Dependencies/libsodium-1.0.10.tar.gz .
2017-08-17 23:57:59,073 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/1.11.136 Python/3.5.2 Linux/3.10.0-514.21.1.el7.x86_64 botocore/1.6.3
2017-08-17 23:57:59,074 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['--debug', 's3', 'cp', 's3://mybucket/Dependencies/libsodium-1.0.10.tar.gz', '.']
2017-08-17 23:57:59,074 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_scalar_parsers at 0x7ff5bd82fea0>
2017-08-17 23:57:59,074 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_assume_role_provider_cache at 0x7ff5bc8bf400>
2017-08-17 23:57:59,075 - MainThread - botocore.hooks - DEBUG - Event building-command-table.s3: calling handler <function add_waiters at 0x7ff5bd854268>
2017-08-17 23:57:59,075 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.s3.anonymous: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,076 - MainThread - botocore.hooks - DEBUG - Event building-command-table.cp: calling handler <function add_waiters at 0x7ff5bd854268>
2017-08-17 23:57:59,078 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.expires: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,078 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.quiet: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,078 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.cp: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7ff5bc900f28>
2017-08-17 23:57:59,078 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.content-disposition: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,079 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.only-show-errors: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,079 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.cp: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7ff5bc900f28>
2017-08-17 23:57:59,079 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.content-encoding: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,079 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.content-language: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,079 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.metadata-directive: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,079 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.sse-c-copy-source-key: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,079 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.website-redirect: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,079 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.ignore-glacier-warnings: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,079 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.cp: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7ff5bc900f28>
2017-08-17 23:57:59,080 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.page-size: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,080 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.expected-size: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,080 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.sse-c-key: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,080 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.anonymous: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,080 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.sse-kms-key-id: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,080 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.cache-control: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,080 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.anonymous: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,080 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.anonymous: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,080 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.metadata: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,081 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.force-glacier-transfer: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,081 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.cp: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7ff5bc900f28>
2017-08-17 23:57:59,081 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.dryrun: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,081 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.cp: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7ff5bc900f28>
2017-08-17 23:57:59,081 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.acl: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,081 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.sse: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,081 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.storage-class: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,081 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.sse-c-copy-source: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,081 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.grants: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,081 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.source-region: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,082 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.sse-c: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,082 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.paths: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,082 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.follow-symlinks: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,082 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.cp: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7ff5bc900f28>
2017-08-17 23:57:59,082 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.cp.content-type: calling handler <function uri_param at 0x7ff5bc8e7400>
2017-08-17 23:57:59,082 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: env
2017-08-17 23:57:59,082 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: assume-role
2017-08-17 23:57:59,082 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: shared-credentials-file
2017-08-17 23:57:59,083 - MainThread - botocore.credentials - INFO - Found credentials in shared credentials file: ~/.aws/credentials
2017-08-17 23:57:59,083 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/lib/python3.5/dist-packages/botocore/data/endpoints.json
2017-08-17 23:57:59,088 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/lib/python3.5/dist-packages/botocore/data/s3/2006-03-01/service-2.json
2017-08-17 23:57:59,099 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.s3: calling handler <function add_generate_presigned_post at 0x7ff5bd19af28>
2017-08-17 23:57:59,100 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.s3: calling handler <function add_generate_presigned_url at 0x7ff5bd19ad08>
2017-08-17 23:57:59,103 - MainThread - botocore.endpoint - DEBUG - Setting s3 timeout as (60, 60)
2017-08-17 23:57:59,104 - MainThread - botocore.client - DEBUG - Registering retry handlers for service: s3
2017-08-17 23:57:59,104 - MainThread - botocore.client - DEBUG - Using S3 virtual host style addressing.
2017-08-17 23:57:59,106 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.s3: calling handler <function add_generate_presigned_post at 0x7ff5bd19af28>
2017-08-17 23:57:59,106 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.s3: calling handler <function add_generate_presigned_url at 0x7ff5bd19ad08>
2017-08-17 23:57:59,109 - MainThread - botocore.endpoint - DEBUG - Setting s3 timeout as (60, 60)
2017-08-17 23:57:59,109 - MainThread - botocore.client - DEBUG - Registering retry handlers for service: s3
2017-08-17 23:57:59,110 - MainThread - botocore.client - DEBUG - Using S3 virtual host style addressing.
2017-08-17 23:57:59,111 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.s3: calling handler <function add_generate_presigned_post at 0x7ff5bd19af28>
2017-08-17 23:57:59,111 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.s3: calling handler <function add_generate_presigned_url at 0x7ff5bd19ad08>
2017-08-17 23:57:59,127 - MainThread - botocore.endpoint - DEBUG - Setting s3 timeout as (60, 60)
2017-08-17 23:57:59,128 - MainThread - botocore.client - DEBUG - Registering retry handlers for service: s3
2017-08-17 23:57:59,128 - MainThread - botocore.client - DEBUG - Using S3 virtual host style addressing.
2017-08-17 23:57:59,129 - MainThread - awscli.customizations.s3.s3handler - DEBUG - Using a multipart threshold of 8388608 and a part size of 8388608
2017-08-17 23:57:59,129 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.s3.HeadObject: calling handler <function sse_md5 at 0x7ff5bccf0bf8>
2017-08-17 23:57:59,129 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.s3.HeadObject: calling handler <function validate_bucket_name at 0x7ff5bccf0b70>
2017-08-17 23:57:59,130 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.s3.HeadObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedirector object at 0x7ff5bc0b6198>>
2017-08-17 23:57:59,130 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.s3.HeadObject: calling handler <function generate_idempotent_uuid at 0x7ff5bccf07b8>
2017-08-17 23:57:59,130 - MainThread - botocore.hooks - DEBUG - Event before-call.s3.HeadObject: calling handler <function add_expect_header at 0x7ff5bccf20d0>
2017-08-17 23:57:59,130 - MainThread - botocore.hooks - DEBUG - Event before-call.s3.HeadObject: calling handler <bound method S3RegionRedirector.set_request_url of <botocore.utils.S3RegionRedirector object at 0x7ff5bc0b6198>>
2017-08-17 23:57:59,130 - MainThread - botocore.endpoint - DEBUG - Making request for OperationModel(name=HeadObject) (verify_ssl=True) with params: {'body': b'', 'query_string': {}, 'context': {'auth_type': None, 'has_streaming_input': False, 'client_region': 'us-east-1', 'client_config': <botocore.config.Config object at 0x7ff5bc20e160>, 'signing': {'bucket': 'mybucket'}}, 'headers': {'User-Agent': 'aws-cli/1.11.136 Python/3.5.2 Linux/3.10.0-514.21.1.el7.x86_64 botocore/1.6.3'}, 'url': 'https://s3.amazonaws.com/mybucket/Dependencies/libsodium-1.0.10.tar.gz', 'method': 'HEAD', 'url_path': '/mybucket/Dependencies/libsodium-1.0.10.tar.gz'}
2017-08-17 23:57:59,131 - MainThread - botocore.hooks - DEBUG - Event request-created.s3.HeadObject: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7ff5bc20e128>>
2017-08-17 23:57:59,131 - MainThread - botocore.hooks - DEBUG - Event choose-signer.s3.HeadObject: calling handler <bound method ClientCreator._default_s3_presign_to_sigv2 of <botocore.client.ClientCreator object at 0x7ff5bc107860>>
2017-08-17 23:57:59,131 - MainThread - botocore.hooks - DEBUG - Event choose-signer.s3.HeadObject: calling handler <function set_operation_specific_signer at 0x7ff5bccf06a8>
2017-08-17 23:57:59,131 - MainThread - botocore.hooks - DEBUG - Event before-sign.s3.HeadObject: calling handler <function switch_to_virtual_host_style at 0x7ff5bd291b70>
2017-08-17 23:57:59,131 - MainThread - botocore.utils - DEBUG - Checking for DNS compatible bucket for: https://s3.amazonaws.com/mybucket/Dependencies/libsodium-1.0.10.tar.gz
2017-08-17 23:57:59,131 - MainThread - botocore.utils - DEBUG - URI updated to: https://mybucket.s3.amazonaws.com/Dependencies/libsodium-1.0.10.tar.gz
2017-08-17 23:57:59,132 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth.
2017-08-17 23:57:59,132 - MainThread - botocore.auth - DEBUG - CanonicalRequest:
HEAD
/Dependencies/libsodium-1.0.10.tar.gz

host:mybucket.s3.amazonaws.com
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20170817T235759Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-08-17 23:57:59,132 - MainThread - botocore.auth - DEBUG - StringToSign:
AWS4-HMAC-SHA256
20170817T235759Z
20170817/us-east-1/s3/aws4_request
11f6edbe52c57acba7b9ed50e7814f6733e976a3a071ffde238eea877519fc96
2017-08-17 23:57:59,132 - MainThread - botocore.auth - DEBUG - Signature:
f397441885327335f668186c4e484636e0684ca22945e2c2dc560aeca455a446
2017-08-17 23:57:59,134 - MainThread - botocore.endpoint - DEBUG - Sending http request: <PreparedRequest [HEAD]>
2017-08-17 23:57:59,135 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTPS connection (1): mybucket.s3.amazonaws.com
2017-08-17 23:57:59,160 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - DEBUG - "HEAD /Dependencies/libsodium-1.0.10.tar.gz HTTP/1.1" 400 0
2017-08-17 23:57:59,161 - MainThread - botocore.parsers - DEBUG - Response headers: {'server': 'AmazonS3', 'date': 'Thu, 17 Aug 2017 23:57:58 GMT', 'content-type': 'application/xml', 'transfer-encoding': 'chunked', 'x-amz-id-2': 'fPqW2iyAjxOuhpcNw8Q0yNrLguN5nPOuN5RzKxNiSOXTjJvSoSqEKIflJTZvuNpUe61UqbX1TYg=', 'connection': 'close', 'x-amz-request-id': 'C7AEA58F262F4BBF'}
2017-08-17 23:57:59,162 - MainThread - botocore.parsers - DEBUG - Response body:
b''
2017-08-17 23:57:59,162 - MainThread - botocore.hooks - DEBUG - Event needs-retry.s3.HeadObject: calling handler <botocore.retryhandler.RetryHandler object at 0x7ff5bc0b6160>
2017-08-17 23:57:59,162 - MainThread - botocore.retryhandler - DEBUG - No retry needed.
2017-08-17 23:57:59,162 - MainThread - botocore.hooks - DEBUG - Event needs-retry.s3.HeadObject: calling handler <bound method S3RegionRedirector.redirect_from_error of <botocore.utils.S3RegionRedirector object at 0x7ff5bc0b6198>>
2017-08-17 23:57:59,163 - MainThread - botocore.hooks - DEBUG - Event after-call.s3.HeadObject: calling handler <function enhance_error_msg at 0x7ff5bd82f9d8>
2017-08-17 23:57:59,165 - MainThread - awscli.customizations.s3.results - DEBUG - Exception caught during command execution: An error occurred (400) when calling the HeadObject operation: Bad Request
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/awscli/customizations/s3/s3handler.py", line 170, in call
    for fileinfo in fileinfos:
  File "/usr/local/lib/python3.5/dist-packages/awscli/customizations/s3/fileinfobuilder.py", line 31, in call
    for file_base in files:
  File "/usr/local/lib/python3.5/dist-packages/awscli/customizations/s3/filegenerator.py", line 142, in call
    for src_path, extra_information in file_iterator:
  File "/usr/local/lib/python3.5/dist-packages/awscli/customizations/s3/filegenerator.py", line 318, in list_objects
    yield self._list_single_object(s3_path)
  File "/usr/local/lib/python3.5/dist-packages/awscli/customizations/s3/filegenerator.py", line 353, in _list_single_object
    response = self._client.head_object(**params)
  File "/usr/local/lib/python3.5/dist-packages/botocore/client.py", line 312, in _api_call
    return self._make_api_call(operation_name, kwargs)
  File "/usr/local/lib/python3.5/dist-packages/botocore/client.py", line 601, in _make_api_call
    raise error_class(parsed_response, operation_name)
botocore.exceptions.ClientError: An error occurred (400) when calling the HeadObject operation: Bad Request
fatal error: An error occurred (400) when calling the HeadObject operation: Bad Request
2017-08-17 23:57:59,166 - Thread-1 - awscli.customizations.s3.results - DEBUG - Shutdown request received in result processing thread, shutting down result thread.
root@a01609ff484c:/#

[cwgem]

With regards to the VPC endpoint usage, I think that the original path style is going to be required, versus the virtual style addressing. Endpoints are meant to re-route specific service endpoints for you in cases such as trying to utilize S3 in a private subnet which cannot interact with a NAT gateway/instance. I'd recommend looking over #1330 which goes into how to interact properly with S3 buckets managed through a VPC endpoint.

[fgimian]

Thanks @cwgem, I'll check it out and let you know how I get on 😄