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

Oct. 16, 2008

      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

from twisted.internet import defer
from twisted.python import failure, log

def succeed(result):
    d = TDeferred()
    d.callback(result)
    return d

def fail(result=defer._nothing):
    if result is defer._nothing:
        result = failure.Failure()
    d = TDeferred()
    d.errback(result)
    return d

def _historyPop(result):
    return result

def _continue(result, d):
    d.result = result
    d.unpause()

class TDeferred(defer.Deferred):
    def __init__(self):
        defer.Deferred.__init__(self)
        self.history = []

    def _startRunCallbacks(self, result):
        self.initialResult = result
        defer.Deferred._startRunCallbacks(self, result)

    def _runCallbacks(self):
        if not self.paused:
            cb = self.cb = self.callbacks
            self.callbacks = []
            while cb:
                item = cb.pop(0)
                isFailure = isinstance(self.result, failure.Failure)
                callback, args, kw = item[isFailure]
                args = args or ()
                kw = kw or {}
                try:
                    self.result = callback(self.result, *args, **kw)
                    if isinstance(self.result, TDeferred):
                        self.callbacks = cb

                        # note: this will cause _runCallbacks to be called
                        # "recursively" sometimes... this shouldn't cause any
                        # problems, since all the state has been set back to
                        # the way it's supposed to be, but it is useful to know
                        # in case something goes wrong.  deferreds really ought
                        # not to return themselves from their callbacks.
                        self.pause()
                        self.result.addBoth(_historyPop)
                        self.result.addBoth(_continue, self)
                        break
                except:
                    self.result = failure.Failure()
                finally:
                    self.history.append(list(item) + [isFailure, self.result])

        if isinstance(self.result, failure.Failure):
            self.result.cleanFailure()
            if self._debugInfo is None:
                self._debugInfo = defer.DebugInfo()
            self._debugInfo.failResult = self.result
        else:
            if self._debugInfo is not None:
                self._debugInfo.failResult = None

def _addHistoryItem(isCallback, f, args, kwargs, indent):
    out = [indent + ('CALLBACK:' if isCallback else 'ERRBACK:')]
    if f is defer.passthru:
        out.append('%s  func   <pass>' % indent)
    elif f is logDeferredHistory:
        out.append('%s  func   <history>' % indent)
    else:
        out.extend([
            '%s  func   = %r' % (indent, f),
            '%s  args   = %r' % (indent, str(args)),
            '%s  kwargs = %r' % (indent, str(kwargs)),
            ])
    return out

def logDeferredHistory(result, d, indent=''):
    out = ['', '%sHistory for deferred %r' % (indent, d)]
    append, extend = out.append, out.extend
    if hasattr(d, 'initialResult'):
        append('%sInitial result = %r' % (indent, d.initialResult))
    if d.history:
        append('%s--- ALREADY FIRED ---' % indent)
        for item in d.history:
            (cb, cba, cbk), (eb, eba, ebk), wasFailure, fResult = item
            if cb is _historyPop:
                return out
            out += _addHistoryItem(True, cb, cba, cbk, indent)
            if not wasFailure:
                append('%s  result = %r' % (indent, fResult))
            if (eb, eba, ebk) == (cb, cba, cbk):
                append('%sERRBACK: <same as CALLBACK>' % indent)
            else:
                out += _addHistoryItem(False, eb, eba, ebk, indent)
            if wasFailure:
                append('%s  result = %r' % (indent, fResult))
            if isinstance(fResult, TDeferred):
                out += logDeferredHistory(None, fResult, indent + '\t')
    if d.cb:
        needHeader = True
        for item in d.cb:
            (cb, cba, cbk), (eb, eba, ebk) = item
            if cb is _continue or cb is _historyPop:
                continue
            if needHeader:
                append('%s--- STILL TO BE FIRED ---' % indent)
                needHeader = False
            out += _addHistoryItem(True, cb, cba, cbk, indent)
            if (eb, eba, ebk) == (cb, cba, cbk):
                append('%sERRBACK: <same as CALLBACK>' % indent)
            else:
                out += _addHistoryItem(False, eb, eba, ebk, indent)
    log.msg('\n'.join(out))
    return result

#!/usr/bin/env python

import sys
from twisted.internet import reactor
from twisted.python import log, failure
from tdefer import TDeferred, logDeferredHistory, succeed

def gen(x):
    D = TDeferred()
    if x:
        reactor.callLater(2, D.callback, x)
    else:
        reactor.callLater(2, D.errback, Exception("one failed!"))
    return D

def ok(result, msg, color='red'):
    print "ok called with %r" % result
    raise Exception("ok raises")

def ok2(result):
    print "ok2 called with %r" % result

def d(result):
    print "d called"
    D = TDeferred()
    D.addCallback(d2)
    # Uncomment the next line to log the history of the deferred D
    # in the middle of running (and printing) the deferred chain
    # started by our original call to gen.
    # D.addCallback(logDeferredHistory, D)
    reactor.callLater(2, D.callback, 33)
    return D

def d2(result):
    return 45

def nok(failure):
    print "nok called"
    return d(1)

def stop(x):
    print 'stop received %r' % x
    if isinstance(x, failure.Failure):
        print x.getTraceback()
    reactor.callLater(0, reactor.stop)

if __name__ == '__main__':
    log.startLogging(sys.stdout)
    x = gen(True)
    log.err('orig deferred is %r' % x)
    x.addBoth(logDeferredHistory, x)
    x.addCallback(d)
    x.addBoth(logDeferredHistory, x)
    x.addCallback(ok, 'hello', color='black')
    x.addErrback(nok)
    x.addCallback(ok2)
    x.addBoth(logDeferredHistory, x)
    x.addBoth(stop)
    reactor.run()

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

Terry Jones