OpenStack Object Storage (swift)

Connection continues to be used after timout

Bug #1709185 reported by Tim Burke on 2017-08-07

This bug affects 1 person

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.1\r\nTransfer-Encoding: chunked\r\n\r\n7\r\n1234567\r\n5\r\n'; sleep 5; echo -ne '89abc\r\n0\r\n\r\nGET /v1/AUTH_test/c/o HTTP/1.1\r\n\r\n' ; sleep 1) | nc saio 8090
HTTP/1.1 201 Created
Last-Modified: Mon, 07 Aug 2017 21:09:09 GMT
Content-Length: 0
Etag: d266f2f31cf903c870027659030e967e
Content-Type: text/html; charset=UTF-8
X-Trans-Id: tx92aa5255ac684b26a3dc0-005988d6f4
X-Openstack-Request-Id: tx92aa5255ac684b26a3dc0-005988d6f4
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: d266f2f31cf903c870027659030e967e
X-Timestamp: 1502140148.12675
Content-Type: application/octet-stream
X-Trans-Id: tx26be65b4e0c04f9a965c7-005988d6f9
X-Openstack-Request-Id: tx26be65b4e0c04f9a965c7-005988d6f9
Date: Mon, 07 Aug 2017 21:09:13 GMT

123456789abc

---

$ (echo -ne 'PUT /v1/AUTH_test/c/o HTTP/1.1\r\nContent-Length: 12\r\n\r\n1234567'; sleep 5; echo -ne '89abcGET /v1/AUTH_test/c/o HTTP/1.1\r\n\r\n' ; sleep 1) | nc saio 8090
HTTP/1.1 201 Created
Last-Modified: Mon, 07 Aug 2017 21:07:19 GMT
Content-Length: 0
Etag: d266f2f31cf903c870027659030e967e
Content-Type: text/html; charset=UTF-8
X-Trans-Id: txe890c6782284485d81d52-005988d686
X-Openstack-Request-Id: txe890c6782284485d81d52-005988d686
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: d266f2f31cf903c870027659030e967e
X-Timestamp: 1502140038.41405
Content-Type: application/octet-stream
X-Trans-Id: tx2b4c01621e4140b6aca1d-005988d68b
X-Openstack-Request-Id: tx2b4c01621e4140b6aca1d-005988d68b
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.1\r\nTransfer-Encoding: chunked\r\n\r\n7\r\n1234567\r\n5\r\n'; sleep 15; echo -ne '89abc\r\n0\r\n\r\nGET /v1/AUTH_test/c/o HTTP/1.1\r\n\r\n' ; sleep 1) | nc saio 8090
HTTP/1.1 408 Request Timeout
Content-Length: 116
Content-Type: text/html; charset=UTF-8
X-Trans-Id: tx32543baa2b6049079d258-005988d780
X-Openstack-Request-Id: tx32543baa2b6049079d258-005988d780
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.</p></html>HTTP/1.1 200 OK
Content-Length: 12
Accept-Ranges: bytes
Last-Modified: Mon, 07 Aug 2017 21:09:09 GMT
Etag: d266f2f31cf903c870027659030e967e
X-Timestamp: 1502140148.12675
Content-Type: application/octet-stream
X-Trans-Id: tx85e8ba4914e542fbb4b4b-005988d78f
X-Openstack-Request-Id: tx85e8ba4914e542fbb4b4b-005988d78f
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.1\r\nContent-Length: 12\r\n\r\n1234567'; sleep 15; echo -ne '89abcGET /v1/AUTH_test/c/o HTTP/1.1\r\n\r\n' ; sleep 1) | nc saio 8090
HTTP/1.1 408 Request Timeout
Content-Length: 116
Content-Type: text/html; charset=UTF-8
X-Trans-Id: tx3df83e45d6b54d4181fdd-005988d74f
X-Openstack-Request-Id: tx3df83e45d6b54d4181fdd-005988d74f
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.</p></html>HTTP/1.1 400 Bad HTTP/0.9 request type ('/AUTH_test/c/o')
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\r\nTransfer-Encoding: chunked\r\n\r\n7\r\n1234567\r\n5\r\n'; sleep 15; echo -ne '89abc\r\n0\r\n\r\nGET /v1/AUTH_test/c/o HTTP/1.1\r\n\r\n' ; sleep 1) | nc saio 8090
HTTP/1.1 100 Continue

HTTP/1.1 408 Request Timeout
Content-Length: 116
Content-Type: text/html; charset=UTF-8
X-Trans-Id: txd99ce43897674234b8a79-005988d834
X-Openstack-Request-Id: txd99ce43897674234b8a79-005988d834
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.</p></html>HTTP/1.1 400 Bad request syntax ('89abc')
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\r\nContent-Length: 12\r\n\r\n1234567'; sleep 15; echo -ne '89abcGET /v1/AUTH_test/c/o HTTP/1.1\r\n\r\n' ; sleep 1) | nc saio 8090
HTTP/1.1 100 Continue

HTTP/1.1 408 Request Timeout
Content-Length: 116
Content-Type: text/html; charset=UTF-8
X-Trans-Id: txe18df188b76b4d8b8f246-005988d864
X-Openstack-Request-Id: txe18df188b76b4d8b8f246-005988d864
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.</p></html>HTTP/1.1 405 Method Not Allowed
Content-Length: 91
Content-Type: text/html; charset=UTF-8
Allow: HEAD, GET, PUT, POST, OPTIONS, DELETE
X-Trans-Id: tx89098c33f40b40e2aeb0e-005988d873
X-Openstack-Request-Id: tx89098c33f40b40e2aeb0e-005988d873
Date: Mon, 07 Aug 2017 21:15:31 GMT

<html><h1>Method Not Allowed</h1><p>The method is not allowed for this resource.</p></html>

###

(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://tools.ietf.org/html/rfc7230#section-3.3.3

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] ": 3aeecf016187de7602a5ce8020e07338" 400 -

messages that are emitted when during test/unit/obj/test_server.py:TestObjectServer.test_multiphase_put_metadata_footer_disconnect

Revision history for this message

clayg (clay-gerrard) wrote on 2017-08-08:

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

Changed in swift:
status:	New → Confirmed
importance:	Undecided → Medium

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.