Opened 2 years ago

Last modified 20 months ago

#5854 enhancement new

When inlineCallbacks is used at multiple stacks levels, tracebacks don't show these levels.

Reported by: talljosh Owned by: talljosh
Priority: normal Milestone:
Component: core Keywords:
Cc: Branch: branches/inlinecallacks-traceback-info-5854-2
(diff, github, buildbot, log)
Author: talljosh, exarkun Launchpad Bug:

Description

Potentially similar tickets: #3622, #5178

Simple example code that creates a call stack using inlineCallbacks and causes an error at the bottom level:

# This example creates a call stack that uses inlineCallbacks and causes an error at the bottom level.

from twisted.internet import defer, reactor

@defer.inlineCallbacks
def a():
    yield 1/0

@defer.inlineCallbacks
def b():
    yield a()

@defer.inlineCallbacks
def c():
    yield b()

def main():
    d = c()
    @d.addErrback
    def caught(x):
        x.printTraceback()
        reactor.stop()

if __name__ == '__main__':
    reactor.callWhenRunning(main)
    reactor.run()

The resulting traceback:

Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/Twisted-11.0.0-py2.7-linux-i686.egg/twisted/internet/defer.py", line 1141, in unwindGenerator
    return _inlineCallbacks(None, f(*args, **kwargs), Deferred())
  File "/usr/local/lib/python2.7/dist-packages/Twisted-11.0.0-py2.7-linux-i686.egg/twisted/internet/defer.py", line 1020, in _inlineCallbacks
    result = g.send(result)
  File "simpletwistedtest.py", line 9, in b
    yield a()
  File "/usr/local/lib/python2.7/dist-packages/Twisted-11.0.0-py2.7-linux-i686.egg/twisted/internet/defer.py", line 1141, in unwindGenerator
    return _inlineCallbacks(None, f(*args, **kwargs), Deferred())
--- <exception caught here> ---
  File "/usr/local/lib/python2.7/dist-packages/Twisted-11.0.0-py2.7-linux-i686.egg/twisted/internet/defer.py", line 1020, in _inlineCallbacks
    result = g.send(result)
  File "simpletwistedtest.py", line 5, in a
    yield 1/0
exceptions.ZeroDivisionError: integer division or modulo by zero

I've created a patch that inserts frames into the failure object to given something more useful:

Traceback (most recent call last):
  File "twistedtest.py", line 171, in unwindGenerator
    return _inlineCallbacks(None, f(*args, **kwargs), defer.Deferred())
  File "twistedtest.py", line 27, in _inlineCallbacks
    result = g.send(result)
  File "twistedtest.py", line 183, in b
    yield a()
  File "twistedtest.py", line 171, in unwindGenerator
    return _inlineCallbacks(None, f(*args, **kwargs), defer.Deferred())
--- <exception caught here> ---
  File "twistedtest.py", line 187, in c
    yield b()
  File "twistedtest.py", line 183, in b
    yield a()
  File "twistedtest.py", line 27, in _inlineCallbacks
    result = g.send(result)
  File "twistedtest.py", line 179, in a
    yield 1/0
exceptions.ZeroDivisionError: integer division or modulo by zero

I intend to submit the patch as soon as I've got some good tests for the code.

Attachments (5)

inlineCallbacks-extra-traceback-info.patch (1.5 KB) - added by talljosh 2 years ago.
Patch to add extra frame information to a failure when it's inlineCallbacks passes it to its caller.
inlineCallbacks-extra-traceback-info.2.patch (3.4 KB) - added by talljosh 2 years ago.
Updated patch that includes a test.
inlinecallbacks-traceback-info-response-to-comments.patch (2.3 KB) - added by talljosh 20 months ago.
Patch against inlinecallacks-traceback-info-5854 branch in response to comments
inlinecallbacks-traceback-info-response-to-comments.2.patch (5.1 KB) - added by talljosh 20 months ago.
Patch against /branches/inlinecallacks-traceback-info-5854-2 which refactors common code into a separate function in response to review by therve.
inlinecallbacks-traceback-info-response-to-comments.3.patch (7.7 KB) - added by talljosh 20 months ago.
Added more tests in response to latest review.

Download all attachments as: .zip

Change History (25)

Changed 2 years ago by talljosh

Patch to add extra frame information to a failure when it's inlineCallbacks passes it to its caller.

comment:1 Changed 2 years ago by talljosh

  • Owner set to talljosh
  • Status changed from new to assigned

Changed 2 years ago by talljosh

Updated patch that includes a test.

comment:2 Changed 2 years ago by talljosh

  • Keywords review added
  • Owner talljosh deleted
  • Status changed from assigned to new

Be nice to me, this is my first contribution to Twisted.

comment:3 Changed 2 years ago by talljosh

  • Owner set to jerub

comment:4 Changed 2 years ago by jerub

  • Author set to jerub
  • Branch set to branches/inlinecallacks-traceback-info-5854

