Reference Guide

Dynamic Logging

Any functions in message 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)
INFO:pid=...:I'm in thread MainThread

This can be useful with partially-bound loggers, which lets us do some cool stuff. Here’s a proxy class that logs which thread accesses attributes.

class ThreadTracker(object):
    """a proxy that logs attribute access"""
    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

Let’s see it in action.

>>> foo = Bunch()
>>> foo.bar = 42
>>> tracked = ThreadTracker(foo)
DEBUG:tracker:obj_id=...:thread=MainThread:started tracking
>>> tracked.bar
DEBUG:tracker:obj_id=...:thread=MainThread:accessed bar
42
>>> import threading
>>> t=threading.Thread(target = lambda: tracked.bar * 2, name = "TheDoubler")
>>> t.start(); t.join()
DEBUG:tracker:obj_id=...:thread=TheDoubler:accessed bar

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

See also

procinfo feature

Features!

Features are optional additons of logging functionality to the log. They encapsulate common logging patterns. Code can be written using a feature, enhancing what information is logged. The feature can be disabled at runtime if desired.

Warning

Features are currently deprecated, pending a reimplementation in version 0.5

>>> from twiggy.features import socket as socket_feature
>>> log.addFeature(socket_feature.socket)
>>> import socket
>>> s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
>>> s.connect(('www.python.org', 80))
>>> log.socket(s).debug("connected")
DEBUG:host=dinsdale.python.org:ip_addr=82.94.164.162:port=80:service=www:connected
>>> # turn off the feature - the name is still available
... log.disableFeature('socket')
>>> log.socket(s).debug("connected")
DEBUG:connected
>>> # use a different implementation
... log.addFeature(socket_feature.socket_minimal, 'socket')
>>> log.socket(s).debug("connected")
DEBUG:ip_addr=82.94.164.162:port=80:connected

Stays Out of Your Way

Twiggy tries to stay out of your way. Specifically, an error in logging should never propogate outside the logging subsystem and cause your main application to crash. Instead, errors are trapped and reported by the internal_log.

Instances of InternalLogger only have a single Output - they do not use emitters. By default, these messages are sent to standard error. You may assign an alternate ouput (such as a file) to twiggy.internal_log.output if desired, with the following conditions:

  • the output should be failsafe - any errors that occur during internal logging will be dumped to standard error, and suppressed, causing the original message to be discarded.
  • accordingly, networked or asynchronous outputs are not recommended.
  • make sure someone is reading these log messages!

Concurrency

Locking in twiggy is as fine-grained as possible. Each individual output has its own lock (if necessary), and only holds that lock when writing. Using redundant outputs (ie, pointing to the same file) is not supported and will cause logfile corruption.

Asynchronous loggers never lock.

Use by Libraries

Libraries require special care to be polite and usable by application code. The library should have a single bound in its top-level package that’s used by modules. Library logging should generally be silent by default.

# in mylib/__init__.py
log = twiggy.log.name('mylib')
log.min_level = twiggy.levels.DISABLED

# in mylib/some_module.py
from . import log
log.debug("hi there")

This allows application code to enable/disable all of library’s logging as needed.

# in twiggy_setup
import mylib
mylib.log.min_level = twiggy.levels.INFO

In addition to min_level, loggers also have a filter. This filter operates only on the format string, and is intended to allow users to selectively disable individual messages in a poorly-written library.

# in mylib:
for i in xrange(1000000):
    log.warning("blah blah {0}", 42)

# in twiggy_setup: turn off stupidness
mylib.log.filter = lambda format_spec: format_spec != "blah blah {0}"

Note that using a filter this way is an optimization - in general, application code should use emitters instead.

Tips And Tricks

Alternate Styles

In addition to the default new-style (braces) format specs, twiggy also supports old-style (percent, aka printf) and templates (dollar).

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

Use Fields

Use fields() to include key-value data in a message instead of embedding it the human-readable string.

# do this:
log.fields(key1='a', key2='b').info("stuff happenend")

# not this:
log.info("stuff happened. key1: {0} key2: {1}", 'a', 'b')

Technical Details

Independence of logger instances

Each log instance created by partial binding is independent from each other. In particular, a logger’s name() has no relation to the object; it’s just for human use.

>>> log.name('bob') is log.name('bob')
False

