IRC user "_kit_" in manta@ reported:
http://dpaste.com/0YXF6T6
A request to PUT and object which contains multiple Content-Length headers fails with
{"NoApiServersAvailable": "Manta is unavailable to serve requests at this time"}
Whilst multiple Content-Length headers is a valid reason to fail the msg returned wasn't very helpful in debugging the underlying problem.
The paste looks like this:
[FAILS]
$ manta /$MANTA_USER/public/test2/test2.txt -X PUT -H 'content-type: application/json' -H 'Content-Length: 18' -H 'Content-Length: 18' -d '{"hello": "world"}'
https://us-east.manta.joyent.com
* About to connect() to us-east.manta.joyent.com port 443 (#0)
* Trying 165.225.164.14... connected
* successfully set certificate verify locations:
* CAfile: none
CApath: /etc/ssl/certs
* SSLv3, TLS handshake, Client hello (1):
* SSLv3, TLS handshake, Server hello (2):
* SSLv3, TLS handshake, CERT (11):
* SSLv3, TLS handshake, Server key exchange (12):
* SSLv3, TLS handshake, Server finished (14):
* SSLv3, TLS handshake, Client key exchange (16):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSL connection using ECDHE-RSA-AES128-GCM-SHA256
* Server certificate:
* subject: C=US; ST=California; L=San Francisco; O=Joyent, Inc.; CN=*.manta.joyent.com
* start date: 2016-11-18 00:00:00 GMT
* expire date: 2017-11-18 23:59:59 GMT
* issuer: C=US; O=thawte, Inc.; CN=thawte SSL CA - G2
* SSL certificate verify ok.
> PUT /greenspun/public/test2/test2.txt HTTP/1.1
> User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> Host: us-east.manta.joyent.com
> Accept: */*
> content-type: application/json
> Content-Length: 18
> Content-Length: 18
> Date: Wed, 01 Nov 2017 18:14:28 GMT
> [ REMOVED FOR SECURITY ]
>
* upload completely sent off: 18out of 18 bytes
< HTTP/1.1 503 Service Unavailable
< Server: Manta
< Cache-Control: no-cache
< Connection: close
< Content-Length: 80
< Content-Type: application/json
< Retry-After: 60
<
* Excess found in a non pipelined read: excess = 1, size = 80, maxdownload = 80, bytecount = 0
* Closing connection #0
* SSLv3, TLS alert, Client hello (1):
{"NoApiServersAvailable": "Manta is unavailable to serve requests at this time"}
[WORKS]
$ manta /$MANTA_USER/public/test2/test2.txt -X PUT -H 'content-type: application/json' -d '{"hello": "world"}'
https://us-east.manta.joyent.com
* About to connect() to us-east.manta.joyent.com port 443 (#0)
* Trying 165.225.164.26... connected
* successfully set certificate verify locations:
* CAfile: none
CApath: /etc/ssl/certs
* SSLv3, TLS handshake, Client hello (1):
* SSLv3, TLS handshake, Server hello (2):
* SSLv3, TLS handshake, CERT (11):
* SSLv3, TLS handshake, Server key exchange (12):
* SSLv3, TLS handshake, Server finished (14):
* SSLv3, TLS handshake, Client key exchange (16):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSL connection using ECDHE-RSA-AES128-GCM-SHA256
* Server certificate:
* subject: C=US; ST=California; L=San Francisco; O=Joyent, Inc.; CN=*.manta.joyent.com
* start date: 2016-11-18 00:00:00 GMT
* expire date: 2017-11-18 23:59:59 GMT
* issuer: C=US; O=thawte, Inc.; CN=thawte SSL CA - G2
* SSL certificate verify ok.
> PUT /greenspun/public/test2/test2.txt HTTP/1.1
> User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> Host: us-east.manta.joyent.com
> Accept: */*
> content-type: application/json
> Date: Wed, 01 Nov 2017 18:14:16 GMT
> [ REMOVED FOR SECURITY ]> Content-Length: 18
>
* upload completely sent off: 18out of 18 bytes
< HTTP/1.1 204 No Content
< Connection: close
< Etag: 46d7a3cc-307a-4bc3-80cb-a8758cb378e0
< Last-Modified: Wed, 01 Nov 2017 18:14:05 GMT
< Computed-MD5: Sd/dVLAcvNLSq16eXua5uQ==
< Date: Wed, 01 Nov 2017 18:14:05 GMT
< Server: Manta
< x-request-id: 71ffe2a0-bf30-11e7-a852-ff5910e9decf
< x-response-time: 267
< x-server-name: 02d02889-cd80-4ac1-bc0c-4775b86661e4
<
* Closing connection #0
* SSLv3, TLS alert, Client hello (1):
[WORKS]
$ manta /$MANTA_USER/public/test2/test2.txt -X PUT -H 'content-type: application/json' -H 'Content-Length: 18' -d '{"hello": "world"}'
https://us-east.manta.joyent.com
* About to connect() to us-east.manta.joyent.com port 443 (#0)
* Trying 165.225.172.22... connected
* successfully set certificate verify locations:
* CAfile: none
CApath: /etc/ssl/certs
* SSLv3, TLS handshake, Client hello (1):
* SSLv3, TLS handshake, Server hello (2):
* SSLv3, TLS handshake, CERT (11):
* SSLv3, TLS handshake, Server key exchange (12):
* SSLv3, TLS handshake, Server finished (14):
* SSLv3, TLS handshake, Client key exchange (16):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSL connection using ECDHE-RSA-AES128-GCM-SHA256
* Server certificate:
* subject: C=US; ST=California; L=San Francisco; O=Joyent, Inc.; CN=*.manta.joyent.com
* start date: 2016-11-18 00:00:00 GMT
* expire date: 2017-11-18 23:59:59 GMT
* issuer: C=US; O=thawte, Inc.; CN=thawte SSL CA - G2
* SSL certificate verify ok.
> PUT /greenspun/public/test2/test2.txt HTTP/1.1
> User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
> Host: us-east.manta.joyent.com
> Accept: */*
> content-type: application/json
> Content-Length: 18
> Date: Wed, 01 Nov 2017 18:14:22 GMT
> [ REMOVED FOR SECURITY ]
>
* upload completely sent off: 18out of 18 bytes
< HTTP/1.1 204 No Content
< Connection: close
< Etag: b11bd2bf-0a27-6510-8868-d6ba70a017ca
< Last-Modified: Wed, 01 Nov 2017 18:14:10 GMT
< Computed-MD5: Sd/dVLAcvNLSq16eXua5uQ==
< Date: Wed, 01 Nov 2017 18:14:10 GMT
< Server: Manta
< x-request-id: 75498f60-bf30-11e7-ae5d-9918098fc7b1
< x-response-time: 259
< x-server-name: 02d02889-cd80-4ac1-bc0c-4775b86661e4
<
* Closing connection #0
* SSLv3, TLS alert, Client hello (1):
Former user commented on 2017-11-01T15:35:19.000-0400:
The user was using the "manta" shell function defined in the documentation:
function manta {
local alg=rsa-sha256
local keyId=/$MANTA_USER/keys/$MANTA_KEY_ID
local now=$(date -u "+%a, %d %h %Y %H:%M:%S GMT")
local sig=$(echo "date:" $now | \
tr -d '\n' | \
openssl dgst -sha256 -sign $HOME/.ssh/id_rsa | \
openssl enc -e -a | tr -d '\n')
curl -sS $MANTA_URL"$@" -H "date: $now" \
-H "Authorization: Signature keyId=\"$keyId\",algorithm=\"$alg\",signature=\"$sig\""
}
I'm able to reproduce this trivially in my Manta deployment:
[root@3ea04ab6 (ops) ~]$ manta /$MANTA_USER/public/test2/test2.txt -X PUT -H 'content-type: application/json' -H 'Content-Length: 18' -H 'Content-Length: 18' -d '{"hello": "world"}' -k -v
* Trying 172.27.10.48...
* Failed to set TCP_KEEPALIVE on fd 4
* Connected to manta.emy-10.joyent.us (172.27.10.48) port 443 (#0)
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* TLSv1.2, TLS handshake, Client hello (1):
* TLSv1.2, TLS handshake, Server hello (2):
* TLSv1.2, TLS handshake, CERT (11):
* TLSv1.2, TLS handshake, Server finished (14):
* TLSv1.2, TLS handshake, Client key exchange (16):
* TLSv1.2, TLS change cipher, Client hello (1):
* TLSv1.2, TLS handshake, Finished (20):
* TLSv1.2, TLS change cipher, Client hello (1):
* TLSv1.2, TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / AES128-GCM-SHA256
* Server certificate:
* subject: C=US; ST=CA; O=Joyent; OU=manta; CN=manta.emy-10.joyent.us
* start date: 2016-09-02 00:38:46 GMT
* expire date: 2017-09-02 00:38:46 GMT
* issuer: C=US; ST=CA; O=Joyent; OU=manta; CN=manta.emy-10.joyent.us
* SSL certificate verify result: self signed certificate (18), continuing anyway.
> PUT /poseidon/public/test2/test2.txt HTTP/1.1
> Host: manta.emy-10.joyent.us
> User-Agent: curl/7.42.0
> Accept: */*
> content-type: application/json
> Content-Length: 18
> Content-Length: 18
> date: Wed, 01 Nov 2017 18:36:15 GMT
> Authorization: Signature keyId="/poseidon/keys/c6:83:1f:28:c2:c3:7f:11:13:c2:49:7a:eb:ca:96:9c",algorithm="rsa-sha256",signature="QZD30Vqkckqu9BLarZMjnxDFo3SS5iiCARSJKuT7LtmuLxj7z0un2BIV3prmfqHzeZBhel/i5XVHtUVq51pzGZGUtb7mk1FXnwYnYqClIeFZzemVopxfiG/2jeN9YC7quGv2eymMewBjmEMBpboQHtuNPaiP6xKQsjhaJ9vhOrWcWDHm8QiNiLWFzAfpMVCwC1EFJGxEHyTEtSQrNhwrsbOsBkecZBxgy7QsrmWuoXD1bwpKJjg0WA40uoi4fZYegApASnM9kyrsnw43Faz9DOq0t4F9OeNnBbzSjp6efuFWxCMCee/mRS/+AV6amdQ1oB/21/LLWDiTW2kEAm6w4A=="
>
* upload completely sent off: 18 out of 18 bytes
< HTTP/1.1 503 Service Unavailable
< Server: Manta
< Cache-Control: no-cache
< Connection: close
< Content-Length: 80
< Content-Type: application/json
< Retry-After: 60
<
* Excess found in a non pipelined read: excess = 1, size = 80, maxdownload = 80, bytecount = 0
* Closing connection 0
* TLSv1.2, TLS alert, Client hello (1):
{"NoApiServersAvailable": "Manta is unavailable to serve requests at this time"}
It's surprising that there's no x-server-name or request id header in this response. That suggests this came from the loadbalancer haproxy and not muskie. Sure enough, I reproduced this with a unique path:
[root@3ea04ab6 (ops) ~]$ manta /$MANTA_USER/public/test2/test12345.txt -X PUT -H 'content-type: application/json' -H 'Content-Length: 18' -H 'Content-Length: 18' -d '{"hello": "world"}' -k -v
* Trying 172.27.10.61...
* Failed to set TCP_KEEPALIVE on fd 4
* Connected to manta.emy-10.joyent.us (172.27.10.61) port 443 (#0)
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* TLSv1.2, TLS handshake, Client hello (1):
* TLSv1.2, TLS handshake, Server hello (2):
* TLSv1.2, TLS handshake, CERT (11):
* TLSv1.2, TLS handshake, Server finished (14):
* TLSv1.2, TLS handshake, Client key exchange (16):
* TLSv1.2, TLS change cipher, Client hello (1):
* TLSv1.2, TLS handshake, Finished (20):
* TLSv1.2, TLS change cipher, Client hello (1):
* TLSv1.2, TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / AES128-GCM-SHA256
* Server certificate:
* subject: C=US; ST=CA; O=Joyent; OU=manta; CN=manta.emy-10.joyent.us
* start date: 2016-09-02 00:38:46 GMT
* expire date: 2017-09-02 00:38:46 GMT
* issuer: C=US; ST=CA; O=Joyent; OU=manta; CN=manta.emy-10.joyent.us
* SSL certificate verify result: self signed certificate (18), continuing anyway.
> PUT /poseidon/public/test2/test12345.txt HTTP/1.1
> Host: manta.emy-10.joyent.us
> User-Agent: curl/7.42.0
> Accept: */*
> content-type: application/json
> Content-Length: 18
> Content-Length: 18
> date: Wed, 01 Nov 2017 18:37:20 GMT
> Authorization: Signature keyId="/poseidon/keys/c6:83:1f:28:c2:c3:7f:11:13:c2:49:7a:eb:ca:96:9c",algorithm="rsa-sha256",signature="XiLlxvDOIlHEMcyZS5X7Cauj/wgYV8TslcOS08WhE5rzW29AaVt6/YsxuMJ75EW6/T+xM9ZwhTho69iqtPwvzI6ACkoZyuANjNzX5nUYzbR/EDbaDeTrEINiZjoW6FUSiIi/AhhYqOPoRy3eMkn9ZeAuqrks/DaI9CnMzoe4o/kUaSK6iSNz7ZzxqxSL39ml0lZfCJ43VhGLs/OvxBl5GI4I2nBXoRPP2DNtB++WJ+hUaHRnawaLNeNLjnxzhYR6CqIgoofTR6pTz0Mp5k9xBq8w02NYnBctRh5ZS2JaI7yaYnwkTtyp2qFEwwSZ7cp/RC4yEvE7dMguR/mbDOPExQ=="
>
* upload completely sent off: 18 out of 18 bytes
< HTTP/1.1 503 Service Unavailable
< Server: Manta
< Cache-Control: no-cache
< Connection: close
< Content-Length: 80
< Content-Type: application/json
< Retry-After: 60
<
* Excess found in a non pipelined read: excess = 1, size = 80, maxdownload = 80, bytecount = 0
* Closing connection 0
* TLSv1.2, TLS alert, Client hello (1):
{"NoApiServersAvailable": "Manta is unavailable to serve requests at this time"}
and then found the haproxy log message:
2017-11-01T18:37:20+00:00 d5d07015-2c7c-4da2-a831-e31a54252907 haproxy[36027]: ::ffff:172.27.10.71:49107 [01/Nov/2017:18:37:20.562] https secure_api/be0 0/0/10/-1/10 502 245 - - SH-- 0/0/0/0/0 0/0 "PUT /poseidon/public/test2/test12345.txt HTTP/1.1"
or, formatted with haplog:
{
"syslog_date": "2017-11-01T18:37:20.000Z",
"syslog_hostname": "d5d07015-2c7c-4da2-a831-e31a54252907",
"pid": 36027,
"client_ip": "172.27.10.71",
"client_port": 49107,
"accept_date": "01/Nov/2017:18:37:20.562",
"frontend_name": "https",
"backend_name": "secure_api",
"server_name": "be0",
"Tq": 0,
"Tw": 0,
"Tc": 10,
"Tr": -1,
"Tt": 10,
"status_code": 502,
"bytes_read": 245,
"termination_state": {
"raw": "SH--",
"termination_cause": "BACKEND_ABORT",
"state_at_close": "WAITING_FOR_RESPONSE_HEADERS",
"persistence_cookie_client": "N/A",
"persistence_cookie_server": "N/A"
},
"actconn": 0,
"feconn": 0,
"beconn": 0,
"srv_conn": 0,
"retries": 0,
"srv_queue": 0,
"backend_queue": 0,
"http_request": "PUT /poseidon/public/test2/test12345.txt HTTP/1.1"
}
So the backend server closed the connection unexpectedly, and haproxy translated that internally to a 502, and then it served a specific 503 response about servers not being available because that's what we've configured it to do for 502s. From the "be0" identifier in the log message plus the haproxy config file, I found the muskie server that would have done this, and I checked its log, but it didn't log anything at all for this.
I experimented with sending this request directly to the haproxy in a muskie zone and got an empty reply, which is consistent with that:
$ MANTA_URL=http://172.27.10.60 manta /$MANTA_USER/public/test2/test12345.txt -X PUT -H 'content-type: application/json' -H 'Content-Length: 18' -H 'Content-Length: 18' -d '{"hello": "world"}' -k -v
* Trying 172.27.10.60...
* Failed to set TCP_KEEPALIVE on fd 3
* Connected to 172.27.10.60 (172.27.10.60) port 80 (#0)
> PUT /poseidon/public/test2/test12345.txt HTTP/1.1
> Host: 172.27.10.60
> User-Agent: curl/7.42.0
> Accept: */*
> content-type: application/json
> Content-Length: 18
> Content-Length: 18
> date: Wed, 01 Nov 2017 18:42:22 GMT
> Authorization: Signature keyId="/poseidon/keys/c6:83:1f:28:c2:c3:7f:11:13:c2:49:7a:eb:ca:96:9c",algorithm="rsa-sha256",signature="GiDBmK5/8g4bnkRJ/WmlUB+uwZaZB5dMI0NSmnfJRvHpVT01Fj+/+gm+WeKR7buxNSo4XBooqbA46uYQQw7PBmWShYxCQjBzgDAh5A/Nd6d5YJm+8CGPEefQlJ1jVCsmiL2R7S0ro+J5eVxzcMurSyjo93BWSNcwrectnsgva+/zQG5BeqK7VqS+oBGltga7vimtDW6xnf0ESBm0xDx0bY0U0y/aGSRK6MxjX0Iie968zBaQ+C9WMlGA9pWjj0xqPLvPfjMeLtthZwfMXsKNhtO0kZTdu7lgERu8SJg7t536mBU5Eo1+wCf4NMeaWxiLJVI+W0DhepYoLwerzUHTeQ=="
>
* upload completely sent off: 18 out of 18 bytes
* Empty reply from server
* Connection #0 to host 172.27.10.60 left intact
curl: (52) Empty reply from server
Then I tried sending it directly to one of the Muskie processes and got the same result:
$ MANTA_URL=http://172.27.10.60:8081 manta /$MANTA_USER/public/test2/test12345.txt -X PUT -H 'content-type: application/json' -H 'Content-Length: 18' -H 'Content-Length: 18' -d '{"hello": "world"}' -k -v
* Trying 172.27.10.60...
* Failed to set TCP_KEEPALIVE on fd 3
* Connected to 172.27.10.60 (172.27.10.60) port 8081 (#0)
> PUT /poseidon/public/test2/test12345.txt HTTP/1.1
> Host: 172.27.10.60:8081
> User-Agent: curl/7.42.0
> Accept: */*
> content-type: application/json
> Content-Length: 18
> Content-Length: 18
> date: Wed, 01 Nov 2017 18:42:40 GMT
> Authorization: Signature keyId="/poseidon/keys/c6:83:1f:28:c2:c3:7f:11:13:c2:49:7a:eb:ca:96:9c",algorithm="rsa-sha256",signature="XD/B3f/02iPz3xHmCiCgJfXHXf2/56QIupoV7xLN7gFf+mrxMZpors+crRFPyQKzSSd2E4CdFEcqT8koaKShiDWFjPiZJN4psxEs02+2fa0XjbdeeFWc0crIqkK9rLLhu4aOE9HJbMty3XA279Ij5QoDo90pcynBo9IZb/gzIMb58u6xHoWh2LMjmA2HZjn98VINe3M5r0gIdOcxgEqwzF25YS1xytPfM/iAxJtCFvUhtUR1ioLNL0dWlEYSI2nvRTNz1kIUokDo3XzwUJ9Zyo7bkI9YihopGsCVio3B8iwP1UTUoGzQZndA+cD+PZ2gtfOQJ72xCf5Fk9gwd1r8Jg=="
>
* upload completely sent off: 18 out of 18 bytes
* Empty reply from server
* Connection #0 to host 172.27.10.60 left intact
curl: (52) Empty reply from server
Finally, I created a simple node http server and confirmed that Node internally seems to reject this HTTP request (by closing the connection) before we get the chance to handle it:
$ cat test-server.js
/* Test Node behavior with multiple content-length headers */
var mod_http = require('http');
var server = mod_http.createServer(function onRequest(request, response) {
console.log('GOT REQUEST: ', request.url);
response.writeHead(200);
response.end('okay\n');
});
server.listen(8999, function () {
console.log('listening on port 8999');
});
[root@2004385c (webapi) ~]$ node -v
v0.10.48
Here's what I ran on the client:
[root@3ea04ab6 (ops) ~]$ curl http://172.27.10.60:8999/test1 -d '{"hello": "world"}'
okay
[root@3ea04ab6 (ops) ~]$ curl http://172.27.10.60:8999/test2 -H 'Content-Length: 18' -d '{"hello": "world"}'
okay
[root@3ea04ab6 (ops) ~]$ curl http://172.27.10.60:8999/test3 -H 'Content-Length: 18' -H 'Content-Length: 18' -d '{"hello": "world"}'
curl: (52) Empty reply from server
[root@3ea04ab6 (ops) ~]$ curl http://172.27.10.60:8999/test4
okay
[root@3ea04ab6 (ops) ~]$
and here's what the server reported:
[root@2004385c (webapi) ~]$ node test-server.js
listening on port 8999
GOT REQUEST: /test1
GOT REQUEST: /test2
GOT REQUEST: /test4
According to RFC 7230 section 3.3.2:
If a message is received that has multiple Content-Length header
fields with field-values consisting of the same decimal value, or a
single Content-Length header field with a field value containing a
list of identical decimal values (e.g., "Content-Length: 42, 42"),
indicating that duplicate Content-Length header fields have been
generated or combined by an upstream message processor, then the
recipient MUST either reject the message as invalid or replace the
duplicated field-values with a single valid Content-Length field
containing that decimal value prior to determining the message body
length or forwarding the message.
In RFC 2616, this looks totally invalid, because a header can't be specified multiple times unless the values can be concatenated with a comma.
There are a few options here:
Node could potentially handle this successfully, although that's only allowed if the two content-length fields have the same value. You could still run into this problem if different values were specified.
Node could report a 400-level response ("bad request") instead of just closing the connection. I'm not sure if this is easy or even feasible. It seems likely that there are HTTP errors where that's not possible. (As it is, the HTTP-level framing is basically ruined by this, so you'd pretty much have to close the connection. The only question is whether you'd send a 400-level response first. That does seem reasonable, but I don't know how easy this is to change in Node.)
haproxy could reject this request with a 400-level error. I believe it's in a position to do that for the first request (i.e., it's parsing the headers on the first request anyway). If this happened on a subsequent request, clients would just get an abrupt termination instead of a response. That'd likely still be better than the 503 that they get today.
We could avoid having haproxy report the 503 for what is a 502 error. We changed haproxy to report a 503 instead of a 502 under MANTA-2904#icft=MANTA-2904 because we felt that the conditions that would generate a 502 are better represented to end users as a 503. I still think 502 is not the right thing to propagate to the end user because that's a gateway error, and they have no reason to know or care about a gateway being present. This option seems the most tempting because it seems strange for haproxy to generate a 503 for what it saw as a 502, but the reality is that a 502 doesn't make much more sense to a client. Only one of the previous three options actually causes the client to see something reasonable.