(In [36211]) Branching to 'inlinecallacks-traceback-info-5854'

comment:5 Changed 2 years ago by jerub

Patch applied in r36212.

comment:6 Changed 2 years ago by jerub

(In [36213]) Add topfile explaining that nested inlineCallbacks tracebacks will now show more levels of stackframe.

Refs #5854

comment:7 Changed 2 years ago by jerub

  • Author changed from jerub to talljosh
  • Keywords review removed
  • Owner changed from jerub to talljosh

Thanks for the patch, I've applied it to a branch and run the tests.

As you're adding a layer to the stackframe, and capturing locals and globals, it would be good if you respected the attribute of the failure object 'twisted.python.failure.Failure.captureVars'. See http://twistedmatrix.com/trac/browser/branches/inlinecallacks-traceback-info-5854/twisted/python/failure.py#L289

'r' is a bad parameter name, it's a contraction of 'result', but in this case we have a Failure object. Rename it to 'f' or something more descriptive.

I find it to be a noxious code smell that in twisted.python.failure the same 20 line section is repeated almost verbatim twice, and then that's been copied here. I deem that outside the scope of this patch due to the complexity of f.f_lineno / tb.tb_lineno and the method of iteration through the linked list.

Please either provide a new patch against trunk, or a patch against the /svn/Twisted/branches/inlinecallacks-traceback-info-5854.

Changed 20 months ago by talljosh

Patch against inlinecallacks-traceback-info-5854 branch in response to comments

comment:8 Changed 20 months ago by talljosh

  • Keywords review added
  • Owner changed from talljosh to jerub

I've attached a patch that should see to the issues you highlighted.

comment:9 Changed 20 months ago by jerub

(In [37574]) Apply inlinecallbacks-traceback-info-response-to-comments.patch by talljosh

Refs #5854

comment:10 Changed 20 months ago by exarkun

  • Author changed from talljosh to talljosh, exarkun
  • Branch changed from branches/inlinecallacks-traceback-info-5854 to branches/inlinecallacks-traceback-info-5854-2

(In [37575]) Branching to 'inlinecallacks-traceback-info-5854-2'

comment:11 follow-up: Changed 20 months ago by therve

I understand the problem, and it's really unfortunate, but the proposed fix is fairly insane. We want to reduce the default complexity, not increase it. Maybe it's OK to do that if defer debugging is set?

comment:12 in reply to: ↑ 11 Changed 20 months ago by talljosh

Replying to therve:

I understand the problem, and it's really unfortunate, but the proposed fix is fairly insane. We want to reduce the default complexity, not increase it. Maybe it's OK to do that if defer debugging is set?

In this case, what do you find to be insane?

comment:13 Changed 20 months ago by therve

Copying locals, globals, and inserting frames are bad things to do. It probably performs terribly, too. If you noticed, the code copied from Failure has been hidden by a self.debug flag because of a performance issue (see #5011 and r31727).

comment:14 Changed 20 months ago by talljosh

After jerub's review, the proposed fix uses the same logic as Failure to determine whether to capture locals and globals - it respects the failure's captureVars attribute.

comment:15 Changed 20 months ago by therve

  • Keywords review removed
  • Owner changed from jerub to talljosh

OK, fair enough. Comments:

  • The test doesn't exercise the captureVars path. We need at least one more test I think.
  • Instead of copying the code from Failure, it should be refactored so that we can call a method of Failure or a function which does the same thing.

Thanks!

Changed 20 months ago by talljosh

Patch against /branches/inlinecallacks-traceback-info-5854-2 which refactors common code into a separate function in response to review by therve.

comment:16 Changed 20 months ago by talljosh

  • Keywords review added
  • Owner changed from talljosh to therve

The patch I've just uploaded refactors the code in Failure into a separate utility function used by Failure (twice) and the new code in defer.py. The captureVars path is covered by existing failure tests.

comment:17 Changed 20 months ago by therve

  • Keywords review removed
  • Owner changed from therve to talljosh

So, the captureVars in failure.py is covered by tests, but it's still missing one test for the captureVars flag being passed in inlineCallbacks itself. Otherwise it looks good I think.

Changed 20 months ago by talljosh

Added more tests in response to latest review.

comment:18 Changed 20 months ago by talljosh

  • Keywords review added
  • Owner changed from talljosh to therve

The latest patch adds tests to check that the deferred debug flag is respected.

comment:19 Changed 20 months ago by therve

  • Keywords review removed
  • Owner changed from therve to talljosh

Arg. I was about to merge this, and noticed that the new tests fail on Python3. Do you think you can have a look? It seems related to Failure behavior there, where we don't copy frames/traceback as we should.

I'm not sure it's actually doable here, maybe we should just skip the tests.

comment:20 Changed 20 months ago by talljosh

I might have a chance to look at this on the weekend, but probably not before.

Note: See TracTickets for help on using tickets.