Opened 6 years ago

Closed 3 years ago

#3622 defect closed invalid (invalid)

Traceback info removed from failure when inlineCallbacks decorated func calls deferred returning func that fails

Reported by: terrycojones Owned by:
Priority: normal Milestone:
Component: core Keywords: inlineCallbacks tracebacks
Cc: Branch:
Author: Launchpad Bug:

Description

In the following code, a function (F1), decorated with defer.inlineCallbacks, calls another function (F2) that returns a deferred. A failure, containing a correct traceback, is passed to the errback of this deferred. However, due to the workings of the deferred failure processing (details below), the traceback in the exception information thrown back to F1 is None. So when F1 raises an exception based on this, the traceback (which is freshly generated) in the exception shows the error as originating on the yield line instead of at the illegal division.

Here's the code:

from twisted.internet import reactor, defer

def ok(r): print 'OK', r
def nok(r): print 'FAILED', r

def F2():
    try:
        1 / 0
    except Exception:
        return defer.fail()

@defer.inlineCallbacks
def F1():
    yield F2()

def F0():
    F1().addCallbacks(ok, nok).addBoth(lambda _: reactor.stop())

reactor.callLater(0, F0)
reactor.run()

This produces the following output:

FAILED [Failure instance: Traceback: <type 'exceptions.ZeroDivisionError'>: integer division or modulo by zero
/usr/lib/python2.5/site-packages/twisted/internet/posixbase.py:228:mainLoop
/usr/lib/python2.5/site-packages/twisted/internet/base.py:561:runUntilCurrent
five.py:18:F0
/usr/lib/python2.5/site-packages/twisted/internet/defer.py:813:unwindGenerator
--- <exception caught here> ---
/usr/lib/python2.5/site-packages/twisted/internet/defer.py:724:_inlineCallbacks
five.py:15:F1
]

As you can see, the traceback shows the exception as having been raised in F1, not F2.

In more detail, the sequence of events is as below. If it's not clear what code I'm talking about, it's almost all in twisted.internet.defer either in _inlineCallbacks or in the Deferred class.

  1. When Python reads the input file and comes across F1, it creates F1d, an inlineCallbacks decorated version of F1.
  2. F0 calls F1 (really F1d).
  3. This results in _inlineCallbacks being called with the result of calling F1. Because F1 yields, _inlineCallbacks gets passed a generator G.
  4. _inlineCallbacks starts G, sending it None.
  5. G runs, calling F2.
  6. defer.fail is called in F2. This
    • creates a deferred and a failure and passes the failure it to errback on the deferred.
    • errback calls _startRunCallbacks with the failure.
    • _startRunCallbacks calls _runCallbacks.
    • There are no callbacks on the deferred.
    • Its result is a failure instance, so cleanFailure is called on it.
    • The failure has its tb attribute set to None by __getstate__.
  7. As a result, the deferred returned by F2 and received by F1d has a failure result in it with None in the tb.
  8. This deferred is received in G.
  9. gotResult is added to the deferred and is called immediately because the deferred has been called. gotResult puts the failure result into waiting[1] and this is then put into result.
  10. _inlineCallbacks loops and its result is now a failure.
  11. It throws the type, value, and (None) tb back to G.
  12. G raises the exception. The traceback is None, so a new one is created at yield in F1. Note: the exception still has type ZeroDivisionError
  13. This is caught by _inlineCallbacks which calls errback on the deferred F0 will receive.
  14. F0 adds its call and errback, which are called with the failure result.

In summary, the failure that propagates back to the nok method is of type ZeroDivisionError (corresponding to the original exception) but its traceback is created by the exception that's raised when F1 yields F2(). The original traceback is gone.

As a result, the programmer who has used inlineCallbacks knows the type of error that has occurred but has no further information about where it happened. This can of course be complicated to track down if F2 is non-trivial and calls other functions (some of which might in turn use inlineCallbacks which might in turn run into the same problem).

Apologies for so much detail. Maybe it's not necessary.

Change History (8)

comment:1 Changed 6 years ago by radix

Can you try this with Twisted 8.2 (or Twisted trunk)? This behavior was improved recently.

comment:2 Changed 6 years ago by radix

For the record, here's what I'm getting (I've changed it to call f.printTraceback() instead of just printing f to be a bit more readable):

FAILED
Traceback (most recent call last):
  File "foo.py", line 15, in F0
    F1().addCallbacks(ok, nok).addBoth(lambda _: reactor.stop())
  File "/home/radix/Projects/Twisted/trunk/twisted/internet/defer.py", line 834, in unwindGenerator
    return _inlineCallbacks(None, f(*args, **kwargs), Deferred())
  File "/home/radix/Projects/Twisted/trunk/twisted/internet/defer.py", line 751, in _inlineCallbacks
    result = g.send(result)
  File "foo.py", line 13, in F1
    yield F2()
--- <exception caught here> ---
  File "foo.py", line 8, in F2
    1 / 0
exceptions.ZeroDivisionError: integer division or modulo by zero

comment:3 Changed 6 years ago by terrycojones

I ran with 8.2 and get the same output you report.

Time for another apology! I actually went and looked at defer.py in trac before I posted originally, to check that deferred processing appeared unchanged. I now see the throwExceptionIntoGenerator in _inlineCallbacks....

Argh. I'm very sorry for even more wasting of time.

I'll let someone else close this tick, assuming we're all done.

Terry

comment:4 Changed 6 years ago by radix

  • Resolution set to invalid
  • Status changed from new to closed

No problem Terry :-)

comment:5 Changed 3 years ago by <automation>

  • Owner glyph deleted

comment:6 Changed 3 years ago by forrestv

  • Resolution invalid deleted
  • Status changed from closed to reopened

This problem still exists in a different form - the actual traceback object is still removed from the Failure with cleanFailure when there are no callbacks to be called. If the exception is thrown into an @inlineCallbacks function and caught as a normal exception, it 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

comment:7 Changed 3 years ago by spiv

This problem still exists in a different form

Probably worth filing a new ticket then, for clarity.

At a glance your case seems difficult to fix without a way to synthesise genuine traceback objects (although even if that were possible we'd probably just invite a new set of bugs saying how pdb doesn't work on tracebacks after cleanFailure...). *Perhaps* we could skip the cleanFailure call you mention if setDebugging(True) is active?

comment:8 Changed 3 years ago by forrestv

  • Resolution set to invalid
  • Status changed from reopened to closed

Ticket set back to invalid, new problem moved to #5178.

Note: See TracTickets for help on using tickets.