Connection continues to be used after timout
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
OpenStack Object Storage (swift) |
Confirmed
|
Medium
|
Unassigned |
Bug Description
(NB: you'll probably want to ratchet down your client_timeout while testing this; I dropped mine down to 10s.)
Pipelining requests is great:
$ (echo -ne 'PUT /v1/AUTH_test/c/o HTTP/1.
HTTP/1.1 201 Created
Last-Modified: Mon, 07 Aug 2017 21:09:09 GMT
Content-Length: 0
Etag: d266f2f31cf903c
Content-Type: text/html; charset=UTF-8
X-Trans-Id: tx92aa5255ac684
X-Openstack-
Date: Mon, 07 Aug 2017 21:09:13 GMT
HTTP/1.1 200 OK
Content-Length: 12
Accept-Ranges: bytes
Last-Modified: Mon, 07 Aug 2017 21:09:09 GMT
Etag: d266f2f31cf903c
X-Timestamp: 1502140148.12675
Content-Type: application/
X-Trans-Id: tx26be65b4e0c04
X-Openstack-
Date: Mon, 07 Aug 2017 21:09:13 GMT
123456789abc
---
$ (echo -ne 'PUT /v1/AUTH_test/c/o HTTP/1.
HTTP/1.1 201 Created
Last-Modified: Mon, 07 Aug 2017 21:07:19 GMT
Content-Length: 0
Etag: d266f2f31cf903c
Content-Type: text/html; charset=UTF-8
X-Trans-Id: txe890c67822844
X-Openstack-
Date: Mon, 07 Aug 2017 21:07:23 GMT
HTTP/1.1 200 OK
Content-Length: 12
Accept-Ranges: bytes
Last-Modified: Mon, 07 Aug 2017 21:07:19 GMT
Etag: d266f2f31cf903c
X-Timestamp: 1502140038.41405
Content-Type: application/
X-Trans-Id: tx2b4c01621e414
X-Openstack-
Date: Mon, 07 Aug 2017 21:07:23 GMT
123456789abc
###
Apparently, it can (sometimes) even work when you hit timeouts:
$ (echo -ne 'PUT /v1/AUTH_test/c/o HTTP/1.
HTTP/1.1 408 Request Timeout
Content-Length: 116
Content-Type: text/html; charset=UTF-8
X-Trans-Id: tx32543baa2b604
X-Openstack-
Date: Mon, 07 Aug 2017 21:11:38 GMT
<html><h1>Request Timeout</h1><p>The server has waited too long for the request to be sent by the client.
Content-Length: 12
Accept-Ranges: bytes
Last-Modified: Mon, 07 Aug 2017 21:09:09 GMT
Etag: d266f2f31cf903c
X-Timestamp: 1502140148.12675
Content-Type: application/
X-Trans-Id: tx85e8ba4914e54
X-Openstack-
Date: Mon, 07 Aug 2017 21:11:43 GMT
123456789abc
###
... but not all the time:
$ (echo -ne 'PUT /v1/AUTH_test/c/o HTTP/1.
HTTP/1.1 408 Request Timeout
Content-Length: 116
Content-Type: text/html; charset=UTF-8
X-Trans-Id: tx3df83e45d6b54
X-Openstack-
Date: Mon, 07 Aug 2017 21:10:49 GMT
<html><h1>Request Timeout</h1><p>The server has waited too long for the request to be sent by the client.
Server: BaseHTTP/0.3 Python/2.7.6
Date: Mon, 07 Aug 2017 21:10:54 GMT
Content-Type: text/html
Connection: close
<head>
<title>Error response</title>
</head>
<body>
<h1>Error response</h1>
<p>Error code 400.
<p>Message: Bad HTTP/0.9 request type ('/AUTH_test/c/o').
<p>Error code explanation: 400 = Bad request syntax or unsupported method.
</body>
###
(Apparently the proxy forgot about the "1234567" entirely due to the timeout, discarded the next 12 bytes [i.e., "89abcGET /v1"], then thought it was at the start of another request.)
You get similar (but slightly different) behavior if you start including expectations:
$ (echo -ne 'PUT /v1/AUTH_test/c/o HTTP/1.1\r\nExpect: 100-continue\
HTTP/1.1 100 Continue
HTTP/1.1 408 Request Timeout
Content-Length: 116
Content-Type: text/html; charset=UTF-8
X-Trans-Id: txd99ce43897674
X-Openstack-
Date: Mon, 07 Aug 2017 21:14:38 GMT
<html><h1>Request Timeout</h1><p>The server has waited too long for the request to be sent by the client.
Server: BaseHTTP/0.3 Python/2.7.6
Date: Mon, 07 Aug 2017 21:14:43 GMT
Content-Type: text/html
Connection: close
<head>
<title>Error response</title>
</head>
<body>
<h1>Error response</h1>
<p>Error code 400.
<p>Message: Bad request syntax ('89abc').
<p>Error code explanation: 400 = Bad request syntax or unsupported method.
</body>
---
$ (echo -ne 'PUT /v1/AUTH_test/c/o HTTP/1.1\r\nExpect: 100-continue\
HTTP/1.1 100 Continue
HTTP/1.1 408 Request Timeout
Content-Length: 116
Content-Type: text/html; charset=UTF-8
X-Trans-Id: txe18df188b76b4
X-Openstack-
Date: Mon, 07 Aug 2017 21:15:26 GMT
<html><h1>Request Timeout</h1><p>The server has waited too long for the request to be sent by the client.
Content-Length: 91
Content-Type: text/html; charset=UTF-8
Allow: HEAD, GET, PUT, POST, OPTIONS, DELETE
X-Trans-Id: tx89098c33f40b4
X-Openstack-
Date: Mon, 07 Aug 2017 21:15:31 GMT
<html><h1>Method Not Allowed</h1><p>The method is not allowed for this resource.
###
(For both of these, the proxy starts reading a new request immediately after the timeout.)
Such frameshift errors are probably why the RFC says
> If ... the recipient times out before the indicated number
> of octets are received, the recipient MUST consider the
> message to be incomplete and *close the connection*.
(Emphasis mine.) See https:/
I believe this explains the
127.0.0.1 - - [07/Aug/2017 21:29:47] code 400, message Bad HTTP/0.9 request type (':')
127.0.0.1 - - [07/Aug/2017 21:29:47] ": 3aeecf016187de7
messages that are emitted when during test/unit/
at somepoint it might be worth it to produce a minimally viable test case against eventlet. wsgi.server and send it upstream to see what temoto thinks