HEAD doesn't return Content-Length header due to catch_errors middleware

[Bhaskar Singhal]

Hello,

I am using CloudBerry to connect to my swift cluster running stable/rocky.

The PUT using cloudberry keeps failing with error (with use Native multi part enabled):
"The server committed a protocol violation. Section=ResponseStatusLine"

The tcpdump shows, that the HEAD response doesn't have Content-Length:0 instead it returns some weird 0 after the headers

HEAD /bucket1/readme.txt HTTP/1.1
User-Agent: CloudBerryLab.Base.HttpUtil.Client 5.9.1 (http://www.cloudberrylab.com/)
x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date: 20191213T105213Z
Authorization: AWS4-HMAC-SHA256 Credential=31b18fccbc88419eb9fcff817af61691/20191213/us-east-1/s3/aws4_request, SignedHeaders=host;user-agent;x-amz-content-sha256;x-amz-date,Signature=c5f65d54374793e9fa6b3becc972de26f53841233e7235196a5b4cca34b8372d
Host: xxxxxxxxxxxxxxxxxxxxx
Connection: Keep-Alive

HTTP/1.1 404 Not Found
x-amz-id-2: tx8a57cd08353143d9bf16a-005df36d5d
x-amz-request-id: tx8a57cd08353143d9bf16a-005df36d5d
Content-Type: application/xml
X-Trans-Id: tx8a57cd08353143d9bf16a-005df36d5d
X-Openstack-Request-Id: tx8a57cd08353143d9bf16a-005df36d5d
Date: Fri, 13 Dec 2019 10:52:13 GMT
Transfer-Encoding: chunked
Connection: keep-alive

0

Upon looking further into this, it looks like this is happening due to the catch_errors.py middleware
probably due to the following (and related) commit https://github.com/openstack/swift/commit/8bfb97a3a8bfe1a1db66560a9dba21277b0c006e#diff-9bcb4cdced486a5ce0f1885ac33009fa

If I disable the enforce_byte_count logic then I get a response with Content-Length header

--- a/swift/common/middleware/catch_errors.py
+++ b/swift/common/middleware/catch_errors.py
@@ -100,10 +100,11 @@ class CatchErrorsContext(WSGIContext):
         # the socket. In that case, we truncate the response body at N bytes
         # and raise an exception to stop any more bytes from being
         # generated and also to kill the TCP connection.
- if env['REQUEST_METHOD'] == 'HEAD':
- resp = enforce_byte_count(resp, 0)
+ #if env['REQUEST_METHOD'] == 'HEAD':
+ # resp = enforce_byte_count(resp, 0)

- elif self._response_headers:
+ #elif self._response_headers:
+ if self._response_headers:
             content_lengths = [val for header, val in self._response_headers
                                if header.lower() == "content-length"]
             if len(content_lengths) == 1:

Response as captured by tcpdump
HEAD /bucket1/errorlog.html HTTP/1.1
User-Agent: CloudBerryLab.Base.HttpUtil.Client 5.9.1 (http://www.cloudberrylab.com/)
x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date: 20191213T102421Z
Authorization: AWS4-HMAC-SHA256 Credential=31b18fccbc88419eb9fcff817af61691/20191213/us-east-1/s3/aws4_request, SignedHeaders=host;user-agent;x-amz-content-sha256;x-amz-date,Signature=6d9d1da81258267379f712ead27c89e013183f3ced9501de8e1af1fbe715fa5c
Host: xxxxxxxxxxxxxxxxxxxxx
Connection: Keep-Alive

HTTP/1.1 404 Not Found
x-amz-id-2: tx318cf1a828b54fe282f5a-005df366d5
x-amz-request-id: tx318cf1a828b54fe282f5a-005df366d5
Content-Type: application/xml
X-Trans-Id: tx318cf1a828b54fe282f5a-005df366d5
X-Openstack-Request-Id: tx318cf1a828b54fe282f5a-005df366d5
Content-Length: 0
Date: Fri, 13 Dec 2019 10:24:21 GMT
Connection: keep-alive

Any pointers why the Content-Length header is missing and what is the 0 in the response?

Regards,
Bhaskar

[clayg (clay-gerrard)]

The response is coming back as Transfer-Encoding: chunked - the 0 in the body is part of the transfer encoding chunked protocol indicating the length of the chunk is 0 (i.e. the body is empty)

I wasn't able to duplicate a transfer encoding chunked response on object 404 in-response to HEAD using the boto client on master or swift 2.18 (rocky release)

Can you provide more info

1) Does using another client (boto, aws cli, s3cmd, etc) to preform a similar request (HEAD to object that responds 404) results in the same transfer-encoding chunked response on this cluster?

2) Is the CloudBerry client sending any additional Content-Encoding aws-chunked request metdata or headers?

[Bhaskar Singhal (bhaskarsinghal)]

Thanks a lot for looking into this.

1) I haven't tried any other client as of now. I'll try and provide the trace. But I did try cloudberry with aws s3 and didn't notice any 0 even though Transfer-Encoding chunked header was set

