[Twisted-Python] Question on default t.p.log output

[glyph at divmod.com]

On 12:53 pm, terry at jon.es wrote:
>Greetings Twisted superheroes!

Hi Terry!
>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 
>to
>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 
>other
>in the same base Factory class, don't give the same [...] component in
>their output. Sometimes I get [Uninitialized], sometimes [-], and 
>sometimes
>[HTTPPageGetter,client] as above - with both starting and stopping
>messages.

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 
>die
>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 
>and
>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
>error.

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 
information.

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 
get it.

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 
understand.

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.