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

[Terry Jones]

>>>>> "glyph" == glyph  <glyph at divmod.com> writes:
glyph> Thank you for at least noticing this ;-).

The 1K char log lines were hard to miss :-)

glyph> The logging code is quite ugly, but unfortunately, almost nobody
glyph> cares.  If you could dedicate any time at all to improving it, even
glyph> a little, we'd all really appreciate it.

You'd all appreciate it but OTOH almost nobody cares??? Hmmm. Hard to
resist :-)

glyph> The way the log prefix is calculated is based on what actual event is 
glyph> firing from the reactor.  So, whatever object *generates* the callback 
glyph> is the one whose log prefix will be used.

But I also see lines like this:

2008/09/29 23:56 +0200 [-] Starting factory <HTTPClientFactory: http://ec2-75-101-219-127.compute-1.amazonaws.com:8001/dummy>
2008/09/29 23:56 +0200 [Uninitialized] Stopping factory <HTTPClientFactory: http://ec2-75-101-219-127.compute-1.amazonaws.com:8001/dummy>

And - and Uninitialized do not have any clear correspondence with reactor
events. (BTW, I do see where these are coming from.)

glyph> It would definitely be nice if the log could follow the asynchronous 
glyph> thread of execution.  Patches accepted :).

Yes, agreed that would be nice. From my memory of defer.py... (insert vague
comment about how this might not be so hard - for you :-)).

glyph> It sounds like you have several complaints here.

glyph> 1.) You don't want logs to go to stdout.

I do want that, that's why I used sys.stdout.

glyph> 2.) Factories are too noisy by default.

glyph> Knowing when factories start up and shut down can actually be incredibly 
glyph> useful.  It's a pain when they're filling up your logs with spam, but a 
glyph> better solution would be some kind of structured log format with a log 
glyph> viewer application, not destroying the information so that viewing logs 
glyph> with 'less' is easier.

Right, and so viewing them when running a script from the command line that
wants to do some logging to stdout is also fine.

glyph> 4.) The log prefix isn't always useful or correct.

glyph> This may be true, but we'd need a ticket filed that includes a
glyph> complete enumeration of exactly _how_ they aren't useful or correct,
glyph> and each case would need to be fixed.

OK, thinking about that.

glyph> 5.) The log prefix for Deferred callbacks doesn't follow the
glyph> asynchronous origin of the callback.

glyph> Figuring out how to do this is really tricky, because in different cases 
glyph> you want different things.  However, twisted.python.context provides a 
glyph> hook for you to potentially capture some state when Deferreds, at least 
glyph> certain Deferreds, are spun up.  If you can come up with a really clear 
glyph> statement of requirements for a particular log prefix, you can probably 
glyph> get it.

And this.

glyph> 6.) The HTTP client is too noisy and should emit fewer log messages.

glyph> Possibly - but then I recently discovered some very interesting
glyph> information by watching a server which had a bunch of outstanding
glyph> getPage connections spew out thousands of 'stopping factory'
glyph> messages in their output - and seeing those URLs was an invaluable
glyph> debugging aid.

OK, but by your own description that's output that's useful for debugging
(and above you call it spam). My only real question was why that output is
on by default instead of off (especially seeing as it's often adding 1K of
output to my log file for a single logged message).

glyph> 7.) Twisted's log messages are generally ugly and difficult to 
glyph> understand.

glyph> Touche

But I didn't say that... I'm very happy to not have to write logging
code. Sure, the [HTTPPageGetter,client] speaking from beyond the grave is a
bit unsettling, but that's minor.

glyph> Except, of course, to come up with some kind of standard for what
glyph> makes up a useful / helpful log message; and that's probably not
glyph> going to be the unstructured mess of strings that currently goes
glyph> into the log.  (Can you tell I'm pushing a structured log format
glyph> that can be parsed?)

Yes, agreed that would be good.

glyph> Please feel free to file some tickets for areas of this behavior that 
glyph> you have noticed.  I wish I had time to pour into the logging system, 
glyph> but neither I (nor any of our sponsors) _really_ needs it to be any 
glyph> better; it's just a constant annoyance.

Understood, thanks. I'm mainly just trying to understand what's going on
and why.

I will have a bit more of a poke around. As I was going to say, from what I
remember about the callback mechanism in defer.py it seems like one should
be able to have some kind of data structure that's being maintained
(pushed, popped) there that could be updating a log prefix in some way.

Thanks!

Terry