Traceback object removed from Failure when it reaches end of Deferred callback chain

[Forrest Voight]

(Moved from mention in #3622)

When a Deferred is errback'd with no handlers currently in the callback chain, the Failure is cleaned (with cleanFailure) and then stored in the Deferred's DebugInfo. However, the Deferred's Failure is not copied, but instead used for this, mutating it.

If the Deferred is used in an @inlineCallbacks function and caught as a normal exception, it then has a useless traceback:

import traceback

from twisted.internet import defer

def a():
   1/0

@defer.inlineCallbacks
def b():
    try:
        result = yield defer.maybeDeferred(a)
    except Exception:
        traceback.print_exc()
    else:
        print result

b()

results in

Traceback (most recent call last):
  File "test_failure_traceback.py", line 11, in b
    result = yield defer.maybeDeferred(a)
ZeroDivisionError: integer division or modulo by zero

[Forrest Voight]

patch to duplicate the Deferred's Failure before cleaning it to store it in DebugInfo

[Jean-Paul Calderone]

Thanks for your interest in this area, forrestv.

I think the solution in the patch is problematic. The rest of the _runCallbacks code takes great care to ensure that an uncleaned Failure will not last past the end of the callback processing. It is not an accident that the Failure on the Deferred is shared with the _DebugInfo and that it gets cleaned, it is intentional.

If the Failure remains uncleaned, then it keeps references to every local on the call stack at the time of the exception. This has terrible consequences for memory usage and cyclic garbage creation.

The issue described here, that tracebacks associated with Deferreds with failure results are not always fully informative, is real. However, limitations in the Python runtime mean that it is very, very difficult to fix this. On the one hand I want to close this ticket as wontfix (or cantfix, but we don't have that status). On the other hand, it is a real shortcoming, and it would be nice if someone figured out a real way to fix it.

Another approach you might consider, though, is that maybeDeferred only serves to introduce this problem in this particular example. Stop using it and the problem goes away:

import traceback

from twisted.internet.defer import inlineCallbacks

def bad():
    raise RuntimeError("foo")

def good():
    return 42

@inlineCallbacks
def foo():
    for f in good, bad:
        try:
            result = yield f()
        except:
            print 'Failure'
            traceback.print_exc()
        else:
            print 'Success', result
        
foo()

produces output:

Success 42
Failure
Traceback (most recent call last):
  File "foo.py", line 16, in foo
    result = yield f()
  File "foo.py", line 7, in bad
    raise RuntimeError("foo")
RuntimeError: foo

[radix]

also, if you use log.err() instead of traceback.print_exc(), you'll get a better traceback, even if you do use maybeDeferred.

[Jean-Paul Calderone]

Thanks again for your interest. In the light of the above comments, I think I will close this as wontfix. Improvements to Failure are welcome, but they need to be made carefully and with consideration of Failure's more subtle (often undocumented) goals. I encourage you to raise the issue on the twisted-python mailing list or the #twisted irc channel on freenode.

[Forrest Voight]

Thanks for the responses. They all make complete sense, of course. However, I just ran into the same problem again, and reduced it down to your example, exarkun, except with bad() and good() being inlineCallbacks functions too:

import traceback

from twisted.internet.defer import inlineCallbacks, returnValue

@inlineCallbacks
def bad():
    raise RuntimeError("foo")
    yield # just to make this a generator

@inlineCallbacks
def good():
    returnValue(42)
    yield # just to make this a generator

@inlineCallbacks
def foo():
    for f in good, bad:
        try:
            result = yield f()
        except:
            print 'Failure'
            traceback.print_exc()
        else:
            print 'Success', result

foo()

produces:

Success 42
Failure
Traceback (most recent call last):
  File "y.py", line 19, in foo
    result = yield f()
RuntimeError: foo

It happens in this situation because the Deferred produced by calling bad/good doesn't have a callback attached until after it has already errback'd.

I thought that it was interesting that this could happen in such a surprising manner: exceptions raised in an inlineCallbacks function after it waits on something for the first time get through with their traceback intact, but exceptions raised before the first yield don't. There's no apparent way to avoid this issue (besides using log.err), unlike my first example, which had to use maybeDeferred.

Leaving closed because all the previous discussion still applies; this is just a postmortem that might help others. However, in #3622, spiv said

*Perhaps* we could skip the cleanFailure call you mention if setDebugging(True) is active?

which seems like a potential fix for the headaches this has caused me (and probably others). Another useful avenue might be stating that log.err is preferred to traceback.print_exc in the documentation for using inlineCallbacks.