new t.web2.client.http.HTTPClientChannelRequest.connectionLost loops and errbacks incorrectly

[camrdale]

The twisted.web2.client.http.HTTPClientChannelRequest.connectionLost function introduced in this revision is broken:

Revision 21366, 11.2 kB  (checked in by therve, 6 months ago)
Merge web2-client-connectionlost-2304
Author: therve
Reviewer: dreid
Fixes #2304
Fix the connectionLost method of web2 client request so that errors are
propagated to the response deferred. Also it handles the case where the headers
are sent and the error happens during the streaming (after the response
deferred).

Firstly, the call to _error() will cause a loop as it calls the channels abortParse(), which calls setReadPersistent() to set it to False, which calls connectionLost(), etc.... This causes an errback to be called multiple times, leading to tracebacks such as:

Traceback (most recent call last):
  File "/usr/lib/python2.5/site-packages/twisted/application/app.py", line 269, in runReactorWithLogging
    reactor.run()
  File "/usr/lib/python2.5/site-packages/twisted/internet/posixbase.py", line 223, in run
    self.mainLoop()
  File "/usr/lib/python2.5/site-packages/twisted/internet/posixbase.py", line 234, in mainLoop
    self.doIteration(t)
  File "/usr/lib/python2.5/site-packages/twisted/internet/selectreactor.py", line 140, in doSelect
    _logrun(selectable, _drdw, selectable, method, dict)
--- <exception caught here> ---
  File "/usr/lib/python2.5/site-packages/twisted/python/log.py", line 51, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/usr/lib/python2.5/site-packages/twisted/python/log.py", line 36, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/usr/lib/python2.5/site-packages/twisted/python/context.py", line 59, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python2.5/site-packages/twisted/python/context.py", line 37, in callWithContext
    return func(*args,**kw)
  File "/usr/lib/python2.5/site-packages/twisted/internet/selectreactor.py", line 156, in _doReadOrWrite
    self._disconnectSelectable(selectable, why, method=="doRead")
  File "/usr/lib/python2.5/site-packages/twisted/internet/posixbase.py", line 262, in _disconnectSelectable
    selectable.connectionLost(failure.Failure(why))
  File "/usr/lib/python2.5/site-packages/twisted/internet/tcp.py", line 576, in connectionLost
    Connection.connectionLost(self, reason)
  File "/usr/lib/python2.5/site-packages/twisted/internet/tcp.py", line 416, in connectionLost
    protocol.connectionLost(reason)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 363, in connectionLost
    request.connectionLost(reason)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 168, in connectionLost
    self._error(reason)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 155, in _error
    self.abortParse()
  File "/usr/lib/python2.5/site-packages/twisted/web2/channel/http.py", line 330, in abortParse
    self.channel.setReadPersistent(False)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 353, in setReadPersistent
    request.connectionLost(None)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 168, in connectionLost
    self._error(reason)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 155, in _error
    self.abortParse()
  File "/usr/lib/python2.5/site-packages/twisted/web2/channel/http.py", line 330, in abortParse
    self.channel.setReadPersistent(False)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 353, in setReadPersistent
    request.connectionLost(None)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 168, in connectionLost
    self._error(reason)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 159, in _error
    self.responseDefer.errback(err)
  File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 264, in errback
    self._startRunCallbacks(fail)
  File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 293, in _startRunCallbacks
    raise AlreadyCalledError
twisted.internet.defer.AlreadyCalledError:

Secondly, the call to connectionLost() on line 353 in the setReadPersistent() function now needs to send a failure as argument rather than None, as this gets passed down to an errback eventually which generates this error:

Traceback (most recent call last):
  File "/usr/lib/python2.5/site-packages/twisted/python/log.py", line 51, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/usr/lib/python2.5/site-packages/twisted/python/log.py", line 36, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/usr/lib/python2.5/site-packages/twisted/python/context.py", line 59, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python2.5/site-packages/twisted/python/context.py", line 37, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/usr/lib/python2.5/site-packages/twisted/internet/selectreactor.py", line 146, in _doReadOrWrite
    why = getattr(selectable, method)()
  File "/usr/lib/python2.5/site-packages/twisted/internet/tcp.py", line 362, in doRead
    return self.protocol.dataReceived(data)
  File "/usr/lib/python2.5/site-packages/twisted/protocols/basic.py", line 239, in dataReceived
    return self.rawDataReceived(data)
  File "/var/lib/python-support/python2.5/apt_p2p/HTTPDownloader.py", line 37, in rawDataReceived
    HTTPClientProtocol.rawDataReceived(self, data)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 293, in rawDataReceived
    self.inRequests[0].rawDataReceived(data)
  File "/usr/lib/python2.5/site-packages/twisted/web2/channel/http.py", line 173, in rawDataReceived
    channel.setLineMode(extraneous)
  File "/usr/lib/python2.5/site-packages/twisted/protocols/basic.py", line 254, in setLineMode
    return self.dataReceived(extra)
  File "/usr/lib/python2.5/site-packages/twisted/protocols/basic.py", line 231, in dataReceived
    why = self.lineReceived(line)
  File "/var/lib/python-support/python2.5/apt_p2p/HTTPDownloader.py", line 32, in lineReceived
    HTTPClientProtocol.lineReceived(self, line)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 281, in lineReceived
    self.inRequests[0].lineReceived(line)
  File "/usr/lib/python2.5/site-packages/twisted/web2/channel/http.py", line 130, in lineReceived
    self.allHeadersReceived()    # can set chunkedIn
  File "/usr/lib/python2.5/site-packages/twisted/web2/channel/http.py", line 193, in allHeadersReceived
    self.setConnectionParams(connHeaders)
  File "/usr/lib/python2.5/site-packages/twisted/web2/channel/http.py", line 324, in setConnectionParams
    self.channel.setReadPersistent(readPersistent)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 353, in setReadPersistent
    request.connectionLost(None)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 168, in connectionLost
    self._error(reason)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 155, in _error
    self.abortParse()
  File "/usr/lib/python2.5/site-packages/twisted/web2/channel/http.py", line 330, in abortParse
    self.channel.setReadPersistent(False)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 353, in setReadPersistent
    request.connectionLost(None)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 168, in connectionLost
    self._error(reason)
  File "/usr/lib/python2.5/site-packages/twisted/web2/client/http.py", line 159, in _error
    self.responseDefer.errback(err)
  File "/usr/lib/python2.5/site-packages/twisted/internet/defer.py", line 262, in errback
    fail = failure.Failure(fail)
  File "/usr/lib/python2.5/site-packages/twisted/python/failure.py", line 173, in __init__
    raise NoCurrentExceptionError()
