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

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()
participants (1)
-
Terry Jones