From ff1f3d9ff195eb59076f20969f3a49ecf72067b4 Mon Sep 17 00:00:00 2001 From: Vinay Sajip Date: Sat, 10 Oct 2015 00:52:35 +0100 Subject: [PATCH] Closes #25344: Added cookbook recipe to show buffering of logging events. --- Doc/howto/logging-cookbook.rst | 137 +++++++++++++++++++++++++++++++++ 1 file changed, 137 insertions(+) diff --git a/Doc/howto/logging-cookbook.rst b/Doc/howto/logging-cookbook.rst index 6305d24bcfb..addaea5243a 100644 --- a/Doc/howto/logging-cookbook.rst +++ b/Doc/howto/logging-cookbook.rst @@ -2142,3 +2142,140 @@ The above approach can, of course, be adapted to other TTS systems and even other systems altogether which can process messages via external programs run from a command line. + +.. _buffered-logging: + +Buffering logging messages and outputting them conditionally +------------------------------------------------------------ + +There might be situations where you want to log messages in a temporary area +and only output them if a certain condition occurs. For example, you may want to +start logging debug events in a function, and if the function completes without +errors, you don't want to clutter the log with the collected debug information, +but if there is an error, you want all the debug information to be output as well +as the error. + +Here is an example which shows how you could do this using a decorator for your +functions where you want logging to behave this way. It makes use of the +:class:`logging.handlers.MemoryHandler`, which allows buffering of logged events +until some condition occurs, at which point the buffered events are ``flushed`` +- passed to another handler (the ``target`` handler) for processing. By default, +the ``MemoryHandler`` flushed when its buffer gets filled up or an event whose +level is greater than or equal to a specified threshold is seen. You can use this +recipe with a more specialised subclass of ``MemoryHandler`` if you want custom +flushing behavior. + +The example script has a simple function, ``foo``, which just cycles through +all the logging levels, writing to ``sys.stderr`` to say what level it's about +to log at, and then actually logging a message that that level. You can pass a +parameter to ``foo`` which, if true, will log at ERROR and CRITICAL levels - +otherwise, it only logs at DEBUG, INFO and WARNING levels. + +The script just arranges to decorate ``foo`` with a decorator which will do the +conditional logging that's required. The decorator takes a logger as a parameter +and attaches a memory handler for the duration of the call to the decorated +function. The decorator can be additionally parameterised using a target handler, +a level at which flushing should occur, and a capacity for the buffer. These +default to a :class:`~logging.StreamHandler` which writes to ``sys.stderr``, +``logging.ERROR`` and ``100`` respectively. + +Here's the script:: + + import logging + from logging.handlers import MemoryHandler + import sys + + logger = logging.getLogger(__name__) + logger.addHandler(logging.NullHandler()) + + def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None): + if target_handler is None: + target_handler = logging.StreamHandler() + if flush_level is None: + flush_level = logging.ERROR + if capacity is None: + capacity = 100 + handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler) + + def decorator(fn): + def wrapper(*args, **kwargs): + logger.addHandler(handler) + try: + return fn(*args, **kwargs) + except Exception: + logger.exception('call failed') + raise + finally: + super(MemoryHandler, handler).flush() + logger.removeHandler(handler) + return wrapper + + return decorator + + def write_line(s): + sys.stderr.write('%s\n' % s) + + def foo(fail=False): + write_line('about to log at DEBUG ...') + logger.debug('Actually logged at DEBUG') + write_line('about to log at INFO ...') + logger.info('Actually logged at INFO') + write_line('about to log at WARNING ...') + logger.warning('Actually logged at WARNING') + if fail: + write_line('about to log at ERROR ...') + logger.error('Actually logged at ERROR') + write_line('about to log at CRITICAL ...') + logger.critical('Actually logged at CRITICAL') + return fail + + decorated_foo = log_if_errors(logger)(foo) + + if __name__ == '__main__': + logger.setLevel(logging.DEBUG) + write_line('Calling undecorated foo with False') + assert not foo(False) + write_line('Calling undecorated foo with True') + assert foo(True) + write_line('Calling decorated foo with False') + assert not decorated_foo(False) + write_line('Calling decorated foo with True') + assert decorated_foo(True) + +When this script is run, the following output should be observed:: + + Calling undecorated foo with False + about to log at DEBUG ... + about to log at INFO ... + about to log at WARNING ... + Calling undecorated foo with True + about to log at DEBUG ... + about to log at INFO ... + about to log at WARNING ... + about to log at ERROR ... + about to log at CRITICAL ... + Calling decorated foo with False + about to log at DEBUG ... + about to log at INFO ... + about to log at WARNING ... + Calling decorated foo with True + about to log at DEBUG ... + about to log at INFO ... + about to log at WARNING ... + about to log at ERROR ... + Actually logged at DEBUG + Actually logged at INFO + Actually logged at WARNING + Actually logged at ERROR + about to log at CRITICAL ... + Actually logged at CRITICAL + +As you can see, actual logging output only occurs when an event is logged whose +severity is ERROR or greater, but in that case, any previous events at lower +severities are also logged. + +You can of course use the conventional means of decoration:: + + @log_if_errors(logger) + def foo(fail=False): + ...