twisted.python.failure.NoCurrentExceptionError:

[therve]

I have to idea on how to reproduce that, so any tests or scripts would help a lot, thanks.

[camrdale]

I don't have any scripts or tests, I just experienced it during a large multiple-file download from a server.

For the first error, it occurred for me when the server sent the 'connection: close' header or left out the 'content-length' header in the middle of a pipelined connection (i.e. after receiving multiple responses, and with multiple requests pending). I'm not sure which happened (I suspect the first) because I never got a chance to print the headers due to the error.

For the second error, any closing of a pipelined connection should generate it. Try halting the server while sending a response that is not the last. You might get both errors that way.

Anyway, both errors are obvious (especially the second) by examining the code.

[camrdale]

Looking at it again, the fix for both is quite simple. The setReadPersistent function just needs to be modified like so:

def setReadPersistent(self, persist):
    self.readPersistent = persist
    if not persist:
        # Tell all requests but first to abort.
        lostRequests = self.inRequests[1:]
        del self.inRequests[1:]
        for request in lostRequests:
            request.connectionLost(ProtocolError('The pipelined connection was lost'))

Deleting the inRequests before calling connectionLost on them prevents the loop when setReadPersistent is called again (could use reactor.callLater for connectionLost instead).

And a failure is returned instead of None, which solves the second problem. Ideally though, I think you'd want to use a new exception here (PipelineError) so that you could trap it as a non-parser problem and resubmit the request on a new connection.

[therve]

OK, I have to no idea on how to test that. David?

[camrdale]

patch to fix web2/client/http.py

[camrdale]

patch to test pipelining in the http client

[camrdale]

I attached 2 patches to this ticket to fix it. The patch to web2/client/http.py changes the setReadPersistent to not loop, and does the same for the connectionLost function which also suffered from this problem. They both now return a new PipelineError exception to any requests that were pipelined but never had a chance to be processed. I also had to change the HTTPClientChannelRequest a little, as it was calling abortParse() for requests that had not even started to be parsed. Finally, I modified setReadPersistent a little as it was inefficiently not pipelining (or at least not informing the manager to pipeline) until after the response to the first request had been completely received, when you can pipeline after only the headers have been received.

The second patch is to the tests for the client, which adds the tests needed to show how the current code fails. You can run it on the current (SVN) web2/client/http.py to see that the test_pipelining succeeds, while the other 3 tests fail. Applying the patch to http.py causes all 4 tests to succeed for me.

[exarkun]

This seems to be up for review.

[exarkun]

(In [23725]) Branching to 'web2-client-connectionlost-loop-3207'

[exarkun]

(In [23727]) apply http.py.patch and test_client.py.patch

refs #3207

[exarkun]

I haven't looked closely at the patch. I don't know this part of the codebase very well. However, I notice that in the branch I created, twisted.web2.test.test_fileupload.MultipartTests.testMissingContentDisposition seems to be failing. The only other thing I noticed is that the tests you added (thanks for doing that!) are a bit on the long side. It'd be nice if what they're testing could be expressed in less code. :) I dunno how feasible that is.

[camrdale]

Hi exarkun, thanks for taking an interest in this! :)

I would say that the test_fileupload failure is unrelated because it doesn't seem to have anything to do with the http module that I changed. Have you tried running that test on the trunk? I have no idea how the fileupload module works, so other than noticing that it imports nothing from the http module, I can't comment.

The tests are unfortunately long, and not nearly ideal, because the testing environment was not setup to test pipelining in any way at all. You may note that, until now, there have been absolutely ZERO tests of the pipelining functionality in web2. I had to do some weird manipulations and ordering of requests/responses to get around the http testing framework's limitations. Unfortunately, I am not familiar enough with web2 to rewrite the testing framework, so the tests I wrote are as short as I could make them (I did try and shorten them as much as possible).

Thanks,
Cameron

[exarkun]

Hi Cameron, I was surprised to see the test_fileupload failure as well since I didn't think these changes would be related. However the test is passing on trunk, and the test_fileupload failure was present only on the branch in a number of different platforms.

Thanks for explaining the previous state of pipelining tests (ie, nonexistent). I didn't realize things were that bad. Maybe when I get a chance to look at the changes in more detail I'll have some suggestions to make (or maybe I'll recognize that it is that way for a reason :).

[exarkun]

Not going to fix this in web2 (See #4821). The Twisted Web client doesn't support persistent connections yet (see #3420). When it does, hopefully we will avoid duplicating this bug. Meanwhile, just closing this ticket.