[Twisted-Python] Question on default t.p.log output
glyph at divmod.com
glyph at divmod.com
Tue Sep 30 07:45:39 MDT 2008
On 12:53 pm, terry at jon.es wrote:
>Greetings Twisted superheroes!
>I have a simple question about logging. Here's a snippet of code:
>First off, the start/stop factory messages are surprising and feel ugly
>me. I mean that's my stdout you're scribbling that stuff all over. The
>starting and stopping factory methods, despite appearing next to each
>in the same base Factory class, don't give the same [...] component in
>their output. Sometimes I get [Uninitialized], sometimes [-], and
>[HTTPPageGetter,client] as above - with both starting and stopping
Thank you for at least noticing this ;-).
The logging code is quite ugly, but unfortunately, almost nobody cares.
If you could dedicate any time at all to improving it, even a little,
we'd all really appreciate it.
>And then, and misleading IMO, is that in a callback attached to the
>deferred from getPage, the log output (to the uninitiated, a class I am
>arguably a prime member of) still appears to have something to do with
>HTTPPageGetter,client when in fact the page has been retrieved, and the
>callback fired. It's like HTTPPageGetter,client refuses to lie down and
>quietly, and insists on sitting up in the casket to holler at its
>ungrateful descendant callbacks: Hey, I'm the one that kicked this off
>don't you forget it!
The way the log prefix is calculated is based on what actual event is
firing from the reactor. So, whatever object *generates* the callback
is the one whose log prefix will be used.
It would definitely be nice if the log could follow the asynchronous
thread of execution. Patches accepted :).
>Ahem. I see that output is controlled by a var called noisy in the base
>Factory class. By why is it True by default if it really is just noise?
>Judging from the code (and the use of log.msg not log.err) it's not an
It sounds like you have several complaints here.
1.) You don't want logs to go to stdout.
This is easy. You can direct the log wherever you want, and overriding
stdout is optional; take a look at the arguments to startLogging.
(Unless you're talking about customizing logging in twistd, which is a
whole other mess that there is a universe of tickets for.)
2.) Factories are too noisy by default.
Knowing when factories start up and shut down can actually be incredibly
useful. It's a pain when they're filling up your logs with spam, but a
better solution would be some kind of structured log format with a log
viewer application, not destroying the information so that viewing logs
with 'less' is easier.
3.) Factories' start and stop messages do not include useful
Quite so. It would be nicer if they did.
4.) The log prefix isn't always useful or correct.
This may be true, but we'd need a ticket filed that includes a complete
enumeration of exactly _how_ they aren't useful or correct, and each
case would need to be fixed.
5.) The log prefix for Deferred callbacks doesn't follow the
asynchronous origin of the callback.
Figuring out how to do this is really tricky, because in different cases
you want different things. However, twisted.python.context provides a
hook for you to potentially capture some state when Deferreds, at least
certain Deferreds, are spun up. If you can come up with a really clear
statement of requirements for a particular log prefix, you can probably
6.) The HTTP client is too noisy and should emit fewer log messages.
Possibly - but then I recently discovered some very interesting
information by watching a server which had a bunch of outstanding
getPage connections spew out thousands of 'stopping factory' messages in
their output - and seeing those URLs was an invaluable debugging aid.
7.) Twisted's log messages are generally ugly and difficult to
Touche - but again, this needs to be fixed on a case-by-case basis;
nothing to be done in general. Except, of course, to come up with some
kind of standard for what makes up a useful / helpful log message; and
that's probably not going to be the unstructured mess of strings that
currently goes into the log. (Can you tell I'm pushing a structured log
format that can be parsed?)
Please feel free to file some tickets for areas of this behavior that
you have noticed. I wish I had time to pour into the logging system,
but neither I (nor any of our sponsors) _really_ needs it to be any
better; it's just a constant annoyance.
More information about the Twisted-Python