Issue2109

classification
Title: Regression test test_httpservers fails, hangs on Windows
Type: behaviour Severity: normal
Components: Library Versions: Jython 2.7
Milestone:
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: jeff.allen Nosy List: jeff.allen, zyasoft
Priority: normal Keywords: test failure causes

Created on 2014-01-07.00:40:51 by jeff.allen, last changed 2015-01-14.17:30:24 by zyasoft.

Messages
msg8217 (view) Author: Jeff Allen (jeff.allen) Date: 2014-01-07.00:40:50
When I run:
    start dist\bin\jython -m test.test_httpservers

test_request_line_trimming reports ERROR, and the test hangs at test_version_none.

I quickly found that CPython does the same thing (2.7 and 3.3) and believe I've tracked the cause down to the Windows platform software. Full story in issue http://bugs.python.org/issue20155, since I did this investigation using CPython.

Rather than just skip the tests, I'll look variants that achieve the same objectives but works on my machine too.

I'm not able to guess at the wider implications of this behaviour: maybe it's actually a bug in Windows; maybe it's acceptable. I think it only manifests in conditions where the client should get an error response, and the bug would be that it doesn't. either the connection is closed prematurely (test_request_line_trimming), or the request gets stuck in transit (test_version_none). That may violate the expectations of an application designer, as it does ours for these tests.
msg8218 (view) Author: Jeff Allen (jeff.allen) Date: 2014-01-08.21:55:15
For the record, test_request_line_trimming fails as follows. The essence of the test is to insert an extra \n at the end of a GET request line. The request is syntactically invalid. The \n\r\n appears like two blank lines, implying no headers, but the headers then follow where no data should be. The server is supposed to respond with status 501, because it does not, in fact, define a GET operation.

Windows "corrects" the \n to \r\n, which is ok, but it holds back the unexpected data (displaced headers). When the server returns a 501 response and closes the connection, the client now in getresponse() appears not to get the response, before it errors on the closure.

If the following trace, I replaced BaseHTTPRequestHandler, with a version that has lots of extra logging:

test_request_line_trimming (__main__.BaseHTTPServerTestCase) ... send: 'GET / HTTP/1.1\n\r\nHost: lo
calhost:49816\r\nAccept-Encoding: identity\r\n\r\n'

127.0.0.1 - - [08/Jan/2014 20:37:52] (parse_request) raw request line: 'GET / HTTP/1.1\r\n'
127.0.0.1 - - [08/Jan/2014 20:37:52] (parse_request) words: ['GET', '/', 'HTTP/1.1']
127.0.0.1 - - [08/Jan/2014 20:37:52] (parse_request) look-ahead: '\r\n'
127.0.0.1 - - [08/Jan/2014 20:37:52] (parse_request) headers: []
127.0.0.1 - - [08/Jan/2014 20:37:52] (parse_request) look-ahead: ''
127.0.0.1 - - [08/Jan/2014 20:37:52] (handle_one_request) socket (u'127.0.0.1', 49816)
127.0.0.1 - - [08/Jan/2014 20:37:52] code 501, message Unsupported method ('GET')
127.0.0.1 - - [08/Jan/2014 20:37:52] "GET / HTTP/1.1" 501 -
127.0.0.1 - - [08/Jan/2014 20:37:52] (send_response) HTTP/1.1 501 "Unsupported method ('GET')"
127.0.0.1 - - [08/Jan/2014 20:37:52] (send_header) Server: BaseHTTP/0.3 Python/2.7b1+
127.0.0.1 - - [08/Jan/2014 20:37:52] (send_header) Date: Wed, 08 Jan 2014 20:37:52 GMT
127.0.0.1 - - [08/Jan/2014 20:37:52] (send_header) Content-Type: text/html
127.0.0.1 - - [08/Jan/2014 20:37:52] (send_header) Connection: close
ERROR

