s3api - 500 r_code when ls a container + wrong date + swift cli getting 403

[Florian Coutard]

Hello,

We are trying to implement the s3api module on our proxy servers, recently upgraded to ussuri version.

We are having the following issues:
- getting 500 error code when trying to ls a bucket/container with aws cli
- getting 403 errors when trying to curl/use swift cli to manage a project when s3api module is enabled
- all buckets are created with "2009-02-03 17:45:09 " date.

We need your help on this as we are unable to see what's wrong with the s3 listing command for a bucket, and why it is preventing swift cli to be used.

Thank you in advance for your input and merry Xmas to you :)

##############################################################

here are some informations:

- We have followed the documentation provided:
https://docs.openstack.org/swift/latest/middleware.html#s3api-s-acls-implementation
- We have succesfully created the ec2 credentials.
- We are testing with s3cmd and aws cli endpoint as suggested here : https://docs.openio.io/latest/source/user-guide/awscli.html or https://docs.ovh.com/ca/fr/public-cloud/swift-s3api/.

We are able to :
- list containers/buckets inside a swift project
aws s3 ls
2009-02-03 17:45:09 container
2009-02-03 17:45:09 container12
2009-02-03 17:45:09 container123456
2009-02-03 17:45:09 container_dev
2009-02-03 17:45:09 container_s3
2009-02-03 17:45:09 container_test_s3
2009-02-03 17:45:09 containerlol
2009-02-03 17:45:09 sergetest
2009-02-03 17:45:09 test-bucket
2009-02-03 17:45:09 test123
2009-02-03 17:45:09 testbucket
2009-02-03 17:45:09 testbucket2

- create a container/bucket
aws --profile default s3 mb s3://bucketopendev
make_bucket: bucketopendev

- upload an object to a container/bucket
 aws --profile default s3 cp test s3://bucketopendev
upload: ./test to s3://bucketopendev/test

- remove an object inside a container/bucket

aws --profile default s3 rm s3://bucketopendev/test
delete: s3://bucketopendev/test
- remove a container/bucket
aws --profile default s3 rb s3://bucketopendev
remove_bucket: bucketopendev

.aws/config file:
cat .aws/config
[plugins]
endpoint = awscli_plugin_endpoint

[default]
aws_access_key_id = 5eXXXXX33981e4
aws_secret_access_key = 816fXXXXX0cb403f2a
s3 =
 endpoint_url = https://api.dev.cdn.net
 signature_version = s3v4

- proxy configuration that might be usefull :
[pipeline:main]
pipeline = catch_errors healthcheck cache authtoken s3api s3token keystoneauth proxy-logging bulk account-quotas container-quotas proxy-server
[app:proxy-server]
use = egg:swift#proxy
allow_account_management = true
account_autocreate = true
request_node_count = 2 * replicas
[filter:authtoken]
paste.filter_factory = keystonemiddleware.auth_token:filter_factory
admin_tenant_name = XW
admin_user = swift
admin_password = X
auth_host = api.ks
auth_port = 443
auth_protocol = https
identity_uri = https://api.ks/admin/
auth_uri = https://api.ks/public/
signing_dir = /tmp/keystone-signing-swift
delay_auth_decision = True
[filter:s3api]
use = egg:swift#s3api
s3_acl = false
dns_compliant_bucket_names = false
check_bucket_owner = false
force_swift_request_proxy_log = True
storage_domain = api.dev.cdn.net
[filter:s3token]
use = egg:swift#s3token
reseller_prefix = AUTH_
delay_auth_decision = True
auth_uri = https://api.ks/public/v3
http_timeout = 10.0
log_name = s3token

Issues seen:

- we are now unable to use the SWIFT CLI, getting a 403. It looks like the s3api is getting ALL the requests as you can see when trying to authenticate to swift after getting a keystone token:
SWIFT CALL FAILED: $VAR1 = {
          'url' => 'https://api.dev.cdn.net/v1/AUTH_supervision',
          'status' => '403',
          'headers' => {
                         'x-amz-id-2' => 'tx863bd0560f1648209f066-005fe4647a',
                         'x-amz-request-id' => 'tx863bd0560f1648209f066-005fe4647a',
                         'server' => 'nginx/1.14.0 (Ubuntu)',
                         'x-trans-id' => 'tx863bd0560f1648209f066-005fe4647a',
                         'x-openstack-request-id' => 'tx863bd0560f1648209f066-005fe4647a',
                         'date' => 'Thu, 24 Dec 2020 09:50:50 GMT',
                         'content-type' => 'application/xml',
                         'connection' => 'keep-alive'
                       },
          'protocol' => 'HTTP/1.1',
          'success' => '',
          'reason' => 'Forbidden'
        };

