From c7403355df5a0d3b45157b5029ca423f15b4ee0b Mon Sep 17 00:00:00 2001 From: Vinay Sajip Date: Fri, 18 Jan 2008 15:54:14 +0000 Subject: [PATCH] Added section on passing contextual information to logging and documentation for the LoggerAdapter class. --- Doc/library/logging.rst | 153 ++++++++++++++++++++++++++++++++++------ 1 file changed, 130 insertions(+), 23 deletions(-) diff --git a/Doc/library/logging.rst b/Doc/library/logging.rst index 800ad62b615..b7600ecffc1 100644 --- a/Doc/library/logging.rst +++ b/Doc/library/logging.rst @@ -1155,33 +1155,113 @@ level of granularity you want to use in logging an application, it could be hard to manage if the number of :class:`Logger` instances becomes effectively unbounded. -There are a number of other ways you can pass contextual information to be -output along with logging event information. +An easy way in which you can pass contextual information to be output along +with logging event information is to use the :class:`LoggerAdapter` class. +This class is designed to look like a :class:`Logger`, so that you can call +:meth:`debug`, :meth:`info`, :meth:`warning`, :meth:`error`, +:meth:`exception`, :meth:`critical` and :meth:`log`. These methods have the +same signatures as their counterparts in :class:`Logger`, so you can use the +two types of instances interchangeably. -* Use an adapter class which has access to the contextual information and - which defines methods :meth:`debug`, :meth:`info` etc. with the same - signatures as used by :class:`Logger`. You instantiate the adapter with a - name, which will be used to create an underlying :class:`Logger` with that - name. In each adpater method, the passed-in message is modified to include - whatever contextual information you want. +When you create an instance of :class:`LoggerAdapter`, you pass it a +:class:`Logger` instance and a dict-like object which contains your contextual +information. When you call one of the logging methods on an instance of +:class:`LoggerAdapter`, it delegates the call to the underlying instance of +:class:`Logger` passed to its constructor, and arranges to pass the contextual +information in the delegated call. Here's a snippet from the code of +:class:`LoggerAdapter`:: -* Use something other than a string to pass the message. Although normally - the first argument to a logger method such as :meth:`debug`, :meth:`info` - etc. is usually a string, it can in fact be any object. This object is the - argument to a :func:`str()` call which is made, in - :meth:`LogRecord.getMessage`, to obtain the actual message string. You can - use this behavior to pass an instance which may be initialized with a - logging message, which redefines :meth:__str__ to return a modified version - of that message with the contextual information added. + def debug(self, msg, *args, **kwargs): + """ + Delegate a debug call to the underlying logger, after adding + contextual information from this adapter instance. + """ + msg, kwargs = self.process(msg, kwargs) + self.logger.debug(msg, *args, **kwargs) -* Use a specialized :class:`Formatter` subclass to add additional information - to the formatted output. The subclass could, for instance, merge some thread - local contextual information (or contextual information obtained in some - other way) with the output generated by the base :class:`Formatter`. +The :meth:`process` method of :class:`LoggerAdapter` is where the contextual +information is added to the logging output. It's passed the message and +keyword arguments of the logging call, and it passes back (potentially) +modified versions of these to use in the call to the underlying logger. The +default implementation of this method leaves the message alone, but inserts +an "extra" key in the keyword argument whose value is the dict-like object +passed to the constructor. Of course, if you had passed an "extra" keyword +argument in the call to the adapter, it will be silently overwritten. + +The advantage of using "extra" is that the values in the dict-like object are +merged into the :class:`LogRecord` instance's __dict__, allowing you to use +customized strings with your :class:`Formatter` instances which know about +the keys of the dict-like object. If you need a different method, e.g. if you +want to prepend or append the contextual information to the message string, +you just need to subclass :class:`LoggerAdapter` and override :meth:`process` +to do what you need. Here's an example script which uses this class, which +also illustrates what dict-like behaviour is needed from an arbitrary +"dict-like" object for use in the constructor:: + +import logging + +class ConnInfo: + """ + An example class which shows how an arbitrary class can be used as + the 'extra' context information repository passed to a LoggerAdapter. + """ + + def __getitem__(self, name): + """ + To allow this instance to look like a dict. + """ + from random import choice + if name == "ip": + result = choice(["127.0.0.1", "192.168.0.1"]) + elif name == "user": + result = choice(["jim", "fred", "sheila"]) + else: + result = self.__dict__.get(name, "?") + return result + + def __iter__(self): + """ + To allow iteration over keys, which will be merged into + the LogRecord dict before formatting and output. + """ + keys = ["ip", "user"] + keys.extend(self.__dict__.keys()) + return keys.__iter__() + +if __name__ == "__main__": + from random import choice + levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL) + a1 = logging.LoggerAdapter(logging.getLogger("a.b.c"), + { "ip" : "123.231.231.123", "user" : "sheila" }) + logging.basicConfig(level=logging.DEBUG, + format="%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s") + a1.debug("A debug message") + a1.info("An info message with %s", "some parameters") + a2 = logging.LoggerAdapter(logging.getLogger("d.e.f"), ConnInfo()) + for x in range(10): + lvl = choice(levels) + lvlname = logging.getLevelName(lvl) + a2.log(lvl, "A message at %s level with %d %s", lvlname, 2, "parameters") + +When this script is run, the output should look something like this:: + +2008-01-18 14:49:54,023 a.b.c DEBUG IP: 123.231.231.123 User: sheila A debug message +2008-01-18 14:49:54,023 a.b.c INFO IP: 123.231.231.123 User: sheila An info message with some parameters +2008-01-18 14:49:54,023 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters +2008-01-18 14:49:54,033 d.e.f INFO IP: 192.168.0.1 User: jim A message at INFO level with 2 parameters +2008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: sheila A message at WARNING level with 2 parameters +2008-01-18 14:49:54,033 d.e.f ERROR IP: 127.0.0.1 User: fred A message at ERROR level with 2 parameters +2008-01-18 14:49:54,033 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters +2008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: sheila A message at WARNING level with 2 parameters +2008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: jim A message at WARNING level with 2 parameters +2008-01-18 14:49:54,033 d.e.f INFO IP: 192.168.0.1 User: fred A message at INFO level with 2 parameters +2008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: sheila A message at WARNING level with 2 parameters +2008-01-18 14:49:54,033 d.e.f WARNING IP: 127.0.0.1 User: jim A message at WARNING level with 2 parameters + +.. versionadded:: 2.6 + +The :class:`LoggerAdapter` class was not present in previous versions. -In each of these three approaches, thread locals can sometimes be a useful way -of passing contextual information without undue coupling between different -parts of your code. .. _network-logging: @@ -2077,6 +2157,33 @@ made, and any exception information to be logged. Returns the message for this :class:`LogRecord` instance after merging any user-supplied arguments with the message. +LoggerAdapter Objects +--------------------- + +.. versionadded:: 2.6 + +:class:`LoggerAdapter` instances are used to conveniently pass contextual +information into logging calls. For a usage example , see context-info_. + +.. class:: LoggerAdapter(logger, extra) + + Returns an instance of :class:`LoggerAdapter` initialized with an + underlying :class:`Logger` instance and a dict-like object. + +.. method:: LoggerAdapter.process(msg, kwargs) + + Modifies the message and/or keyword arguments passed to a logging call in + order to insert contextual information. This implementation takes the + object passed as *extra* to the constructor and adds it to *kwargs* using + key 'extra'. The return value is a (*msg*, *kwargs*) tuple which has the + (possibly modified) versions of the arguments passed in. + +In addition to the above, :class:`LoggerAdapter` supports all the logging +methods of :class:`Logger`, i.e. :meth:`debug`, :meth:`info`, :meth:`warning`, +:meth:`error`, :meth:`exception`, :meth:`critical` and :meth:`log`. These +methods have the same signatures as their counterparts in :class:`Logger`, so +you can use the two types of instances interchangeably. + Thread Safety -------------