[Twisted-Python] A deferred class that keeps and can log its call/errback history

[Terry Jones]

A few days ago I thought it might be nice to augment the Deferred class to
allow you to look at the callback/errback chain to see what's going on.

Tonight I went to do it. I was nearly done in about 15 minutes, and then it
took another 4 hours to finish....  :-)

It's still a bit rough, but it seems to work.

The code comes with a history logging function that you can insert into a
callback chain. When it's run, it prints the history of the chain,
including also printing the history of any deferreds that were returned
along the way, and then prints the call/errback functions yet to be called.
You get to see the initial result passed to the first call/errback, and the
results along the way.

Output is still grungy. Here's what you get from the attached test code:

        History for deferred <TDeferred at 0xbf1e60  current result: 45>
        Initial result = True
        --- ALREADY FIRED ---
        CALLBACK:
          func   <history>
          result = True
        ERRBACK: <same as CALLBACK>
        CALLBACK:
          func   = <function d at 0xbf46e0>
          args   = '()'
          kwargs = '{}'
          result = <TDeferred at 0xbf6290  current result: 45>
        ERRBACK:
          func   <pass>

                History for deferred <TDeferred at 0xbf6290  current result: 45>
                Initial result = 33
                --- ALREADY FIRED ---
                CALLBACK:
                  func   = <function d2 at 0xbf4758>
                  args   = '()'
                  kwargs = '{}'
                  result = 45
                ERRBACK:
                  func   <pass>
        --- STILL TO BE FIRED ---
        CALLBACK:
          func   = <function ok at 0xbf41b8>
          args   = "('hello',)"
          kwargs = "{'color': 'black'}"
        ERRBACK:
          func   <pass>
        CALLBACK:
          func   <pass>
        ERRBACK:
          func   = <function nok at 0xbf47d0>
          args   = '()'
          kwargs = '{}'
        CALLBACK:
          func   = <function ok2 at 0xbf4668>
          args   = '()'
          kwargs = '{}'
        ERRBACK:
          func   <pass>
        CALLBACK:
          func   <history>
        ERRBACK: <same as CALLBACK>
        CALLBACK:
          func   = <function stop at 0xbf4848>
          args   = '()'
          kwargs = '{}'
        ERRBACK: <same as CALLBACK>

If you examine this you'll see that I'm using <pass> and <history> to
indicate uninteresting call/errbacks (these correspond to the
defer.passthru and the history function itself).  When the errback is the
same as the callback (due to d.addBoth), that's indicated.

If you look at the attached code you'll see I also do a bit of hiding of
housekeeping callbacks: the _continue and my own (perhaps unnecessary)
_historyPop. Those are things the caller isn't aware of, and they're just
clutter, so I don't print them.

I made the logDeferredHistory function be standalone (not a class method)
to make it easier to log any deferred (not just the current instance) and
also because it's then simpler to identify when the callback is the history
function itself (to be able to print that concisely).

You use the logging callback pretty much like any other. E.g.:

    if __name__ == '__main__':
        log.startLogging(sys.stdout)
        x = funcReturningADeferred()
        x.addCallback(d)
        x.addBoth(logDeferredHistory, x)
        x.addCallback(ok, 'hello', color='black')
        x.addBoth(logDeferredHistory, x)

Right now it logs the history. But you could pass it a file descriptor
or something else, like a list.

It would be nice to be able to make this a trivial drop-in replacement for
normal Deferreds for when you're debugging. In that case logDeferredHistory
could test to see if its deferred arg is an instance of a history deferred
and if not just act as a passthrough. Then people might be able to do
something like this when debugging:

    from twisted..... import historyDeffered as defer

and otherwise not alter their code.  Or we could add an optional argument
to Deferred.__init__ indicating that the deferred should maintain its
history. It doesn't involve much extra work - mainly just pushing things
onto a list during _runCallbacks.

Terry


-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: tdefer.py
URL: </pipermail/twisted-python/attachments/20081016/328d318d/attachment.ksh>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: tdefer_test.py
URL: </pipermail/twisted-python/attachments/20081016/328d318d/attachment-0001.ksh>