When s3api is disabled we are able to use swift cli again .

- error 500 when trying to ls a container :
I've run a debug command if it can help. Trying to list rthe bucket that contains an object i've just uploaded :

24-12-2020 10:43:20 :] fcoutard@fcoutard /home/fcoutard : aws --profile default s3 mb s3://bucketopendev
make_bucket: bucketopendev
24-12-2020 10:43:34 :] fcoutard@fcoutard /home/fcoutard : aws s3 ls
2009-02-03 17:45:09 bucketopendev
2009-02-03 17:45:09 container

24-12-2020 10:43:37 :] fcoutard@fcoutard /home/fcoutard : vi test
24-12-2020 10:43:57 :] fcoutard@fcoutard /home/fcoutard : aws --profile default s3 cp test s3://bucketopendev
upload: ./test to s3://bucketopendev/test

s3cmd debug mode is more verbose so i'm using this one :
DEBUG: Command: ls
DEBUG: Bucket 's3://bucketopendev':
DEBUG: CreateRequest: resource[uri]=/
DEBUG: ===== SEND Inner request to determine the bucket region =====
DEBUG: CreateRequest: resource[uri]=/
DEBUG: Using signature v4
DEBUG: get_hostname(bucketopendev): api.dev.cdn.net
DEBUG: canonical_headers = host:api.dev.cdn.net
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20201224T101500Z

