Coming from a self-taught, hack-tastic, stack-overflow, LMGTFY background, finding best practices has required a lot of unlearning. Python Hitchhiker’s Guide is an excellent resource, but I end up learning most from personal failure. I imagine many other homegamer-grade devs feel a similar frustration in their coding, maybe unaware of built-in tools or how to use them.
I’ve come around to logging in a big way recently. Though swapping out debug print statements for a proper logger seems easy and obvious, I think many devs underestimate the power of python’s built-in logger. Not only can a good logging system aide debugging and development, but it also can be used to automatically alert humans when things go wrong.
How Python Handles Logging
Python’s logger is split into two parts, the logger and its handlers. The logger allows messages to be passed into the logging chain, and the handler objects dictate what happens to those messages.
This means you can configure and attachhandler objects to suit the needs of your app. Need to debug print to stdout — StreamHandler(). Need to log to file, but auto-delete after x days— TimedRotatingFileHandler(). Need to use the system log— SysLogHandler().
What’s more, because handlers are called at execution time, humans can be alerted of bad behavior immediately using something like SMTPhandler(). It’s so useful, I have written custom webhook handlers so critical errors make it to HipChat, Slack, or Discord.
Life Hacking Your Logging Tools
Common Coding Your Logger
To make my life easier, I wrote a log-builder in ProsperCommon to wrap major functionality in a standardized way: defining things from formats and file behavior to specific handler wrapping. Now every app can import the one library and easily setup the logger it needs in a few lines.
Though this is powerful, I would caution against distributing this on PyPI. I use GemFury to host personal libraries and keep tighter control on releases.
Make Your Own Handlers
Don’t be afraid to roll-your-own handlers. Though python comes with many handlers built-in, sometimes DIY is best.
class MyNewHandler(logging.Handler): # inherit from Handler class
def __init__(self, special_args):
logging.Handler.__init__(self) # run parent __init__ class
## Do custom setup stuff
## Save special_args, setup files, etc def emit(self, record): # override Handler's `emit` method
## Do log-time actions here
## Send to webhook, send to file, write an email, whatever
By hijacking the existing Handler class, it’s easy to add whatever custom behavior to a new handler. Additionally, platform-specific flourishes such as HipChat’s coloring or Slack’s formatting can be implemented here. Anything in emit() will be executed when a log message arrives.
Make Your Own Levels
Especially useful when using logging as an alerting service, custom levels provide a way to better control logging behavior. Refer to Logging Levels for more notes.
logging.addLevelName(int_custom_level, 'ALERT')
def alert(self, message, *args, **kwargs):
"""http://stackoverflow.com/a/13638084"""
if self.isEnabledFor(int_custom_level):
self._log(int_custom_level, message, args, **kwargs)
logging.Logger.alert = alertEmbracing Best Practices
Library Loggers are Null Loggers
Though you should absolutely write logging messages everywhere in the codebase, there are a lot of places where yielding those log messages isn’t desired. Push loggers into libraries, rather than collecting logs unexpectedly. Also a NullHandler will avoid errors such as: AttributeError: ‘NoneType' object has no attribute ‘debug'
import loggingDEFAULT_LOGGER = logging.getLogger('NULL')
DEFAULT_LOGGER.addHandler(logging.NullHandler())
Only Create Loggers In Main
This ties in with the previous point: the only place that should create an active logging object is main(). There are many services that can execute main, like create_app() in Flask or main(self) in Plumbum, but active loggers should only come from these runtime functions.
We want to control behavior between modes. Production, Testing, and Debug are three different modes with their own requirements. Testing shouldn’t alert chat-webhooks. Production shouldn’t log to stdout.
Capture Those Exceptions
Funfact: str(Exception) == '', be careful when logging exception objects.
except Exception as err_msg:
## Bad Logging ##
logging.error('Things went wrong: {0}'.format(err_msg))
## "Things went wrong: "## Better Logging ##
logging.error('Things went wrong: {0}'.format(repr(err_msg)))
## "Things went wrong: Execption_class message"## Best Logging ##
logging.error('Things went wrong', exc_info=True)
## "Things went wrong <stack_trace>"
Though repr() is a better tool for capturing the exception name, using exc_info=True will attach a stack trace into the log message. An excellent resource for debugging when things go terribly wrong, though maybe overkill for less-than-critical errors.
Death To Print(), Long Live Logger
Switching to logging has changed the way I approach code. Instead of working backwards at the end to change debug prints into useful information, logging messages act more like comments. Additionally, I’ve gained the confidence to launch always-on services such as webhosts and bots, because someone will be notified when things go down in flames. It also makes bugs obvious and loud at work, compelling devs to fix bad behavior.
