log more info about Foolscap disconnections on storages nodes (to twistd.log) #896

New Issue

tahoe-lafs · 2010-01-12T13:37:10Z

francois commented

2010-01-12 13:37:10 +00:00

All the storage nodes in my grid are logging the following exception a few times a day in logs/twistd.log.

2010-01-04 01:37:21+0100 [-] Unhandled Error
        Traceback (most recent call last):
        Failure: foolscap.ipb.DeadReferenceError: Connection was lost

It'd be great to have a little more details about those disconnections, especially the peerid of the node with which the connection was lost.

All the storage nodes in my grid are logging the following exception a few times a day in `logs/twistd.log`. ``` 2010-01-04 01:37:21+0100 [-] Unhandled Error Traceback (most recent call last): Failure: foolscap.ipb.DeadReferenceError: Connection was lost ``` It'd be great to have a little more details about those disconnections, especially the **peerid** of the node with which the connection was lost.

tahoe-lafs added the

labels 2010-01-12 13:37:10 +00:00

tahoe-lafs added this to the undecided milestone 2010-01-12 13:37:10 +00:00

warner commented

2010-01-13 00:13:39 +00:00

hm, is there anything else in twistd.log that might help us figure out which piece of code is emitting that? We probably have dozens of bare log.err calls that could be producing it.

OTOH, we should probably do a comprehensive audit and add at least a msgid to all of our log.err calls.

hm, is there anything else in twistd.log that might help us figure out which piece of code is emitting that? We probably have dozens of bare log.err calls that could be producing it. OTOH, we should probably do a comprehensive audit and add at least a msgid to all of our log.err calls.

warner changed title from ~~Foolscap disconnections on storages nodes~~ to log more info about Foolscap disconnections on storages nodes (to twistd.log)

2010-01-13 00:13:39 +00:00

francois commented

2010-01-13 08:54:39 +00:00

Replying to warner:

hm, is there anything else in twistd.log that might help us figure out which piece of code is emitting that? We probably have dozens of bare log.err calls that could be producing it.

Unfortunately not.

OTOH, we should probably do a comprehensive audit and add at least a msgid to all of our log.err calls.

I can take care of it, but how do you generate these msgid's ?

Replying to [warner](/tahoe-lafs/trac-2024-07-25/issues/896#issuecomment-74565): > hm, is there anything else in twistd.log that might help us figure out which piece of code is emitting that? We probably have dozens of bare log.err calls that could be producing it. Unfortunately not. > OTOH, we should probably do a comprehensive audit and add at least a msgid to all of our log.err calls. I can take care of it, but how do you generate these `msgid`'s ?

warner commented

2010-01-13 18:56:26 +00:00

In the context of twisted's log.err, it means adding a second positional
argument to all invocations of twisted.python.log.err, a string with a unique
name. For example, turning log.err(f) into
log.err(f, "OMG kaboom") will turn this:

2010-01-13 10:26:08-0800 [-] Unhandled Error
        Traceback (most recent call last):
          File "/usr/lib/python/twisted/internet/base.py", line 757, in runUntilCurrent
            call.func(*call.args, **call.kw)
        --- <exception caught here> ---
          File "/tmp/ftest.py", line 13, in fire
            raise ValueError("oops")
        exceptions.ValueError: oops

into this:

2010-01-13 10:26:08-0800 [-] OMG kaboom
        Traceback (most recent call last):
          File "/usr/lib/python/twisted/internet/base.py", line 757, in runUntilCurrent
            call.func(*call.args, **call.kw)
        --- <exception caught here> ---
          File "/tmp/ftest.py", line 13, in fire
            raise ValueError("oops")
        exceptions.ValueError: oops

The source tree has a simple tool for creating (probably-) unique message ids
(UMIDs), just run python misc/make_umid. Putting that in the log.err()
call will then let us grep the source tree for the UMID later. It would also
be appropriate to include a short description of the code path that led to
the log.err call, but in practice it's usually more precise to use the UMID,
since the descriptions frequently end up saying stuff like "got unhandled
error from peer", without also saying "while we were trying to download the
share hash tree for an immutable file in
src/allmydata/immutable/downloader.py line 1234". But if you're feeling
wordy, go for it :)

