Connection continues to be used after timout

Bug #1709185 reported by Tim Burke on 2017-08-07
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Object Storage (swift)
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

clayg (clay-gerrard) wrote :

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
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers