Twiggy 0.2

Twiggy is a more Pythonic logger

Flubberage:

• author Peter Fein

• email [e-mail]

• web http://python-twiggy.googlecode.com

• hg https://python-twiggy.googlecode.com/hg/

Usage:

Make display work:

>>> import sys; sys.stderr = sys.stdout

Setup is simple

In your main.py:

>>> import twiggy
>>> twiggy.quick_setup()

Logging Messages

>>> from twiggy import *

Main interface is the the magic log:

>>> log #doctest:+ELLIPSIS
<twiggy.Logger.Logger object at 0x...>

It works out of the box, using standard levels:

>>> log.debug('You may not care')
DEBUG:You may not care
>>> log.error('OMFG! Pants on fire!')
ERROR:OMFG! Pants on fire!

It supports a variety of format strings, defaulting to new-style:

>>> log.info('I wear {0} on my {where}', 'pants', where='legs')
INFO:I wear pants on my legs

Old style works fine though:

>>> log.options(style='percent').info('I like %s', "bikes")
INFO:I like bikes

As do templates:

>>> log.options(style='dollar').info('$what kill', what='Cars')
INFO:Cars kill

You can name your loggers:

>>> mylog = log.name('alfredo')
>>> mylog.debug('hello')
DEBUG:alfredo:hello

But the name has no relation to the object; it’s just for human use:

>>> mylog is log.name('alfredo')
False

Emitting Messages

Emitters are loosely coupled:

>>> twiggy.emitters #doctest:+ELLIPSIS
{'*': <twiggy.Emitter.Emitter object at 0x...>}

You can set a min_level on Emitters:

>>> twiggy.emitters['*'].min_level = twiggy.Levels.INFO
>>> log.debug("Help, help I'm being suppressed")
>>> log.info("I'm not quite dead yet")
INFO:I'm not quite dead yet

You can filter on regexes, or with arbitrary functions:

>>> twiggy.emitters['*'].filter = ".*pants.*"
>>> log.info("Got my {0} on", "pants")
INFO:Got my pants on
>>> log.info("Got my {0} on", "shirt")

Let’s reset all that:

>>> twiggy.emitters['*'].filter = True
>>> twiggy.emitters['*'].min_level = twiggy.Levels.DEBUG

Better output

Newlines are suppressed by default; that can be turned off per-message:

>>> log.info('user\ninput\nannoys\nus')
INFO:user\ninput\nannoys\nus

>>> log.options(suppress_newlines=False).info('we\ndeal')
INFO:we
deal

Exceptions are prefixed. Can also pass exc_info. Use ‘\n’ as a prefix to fold into a single line:

>>> try:
...     1/0
... except:
...     log.trace('error').warning('oh noes') #doctest:+ELLIPSIS
WARNING:oh noes
TRACE Traceback (most recent call last):
TRACE   File "<doctest notes.txt[...]>", line 2, in <module>
TRACE     1/0
TRACE ZeroDivisionError: integer division or modulo by zero

Method Chaining

I like this chained style a lot.

>>> log.name('benito').info('hi there')
INFO:benito:hi there

It makes structured logging easy:

>>> log.fields(paths=42).info('Going for a walk')
INFO:paths=42:Going for a walk

Short cut. Great for runtime statistics gathering.

>>> log.struct(paths=42, dolphins='thankful')
INFO:dolphins=thankful:paths=42:

Partial binding can be useful for webapps:

>>> per_request_log = log.fields(request_id='12345')
>>> per_request_log.fields(rows=100, user='frank').info('frobnicating database')
INFO:request_id=12345:rows=100:user=frank:frobnicating database
>>> per_request_log.fields(bytes=5678).info('sending page over tubes')
INFO:bytes=5678:request_id=12345:sending page over tubes

Chained style is awesome:

>>> log.name('donjuan').fields(pants='sexy').info("hello, {who} want to {what}?", who='ladies', what='dance')
INFO:donjuan:pants=sexy:hello, ladies want to dance?

Dynamic!

Any functions in args/fields are called and the value substitued:

>>> import os
>>> from twiggy.lib import thread_name
>>> thread_name()
'MainThread'
>>> log.fields(pid=os.getpid).info("I'm in thread {0}", thread_name) #doctest:+ELLIPSIS
INFO:pid=1076:I'm in thread MainThread

This can be useful with partially-bound loggers, which let’s us do some cool stuff:

>>> class ThreadTracker(object):
...     def __init__(self, obj):
...         self.__obj = obj
...         # a partially bound logger
...         self.__log = log.name("tracker").fields(obj_id=id(obj), thread=thread_name)
...         self.__log.debug("started tracking")
...     def __getattr__(self, attr):
...         self.__log.debug("accessed {0}", attr)
...         return getattr(self.__obj, attr)
...
>>> class Bunch(object):
...     pass
...
>>> foo = Bunch()
>>> foo.bar = 42
>>> tracked = ThreadTracker(foo)
DEBUG:tracker:obj_id=14063980:thread=MainThread:started tracking
>>> tracked.bar
DEBUG:tracker:obj_id=14063980:thread=MainThread:accessed bar
42
>>> import threading
>>> t=threading.Thread(target = lambda: tracked.bar * 2, name = "TheDoubler")
>>> t.start()
DEBUG:tracker:obj_id=14063980:thread=TheDoubler:accessed bar

If you really want to log a callable, repr() it or wrap it in lambda.

Optimizations

As an optimization, a min_level can be set on loggers:

>>> mylog.min_level = twiggy.Levels.INFO
>>> mylog.info("You see this")
INFO:alfredo:You see this
>>> mylog.debug("This is hidden")

They also take a filter that operates on format_spec. The use case is efficiently shutting off specific messages in a library which is doing something stupid:

>>> mylog.filter = lambda s: "shenanigans" not in s
>>> mylog.info("Starting silliness")
INFO:alfredo:Starting silliness
>>> for i in xrange(3): # for large values of 3
...     mylog.info("I call shenanigans!")
>>> mylog.info("End silliness")
INFO:alfredo:End silliness