For foolscap log calls, we usually pass this UMID as the msgid=
argument, because it's pretty easy to extract the extra keyword arguments
from the logged message later on. But Twisted's log.err doesn't make this so
easy (kwargs are passed to observers but the twisted.log writer ignores
them), so the msgid needs to be passed as the second positional argument
(which does get written to twistd.log). Foolscap's log.err (and the tahoe
allmydata.util.log.err wrapper) accept the same second posarg.

find src -name '*.py' | xargs grep -n log.err will tell you about all
the calls to log.err. There are three forms to be aware of:

d = create_some_deferred()
d.addCallback(do_some_stuff)
d.addErrback(log.err)   # turn into d.addErrback(log.err, "message")

d = create_some_deferred()
d.addCallback(do_some_stuff)
def error_handler(f)
    log.err(f)   # turn into log.err(f, "message")
d.addErrback(error_handler)

from twisted.python.failure import Failure
try:
    do_stuff()
except ExceptionType:
    log.err()  # turn into log.err(Failure(), "message")

thanks!

In the context of twisted's log.err, it means adding a second positional argument to all invocations of twisted.python.log.err, a string with a unique name. For example, turning `log.err(f)` into `log.err(f, "OMG kaboom")` will turn this: ``` 2010-01-13 10:26:08-0800 [-] Unhandled Error Traceback (most recent call last): File "/usr/lib/python/twisted/internet/base.py", line 757, in runUntilCurrent call.func(*call.args, **call.kw) --- <exception caught here> --- File "/tmp/ftest.py", line 13, in fire raise ValueError("oops") exceptions.ValueError: oops ``` into this: ``` 2010-01-13 10:26:08-0800 [-] OMG kaboom Traceback (most recent call last): File "/usr/lib/python/twisted/internet/base.py", line 757, in runUntilCurrent call.func(*call.args, **call.kw) --- <exception caught here> --- File "/tmp/ftest.py", line 13, in fire raise ValueError("oops") exceptions.ValueError: oops ``` The source tree has a simple tool for creating (probably-) unique message ids (UMIDs), just run `python misc/make_umid`. Putting that in the log.err() call will then let us grep the source tree for the UMID later. It would also be appropriate to include a short description of the code path that led to the log.err call, but in practice it's usually more precise to use the UMID, since the descriptions frequently end up saying stuff like "got unhandled error from peer", without also saying "while we were trying to download the share hash tree for an immutable file in src/allmydata/immutable/downloader.py line 1234". But if you're feeling wordy, go for it :) For *foolscap* log calls, we usually pass this UMID as the `msgid=` argument, because it's pretty easy to extract the extra keyword arguments from the logged message later on. But Twisted's log.err doesn't make this so easy (kwargs are passed to observers but the twisted.log writer ignores them), so the msgid needs to be passed as the second positional argument (which *does* get written to twistd.log). Foolscap's log.err (and the tahoe allmydata.util.log.err wrapper) accept the same second posarg. `find src -name '*.py' | xargs grep -n log.err` will tell you about all the calls to log.err. There are three forms to be aware of: ``` d = create_some_deferred() d.addCallback(do_some_stuff) d.addErrback(log.err) # turn into d.addErrback(log.err, "message") ``` ``` d = create_some_deferred() d.addCallback(do_some_stuff) def error_handler(f) log.err(f) # turn into log.err(f, "message") d.addErrback(error_handler) ``` ``` from twisted.python.failure import Failure try: do_stuff() except ExceptionType: log.err() # turn into log.err(Failure(), "message") ``` thanks!

Sign in to join this conversation.