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=...:ip_addr=...:port=80:service=http|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=...: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). The aliases {}, % and $ are also supported.
>>> 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
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.fields_dict(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',
convert_value = str.upper,
convert_item = '{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.generic_value = str
# show unknown items as "<key>=<value>"
conversion.generic_item = "{0}={1}".format
# convert!
print(conversion.convert(fields))
SQUARE:height is 10.00:color=blue:width=5