Optimizations

Twiggy has been written to be fast, minimizing the performance impact on the main execution path. In particular, messages that will cause no output are handled as quickly as possible. Users are therefore encouraged to add lots of logging for development/debugging purposes and then turn them off in production.

The emit methods can be hidden behind an appropriate assert. Python will eliminate the statement entirely when run with bytecode optimization (python -O).

assert log.debug("This goes away with python -O") is None
assert not log.debug("So does this")

Note

The author doesn’t particularly care for code written like this, but likes making his users happy more.

Extending Twiggy

When developing extensions to twiggy, use the devel_log. An InternalLogger, the devel_log is completely separate from the main log. By default, messages logged to the devel_log are discarded; assigning an appropriate Output to its output attribute before using.

Writing Features

Warning

Features are currently deprecated, pending a reimplementation in version 0.5

Features are used to encapsulate common logging patterns. They are implemented as methods added to the Logger class. They receive an instance as the first argument (ie, self). Enable the feature before using.

Features come in two flavors: those that add information to a message’s fields or set options, and those that cause output.

Features which only add fields/set options should simply call the appropriate method on self and return the resultant object.:

def dimensions(self, shape):
    return self.fields(height=shape.height, width=shape.width)

Features can also emit messages as usual. Do not return from these methods.:

def sayhi(self, lang):
    if lang == 'en':
        self.info("Hello world")
    elif lang == 'fr':
        self.info("Bonjour tout le monde")

If the feature should add fields and emit in the same step (like struct()), use the emit() decorators. Here’s a prototype feature that dumps information about a WSGI environ.:

from twiggy.logger import emit

@emit.info
def dump_wsgi(self, wsgi_environ):
    keys = ['SERVER_PROTOCOL', 'SERVER_PORT', 'SERVER_NAME', 'CONTENT_LENGTH', 'CONTENT_TYPE', 'QUERY_STRING', 'PATH_INFO', 'SCRIPT_NAME', 'REQUEST_METHOD']
    d = {}
    for k in keys:
        d[k] = wsgi_environ.get(k, '')

    for k, v in wsgi_environ.iteritems():
        if k.startswith('HTTP_'):
            k = k[5:].title().replace('_', '-')
            d[k] = v

    # if called on an unnamed logger, add a name
    if name not in self._fields:
        self = self.name('dumpwsgi')

    return self.fieldsDict(d)

Writing Outputs and Formats

Outputs do the work of writing a message to an external resource (file, socket, etc.). User-defined outputs should inherit from Output or AsyncOutput if they wish to support asynchronous logging (preferred).

An Output subclass’s __init__ should take a format and any parameters needed to acquire resources (filename, hostname, etc.), but not the resources themselves. These are created in _open(). Implementations supporting asynchronous logging should also take a msg_buffer argument.

Outputs should define the following:

Output._open()

Acquire any resources needed for writing (files, sockets, etc.)

Output._close()

Release any resources acquired in _open

Output._write(x)

Do the work of writing

Parameters:x – an implementation-dependent object to be written.

If the output requires locking to be thread-safe, set the class attribute use_locks to True (the default). Turning off may give slightly higher throughput.

The format callable is Output-specific; it should take a Message and return an appropriate object (string, database row, etc.) to be written. Do not modify the received message - it is shared by all outputs.

ConversionTables are particulary useful for formatting fields. They are commonly used with LineFormat to format messages for text-oriented output.

from twiggy.lib.converter import ConversionTable
conversion = ConversionTable()

fields = {'shape': 'square',
          'height': 10,
          'width': 5,
          'color': 'blue'}

# hide shape field name
# uppercase value
# make mandatory
conversion.add(key = 'shape',
               convertValue = str.upper,
               convertItem = '{1}'.format, # stringify 2nd item (value)
               required = True)

# format height value with two decimal places
# show as "<key> is <value>"
conversion.add('height', '{0:.2f}'.format, "{0} is {1}".format)

# separate fields in final output by colons
conversion.aggregate = ':'.join

# unknown items are sorted by key

# unknown values are stringified
conversion.genericValue = str

# show unknown items as "<key>=<value>"
conversion.genericItem = "{0}={1}".format

# convert!
print conversion.convert(fields)
SQUARE:height is 10.00:color=blue:width=5