Python logging
Update (2009-09-29): see http://plumberjack.blogspot.com/2009/09/python-logging-101.html
A friend at the local Park Service office mentioned to me that he's become a Python user and has been looking at some of my published code examples. I'm inspired to post more of these, and more that are useful to the ESRI ArcGIS scripting user. Python serves the ESRI community as a replacement for Avenue, but is a far more rich language and platform. Today's tip: excellent application logging and how to avoid using print statements in your production code.
I tripped myself using print statements recently, and have seen it in the code of others. While not a mortal sin, it does reduce the code's potential for reuse. A print statement might be tolerable when you're running the code at a shell prompt, but what if you wanted to execute the same code in a service? Better not to fill your service logs (or wherever stdout goes) with unnecessary debugging noise, yes? Here's where Python's logging module steps in to help: your information-processing classes write messages to a logging interface, any Python application then configures the logger appropriately. Log messages can be sent to single files on disk, rotating log files, sent to SMTP servers -- you could probably even create your own XMPP handler.
Say, for example, you have a class that patches elements into XML files (inspired by Dave Bouwman's post). Using a Python logger instead of a print statement requires only 2 extra lines of code (zero if you use the root logger):
import getopt import glob import logging import sys from lxml import etree # Create a logger log = logging.getLogger('file-patcher') # Example of reusable code class FilePatcher(object): """ Patch edit permissions into an XML configuration file and write new files to disk. """ def __call__(self): for infilename in glob.glob('*.xml'): tree = etree.parse(infilename) log.info('Opening file %s.', infilename) root = tree.getroot() for perms in root.xpath(".//property[@name='permissions']"): if not perms.xpath("element[@value='Edit']"): e = etree.SubElement(perms, 'element') e.attrib['value'] = 'Edit' log.info('Patched perms: %s.', str(perms)) outfilename = 'patched-%s' % infilename fout = file(outfilename, 'w') fout.write(etree.tostring(root, pretty_print=True)) log.info('Wrote file %s.', outfilename)
Now, we can make a script that uses this class in a verbose (all logged info) mode or a quieter (logged errors only) mode:
# Script if __name__ == '__main__': verbose = False # Get command line options and args opts, args = getopt.getopt(sys.argv[1:], 'v') for o, a in opts: if o == '-v': verbose = True # Get the file patching logger log = logging.getLogger('file-patcher') # Logging configuration, to stdout in this case console = logging.StreamHandler() log.addHandler(console) if verbose: log.setLevel(logging.INFO) else: log.setLevel(logging.ERROR) # Process data patch_files = FilePatcher() patch_files()
Duke University's GeoEco project has more examples of professional logging, many in an ArcGIS scripting context.
Comments
Re: Python logging
Author: timmie
HI! Thanks for the post. I recently discovered that this module exists but not yet managed to use it. Particularly because I still use man "prints" for fast debugging on command line. I really do not know how to get around this. I am not a full time software developer and professional debugging/testing seems to be a lot of overhead at my current stage of knowledge. > I'm inspired to post more of these, and more that are useful to the ESRI ArcGIS scripting user. I would be enlighted to see more of these posts. As outlines above, gentle introductions to good coding practices can help a lot: * Fast, pragmatic debugging * Using tests in development of scientific / geospatial scripts. Kind regards.Re: Python logging
Author: oblivion
I like to do this:import logging log = logging.getLogger(__name__)Then, log messages are always identified by their sub-packages of origin, and they can even be filtered on that basis. Also, if you do this:log.info('Opening file %s in mode %s.', infilename, mode)then the runtime penalty is tiny, since the string substitution does not occur if the log record is filtered, but I still prefer to do this:log.info('Opening file %s in mode %s.' %(infilename, mode))The substitution definitely occurs only once, no matter how many handlers exist. I simply avoid logging anything in runtime-critical sections of code.Re: Python logging
Author: Allan Doyle
My contribution (works on Python 2.5, haven't done much Python hacking lately):#! /usr/bin/env python """ debugging - inspired by the debugging.h and error_handling.c modules of OpenMap's C-based "toollib" that I originally wrote in the 90's while at BBN. Debug([word]) Looks in the current environment (via getenv) to look for an environment variable called 'DEBUG'. If there is none, then it returns False If there is one, and it was called with an argument, then if the DEBUG variable contains that argument, it returns True otherwise, it returns false. Note that it does this with 'word' boundaries. Examples: Assume no DEBUG environment variable is set Debug() --> False Debug("foo") --> False Debug("bar") --> False Assume DEBUG is set to "foo foobar" Debug() --> True Debug("foo") --> True Debug("bar") --> False DebugSet([word]) Allows you to add strings to the set that are in the DEBUG environment variable. Examples: Assume DEBUG is set to "foo foobar" DebugSet("bar") Debug("bar") now returns True DebugUnset([word]) If called with no arguments, it makes all subsequent calls to Debug return False If called with a word, it makes all subsequent calls to Debug with that word return False DebugMessage(message, [level]) message is a string level is one of "CRITICAL", "ERROR", "WARNING", "INFO", "DEBUG" Prints the message to stderr, along with date, time, level, and source file name and line number where the call was made. """ # ------------------------------------------------------------------------ # # Copyright (c) 2006 Allan Doyle # # Permission is hereby granted, free of charge, to any person # obtaining a copy of this software and associated documentation # files (the "Software"), to deal in the Software without # restriction, including without limitation the rights to use, copy, # modify, merge, publish, distribute, sublicense, and/or sell copies # of the Software, and to permit persons to whom the Software is # furnished to do so, subject to the following conditions: # # The above copyright notice and this permission notice shall be # included in all copies or substantial portions of the Software. # # THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, # EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF # MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND # NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT # HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, # WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, # OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER # DEALINGS IN THE SOFTWARE. # # ------------------------------------------------------------------------ import inspect import logging import os import os.path import sys ## Set up the Debug part of this code... __vars = {} __debug = os.getenv("DEBUG") if __debug: __vars[' '] = ' ' # we use ' ' as a marker for DEBUG # being set, even if it has no content try: # each separate string in DEBUG gets used as a key in a dictionary # later on, this makes it easy to tell if that string was set for v in os.getenv("DEBUG").split(): __vars[v] = v except AttributeError: pass except TypeError: pass def Debug(name=" "): """ Checks to see if the "DEBUG" environment variable is set, if an optional string is passed in, if that string is set in the "DEBUG" environment variable. """ global __vars return __vars.has_key(name) def DebugSet(name=" "): """ If called with no argument, causes subsequent calls to Debug() to return True. If called with an argument, causes subsequent calls to Debug() with the same string to return True """ global __vars global __debug __debug = True __vars[name] = name return(True) def DebugUnset(name=" "): """ If called with no argument, causes subsequent calls to Debug() to return False. If called with an argument, causes subsequent calls to Debug() with the same string to return False. """ global __vars global __debug if name == " ": __debug = False __vars = {} return try: del __vars[name] except KeyError: pass return ## Set up the DebugMessage part of this. We use the logging module, ## but send everything to stderr. Someday, this could get expanded ## to also have a logfile, etc. logging.basicConfig(level=logging.DEBUG, format='%(levelname)-8s %(message)s', stream=sys.stderr) levels = {'CRITICAL':logging.critical, 'ERROR':logging.error, 'WARNING':logging.warning, 'INFO':logging.info, 'DEBUG':logging.debug} def DebugMessage(msg, level="DEBUG"): """ Produces nicely formatted output to stderr. If called with the wrong level, it complains, and behaves as though the level was "ERROR" If called with no level, it uses "DEBUG" The allowed levels are "CRITICAL", "ERROR", "WARNING", "INFO", "DEBUG" """ current = inspect.currentframe() outer = inspect.getouterframes(current) try: levels[level]('%s - %4d: %s' % (os.path.basename(outer[1][1]), outer[1][2], msg)) except KeyError: DebugMessage('DebugMessage() called with unknown level: %s' % level) logging.error('%s - %4d: %s' % (os.path.basename(outer[1][1]), outer[1][2], msg)) del outer del current __version__ = '$Id$' if Debug('version'): print __version__Then, to use it:# Grab some of the debugging stuff... from debugging import Debug, DebugSet, DebugMessage # Put this in every module. Later on, you can 'setenv DEBUG version' # and your code will print out the version of every module when it runs __version__ = '$Id$' if Debug('version'): print __version__ # Now you can do stuff like if Debug("time"): print "a. %.2f %s" % (time.time()-self.start, path) # or if of.GetLayerCount() == 0: DebugMessage("No layers in %s" % filename) # or if Debug("filename") or Debug("verbose"): print "fileinfo", filenameRe: Python logging
Author: Sean
Wow, my blog comments do not render code well at all. Good tips, oblivion and Allan. Testing and debugging are big topics. To get started with debugging Python, you could a lot worse than to add before a troubled section of code. Run your script and set_trace() gives you a Python prompt at that point. From the prompt you can inspect all objects in scope, step through statements, and go up (and back down) the stack of execution frames. Jeremy Jones's pdb tutorial explains all you need to begin.Re: Python logging
Author: Kyle VanderBeek
I generally recommend against creating logger objects at load time (which will happen due to where your library's getLogger() call is). I do it in the __init__ of an object, and use both the module name and object name together to former a proper category heirarchy:def __init__(self): self._log = logging.getLogger('%s.%s' % (__name__, self.__class__.__name__))This idiom gives you a dot-separated hierarchy of logger categories, allowing you to configure filters and handlers to send different categories to different destinations, mute some module's log messages, or turn up and down levels in a more granular fashion. Lastly, you're working too hard configuring the log. Look at logging.basicConfig(). And, actually, you should be configuring the root logger (by calling logging.getLogger() with no arguments), not one named with a particular category, in your main program. This will become important as your project grows to multiple modules.Re: Python logging
Author: Sean
Great tips, Kyle. Thanks.