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

[Terry Jones]

Greetings Twisted superheroes!

I have a simple question about logging. Here's a snippet of code:

    from twisted.python import log
    from twisted.web import client
    from twisted.internet import reactor
    import sys

    log.startLogging(sys.stdout)
    def stop(x): reactor.callLater(0, reactor.stop)
    client.getPage('http://www.divmod.com').addBoth(stop)
    reactor.run()

This produces the output

    2008/09/30 14:16 +0200 [-] Log opened.
    2008/09/30 14:16 +0200 [-] Starting factory <HTTPClientFactory: http://www.divmod.com>
    2008/09/30 14:16 +0200 [HTTPPageGetter,client] Stopping factory <HTTPClientFactory: http://divmod.com/?__session_just_started__=1>
    2008/09/30 14:16 +0200 [-] Main loop terminated.

I had a look around and can see where (most) of this is coming from.

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.

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!

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.

In my actual use case, I see my log filling up with output like this:

2008/09/29 23:55 +0200 [HTTPPageGetter,client] Stopping factory <HTTPClientFactory: https://ec2.amazonaws.com:443/?Action=RunInstances&AWSAccessKeyId=92383292629273839262&ImageId=ami-6bd03402&InstanceType=m1.small&KeyName=xxx-keypair&MaxCount=1&MinCount=1&SecurityGroup.1=coordinator&SignatureVersion=1&Timestamp=2008-09-29T21%3A55%3A23&UserData=QVdTX0FDQ0VTU19LRVlfSUQ6IDBKU1NNSzVOS000N0RHN1dTRDAyCkFXU19TRUNSRVRfQUNDRVNTX0tFWTogZ3J3UDFWaTdHbjg4Y3hMdy9UcDIrdWIxeENUdWVwUmUvV3JHdXRGYQpTM0J1Y2tldE5hbWU6IGZsdWlkaW5mby5jb20KaW5pdEtleU5hbWU6IG9wdC9mbHVpZGluZm8vYmluL2luaXQucHkKcHJvY2Vzc0FyZ3M6IFstLWxvZ2ZpbGUsIC9tbnQvdG1wLzEyMjI3MjUzMjIuNi5sb2csIC0tcGlkZmlsZSwgL21udC90bXAvMTIyMjcyNTMyMi42LnBpZCwKICAtLW5vX3NhdmUsIC0tbm9kYWVtb24sIGF0dHJpYmFzZS1odHRwLXByb2Nlc3MtcG9vbCwgLS1wb3J0LCAnODAwMSddCnJlc3VsdHNLZXlOYW1lOiBpbnN0YW5jZXMvMC9yZXN1bHRzLwpzY3JpcHRQYXRoOiAvdXNyL2Jpbi90d2lzdGQKc291cmNlTGlicmFyeUtleU5hbWU6IGluc3RhbmNlcy8wL3NyYy8yMDA4MDkyNwo%3D&Version=2008-05-05&Signature=mPRws2HDxQaF4lMcmL7Ikc8Txqo%3D>

I guess the answer might be that I should make my own version of getPage
that sets noisy to False after making its HTTPClientFactory, or maybe
subclass FileLogObserver and override emit. Or I guess I could be calling
functions with log.callWithContext.

But those approached seem to be wheeling in a lot of machinery just to set
to False a variable that (arguably?) should be False to begin with.

See - told you it was simple. I'm at my very best nibbling away on the very
edges of the Twist-o-verse.

Terry