Opened 16 years ago

Last modified 12 years ago

#1402 enhancement new

Make deferred callback chains debuggable

Reported by: moof Owned by:
Priority: normal Milestone:
Component: core Keywords:
Cc: spiv, warner, moof, terrycojones Branch:
Author:

Description


Change History (8)

comment:1 Changed 16 years ago by moof

Add an optional way to enable debuggable deferreds that will contain a trace of
which functions were called and with what results and arguments, such that when
you can't work out where in your callback chain something has gone out of kilter
you can see, step by step, and preferably post-mortem, what was called and
hence, hopefully, what went wrong.

I assume this will have to be a gloabl option within t.i.defer

comment:2 Changed 16 years ago by spiv

Note that we already have a "debuggable deferred" when you call
t.i.defer.setDebugging(True); I've changed the title to be a little more
specific to what I think you want.

A sketch of the sort of API you expect, or what an example trace might look
like, would help someone interested in implementing what you want.

comment:3 Changed 16 years ago by warner

Ooh! Ooh!

 http://www.erights.org/elang/tools/causeway/

I've been thinking about how to implement this sort of causality-tracing in
newpb, and I think it would be appropriate to put them into Deferreds and
DelayedCalls too. Basically each time one is created or fired, you record some
context information and emit it to a logfile, then you have a post-mortem tool
which examines these logs and presents the causal-ordered events to you (in
addition to the temporally-ordered view).

comment:4 Changed 16 years ago by moof

Sorry, yeah, I've been a bit offline recently.

A Use Case:

Recently I had to modify one of my deferred chains in a heavily database-centric
app, which implies a lot of little functions reacting to individual database
queries. I also had to branch out a bunch of things and do them "in parallel"
rather than sequentially, as they involved updating a database, and that didn't
need to be done sequentially in this case, before going on to do a bunch of
other things, each request on its own. These deferreds then got collected in a
DeferredList to trigger an action once all of them had been done.

At some point, I returned the wrong deferred in my methods, and it ended up
being attached to my DeferredList as well as having a bunch of other callbakcs
added to it later, which were expectign the result from a DB Query and got None
instead, as it got what was returned from the DeferredList call.

Given that this was being done through a large number of "return" statements and
somewhere conceptually quite different to my database result-handling code, I
was at a loss as to where to look, or how to debug this. I eventually ended up
getting hold of the deferred in question and having to pritn its callbacks, and
realising I have another deferred's _continue method at the start of my callback
chain. Eventually after much peppering of my code with crap like "print
d.callbacks[0][0][0].im_self.callbacks[0]" and so on I eventually located the
fact that it was calling a DeferredList's callbacks, and saw the problem, and
corrected the spurious return statement.

What I'm after is a way to debug this sort of problem.

Something like Causeway would be ideal, but that implies a lot of work. I'll
settle for a log file I can grep through myself, somewhat along the lines of:

...
1136975352.983 <Deferred at 0x20098f0>: created in method do_blocking_thing of
<SomeFunkyClass instance at 0x20093a0>
1136975353.122 <Deferred at 0x20098f0>: method do_blocking_thing of
<SomeFunkyClass instance at 0x20093a0> added callbacks: _handle_blocked_result,
passthru
1136975353.131 <Deferred at 0x20098f0>: method do_blocking_thing of
<SomeFunkyClass instance at 0x20093a0> added callbacks: passthru,
_handle_blocked_error
1136975354.267 <Deferred at 0x20098f0>: callback called by method _runCallbacks
in <Deferred at 0x2009ac0> with result "this is a result"
1136975354.267 <Deferred at 0x20098f0>: calling _handle_blocked_result of
<SomeFunkyClass instance at 0x20093a0> with args: ("this is a result", 1) and kw: {}
1136975354.314 <Deferred at 0x2009b20>: created in method
do_another_blocking_thing of <SomeFunkyClass instance at 0x20093a0>
1136975354.324 <Deferred at 0x20098f0>: result is <Deferred at 0x2009b20>
1136975354.324 <Deferred at 0x20098f0>: attaching callbacks to <Deferred at
0x2009b20> and pausing
1136975355.555 <Deferred at 0x2009b20>: callback called by method
do_another_blocking_thing of <SomeFunkyClass instance at 0x20093a0> with result
"this is another result"
1136975355.555 <Deferred at 0x2009b20>: calling _continue of <Deferred at
0x20098f0> with args: ("this is another result") and kw: {}
1136975355.631 <Deferred at 0x20098f0>: result is "this is another result"
1136975355.631 <Deferred at 0x20098f0>: calling passthru of <module
twisted.internet.defer> with args: ("this is another result") and kw: {}
1136975355.650 <Deferred at 0x20098f0>: result is "this is another result"
....

And so on. It's a bit heavy on the information, and dry, but it will probably be
easy to code, and easily greppable for the different deferreds. Maybe a logfile
format that's easier to parse so a GUI can be written might be a better idea, as
long as it's fairly readable.

comment:5 Changed 12 years ago by Jean-Paul Calderone

Component: core
Keywords: core removed
Owner: set to radix
Priority: lownormal

#3858 was a duplicate of this.

comment:6 Changed 12 years ago by radix

Terry Jones implemented a nice class for tracking deferred history to help debugging strange Deferred problems. It'd be nice to test this code and integrate it into the core of Twisted, with something like defer.setHistoryTracking(True) to turn it on.

The original mailing list post is here:

http://www.twistedmatrix.com/pipermail/twisted-python/2008-October/018535.html

comment:7 Changed 12 years ago by terrycojones

Cc: terrycojones added

comment:8 Changed 11 years ago by <automation>

Owner: radix deleted
Note: See TracTickets for help on using tickets.