[Twisted-Python] Strategy for finding source of unhandled error in Deferred
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?
On Sun, Mar 18, 2018 at 11:04 AM, Alex Railean <ralienpp@gmail.com> wrote:
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.
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?
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com https://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
On Sun, Mar 18, 2018 at 11:21 AM, Jean-Paul Calderone < exarkun@twistedmatrix.com> wrote:
On Sun, Mar 18, 2018 at 11:04 AM, Alex Railean <ralienpp@gmail.com> wrote:
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.
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.
Try this: from twisted.internet.defer import setDebugging setDebugging(True) This gives you creation and callback stacks in the logs. Jean-Paul
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?
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com https://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
On Sunday, 18 March 2018 15:23:58 BST Jean-Paul Calderone wrote:
On Sun, Mar 18, 2018 at 11:21 AM, Jean-Paul Calderone <
exarkun@twistedmatrix.com> wrote:
On Sun, Mar 18, 2018 at 11:04 AM, Alex Railean <ralienpp@gmail.com> wrote:
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.
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.
Try this:
from twisted.internet.defer import setDebugging setDebugging(True)
This gives you creation and callback stacks in the logs.
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
Jean-Paul
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?
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com https://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
On Mon, Mar 26, 2018 at 10:47 AM, Barry Scott <barry.scott@forcepoint.com> wrote:
On Sunday, 18 March 2018 15:23:58 BST Jean-Paul Calderone wrote:
Try this:
from twisted.internet.defer import setDebugging setDebugging(True)
This gives you creation and callback stacks in the logs.
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)
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