One usually adds StreamHandler to logger in order to achieve the effect of printing the logging calls to console and not having to use print throughout the code. In this approach, one ignores what messages get printed to stdout and stderr.
The way I recommend is to send INFO to stdout but WARN, DEBUG, ERROR, CRITICAL to stderr. In addition, ERROR messages (excluding other levels) are also printed with a "error: " prefix. There is also a 'verbosity level' feature which means verbosity level 0 prunes DEBUG/tracebacks .. while level 1 allows tracebacks and level 2 also allows DEBUG messages.
To use this recipe, simply call the 'setup_console' method in your program.
| Python |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 | import logging
from contextlib import contextmanager
def setup_console(l, verbosity_level):
"""Setup console output for logging calls"""
l.setLevel(logging.DEBUG) # level-logic is instead in the handler
existing_consoles = [h for h in l.handlers if isinstance(h, ConsoleHandler)]
if existing_consoles:
if len(existing_consoles) == 1:
# re-use existing console handler
h = existing_consoles[0]
assert h.verbosity_level == verbosity_level, \
'already has console with different verbosity level'
else:
raise RuntimeError, 'more than one console installed. not possible.'
else:
# create a new console handler
h = ConsoleHandler(verbosity_level)
h.setFormatter(ConsoleFormatter())
l.addHandler(h)
class ConsoleHandler(logging.StreamHandler):
"""Send messages to console
INFO messages are sent to stdout. Other levels to stderr.
By default, INFO/WARN/ERROR messages are sent as-it-is to console .. while
EXCEPTION messages are pruned and shown as error unless verbosity level is
greater than zero. If verbosity level is greater than one, then DEBUG
messages are also shown.
"""
def __init__(self, verbosity_level):
logging.StreamHandler.__init__(self)
self.stream = None # reset it; we are not going to use it anyway
self.verbosity_level = verbosity_level
def emit(self, record):
if record.levelno == logging.INFO:
self.__emit(record, sys.stdout)
elif record.levelno == logging.WARN:
self.__emit(record, sys.stderr)
elif record.levelno == logging.DEBUG:
# show DEBUG messages with verbosity_level >= 2
if self.verbosity_level > 1:
self.__emit(record, sys.stderr)
elif record.levelno >= logging.ERROR:
if record.exc_info and self.verbosity_level < 1:
# supress full traceback with verbosity_level <= 0
with new_record_exc_info(record, None):
self.__emit(record, sys.stderr)
else:
self.__emit(record, sys.stderr)
else:
raise NotImplementedError, \
"don't know about level: {0}".format(record.levelno)
def __emit(self, record, strm):
# override handler stream with ours (which could stdout or stderr)
self.stream = strm
logging.StreamHandler.emit(self, record)
def flush(self):
# Workaround a bug in logging module
# See:
# http://bugs.python.org/issue6333
if self.stream and hasattr(self.stream, 'flush') and not self.stream.closed:
logging.StreamHandler.flush(self)
def _clear_record_traceback_cache(record):
"""Clear the traceback cache stored in `record` (LogRecord)
Workaround for: http://bugs.python.org/issue6435
"""
record.exc_text = None
@contextmanager
def new_record_exc_info(record, exc_info):
"""Temporarily assign `exc_info` to `record`"""
_clear_record_traceback_cache(record)
old_exc_info = record.exc_info
record.exc_info = exc_info
try:
yield
finally:
record.exc_info = old_exc_info
_clear_record_traceback_cache(record)
class ConsoleFormatter(logging.Formatter):
"""A formatter that attaches 'error:' prefix to error/critical messages"""
def format(self, record):
# attach 'error:' prefix to error/critical messages
s = logging.Formatter.format(self, record)
if record.levelno >= logging.ERROR:
return 'error: {0}'.format(s)
else:
return s
|
Comments
I'm bewildered by these assertions that the "correct way" is to spam stdout with unimportant logging messages.
Stdout is for the output of the program. It's the thing that is easy to pipe around to files or to other processes. Status messages and debugging information don't belong in stdout.
Stderr is the stuff that by default goes to console even when a command is used in a pipeline. It is seldom expected to be of any rigid format that can be piped through to another program to consume it, thus it's usually "safe" to jam it full of the noise of status logging.
Are there examples of good programs that actually behave the way these recipes suggest? This kind of nonsense would drive me crazy!
You are apparently assuming that I intend to use LOG.info only for logging status information. The point of this recipe is to enable one to rely on LOG.info instead of
printso that if the program is run on console as a console application,setup_console()will be invoked and not otherwise. Thus, for instance, if a GUI frontend is run .. nothing gets printed to stdout. I'd not recommend this sort of approach for writing programs like awk, but for programs like apt-get and bzr .. as programs that process input can send huge amount of text to stdout (thus writing the same to the application log file).Indeed, it is not so uncommon that logging is used in place of
print.. for just one example look at trace.py in bzr.As for DEBUG, I now think that it is better to send it to stderr.
Will modify the recipe later clarifying this.
DEBUG messages perhaps. There is not set standard stating "status messages don't belong in stdout". Try running "sudo aptitude install kde 2> /dev/null" on a debian machine.
Indeed sir .. there is no 'correct way' here.
-srid
Comments from Vinay (author of logging) from http://bugs.python.org/issue6435
(...) Create a StreamHandler(sys.stderr) and a StreamHandler(sys.stdout). Create a Formatter and attach it to the output handler. Create a Formatter with the format string used above but with an "error:" prefix, and attach it to the error handler. Add a Filter to each handler. This can be a single Filter class which either passes everything above a threshold or everything below a threshold. This will only have a few lines of code. Attach two such instances, suitably configured, to the appropriate handlers. Attach both handlers to the root logger (or some other logger). (...)
Wouldn't it improve your recipe further to use more effectively functionality which is already present in the logging package, instead of re-inventing the wheel? Filter has been part of the logging package design from the beginning, and is reasonably well documented.
If my suggestion has the same effect as your recipe, it has the further benefit of users being able to specify thresholds more flexibly. For example, in your response to a comment on your recipe, you acknowledge that perhaps the destination you initially chose for DEBUG message might need to be reconsidered. This means that it's probably better to provide mechanism, and leave policy more to the user. With moderately careful design of the Filter class, more flexibility could be provided with no real penalty in code size or complexity.
Sign in to comment