ERROR: test_request_line_trimming (__main__.BaseHTTPServerTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "jython-trunk\dist\Lib\test\test_httpservers.py", line 197, i
n test_request_line_trimming
    res = self.con.getresponse()
  File "jython-trunk\dist\Lib\httplib.py", line 1045, in getresponse

    response.begin()
  File "jython-trunk\dist\Lib\httplib.py", line 409, in begin
    version, status, reason = self._read_status()
  File "jython-trunk\dist\Lib\httplib.py", line 365, in _read_status

    line = self.fp.readline(_MAXLINE + 1)
  File "jython-trunk\dist\Lib\socket.py", line 1733, in readline
    data = self._sock.recv(self._rbufsize)
  File "jython-trunk\dist\Lib\socket.py", line 174, in handle_except
ion
    raise _map_exception(jlx)
error: [Errno 10054] Software caused connection abort
msg8223 (view) Author: Jeff Allen (jeff.allen) Date: 2014-01-12.20:11:51
test_version_none hangs without even the request line reaching the server (no log messages):

test_version_none (__main__.BaseHTTPServerTestCase) ... send: 'PUT / \r\nHost: localhost:51309\r\nAccept-Encoding: identity\r\n\r\n'

The test failure is not wholly repeatable but depends on preceding activity. (I can't find anything in the test itself to explain this: it appears to create the client and server afresh each time.) If all other tests are skipped, test_version_none runs reliably.

But it also runs reliably, even in the context of other tests, if the PUT request contains a "Content-Length" header:

test_version_none (__main__.BaseHTTPServerTestCase) ... send: 'PUT / \r\nHost: localhost:51374\r\nAccept-Encoding: identity\r\nContent-Length: 0\r\n\r\n'

127.0.0.1 - - [12/Jan/2014 20:02:45] (parse_request) raw request line: 'PUT / \r\n'
127.0.0.1 - - [12/Jan/2014 20:02:45] (parse_request) words: ['PUT', '/']
127.0.0.1 - - [12/Jan/2014 20:02:45] (parse_request) look-ahead: 'Host: localhost:51374\r\nAccept-Encoding: identity\r\nContent-Length: 0\r\n\r\n'
127.0.0.1 - - [12/Jan/2014 20:02:45] code 400, message Bad HTTP/0.9 request type ('PUT')
127.0.0.1 - - [12/Jan/2014 20:02:45] "PUT / " 400 -
127.0.0.1 - - [12/Jan/2014 20:02:45] (send_response) HTTP/1.1 400 "Bad HTTP/0.9 request type ('PUT')"
127.0.0.1 - - [12/Jan/2014 20:02:45] (send_header) Server: BaseHTTP/0.3 Python/2.7b1+
127.0.0.1 - - [12/Jan/2014 20:02:45] (send_header) Date: Sun, 12 Jan 2014 20:02:45 GMT
127.0.0.1 - - [12/Jan/2014 20:02:45] (send_header) Content-Type: text/html
127.0.0.1 - - [12/Jan/2014 20:02:45] (send_header) Connection: close
reply: "HTTP/1.1 400 Bad HTTP/0.9 request type ('PUT')\r\n"
header: Server: BaseHTTP/0.3 Python/2.7b1+
header: Date: Sun, 12 Jan 2014 20:02:45 GMT
header: Content-Type: text/html
header: Connection: close
ok

My theory is that the BFE is intercepting the request and waiting for data following.
msg8226 (view) Author: Jeff Allen (jeff.allen) Date: 2014-01-12.23:20:58
I'd like to make minimal changes so we test the same things, but in a way compatible with the BFE on Windows. In view of the experience above, I think this means:

test_request_line_trimming: the test fundamentally involves a malformed request, with a verb the server doesn't support. I propose to change the verb to one the BFE doesn't know either (like 'XYZ').

test_version_none: the intent is to check that a potentially valid verb is rejected when submitted using "no version protocol" (HTTP/0.9), for which only GET should be valid. Options to fix are: 1. choose a verb the server actually supports (and the BFE doesn't know) like 'CUSTOM'; 2. keep 'PUT' but add a Content-Length header. Of these two, option 1. meets the intent better than the original test.
msg8235 (view) Author: Jeff Allen (jeff.allen) Date: 2014-01-25.23:07:33
Now at http://hg.python.org/jython/rev/6441fcfd940b

If this seems acceptable to everyone I'll close, and propose to address the equivalent CPython issue the same way.
msg9392 (view) Author: Jim Baker (zyasoft) Date: 2015-01-14.17:30:24
I'm going to close, given msg8235 and the fact that we are running this test without hanging on Windows
History
Date User Action Args
2015-01-14 17:30:24zyasoftsetstatus: open -> closed
resolution: fixed
messages: + msg9392
nosy: + zyasoft
2014-01-25 23:07:33jeff.allensetmessages: + msg8235
2014-01-12 23:20:59jeff.allensetmessages: + msg8226
2014-01-12 20:11:52jeff.allensetmessages: + msg8223
2014-01-08 21:55:16jeff.allensetmessages: + msg8218
2014-01-07 00:40:51jeff.allencreate