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.
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.
#! /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", filename
import pdb; pdb.set_trace()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.
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.Comments are closed after 13 days.
1Re: Python logging
timmie, 2008-11-11T22:36:45Z