HEAD /readme.txt HTTP/1.1
User-Agent: APN/1.0 CloudBerry Lab/1.0 Explorer/5.9
x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date: 20191213T031037Z
Authorization: AWS4-HMAC-SHA256 Credential=AKIAJBKELMZN3VLNRCKA/20191213/us-east-1/s3/aws4_request, SignedHeaders=host;user-agent;x-amz-content-sha256;x-amz-date,Signature=70acab072267d42faa6f61c4cff47bb4456379dde4f8322c41344f5f7158cd39
Host: bhaskartestbucket16052018.s3.amazonaws.com

HTTP/1.1 404 Not Found
x-amz-request-id: 0DF9953EACD70702
x-amz-id-2: ZbxLAXPffPBGxaILWwgpmfRevDaTFTMB82C1Mj1hEjw8MUeCm1HNZGFYYEbOpI6t7rF6PwZTfTI=
Content-Type: application/xml
Transfer-Encoding: chunked
Date: Fri, 13 Dec 2019 03:10:37 GMT
Server: AmazonS3

2) No, I don't think cloudberry is sending any extra header or request metadata. The same set of operation works with AWS s3.

Regards,
Bhaskar

[clayg (clay-gerrard)]

so the chunked response is either being caused by your cluster (since your client works fine against aws) or an interaction of your client & s3api (since other clients worked with all the versions of s3api i could test).

We can cut the problem in half if we could either:

1) verify other clients work against your cluster
2) duplicate the issue on another cluster w/ cloudberry

I think either result would potentially be interesting, is there like a trial addition or standalone cloudberry client available?

[Tim Burke (1-tim-z)]

FWIW, the RFCs are pretty clear[0][1] that *no* HEAD responses may have a body, even if there's a 'Transfer-Encoding: chunked' header in the response:

> 1.Any response message which "MUST NOT" include a message-body (such
> as the 1xx, 204, and 304 responses and any response to a HEAD
> request) is always terminated by the first empty line after the
> header fields, regardless of the entity-header fields present in
> the message.

What's your proxy pipeline look like? I know I've managed to get some strange behaviors with quick-n-dirty custom middlewares before. I happen to have one handy that wraps the app_iter in a generator and lets me get a similar error when talking to an object-server:

