On 04:12 pm, poalman@gmail.com wrote:

Hey,

I'm getting the following error in my logs (lots and lots), but only after the server has been running for some time, I'm not sure what the cause is or what I can do to remedy it.

This seems like a bug in `Agent`, perhaps related to `stopProducing` being called more than once. It would be great if you could produce a minimal example to include with a bug report in the issue tracker. An example that reproduces the problem will also make it easier to see where the bug is in your code, if it happens to be there rather than in Twisted. Jean-Paul

This is what I see in the logs:

2012-12-20 17:07:17+0000 [HTTP11ClientProtocol,client] Unhandled Error Traceback (most recent call last): Failure: twisted.web._newclient.RequestTransmissionFailed: [>]

2012-12-20 17:07:17+0000 [HTTP11ClientProtocol,client] Unexpected exception from twisted.web.client.FileBodyProducer.stopProducing Traceback (most recent call last): File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/endpoints.py", line 99, in connectionLost return self._wrappedProtocol.connectionLost(reason) File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/web/_newclient.py", line 859, in dispatcher return func(*args, **kwargs) File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/web/_newclient.py", line 1458, in _connectionLost_TRANSMITTING self._currentRequest.stopWriting() File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/web/_newclient.py", line 760, in stopWriting _callAppFunction(self.bodyProducer.stopProducing) --- <exception caught here> --- File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/web/_newclient.py", line 191, in _callAppFunction function() File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/web/client.py", line 760, in stopProducing self._task.stop() File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/task.py", line 459, in stop self._checkFinish() File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/task.py", line 469, in _checkFinish raise self._completionState twisted.internet.task.TaskStopped:

Just loads of those, they always seem to come through in pairs (the first twisted.internet.error.ConnectionDone, and then the twisted.internet.task.TaskStopped as above)

I'm just doing PUT requests with twisted.web.client.Agent and using a twisted.web.client.FileBodyProducer to provide the content.

I'm doing the PUT while I still have the request from a render_GET, so I thought maybe it's caused if the user disconnects while I'm doing the PUT? The idea is I redirect them to the file I PUT with request.redirect, which seems to work fine (until I get this error and it doesn't)

The reason I do a PUT and redirect, instead of just writing back to the request is that I check if the file is in a cache first, I then only PUT if it's not there- then redirect afterwards.

Any clues or ideas of what is happening would be hugely helpful

thanks!!

Paul

_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

On 27 December 2012 14:49, Paul Wiseman wrote:

On 21 December 2012 18:08, wrote:

...

On 04:12 pm, poalman@gmail.com wrote:

...

Hey,

I'm getting the following error in my logs (lots and lots), but only after the server has been running for some time, I'm not sure what the cause is or what I can do to remedy it.

This seems like a bug in `Agent`, perhaps related to `stopProducing` being called more than once. It would be great if you could produce a minimal example to include with a bug report in the issue tracker. An example that reproduces the problem will also make it easier to see where the bug is in your code, if it happens to be there rather than in Twisted.

I'll try my best! The problem is I don't seem to see this at all for 10k+ requests ish then I guess something must trigger it as it will start happening a lot, so it may be difficult to reproduce.

I've still not been able to reproduce this on demand.. the least amount of request I've seen before getting the error is 6500 :/ I've also seen this stack trace which I didn't notice before 2013-02-08 10:07:28+0000 [HTTP11ClientProtocol,client] Unhandled Error Traceback (most recent call last): File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/application/app.py", line 323, in runReactorWithLogging reactor.run() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/base.py", line 1169, in run self.mainLoop() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/base.py", line 1181, in mainLoop self.doIteration(t) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/epollreactor.py", line 379, in doPoll log.callWithLogger(selectable, _drdw, selectable, fd, event) --- <exception caught here> --- File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/python/log.py", line 84, in callWithLogger return callWithContext({"system": lp}, func, *args, **kw) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/python/log.py", line 69, in callWithContext return context.call({ILogContext: newCtx}, func, *args, **kw) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/python/context.py", line 118, in callWithContext return self.currentContext().callWithContext(ctx, func, *args, **kw) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/python/context.py", line 81, in callWithContext return func(*args,**kw) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/posixbase.py", line 639, in _doReadOrWrite self._disconnectSelectable(selectable, why, inRead) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/posixbase.py", line 258, in _disconnectSelectable selectable.readConnectionLost(f) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/tcp.py", line 267, in readConnectionLost self.connectionLost(reason) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/tcp.py", line 473, in connectionLost self._commonConnection.connectionLost(self, reason) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/tcp.py", line 281, in connectionLost abstract.FileDescriptor.connectionLost(self, reason) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/abstract.py", line 182, in connectionLost self.producer.stopProducing() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/web/client.py", line 760, in stopProducing self._task.stop() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/task.py", line 460, in stop self._completeWith(TaskStopped(), Failure(TaskStopped())) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/task.py", line 439, in _completeWith self._cooperator._removeTask(self) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/task.py", line 578, in _removeTask self._delayedCall.cancel() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/base.py", line 89, in cancel raise error.AlreadyCalled twisted.internet.error.AlreadyCalled: Tried to cancel an already-called event. I'll keep trying to work out the issue, any suggestions on what I might try to reproduce it or guesses at causes?

