[Twisted-Python] logging (was: "Injecting" ...)

glyph at divmod.com glyph at divmod.com
Tue Aug 1 18:36:29 EDT 2006

On Tue, 1 Aug 2006 17:19:43 -0400, glyph at divmod.com wrote:

>>Was I wrong in this assessment?

>Not necessarily.

Hmm, my reply wasn't terribly clear.  I was really saying a few different things, all jumbled together.  First of all, just regarding your decision to use the logging module:

You made the correct decision.  If you need the features the logging module provides, you are best off using it, rather than modifying Twisted to do what it does.  I think the logging module serves its intended audience well, although I am not in its intended audience.

This is _especially_ true if your clients are requesting advanced features like log levels, verbosity selection, and a console log viewer.

what Twisted's log module can currently do:

You *CAN* include a 'level' and a 'debug flag' in Twisted log messages if you want.  Feel free to pass them along:

  log.msg("hi there", level=7, debug="banana")

but that's only because you can pass any other data you like as well.  This will be silently dropped by the default log observer, but you could write a different log observer (even one that invoked the 'logging' module ^_-) which honored your custom log variables.

Now, a bit more about my personal design choices regarding logging:

Logs are stored mainly to be analyzed: without analysis, log messages are just debug spew.  Sadly, despite the fact that it can handle arbitrary events and NOT just text messages, that's most of what the Twisted log module is currently used for: events which you can grep for in a text file if something goes wrong.  That's not really what I want to use it for though.

My preferred method of implementing log analysis is showcased in Mantissa; Allen Short wrote a pretty nice statistics-gathering system which uses the 'log' module to *collect* the statistics, but then stores them in a database, and then provides a DB-backed API for accessing specific statistics nor , not a generic "log analysis" tool which works on flat text files.

  (You can see that here: http://divmod.org/trac/browser/trunk/Mantissa/xmantissa/stats.py )

Rather than having a restricted set of data like "level" and "debug", "log events" in Twisted are really just arbitrary events which can contain equally arbitrary data.  The "_observeStatEvent" method in that module makes use of this feature.

My long-term vision for log events is for every log message in Twisted to eventually go from looking like this:

  log.msg("did some stuff %s %r" % (a, b))

to looking like this:

          format="did some stuff %(stuff)s %(morestuff)r",

Like this, textual observers have a formatting argument that they can use to log the debug message to a file for debugging, and and structured observers which understand the IDidSomeStuff log interface can capture this message and do something more specific with the 'stuff' and 'morestuff' attributes (which are presumably objects that can be manipulated in some other way than simple stringification).

However, logging is a low-priority area of development for Twisted right now, and while  there seems to be at least _rough_ consensus around the features I'm proposing here, the specifics of implementation have been bogged down in details.

There is a lot of grumbling about the current interface.  In particular various people think that formatting should be specified differently, or that the default logfile format needs to be changed to be structured, or that the **kw-dict-as-log-object API is unnecessary micro-optimization and we should use actual providers of the declared interface, or... well, it should suffice to say there are a lot of disagreements.  Nobody wants to commit extensively to an interface which is going to be changed, and hence, nobody wants to do the work to change the existing log messages -- or, even if someone volunteered to do that, nobody wants to be responsible for the _future_ work to make the existing log messages work some _other_ new way.

Despite the fact that we all know it's sub-optimal, everyone can agree that the current 'log.msg as persistent debug print' usage will continue to be supported into the indefinite future, so that's the one that gets used.

More information about the Twisted-Python mailing list