always include a useful message in calls to log.err #1770

New Issue

tahoe-lafs · 2012-06-15T17:39:43Z

davidsarah commented

2012-06-15 17:39:43 +00:00

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.

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.

tahoe-lafs added the

labels 2012-06-15 17:39:43 +00:00

tahoe-lafs added this to the 1.10.0 milestone 2012-06-15 17:39:43 +00:00

zooko commented

2012-06-17 13:00:49 +00:00

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.

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 commented

2012-06-21 22:56:50 +00:00

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.

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.

tahoe-lafs modified the milestone from 1.10.0 to 1.11.0

2012-12-20 16:34:49 +00:00

Sign in to join this conversation.