...

Jean-Paul

...

This is what I see in the logs:

2012-12-20 17:07:17+0000 [HTTP11ClientProtocol,client] Unhandled Error Traceback (most recent call last): Failure: twisted.web._newclient.RequestTransmissionFailed: [>]

2012-12-20 17:07:17+0000 [HTTP11ClientProtocol,client] Unexpected exception from twisted.web.client.FileBodyProducer.stopProducing Traceback (most recent call last): File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/endpoints.py", line 99, in connectionLost return self._wrappedProtocol.connectionLost(reason) File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/web/_newclient.py", line 859, in dispatcher return func(*args, **kwargs) File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/web/_newclient.py", line 1458, in _connectionLost_TRANSMITTING self._currentRequest.stopWriting() File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/web/_newclient.py", line 760, in stopWriting _callAppFunction(self.bodyProducer.stopProducing) --- <exception caught here> --- File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/web/_newclient.py", line 191, in _callAppFunction function() File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/web/client.py", line 760, in stopProducing self._task.stop() File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/task.py", line 459, in stop self._checkFinish() File "/usr/local/lib/python2.7/site- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/task.py", line 469, in _checkFinish raise self._completionState twisted.internet.task.TaskStopped:

Just loads of those, they always seem to come through in pairs (the first twisted.internet.error.ConnectionDone, and then the twisted.internet.task.TaskStopped as above)

I'm just doing PUT requests with twisted.web.client.Agent and using a twisted.web.client.FileBodyProducer to provide the content.

I'm doing the PUT while I still have the request from a render_GET, so I thought maybe it's caused if the user disconnects while I'm doing the PUT? The idea is I redirect them to the file I PUT with request.redirect, which seems to work fine (until I get this error and it doesn't)

The reason I do a PUT and redirect, instead of just writing back to the request is that I check if the file is in a cache first, I then only PUT if it's not there- then redirect afterwards.

Any clues or ideas of what is happening would be hugely helpful

thanks!!

Paul

_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python

On 8 February 2013 19:03, wrote:

On 03:12 pm, poalman@gmail.com wrote:

...

I've still not been able to reproduce this on demand.. the least amount of request I've seen before getting the error is 6500 :/

I've also seen this stack trace which I didn't notice before

2013-02-08 10:07:28+0000 [HTTP11ClientProtocol,client] Unhandled Error Traceback (most recent call last): File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/application/app.py", line 323, in runReactorWithLogging reactor.run() File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/base.py", line 1169, in run self.mainLoop() File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/base.py", line 1181, in mainLoop self.doIteration(t) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/epollreactor.py", line 379, in doPoll log.callWithLogger(selectable, _drdw, selectable, fd, event) --- <exception caught here> --- File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/python/log.py", line 84, in callWithLogger return callWithContext({"system": lp}, func, *args, **kw) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/python/log.py", line 69, in callWithContext return context.call({ILogContext: newCtx}, func, *args, **kw) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/python/context.py", line 118, in callWithContext return self.currentContext().callWithContext(ctx, func, *args, **kw) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/python/context.py", line 81, in callWithContext return func(*args,**kw) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/posixbase.py", line 639, in _doReadOrWrite self._disconnectSelectable(selectable, why, inRead) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/posixbase.py", line 258, in _disconnectSelectable selectable.readConnectionLost(f) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/tcp.py", line 267, in readConnectionLost self.connectionLost(reason) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/tcp.py", line 473, in connectionLost self._commonConnection.connectionLost(self, reason) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/tcp.py", line 281, in connectionLost abstract.FileDescriptor.connectionLost(self, reason) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/abstract.py", line 182, in connectionLost self.producer.stopProducing() File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/web/client.py", line 760, in stopProducing self._task.stop() File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/task.py", line 460, in stop self._completeWith(TaskStopped(), Failure(TaskStopped())) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/task.py", line 439, in _completeWith self._cooperator._removeTask(self) File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/task.py", line 578, in _removeTask self._delayedCall.cancel() File "/usr/local/lib/python2.7/dist- packages/Twisted-12.2.0-py2.7-linux- x86_64.egg/twisted/internet/base.py", line 89, in cancel raise error.AlreadyCalled twisted.internet.error.AlreadyCalled: Tried to cancel an already-called event.

