always include a useful message in calls to log.err

[davidsarah]

From #1768:

The "Unhandled Error" (as opposed to the usual "Unhandled Error in Deferred") means that something called twisted's log.err() with a Failure or Exception, but nothing else (in particular not a why= argument). This is a pretty common (perhaps unfortunate) pattern in our code: tahoe has roughly 47 such calls, and Foolscap has about 29. So we don't really know what caught the exception (and therefore what ought to be handling it differently).

We should fix all of these.

[zooko]

Could we make a utility function that extracts the current stack trace and encodes that into the why= argument? Then lazy programmers could just call that function instead of writing a why= explanation themselves.

[warner]

Hm, maybe. It'd have to look something like this:

    d = ...
    d.addCallback(...)
    util.terminateDeferredChain(d)

def terminateDeferredChain(d):
    stack = traceback.format_stack(1)
    d.addErrback(log.err, why="call stack was %s" % (stack,))

(since log.err is usually added to the end of a Deferred chain, by the time it's called, the stack no longer contains any information about what caused the log.err to be added)

My problem with that is twofold:

• tracebacks are expensive to create, and terminateDeferredChain() gets called every time, not just in the case where log.err() gets invoked
• I've rarely found a whole stacktrace to be significantly more useful than a UMID, at least for async errors. There just aren't very many different ways to reach the same function: the top stack frame is enough to guess the rest, and a UMID is enough to deduce the top frame.

Also, the "util.terminateDeferredChain(d)" at the end of a series of "d.addCallback" lines would look kind of out-of-place, but maybe I could get used to it.

It might be worth testing how expensive it is to extract just a single stack frame, instead of the whole traceback. If terminateDeferredChain() could grab just the file+lineno+name of the calling function, that'd contain as much information as a UMID but tolerate cut-and-paste coding a lot better. OTOH, a static UMID is super-fast.