DEBUG: Canonical Request:
GET
/bucketopendev/
location=
host:api.dev.cdn.net
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20201224T101500Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
----------------------
DEBUG: signature-v4 headers: {'x-amz-date': '20201224T101500Z', 'Authorization': 'AWS4-HMAC-SHA256 Credential=5e466e028db8492da4ddabe6433981e4/20201224/us-east-1/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date,Signature=a1b961f33b9a783f738f0298753fd47558c6295a97b5288be762c744c1ce8ea0', 'x-amz-content-sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855'}
DEBUG: Processing request, please wait...
DEBUG: get_hostname(bucketopendev): api.dev.cdn.net
DEBUG: ConnMan.get(): creating new connection: https://api.dev.cdn.net
DEBUG: Using ca_certs_file None
DEBUG: httplib.HTTPSConnection() has both context and check_hostname
DEBUG: non-proxied HTTPSConnection(api.dev.cdn.net, None)
DEBUG: format_uri(): /bucketopendev/?location
DEBUG: Sending request method_string='GET', uri='/bucketopendev/?location', headers={'x-amz-date': '20201224T101500Z', 'Authorization': 'AWS4-HMAC-SHA256 Credential=5e466e028db8492da4ddabe6433981e4/20201224/us-east-1/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date,Signature=a1b961f33b9a783f738f0298753fd47558c6295a97b5288be762c744c1ce8ea0', 'x-amz-content-sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855'}, body=(0 bytes)
DEBUG: ConnMan.put(): connection put back to pool (https://api.dev.cdn.net#1)
DEBUG: Response:
{'data': b"<?xml version='1.0' encoding='UTF-8'?>\n<LocationConstraint xmlns"
         b'="http://s3.amazonaws.com/doc/2006-03-01/"/>',
 'headers': {'connection': 'keep-alive',
             'content-length': '108',
             'content-type': 'application/xml',
             'date': 'Thu, 24 Dec 2020 10:15:00 GMT',
             'server': 'nginx/1.14.0 (Ubuntu)',
             'x-amz-id-2': 'txf7ea2b8c43aa44c783050-005fe46a24',
             'x-amz-request-id': 'txf7ea2b8c43aa44c783050-005fe46a24',
             'x-openstack-request-id': 'txf7ea2b8c43aa44c783050-005fe46a24',
             'x-trans-id': 'txf7ea2b8c43aa44c783050-005fe46a24'},
 'reason': 'OK',
 'status': 200}
DEBUG: ===== SUCCESS Inner request to determine the bucket region ('us-east-1') =====
DEBUG: Using signature v4
DEBUG: get_hostname(bucketopendev): api.dev.cdn.net
DEBUG: canonical_headers = host:api.dev.cdn.net
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20201224T101500Z

DEBUG: Canonical Request:
GET
/bucketopendev/
delimiter=%2F
host:api.dev.cdn.net
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20201224T101500Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
----------------------
DEBUG: signature-v4 headers: {'x-amz-date': '20201224T101500Z', 'Authorization': 'AWS4-HMAC-SHA256 Credential=5e466e028db8492da4ddabe6433981e4/20201224/us-east-1/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date,Signature=954e8893faa07b5c5835cbb0b67d2749d8350e8633571e6193af97cbce431066', 'x-amz-content-sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855'}
DEBUG: Processing request, please wait...
DEBUG: get_hostname(bucketopendev): api.dev.cdn.net
DEBUG: ConnMan.get(): re-using connection: https://api.dev.cdn.net#1
DEBUG: format_uri(): /bucketopendev/?delimiter=%2F
DEBUG: Sending request method_string='GET', uri='/bucketopendev/?delimiter=%2F', headers={'x-amz-date': '20201224T101500Z', 'Authorization': 'AWS4-HMAC-SHA256 Credential=5e466e028db8492da4ddabe6433981e4/20201224/us-east-1/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date,Signature=954e8893faa07b5c5835cbb0b67d2749d8350e8633571e6193af97cbce431066', 'x-amz-content-sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855'}, body=(0 bytes)
DEBUG: ConnMan.put(): connection put back to pool (https://api.dev.cdn.net#2)
DEBUG: Response:
{'data': b"<?xml version='1.0' encoding='UTF-8'?>\n<Error><Code>InternalErro"
         b'r</Code><Message>We encountered an internal error. Please try again.'
         b'</Message><RequestId>tx4be0e45646954d11b0ef4-005fe46a24</RequestId><'
         b'Reason>Expecting value: line 1 column 1 (char 0)'
         b'</Reason></Error>',
 'headers': {'connection': 'keep-alive',
             'content-type': 'application/xml',
             'date': 'Thu, 24 Dec 2020 10:15:00 GMT',
             'server': 'nginx/1.14.0 (Ubuntu)',
             'transfer-encoding': 'chunked',
             'x-amz-id-2': 'tx4be0e45646954d11b0ef4-005fe46a24',
             'x-amz-request-id': 'tx4be0e45646954d11b0ef4-005fe46a24',
             'x-openstack-request-id': 'tx4be0e45646954d11b0ef4-005fe46a24',
             'x-trans-id': 'tx4be0e45646954d11b0ef4-005fe46a24'},
 'reason': 'Internal Server Error',
 'status': 500}
DEBUG: S3Error: 500 (Internal Server Error)
DEBUG: HttpHeader: server: nginx/1.14.0 (Ubuntu)
DEBUG: HttpHeader: date: Thu, 24 Dec 2020 10:15:00 GMT
DEBUG: HttpHeader: content-type: application/xml
DEBUG: HttpHeader: transfer-encoding: chunked
DEBUG: HttpHeader: connection: keep-alive
DEBUG: HttpHeader: x-amz-id-2: tx4be0e45646954d11b0ef4-005fe46a24
DEBUG: HttpHeader: x-amz-request-id: tx4be0e45646954d11b0ef4-005fe46a24
DEBUG: HttpHeader: x-trans-id: tx4be0e45646954d11b0ef4-005fe46a24
DEBUG: HttpHeader: x-openstack-request-id: tx4be0e45646954d11b0ef4-005fe46a24
DEBUG: ErrorXML: Code: 'InternalError'
DEBUG: ErrorXML: Message: 'We encountered an internal error. Please try again.'
DEBUG: ErrorXML: RequestId: 'tx4be0e45646954d11b0ef4-005fe46a24'
DEBUG: ErrorXML: Reason: 'Expecting value [[test\ntest1\n]]: line 1 column 1 (char 0)'
WARNING: Retrying failed request: /?delimiter=%2F (500 (InternalError): We encountered an internal error. Please try again.)
WARNING: Waiting 3 sec...

By displaying the error string in the python code we were able to see that : Expecting value: line 1 column 1 (char 0)' was :
'Reason>Expecting value [[test\ntest1\n]]: line 1 column 1 (char 0)' so we can it contains the 2 objects but it is not displayed properly.

On the proxy we are getting the following error output:
Expecting value: line 1 column 1 (char 0): #012Traceback (most recent call last):#012
File "/usr/lib/python3/dist-packages/swift/common/middleware/s3api/s3api.py", line 292, in __call__#012 resp = self.handle_request(req)#012
File "/usr/lib/python3/dist-packages/swift/common/middleware/s3api/s3api.py", line 328, in handle_request#012 res = handler(req)#012
File "/usr/lib/python3/dist-packages/swift/common/middleware/s3api/controllers/bucket.py", line 307, in GET#012 objects = json.loads(resp.body)#012
File "/usr/lib/python3.6/json/__init__.py", line 354, in loads#012 return _default_decoder.decode(s)#012
File "/usr/lib/python3.6/json/decoder.py", line 339, in decode#012 obj, end = self.raw_decode(s, idx=_w(s, 0).end())#012
File "/usr/lib/python3.6/json/decoder.py", line 355, in raw_decode#012 raise JSONDecodeError("Expecting value", s, err.value) from None#012json.decoder.JSONDecodeError: Expecting value [[test\ntest1\n]]: line 1 column 1 (char 0) (txn: t tx4be0e45646954d11b0ef4-005fe46a24) (client_ip: 127.0.0.1)

[Tim Burke (1-tim-z)]

Thank you for the detailed bug report! The problem seems to be our middleware auto-insertion, for listing_formats in particular. I expect when your proxy starts you see log lines like

Adding required filter versioned_writes to pipeline at position 8
Adding required filter dlo to pipeline at position 8
Adding required filter copy to pipeline at position 8
Adding required filter listing_formats to pipeline at position 8
Adding required filter gatekeeper to pipeline at position 1
Pipeline was modified. New pipeline is "catch_errors gatekeeper healthcheck cache authtoken s3api s3token keystoneauth proxy-logging listing_formats copy dlo versioned_writes bulk account-quotas container-quotas proxy-server".

The specific issue is how far to the right we insert the listing_formats middleware; we want it pretty close to the client so other middleware can rely on receiving JSON listings. The reason comes down to the limitations of how we do auto-insertion and the fact that there's only one instance of proxy-logging in the pipeline. We've recommended two for a while (see https://github.com/openstack/swift/commit/a622349) -- but as long as old configs were working, I completely understand the desire to not muck with them.

I think a pipeline like

pipeline = catch_errors healthcheck proxy-logging cache authtoken s3api s3token keystoneauth bulk account-quotas container-quotas proxy-logging proxy-server

should get you squared; there will be some auto-insertion going on, but it should arrive at much better placement. FWIW, we've had some patches (like https://review.opendev.org/c/openstack/swift/+/635040 and https://review.opendev.org/c/openstack/swift/+/504472) to try to help with this general problem, but haven't polished any of them to the point of being able to land them on master :-/

[Florian Coutard (flo06800)]

Hello Tim !

Sorry, i was on vacations these last 2 weeks, I did not have the chance to look at this !
We'll check that this week and will get back to you as soon as we have tested this workaround.

[Florian Coutard (flo06800)]

Hello Tim,

So far so good, the workaround you've mentionned is working great ! We are able to have both swift api and s3api working on our proxy.

The only issue remaining that I can see at the moment is the following:
when I do an "ls" command with s3api in the project, i'm seeing all containers/buckets created in 2009. But when I do an "ls" inside a bucket/container, i'm seeing correct dates.

Here is an example:
15-01-2021 14:18:46 :] : s3cmd ls
2009-02-03 16:45 s3://autretest
2009-02-03 16:45 s3://bucketopendev
2009-02-03 16:45 s3://container
2009-02-03 16:45 s3://container12
2009-02-03 16:45 s3://container123456
2009-02-03 16:45 s3://container13
2009-02-03 16:45 s3://container_dev
2009-02-03 16:45 s3://container_s3
2009-02-03 16:45 s3://container_test_s3
2009-02-03 16:45 s3://containerlol
2009-02-03 16:45 s3://sergetest
2009-02-03 16:45 s3://test-bucket
2009-02-03 16:45 s3://test123
2009-02-03 16:45 s3://testbucket
2009-02-03 16:45 s3://testbucket2
15-01-2021 14:18:49 :] s3cmd ls s3://testbucket2
2020-12-23 10:42 4802 s3://testbucket2/README.md

Any idea on why we are seeing this behaviour ?

Thanks a lot !

[Florian Coutard (flo06800)]

Hello Tim, just checking if you had any chances to look into our last message ?

Thanks !