[Twisted-web] treq requests failing with twisted.web._newclient.ResponseNeverReceived

Wed Apr 8 11:44:56 MDT 2015

Through some trial and error, I have finally managed to produce a reduced test 
case that can actually reproduce this problem:

1. Install and start a local webserver with a keep-alive timeout of one 
second.
For Apache, the relevant configuration entries look like this:

KeepAlive On
KeepAliveTimeout 1
MaxKeepAliveRequests 1000

(MaxKeepAliveRequests is not that important, just so long as it isn't reached 
during the test.)

The bug is not triggered if the webserver includes a "Connection: close" 
header, which Apache does if you disable KeepAlive entirely.

2. Run this Python script:
==============
import time
import treq
from twisted.internet import reactor
from twisted.internet.defer import inlineCallbacks, returnValue

@inlineCallbacks
def post_data():
  try:
    resp = yield treq.post("http://127.0.0.1/",
                  data="bla",
                  persistent=True)

    print("response code: %s" % resp.code)
    data = yield treq.content(resp)
    print("data: %r" % data)

  except Exception as failure:
    print("failure: %r" % failure)
    returnValue(None)

  returnValue(data)

def call_again(_):
  time.sleep(1.1)
  d = post_data()
  d.addBoth(lambda _: reactor.stop())

d = post_data()
d.addCallback(call_again)

reactor.run()
==============

The output from that looks like this on my machine:
==============
response code: 404
data: '<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 
2.0//EN">\n<html><head>\n<title>404 Not Found</title>\n</head><body>\n<h1>Not 
Found</h1>\n<p>The requested URL / was not found on this 
server.</p>\n<hr>\n<address>Apache Server at 127.0.0.1 Port 
80</address>\n</body></html>\n'
failure: ResponseNeverReceived([<twisted.python.failure.Failure <class 
'twisted.internet.error.ConnectionDone'>>],)
==============

As you can see, the second request fails with "ResponseNeverReceived".

As far as I can tell, twisted.web.client.HTTPConnectionPool simply fails to 
notice that the server has closed the underlying connection in the meantime.

According to the RFC, the server is allowed to close the connection at any 
time if it is idle from the server's point of view (explicitly even if a new 
request from the client has already arrived).

Regards,
	Guido W.

On Wednesday 08 April 2015 14:24:45 Guido Winkelmann wrote:
>An update on the situation:
>
>I tried downgrading both Twisted and treq to <15.0. The problem remained, so
>this issue is /not/ new in 15.0.
>
>When I remove the "pool" parameter in this line in treq/api.py:113:
>
>agent = Agent(reactor, pool=pool)
>
>the problem completely disappears, so I'm assuming the problems lies
>somewhere in the connection pooling logic.
>
>The web server I am using in these tests is flask's built-in standalone
>webserver (http://flask.pocoo.org/). This webserver speaks HTTP 1.1, but does
>not support keep-alive (at least not with non-static content), which is
>technically allowed but may be a slightly unusual combination these days.
>
>Regards,
>	Guido W.
>
>On Thursday 02 April 2015 19:49:59 Guido Winkelmann wrote:
>>Hi,
>>
>>Recently, I have been experiencing some problems in our codebase wth treq
>>requests failing with error messages like this:
>>
>>2015-04-02 19:20:22 ERROR    - pf.agent.http.client - POST
>>http://127.0.0.1:5000/api/v1/agents/a113b5a8-9822-413b-b1fd-fce3014956cf has
>>failed (uid: 78c7ec2a4b4d):
>>Traceback (most recent call last):
>>Failure: twisted.web._newclient.ResponseNeverReceived:
>>[<twisted.python.failure.Failure <class
>>'twisted.internet.error.ConnectionDone'>>]
>>
>>Unfortunately, I have not been able to successfully produce a reduced test
>>case that will reproduce this behaviour.  It only happens under some weird
>>set of circumstances, and I am still not sure exactly which.  It appears to
>>be highly sensitive to the order of requests.  Funnily enough, this error
>>does not show in the codebase as it is on github right now, but if I reorder
>>some of the requests, it will show.  Here is one example that has cost me
>>some time and head-scratching:
>>
>>https://github.com/pyfarm/pyfarm-agent/issues/249
>>
>>I think that these problems have started after upgrading to Twisted 15.0,
>>but I'm not completely certain about this.
>>
>>Here is one of the methods that's affected by this:
>>
>>https://github.com/pyfarm/pyfarm-agent/blob/master/pyfarm/agent/service.py#L
>>2 31
>>
>>(post_direct() is just a thin wrapper over treq.request that adds some
>>headers we need in our codebase.  I have tried just using treq.request
>>directly instead, the result was the same.)
>>
>>Can someone tell me under which circumstances treq.request would produce an
>>error like this?
>>
>>Without actually knowing the source in question, I would guess that
>>something in there is, for some some reason, erroneously trying to reuse a
>>TCP connection that has already been closed.
>>
>>Regards,
>>
>>	Guido W.
>>
>>_______________________________________________
>>Twisted-web mailing list
>>Twisted-web at twistedmatrix.com
>>http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-web
>
>_______________________________________________
>Twisted-web mailing list
>Twisted-web at twistedmatrix.com
>http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-web