[Twisted-Python] Strategy for finding source of unhandled error in Deferred
![](https://secure.gravatar.com/avatar/16d5426dece90384db01d8a495f7d828.jpg?s=120&d=mm&r=g)
Hello, I have inherited a misbehaving system and am trying to troubleshoot it. The code is not documented and I cannot produce a minimal working example that illustrates the problem yet, as I don't know which parts are involved and how they relate. The version of Twisted used is 16.1.1, running on Fedora 15. My first attempt is to leverage Twisted's logging capabilities and retrieve information about the place in the code that leads to the error: from twisted.python import log as twisted_log observer = twisted_log.PythonLoggingObserver(loggerName='twcore') observer.start() This produces the following entries in the log: Unhandled error in Deferred: CRITICAL _legacy twcore Unhandled error in Deferred: Traceback (most recent call last): Failure: __builtin__.type: <class 'twisted.internet.error.TimeoutError'> CRITICAL _legacy twcore How can I get more clues about what is going on? I was expecting a line number, or a complete call-stack. What are the recommended troubleshooting steps for finding the Deferred in which the error occurred? There are are around 30 of them throughout the code, is there a heuristic I can use to narrow down the list of suspects?
![](https://secure.gravatar.com/avatar/607cfd4a5b41fe6c886c978128b9c03e.jpg?s=120&d=mm&r=g)
On Sun, Mar 18, 2018 at 11:21 AM, Jean-Paul Calderone < exarkun@twistedmatrix.com> wrote:
Try this: from twisted.internet.defer import setDebugging setDebugging(True) This gives you creation and callback stacks in the logs. Jean-Paul
![](https://secure.gravatar.com/avatar/cf223b7cf77583c0a2665bad01f84f11.jpg?s=120&d=mm&r=g)
On Sunday, 18 March 2018 15:23:58 BST Jean-Paul Calderone wrote:
If you need to track down who put the value into the deferred you need to patch the defer.py code to log that info. There are 2 places that a value enters the Deferred. The first is the callback() call. The other is in defer.py:653 Deffered._runCallbacks() 653: current.result = callback(current.result, *args, **kw) Barry
![](https://secure.gravatar.com/avatar/607cfd4a5b41fe6c886c978128b9c03e.jpg?s=120&d=mm&r=g)
On Mon, Mar 26, 2018 at 10:47 AM, Barry Scott <barry.scott@forcepoint.com> wrote:
No, you don't: exarkun@baryon:/tmp$ cat deferreddebug.py from twisted.internet.defer import fail, setDebugging setDebugging(True) def foo(): return fail(Exception("boo")) foo() exarkun@baryon:/tmp$ python deferreddebug.py Unhandled error in Deferred: (debug: C: Deferred was created: C: File "deferreddebug.py", line 5, in <module> C: foo() C: File "deferreddebug.py", line 4, in foo C: return fail(Exception("boo")) C: File "/home/exarkun/.local/lib/python2.7/site-packages/twisted/internet/defer.py", line 106, in fail C: d = Deferred() I: First Invoker was: I: File "deferreddebug.py", line 5, in <module> I: foo() I: File "deferreddebug.py", line 4, in foo I: return fail(Exception("boo")) I: File "/home/exarkun/.local/lib/python2.7/site-packages/twisted/internet/defer.py", line 107, in fail I: d.errback(result) ) exarkun@baryon:/tmp$ Although it is true that you only get this behavior for the "Unhandled error in Deferred" case. If you explicitly log a Failure from a Deferred, even with Deferred debugging on, you will not get a callstack for the creator or invoker. You'll just get whatever callstack the Failure has (and the Failure is independent of the Deferred). Jean-Paul
![](https://secure.gravatar.com/avatar/607cfd4a5b41fe6c886c978128b9c03e.jpg?s=120&d=mm&r=g)
On Sun, Mar 18, 2018 at 11:21 AM, Jean-Paul Calderone < exarkun@twistedmatrix.com> wrote:
Try this: from twisted.internet.defer import setDebugging setDebugging(True) This gives you creation and callback stacks in the logs. Jean-Paul
![](https://secure.gravatar.com/avatar/cf223b7cf77583c0a2665bad01f84f11.jpg?s=120&d=mm&r=g)
On Sunday, 18 March 2018 15:23:58 BST Jean-Paul Calderone wrote:
If you need to track down who put the value into the deferred you need to patch the defer.py code to log that info. There are 2 places that a value enters the Deferred. The first is the callback() call. The other is in defer.py:653 Deffered._runCallbacks() 653: current.result = callback(current.result, *args, **kw) Barry
![](https://secure.gravatar.com/avatar/607cfd4a5b41fe6c886c978128b9c03e.jpg?s=120&d=mm&r=g)
On Mon, Mar 26, 2018 at 10:47 AM, Barry Scott <barry.scott@forcepoint.com> wrote:
No, you don't: exarkun@baryon:/tmp$ cat deferreddebug.py from twisted.internet.defer import fail, setDebugging setDebugging(True) def foo(): return fail(Exception("boo")) foo() exarkun@baryon:/tmp$ python deferreddebug.py Unhandled error in Deferred: (debug: C: Deferred was created: C: File "deferreddebug.py", line 5, in <module> C: foo() C: File "deferreddebug.py", line 4, in foo C: return fail(Exception("boo")) C: File "/home/exarkun/.local/lib/python2.7/site-packages/twisted/internet/defer.py", line 106, in fail C: d = Deferred() I: First Invoker was: I: File "deferreddebug.py", line 5, in <module> I: foo() I: File "deferreddebug.py", line 4, in foo I: return fail(Exception("boo")) I: File "/home/exarkun/.local/lib/python2.7/site-packages/twisted/internet/defer.py", line 107, in fail I: d.errback(result) ) exarkun@baryon:/tmp$ Although it is true that you only get this behavior for the "Unhandled error in Deferred" case. If you explicitly log a Failure from a Deferred, even with Deferred debugging on, you will not get a callstack for the creator or invoker. You'll just get whatever callstack the Failure has (and the Failure is independent of the Deferred). Jean-Paul
participants (3)
-
Alex Railean
-
Barry Scott
-
Jean-Paul Calderone