vagrant@saio:/vagrant/swift$ curl "http://127.0.0.1:6030/sdb3/996/AUTH_test/c/qwer" -H "X-Backend-Storage-Policy-Index: 1" -svI > /dev/null
* Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 6030 (#0)
> HEAD /sdb3/996/AUTH_test/c/qwer HTTP/1.1
> Host: 127.0.0.1:6030
> User-Agent: curl/7.58.0
> Accept: */*
> X-Backend-Storage-Policy-Index: 1
>
< HTTP/1.1 404 Not Found
< Content-Type: text/html; charset=UTF-8
< Date: Sat, 14 Dec 2019 02:22:04 GMT
< Transfer-Encoding: chunked
<
* Excess found in a non pipelined read: excess = 5 url = /sdb3/996/AUTH_test/c/qwer (zero-length body)
* Connection #0 to host 127.0.0.1 left intact

(Excess is five for b"0\r\n\r\n".) It doesn't work against the proxy for me, though:

vagrant@saio:/vagrant/swift$ curl http://saio:8090/v1/AUTH_test/c/qwer -svI > /dev/null
* Trying 10.0.2.15...
* TCP_NODELAY set
* Connected to saio (10.0.2.15) port 8090 (#0)
> HEAD /v1/AUTH_test/c/qwer HTTP/1.1
> Host: saio:8090
> User-Agent: curl/7.58.0
> Accept: */*
>
< HTTP/1.1 404 Not Found
< Content-Type: text/html; charset=UTF-8
< Content-Length: 0
< Transfer-Encoding: chunked
< X-Trans-Id: txa18c02d37778489592964-005df44763
< X-Openstack-Request-Id: txa18c02d37778489592964-005df44763
< Date: Sat, 14 Dec 2019 02:22:27 GMT
<
* Connection #0 to host saio left intact

I guess the 'Content-Length: 0' saves us somehow? Anyway, kinda smells like an eventlet bug to me... it definitely shouldn't be sending any body in response to a HEAD, even if the application provides one.

[0] https://tools.ietf.org/html/rfc2616#section-4.4
[1] https://tools.ietf.org/html/rfc7230#section-3.3.3

[Bhaskar Singhal (bhaskarsinghal)]

1. I am able to reproduce the issue with aws s3api cli.

2019-12-14 04:43:49,645 - MainThread - urllib3.connectionpool - DEBUG - http://xxxxxxxxxxxxxxxxxxx:80 "HEAD /bucket1/abcdefg HTTP/1.1" 404 0
2019-12-14 04:43:49,646 - MainThread - botocore.parsers - DEBUG - Response headers: {'x-amz-id-2': 'tx9b6cfc6a732e4490a931c-005df44c65', 'Transfer-Encoding': 'chunked', 'x-amz-request-id': 'tx9b6cfc6a732e4490a931c-005df44c65', 'X-Trans-Id': 'tx9b6cfc6a732e4490a931c-005df44c65', 'Date': 'Sat, 14 Dec 2019 02:43:49 GMT', 'Content-Type': 'application/xml', 'X-Openstack-Request-Id': 'tx9b6cfc6a732e4490a931c-005df44c65'}
2019-12-14 04:43:49,646 - MainThread - botocore.parsers - DEBUG - Response body:

2019-12-14 04:43:49,647 - MainThread - botocore.hooks - DEBUG - Event needs-retry.s3.HeadObject: calling handler <botocore.retryhandler.RetryHandler object at 0x7fc1d8138d10>
2019-12-14 04:43:49,647 - MainThread - botocore.retryhandler - DEBUG - No retry needed.

HEAD /bucket1/abcdefg HTTP/1.1
Host: xxxxxxxxxxxxxxxxxxx
Accept-Encoding: identity
Date: Sat, 14 Dec 2019 02:43:44 GMT
Authorization: AWS 31b18fccbc88419eb9fcff817af61691:6Z7AyM+hDsbA1bFQCzC91lQxasQ=
User-Agent: aws-cli/1.16.111 Python/2.7.12 Linux/4.15.0-43-generic botocore/1.12.101

HTTP/1.1 404 Not Found
x-amz-id-2: tx9b6cfc6a732e4490a931c-005df44c65
x-amz-request-id: tx9b6cfc6a732e4490a931c-005df44c65
Content-Type: application/xml
X-Trans-Id: tx9b6cfc6a732e4490a931c-005df44c65
X-Openstack-Request-Id: tx9b6cfc6a732e4490a931c-005df44c65
Date: Sat, 14 Dec 2019 02:43:49 GMT
Transfer-Encoding: chunked

0

2. Cloudberry client is available with 15 days trial license at https://www.cloudberrylab.com/explorer.aspx

3. Proxy server pipeline
pipeline = catch_errors gatekeeper healthcheck cache listing_formats bulk tempurl crossdomain authtoken s3api s3token keystoneauth staticweb copy container-quotas account-quotas slo dlo versioned_writes swift-proxy-logging proxy-server

[Tim Burke (1-tim-z)]

Iiiinteresting...

So if I take out one of my proxy-logging middlewares, I can (mostly) repro:

$ curl $(aws s3 presign s3://bucket/obj) -svI >/dev/null
* Trying 10.0.2.15...
* TCP_NODELAY set
* Connected to saio (10.0.2.15) port 8080 (#0)
> HEAD /bucket/obj?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=test%3Atester%2F20191217%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20191217T221750Z&X-Amz-Expires=3600&X-Amz-SignedHeaders=host&X-Amz-Signature=f338a86dbd7d7c8edbf3556087f70fa1085717c900498fe4cbebffe397a26481 HTTP/1.1
> Host: saio:8080
> User-Agent: curl/7.58.0
> Accept: */*
>
< HTTP/1.1 403 Forbidden
< Content-Type: application/xml
< x-amz-id-2: tx6bd6efa997a04ee58c633-005df9540e
< x-amz-request-id: tx6bd6efa997a04ee58c633-005df9540e
< X-Trans-Id: tx6bd6efa997a04ee58c633-005df9540e
< X-Openstack-Request-Id: tx6bd6efa997a04ee58c633-005df9540e
< Date: Tue, 17 Dec 2019 22:17:50 GMT
< Transfer-Encoding: chunked
<
* Excess found in a non pipelined read: excess = 5 url = /bucket/obj?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=test%3Atester%2F20191217%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20191217T221750Z&X-Amz-Expires=3600&X-Amz-SignedHeaders=host&X-Amz-Signature=f338a86dbd7d7c8edbf3556087f70fa1085717c900498fe4cbebffe397a26481 (zero-length body)
* Connection #0 to host saio left intact

(There's a slight difference in that I get a 403 since I can't seem to convince awscli to presign a non-GET request, but the "Transfer-Encoding: chunked" and "Excess found in a non pipelined read: excess = 5" bad are still there.)

Can you try putting a second swift-proxy-logging in your pipeline? If it were me, I'd probably put it between healthcheck and cache, like

pipeline = catch_errors gatekeeper healthcheck swift-proxy-logging cache listing_formats bulk tempurl crossdomain authtoken s3api s3token keystoneauth staticweb copy container-quotas account-quotas slo dlo versioned_writes swift-proxy-logging proxy-server

Don't need to do any other config, I don't think; it'll use the same [filter:swift-proxy-logging] section for both instances. FWIW, we've recommended doubled-up logging filters like that for quite a while, since https://github.com/openstack/swift/commit/a622349 -- it helps you have a more complete picture of what (sub)requests are getting made and by whom.

[Bhaskar Singhal (bhaskarsinghal)]

Thanks Tim!

After adding another proxy-logging middleware between healthcheck and cache in the pipeline, I am not seeing the issue on HEAD.