Exception with --http11 when browsing ticket other than last ticket added

[Lance Hendrix <lance@…>]

Found this issue while I was load testing and it is rather interesting.

This issue was discovered with tracd (so I don't know if it has any impact on mod_python with apache); however, if you start the tracd daemon with —htp11 and ask for a ticket other than the last ticket added, you get the following exception and backtrace:

Exception happened during processing of request from ('192.168.1.111', 53060)
Traceback (most recent call last):
  File "/usr/lib/python2.5/SocketServer.py", line 464, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib/python2.5/SocketServer.py", line 254, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python2.5/SocketServer.py", line 522, in __init__
    self.handle()
  File "/usr/lib/python2.5/BaseHTTPServer.py", line 318, in handle
    self.handle_one_request()
  File "/home/lance/workspace/trac-0.11-stable/trac/web/wsgi.py", line 181, in handle_one_request
    environ = self.setup_environ()
  File "/home/lance/workspace/trac-0.11-stable/trac/web/wsgi.py", line 132, in setup_environ
    self.raw_requestline = self.rfile.readline()
  File "/usr/lib/python2.5/socket.py", line 381, in readline
    data = self._sock.recv(self._rbufsize)
error: (104, 'Connection reset by peer')

I can reproduce this with a new/default installation by creating a new ticket (#1) and then immediately creating a second ticket (#2). If you then either browse the tickets using the report (#1) or through directly entering the ticket number on the url and your request is for ticket #1, then tracd will give you the exception.

Another interesting thing about this is that the page *seems* to be properly rendered in the browser in spite of the issue. If you then use the exact same environment and do not use the —http11 option, you will not get the exception, but if you stop/kill tracd and start it up again with the —http11 option, you will get the exception again.

I have not checked for this issue in trunk as the work I was doing was in the trac-0.11-stable branch.

[Lance Hendrix <lance@…>]

More info… This happens when using Firefox (3.0.10) which uses (requests) HTTP/1.1 regardless; however in Google Chrome (2.0.172.30) this issue does not happen. It seems Google Chrome is only HTTP/1.0, so even when using the —htp11 the exception doesn't happen, so it has to be something with HTTP/1.1 and I am thinking that it is an issue with content length header field returned by tracd.

That is the client size received by the client differs from that sent by the server, so the client (at least Firefox) closes the connection, per RFC2616.

Opera seems to be HTTP/1.0 (9.64) and thus does not cause the issue. IE 8.0 also seems to be HTTP/1.0 and thus does not cause the issue.

Seems Firefox is the only HTTP/1.1 compliant browser (of the ones I have installed in their default configurations at least). This is not to say that they don't use "keep-alives" (can be done somewhat with HTTP/1.0 using the connection request header field with "keep-alive" and the "keep-alive" header (see RFC2068 for more information).

[Christian Boos]

Replying to Lance Hendrix <lance@…>:

Found this issue while I was load testing and it is rather interesting.

This issue was discovered with tracd (so I don't know if it has any impact on mod_python with apache); however, if you start the tracd daemon with —htp11 and ask for a ticket other than the last ticket added, you get the following exception and backtrace: … error: (104, 'Connection reset by peer')

… and your request is for ticket #1, then tracd will give you the exception.

Another interesting thing about this is that the page *seems* to be properly rendered in the browser in spite of the issue.

I guess that if you see the ticket 1, the request which is failing is the implicit one for ticket 2 (Firefox does a prefetch of the <link rel="next" href=…> page).

I have not checked for this issue in trunk as the work I was doing was in the trac-0.11-stable branch.

I don't see the connection reset problem, testing both tracd 0.11-stable and Firefox 3.0.10 on Windows. Using ​NetTool, I see all requests go through, including the one for the next ticket (you can see the "X-Moz: prefetch" header for this one). Maybe you could get more details on what's happening by using the above tool (though it's far from perfect for checking the actual content length, so you might find other tools more appropriate).

[Christian Boos]

Replying to Lance Hendrix <lance@…>:

I've also checked Google Chrome (2.0.172.30), Opera 9.64 and IE 7.0.6001.18000, all seem to keep sending HTTP/1.1 requests during the exchange, and there seem to be no issues. None of those do a prefetch like Firefox does, though.

Seems Firefox is the only HTTP/1.1 compliant browser …

This I don't know… And actually when I did the whole #8020 stuff, the emphasize on HTTP/1.1 was perhaps exaggerated, as the only 1.1 thing that we do is to advertise as being 1.1 so that the Keep-Alive is honored by the browsers. For the rest, we're only as HTTP/1.1 compliant as the BaseHTTPServer is (see e.g. ​PythonBug:1491).

Bottom-line: you should try to see more precisely why the Firefox prefetch request fails (if this is indeed this one) and if this is related to content-length at all, or some other reasons(?), by using a network analysis tool.

[Lance Hendrix <lance@…>]

Two new items to add. First, the reason the other browsers were not using HTTP/1.1 was due to proxy settings and the fact that they were not setup to bypass the proxy for this server. The proxy is Squid and it correctly changes the request from HTTP/1.0 to HTTP/1.1 (this is squid's current default configuration as they are apparently not finished with their HTTP/1.1 implementation last I checked).

I also used a packet capture and was able to see the conversation a little bit better. It does seem related to Firefox's behavior in that if I request ticket/2 (with three tickets in the system), it does also attempt to fetch ticket/3, which is when the exception occurs. Specifically, Firefox is requesting a reset (TCP Flags: …..R..) on the connection and then it appears that Firefox closes the connection, which causes tracd to attempt to write to a closed socket.

As you mentioned, I don't know if this is specifically an issue with tracd or if it is an issue with the python implementation of (their) HTTP server.

[Lance Hendrix <lance@…>]

Replying to Lance Hendrix <lance@…>:

from HTTP/1.0 to HTTP/1.1

Should read from HTTP/1.1 to HTTP/1.0

I am still also unsure of why Firefox is requesting a reset on the connection (rather than leaving it open) as none of the other browsers exhibit this behavior…

[Christian Boos]

Replying to Lance Hendrix <lance@…>:

I am still also unsure of why Firefox is requesting a reset on the connection

Well, "mine" does not, and it's also a version 3.0.10 one (Windows x86). Maybe this can be due to a Firefox plugin? Try disabling them all…

[Lance Hendrix <lance@…>]

I turned off all plug-ins in Firefox and still had the same issue. I also did the test on Windows and did not get the issue, so it seems it is only an issue on Linux.

The details of my /about on the Linux box are included for your reference.

System Information
Trac: 	        0.11.5stable-r0
Python: 	2.5.4 (r254:67916, Jun 4 2009, 14:14:44) [GCC 4.3.2]
setuptools: 	0.6c9
SQLite: 	3.6.13
pysqlite: 	2.5.5
Genshi: 	0.6dev-r1062
Pygments: 	1.0
Subversion: 	1.5.6 (r36142)
jQuery:	1.2.6

As a result I am guessing this is probably an issue with Python on Linux and probably not an issue with Trac.

[Christian Boos]

Still a problem with FF 3.5 (and Trac 0.11.5?)

[Christian Boos]

Remy, any chance you could verify that on Linux? (I may have only 2.0.x or something…).

[Remy Blank]

I can confirm this on current 0.11-stable, using Firefox 3.0.14 on Linux.

127.0.0.1 - - [28/Oct/2009 22:36:22] "GET /ticket/15 HTTP/1.1" 200 -
----------------------------------------
Exception happened during processing of request from ('127.0.0.1', 46523)
Traceback (most recent call last):
  File "/usr/lib/python2.6/SocketServer.py", line 558, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib/python2.6/SocketServer.py", line 320, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python2.6/SocketServer.py", line 615, in __init__
    self.handle()
  File "/usr/lib/python2.6/BaseHTTPServer.py", line 331, in handle
    self.handle_one_request()
  File "/home/joe/src/trac/0.11-stable/trac/web/wsgi.py", line 183, in handle_one_request
    environ = self.setup_environ()
  File "/home/joe/src/trac/0.11-stable/trac/web/wsgi.py", line 133, in setup_environ
    self.raw_requestline = self.rfile.readline()
  File "/usr/lib/python2.6/socket.py", line 404, in readline
    data = self._sock.recv(self._rbufsize)
error: [Errno 104] Connection reset by peer
----------------------------------------

I followed the exact procedure from the description: created #14, created #15, then changed the URL to go back to #14 and this traceback comes at the end. Note that it refers to #15, so Firefox must be doing some prefetching, using GET instead of HEAD and closing the connection if the page hasn't changed.

[Remy Blank]

Suggested fix (tested with the same configuration):

trac/web/wsgi.py

@@ -183 +183 @@
             environ = self.setup_environ()
         except IOError, e:
             environ = None
-            if e.errno in (errno.EPIPE, 10053, 10054): # client disconnect
+            if e.errno in (errno.EPIPE, errno.ECONNRESET, 10053, 10054):
+                # client disconnect
                 self.close_connection = 1
             else:
                 raise

[Remy Blank]

I suggest we at least apply the fix in comment:11 for 0.11.6. It's a minor change with low risk.

[Christian Boos]

Sure, please apply.

[Remy Blank]

Patch applied in [8814].

[Remy Blank]

Follow-up applied in [8849].