I'll keep trying to work out the issue, any suggestions on what I might try to reproduce it or guesses at causes?

Since it seems to be related to handling of lost connections, you may be able to reproduce it more easily if you issue your requests to an HTTP server which drops connections more often. Presumably the production service you're issuing requests too tries pretty hard to properly serve responses to every request. If you point `Agent` at a worse HTTP server (eg, one you write using twisted.web and implement to close connections prematurely at various points during the response) this may produce the issue more quickly.

You could also try hooking `Agent` up to one of the in-memory reactors/transports. The advantage of this is that it will be much easier to "close" the connection at a specific point (deterministically). The disadvantage is that the in-memory reactor/transport may not exactly replicate the real reactor/transport behavior and so fail to reproduce the issue entirely.

Jean-Paul

Hey, I'm more and more sure it's the PUT request, and I think you're right it is likely to do with the server that I'm putting to (Google Cloud Storage) doing something odd occasionally. I'm trying to reproduce it with a small twisted client and server, using a PUT request to send to the server but I can't seem to close the connection uncleanly. How would you recommend I do that? I've tried adding request.finish() on a callLater but that seems to finish the connection in a clean way. How can I close the connection in the way you suggest? Also I put a bit in FileBodyProducer that looks at the stack when the error starts to see where it was being called from, but it didn't help me too much. This is the stack anyway File "/usr/local/bin/twistd", line 5, in <module> pkg_resources.run_script('Twisted==12.2.0', 'twistd') File "/usr/lib/python2.7/dist-packages/pkg_resources.py", line 499, in run_script self.require(requires)[0].run_script(script_name, ns) File "/usr/lib/python2.7/dist-packages/pkg_resources.py", line 1235, in run_script execfile(script_filename, namespace, namespace) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/EGG-INFO/scripts/twistd", line 14, in <module> run() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/scripts/twistd.py", line 27, in run app.run(runApp, ServerOptions) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/application/app.py", line 652, in run runApp(config) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/scripts/twistd.py", line 23, in runApp _SomeApplicationRunner(config).run() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/application/app.py", line 390, in run self.postApplication() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/scripts/_twistd_unix.py", line 231, in postApplication self.startReactor(None, self.oldstdout, self.oldstderr) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/application/app.py", line 402, in startReactor self.config, oldstdout, oldstderr, self.profiler, reactor) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/application/app.py", line 323, in runReactorWithLogging reactor.run() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/base.py", line 1169, in run self.mainLoop() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/base.py", line 1181, in mainLoop self.doIteration(t) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/epollreactor.py", line 379, in doPoll log.callWithLogger(selectable, _drdw, selectable, fd, event) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/python/log.py", line 84, in callWithLogger return callWithContext({"system": lp}, func, *args, **kw) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/python/log.py", line 69, in callWithContext return context.call({ILogContext: newCtx}, func, *args, **kw) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/python/context.py", line 118, in callWithContext return self.currentContext().callWithContext(ctx, func, *args, **kw) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/python/context.py", line 81, in callWithContext return func(*args,**kw) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/posixbase.py", line 639, in _doReadOrWrite self._disconnectSelectable(selectable, why, inRead) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/posixbase.py", line 258, in _disconnectSelectable selectable.readConnectionLost(f) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/tcp.py", line 267, in readConnectionLost self.connectionLost(reason) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/tcp.py", line 473, in connectionLost self._commonConnection.connectionLost(self, reason) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/tcp.py", line 287, in connectionLost protocol.connectionLost(reason) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/internet/endpoints.py", line 99, in connectionLost return self._wrappedProtocol.connectionLost(reason) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/web/_newclient.py", line 859, in dispatcher return func(*args, **kwargs) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/web/_newclient.py", line 1458, in _connectionLost_TRANSMITTING self._currentRequest.stopWriting() File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/web/_newclient.py", line 760, in stopWriting _callAppFunction(self.bodyProducer.stopProducing) File "/usr/local/lib/python2.7/dist-packages/Twisted-12.2.0-py2.7-linux-x86_64.egg/twisted/web/_newclient.py", line 191, in _callAppFunction function() File "main.tac", line 65, in stopProducing log_stack() File "main.tac", line 55, in log_stack stack_trace = traceback.format_stack(frame)

_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python