Twiggy is a new Pythonic logger.
>>> log.name(‘frank’).fields(number=42).info(“hello {who}, it’s a {} day”, ‘sunny’, who=’world’) INFO:frank:number=42:hello world, it’s a sunny day
I started the project at Pycon. I was suffering from burnout, and looking to rekindle my interest in programming. I whined about the standard library’s logging package on IRC and Jesse Noller “invited” me to do something about it. I’m developing Twiggy because I want to give something back to the Python community, of which it’s been an honor and pleasure to be a member of these past eight years. I don’t have any immediate need for such a thing in a larger project- heck, I’m not even working right now.
This post is intended to give an overview of Twiggy, and persuade you that it should be your new logger. For a more complete introduction, please see the documentation.
Why Logging Matters
When we write code, logging is often an afterthought. I think this is a mistake. Logging is:
- your only view into a running program
- your only view of past execution
- your data for post-mortem analysis and domain-specific measurement
Given that, I think we should be logging more than we do. A lot more. Though given logging’s history as being slow, error-prone and generally unfun, it’s excusable that we don’t.
Want to know what your code is doing without dropping into a debugger or cluttering up with print statements? Logging. Need to figure out why that daemon keeps crashing? Logging. Business guys want to know what the customers bought and why? Logging.
Logging. We can’t live without it. So let’s do it better.
What’s Wrong with the Standard Library’s logging
Let me begin by expressing my sincere gratitude to Vinay Sajip for developing and maintaining the standard lib’s logging package since 2002. I mean that. In the numerous applications I’ve used it in, I’ve found it to be useful, featureful and very well documented. You have my thanks.
When talking to folks in the community, I heard vague displeasure with the standard lib’s logging.
- It’s complicated.
- It’s slow.
- 3rd place in poll of modules needing a redesign.
- People are flaming mad.
Folks had some pet peeves too.
- newlines in output
- unhandled exceptions during logging bring down the whole program
- only supports tuples for format strings
- too much locking
Whatever. The big problem in my opinion is that it’s full of Java. The standard lib’s logging is a port of log4j, just like PEP-282 says.
Twiggy: More Pythonic
As near as I can tell, Twiggy is the first totally new design for a logger since log4j was developed in 1996. Let me say that again: Twiggy is the first new logger in 15 years. We’ve learned a lot about how to build software in that time. Let’s make use of that knowledge.
Logging Should be Fun
Let’s start with messages. Twiggy uses new-style format strings by default. Way nicer than %s (printf).
>>> from twiggy import log >>> log.name(‘twiggy’).info(‘I wear {} on my {where}’, ‘pants’, where=’legs’) INFO:twiggy:I wear pants on my legs
Output is better. No more hard-to-grep traceback lines cluttering up your logs.
>>> try: … 1/0 … except: … log.trace(‘error’).warning(‘oh noes’) WARNING:oh noes TRACE Traceback (most recent call last): TRACE File “<meet_twiggy.py>”, line 2, in <module> TRACE ZeroDivisionError: integer division or modulo by zero
Twiggy includes easy support for structured logging. In the past, we stuffed key-value data into our human readable messages.
>>> log = logging.getLogger(“stdlib.logging”) >>> log.info(‘Going for a walk. path: %s roads: %d’, “less traveled”, 42) INFO:stdlib.logging:Going for a walk. path: less traveled roads: 42
Twiggy preserves the structure in such messages, making parsing and sophisticated formatting possible.
>>> log.name(‘twiggy’).fields(path=”less traveled”, roads=42).info(‘Going for a walk’) INFO:twiggy:path=less traveled:roads=42:Going for a walk
Modern Configuration
Twiggy uses loose coupling between loggers and outputs for configuration. This approach should look familiar to anyone who’s used Django’s URLconfs.
from twiggy import addEmitters, outputs, levels, filters, formats, emitters # import * is also ok def twiggy_setup(): alice_output = outputs.FileOutput(“alice.log”, format=formats.line_format) bob_output = outputs.FileOutput(“bob.log”, format=formats.line_format) addEmitters( # (name, min_level, filter, output), (“alice”, levels.DEBUG, None, alice_output), (“betty”, levels.INFO, filters.names(“betty”), bob_output), (“brian.*”, levels.DEBUG, filters.glob_names(“brian.*”), bob_output), ) # near the top of your __main__ twiggy_setup()
Filtering in Twiggy is smart. You can use builtin types as filters and Twiggy will just do the right thing. Strings are treated as regexps on message text.
emitters[‘alice’].filter = “.*pants.*” # alice only gets messages with pants
So Fast it’s Free
Outputs in Twiggy support asynchronous logging using the multiprocessing module. Twiggy can move the operation of writing to a file, database or server to a separate process and out of your application’s critical path. That makes logging basically free. And the best part is that Twiggy handles this for you, which means any outputs you write can take advantage of asynchronous support with no additional work.
Solves Your Problems. Pets Your Puppy.
A common problem in logging is the need to maintain context across several messages. This often comes up in webapps, where you’re shuttling request objects around. You can extract that context each time, but that quickly gets tiresome and may be impossible if it was created somewhere else. Twiggy makes this easy. Each call to fields() creates a new, partially-bound logger that can be passed around.
>>> ## an application-level log … webapp_log = log.name(“myblog”) >>> ## a log for the individual request … some_request.log = webapp_log.fields(request_id=‘12345’) >>> some_request.log.fields(rows=100, user=’frank’).info(‘frobnicating database’) INFO:myblog:request_id=12345:rows=100:user=frank:frobnicating database >>> some_request.log.fields(bytes=5678).info(‘sending page over tubes’) INFO:myblog:bytes=5678:request_id=12345:sending page over tubes >>> ## a log for a different request … other_request.log = webapp_log.fields(request_id=‘67890’) >>> other_request.log.debug(‘Client connected’) DEBUG:myblog:request_id=67890:Client connected
And we haven’t even gotten to the cool stuff or the features.
The Future
Twiggy works well now – you can start using it today. Since it’s core infrastructure, I believe a logger should be absolutely bulletproof. Twiggy’s not there yet. I’ll be focusing on getting it into rock solid shape over the next few weeks. I’ll also be porting to Python 3.x, mainly for its saner unicode support (I’ll maintain a 2.x branch if there’s sufficient interest).
Output backends are one of Twiggy’s weak spots. Currently, there’s only support for files. Future outputs will likely include: email, SQL database, syslog/NT event log, JSON/HTTP (CouchDB anyone?), message queues, etc.. Really, the sky/boredom’s the limit. ;–)
I’ll be adding some features to support common use cases – timing context managers, argument inspection decorators, that sort of thing. Also in the works is unittesting support – the ability to ensure that particular paths through your code produce the correct log output.
I’m planning support for a standard library logging compatibility mode. Ideally, one should be able have 90% of code that uses logging work out of the box.
from twiggy import logging_compat as logging log = logging.getLogger(“oldcode”) log.info(“Shh, don’t tell”)
Even better, Twiggy could inject the compatibility layer into sys.modules, meaning no modification to old code at all.
# in your twiggy_setup: from twiggy import logging_compat logging_compat.hijack() # take over!
Way further down the road, I’ve got ideas for a zero-configuration log analysis tool called hatchet. But for now, I’m excited about Twiggy – I hope you are too.
See also: Discussion on reddit