MANTA-3489

poor error message for some request errors

Status:
Open
Created:
2017-11-01T14:55:39.000-0400
Updated:
2018-03-12T18:38:26.211-0400

Description

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):

Comments (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: