Logging documentation reorganised.

1 files changed, 929 insertions, 0 deletions

diff --git a/Doc/howto/logging-cookbook.rst b/Doc/howto/logging-cookbook.rst
new file mode 100644
index 0000000..ea1756b
--- /dev/null
+++ b/Doc/howto/logging-cookbook.rst
@@ -0,0 +1,929 @@
+.. _logging-cookbook:
+
+================
+Logging Cookbook
+================
+
+:Author: Vinay Sajip <vinay_sajip at red-dove dot com>
+
+This page contains a number of recipes related to logging, which have been found useful in the past.
+
+.. Contents::
+
+.. currentmodule:: logging
+
+Using logging in multiple modules
+---------------------------------
+
+It was mentioned above that multiple calls to
+``logging.getLogger('someLogger')`` return a reference to the same logger
+object.  This is true not only within the same module, but also across modules
+as long as it is in the same Python interpreter process.  It is true for
+references to the same object; additionally, application code can define and
+configure a parent logger in one module and create (but not configure) a child
+logger in a separate module, and all logger calls to the child will pass up to
+the parent.  Here is a main module::
+
+    import logging
+    import auxiliary_module
+
+    # create logger with 'spam_application'
+    logger = logging.getLogger('spam_application')
+    logger.setLevel(logging.DEBUG)
+    # create file handler which logs even debug messages
+    fh = logging.FileHandler('spam.log')
+    fh.setLevel(logging.DEBUG)
+    # create console handler with a higher log level
+    ch = logging.StreamHandler()
+    ch.setLevel(logging.ERROR)
+    # create formatter and add it to the handlers
+    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
+    fh.setFormatter(formatter)
+    ch.setFormatter(formatter)
+    # add the handlers to the logger
+    logger.addHandler(fh)
+    logger.addHandler(ch)
+
+    logger.info('creating an instance of auxiliary_module.Auxiliary')
+    a = auxiliary_module.Auxiliary()
+    logger.info('created an instance of auxiliary_module.Auxiliary')
+    logger.info('calling auxiliary_module.Auxiliary.do_something')
+    a.do_something()
+    logger.info('finished auxiliary_module.Auxiliary.do_something')
+    logger.info('calling auxiliary_module.some_function()')
+    auxiliary_module.some_function()
+    logger.info('done with auxiliary_module.some_function()')
+
+Here is the auxiliary module::
+
+    import logging
+
+    # create logger
+    module_logger = logging.getLogger('spam_application.auxiliary')
+
+    class Auxiliary:
+        def __init__(self):
+            self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
+            self.logger.info('creating an instance of Auxiliary')
+        def do_something(self):
+            self.logger.info('doing something')
+            a = 1 + 1
+            self.logger.info('done doing something')
+
+    def some_function():
+        module_logger.info('received a call to "some_function"')
+
+The output looks like this::
+
+    2005-03-23 23:47:11,663 - spam_application - INFO -
+       creating an instance of auxiliary_module.Auxiliary
+    2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -
+       creating an instance of Auxiliary
+    2005-03-23 23:47:11,665 - spam_application - INFO -
+       created an instance of auxiliary_module.Auxiliary
+    2005-03-23 23:47:11,668 - spam_application - INFO -
+       calling auxiliary_module.Auxiliary.do_something
+    2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -
+       doing something
+    2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -
+       done doing something
+    2005-03-23 23:47:11,670 - spam_application - INFO -
+       finished auxiliary_module.Auxiliary.do_something
+    2005-03-23 23:47:11,671 - spam_application - INFO -
+       calling auxiliary_module.some_function()
+    2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -
+       received a call to 'some_function'
+    2005-03-23 23:47:11,673 - spam_application - INFO -
+       done with auxiliary_module.some_function()
+
+Multiple handlers and formatters
+--------------------------------
+
+Loggers are plain Python objects.  The :func:`addHandler` method has no minimum
+or maximum quota for the number of handlers you may add.  Sometimes it will be
+beneficial for an application to log all messages of all severities to a text
+file while simultaneously logging errors or above to the console.  To set this
+up, simply configure the appropriate handlers.  The logging calls in the
+application code will remain unchanged.  Here is a slight modification to the
+previous simple module-based configuration example::
+
+    import logging
+
+    logger = logging.getLogger('simple_example')
+    logger.setLevel(logging.DEBUG)
+    # create file handler which logs even debug messages
+    fh = logging.FileHandler('spam.log')
+    fh.setLevel(logging.DEBUG)
+    # create console handler with a higher log level
+    ch = logging.StreamHandler()
+    ch.setLevel(logging.ERROR)
+    # create formatter and add it to the handlers
+    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
+    ch.setFormatter(formatter)
+    fh.setFormatter(formatter)
+    # add the handlers to logger
+    logger.addHandler(ch)
+    logger.addHandler(fh)
+
+    # 'application' code
+    logger.debug('debug message')
+    logger.info('info message')
+    logger.warn('warn message')
+    logger.error('error message')
+    logger.critical('critical message')
+
+Notice that the 'application' code does not care about multiple handlers.  All
+that changed was the addition and configuration of a new handler named *fh*.
+
+The ability to create new handlers with higher- or lower-severity filters can be
+very helpful when writing and testing an application.  Instead of using many
+``print`` statements for debugging, use ``logger.debug``: Unlike the print
+statements, which you will have to delete or comment out later, the logger.debug
+statements can remain intact in the source code and remain dormant until you
+need them again.  At that time, the only change that needs to happen is to
+modify the severity level of the logger and/or handler to debug.
+
+.. _multiple-destinations:
+
+Logging to multiple destinations
+--------------------------------
+
+Let's say you want to log to console and file with different message formats and
+in differing circumstances. Say you want to log messages with levels of DEBUG
+and higher to file, and those messages at level INFO and higher to the console.
+Let's also assume that the file should contain timestamps, but the console
+messages should not. Here's how you can achieve this::
+
+   import logging
+
+   # set up logging to file - see previous section for more details
+   logging.basicConfig(level=logging.DEBUG,
+                       format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
+                       datefmt='%m-%d %H:%M',
+                       filename='/temp/myapp.log',
+                       filemode='w')
+   # define a Handler which writes INFO messages or higher to the sys.stderr
+   console = logging.StreamHandler()
+   console.setLevel(logging.INFO)
+   # set a format which is simpler for console use
+   formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
+   # tell the handler to use this format
+   console.setFormatter(formatter)
+   # add the handler to the root logger
+   logging.getLogger('').addHandler(console)
+
+   # Now, we can log to the root logger, or any other logger. First the root...
+   logging.info('Jackdaws love my big sphinx of quartz.')
+
+   # Now, define a couple of other loggers which might represent areas in your
+   # application:
+
+   logger1 = logging.getLogger('myapp.area1')
+   logger2 = logging.getLogger('myapp.area2')
+
+   logger1.debug('Quick zephyrs blow, vexing daft Jim.')
+   logger1.info('How quickly daft jumping zebras vex.')
+   logger2.warning('Jail zesty vixen who grabbed pay from quack.')
+   logger2.error('The five boxing wizards jump quickly.')
+
+When you run this, on the console you will see ::
+
+   root        : INFO     Jackdaws love my big sphinx of quartz.
+   myapp.area1 : INFO     How quickly daft jumping zebras vex.
+   myapp.area2 : WARNING  Jail zesty vixen who grabbed pay from quack.
+   myapp.area2 : ERROR    The five boxing wizards jump quickly.
+
+and in the file you will see something like ::
+
+   10-22 22:19 root         INFO     Jackdaws love my big sphinx of quartz.
+   10-22 22:19 myapp.area1  DEBUG    Quick zephyrs blow, vexing daft Jim.
+   10-22 22:19 myapp.area1  INFO     How quickly daft jumping zebras vex.
+   10-22 22:19 myapp.area2  WARNING  Jail zesty vixen who grabbed pay from quack.
+   10-22 22:19 myapp.area2  ERROR    The five boxing wizards jump quickly.
+
+As you can see, the DEBUG message only shows up in the file. The other messages
+are sent to both destinations.
+
+This example uses console and file handlers, but you can use any number and
+combination of handlers you choose.
+
+
+Configuration server example
+----------------------------
+
+Here is an example of a module using the logging configuration server::
+
+    import logging
+    import logging.config
+    import time
+    import os
+
+    # read initial config file
+    logging.config.fileConfig('logging.conf')
+
+    # create and start listener on port 9999
+    t = logging.config.listen(9999)
+    t.start()
+
+    logger = logging.getLogger('simpleExample')
+
+    try:
+        # loop through logging calls to see the difference
+        # new configurations make, until Ctrl+C is pressed
+        while True:
+            logger.debug('debug message')
+            logger.info('info message')
+            logger.warn('warn message')
+            logger.error('error message')
+            logger.critical('critical message')
+            time.sleep(5)
+    except KeyboardInterrupt:
+        # cleanup
+        logging.config.stopListening()
+        t.join()
+
+And here is a script that takes a filename and sends that file to the server,
+properly preceded with the binary-encoded length, as the new logging
+configuration::
+
+    #!/usr/bin/env python
+    import socket, sys, struct
+
+    data_to_send = open(sys.argv[1], 'r').read()
+
+    HOST = 'localhost'
+    PORT = 9999
+    s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
+    print('connecting...')
+    s.connect((HOST, PORT))
+    print('sending config...')
+    s.send(struct.pack('>L', len(data_to_send)))
+    s.send(data_to_send)
+    s.close()
+    print('complete')
+
+
+Dealing with handlers that block
+--------------------------------
+
+.. currentmodule:: logging.handlers
+
+Sometimes you have to get your logging handlers to do their work without
+blocking the thread you’re logging from. This is common in Web applications,
+though of course it also occurs in other scenarios.
+
+A common culprit which demonstrates sluggish behaviour is the
+:class:`SMTPHandler`: sending emails can take a long time, for a
+number of reasons outside the developer’s control (for example, a poorly
+performing mail or network infrastructure). But almost any network-based
+handler can block: Even a :class:`SocketHandler` operation may do a
+DNS query under the hood which is too slow (and this query can be deep in the
+socket library code, below the Python layer, and outside your control).
+
+One solution is to use a two-part approach. For the first part, attach only a
+:class:`QueueHandler` to those loggers which are accessed from
+performance-critical threads. They simply write to their queue, which can be
+sized to a large enough capacity or initialized with no upper bound to their
+size. The write to the queue will typically be accepted quickly, though you
+will probably need to catch the :ref:`queue.Full` exception as a precaution
+in your code. If you are a library developer who has performance-critical
+threads in their code, be sure to document this (together with a suggestion to
+attach only ``QueueHandlers`` to your loggers) for the benefit of other
+developers who will use your code.
+
+The second part of the solution is :class:`QueueListener`, which has been
+designed as the counterpart to :class:`QueueHandler`.  A
+:class:`QueueListener` is very simple: it’s passed a queue and some handlers,
+and it fires up an internal thread which listens to its queue for LogRecords
+sent from ``QueueHandlers`` (or any other source of ``LogRecords``, for that
+matter). The ``LogRecords`` are removed from the queue and passed to the
+handlers for processing.
+
+The advantage of having a separate :class:`QueueListener` class is that you
+can use the same instance to service multiple ``QueueHandlers``. This is more
+resource-friendly than, say, having threaded versions of the existing handler
+classes, which would eat up one thread per handler for no particular benefit.
+
+An example of using these two classes follows (imports omitted)::
+
+    que = queue.Queue(-1) # no limit on size
+    queue_handler = QueueHandler(que)
+    handler = logging.StreamHandler()
+    listener = QueueListener(que, handler)
+    root = logging.getLogger()
+    root.addHandler(queue_handler)
+    formatter = logging.Formatter('%(threadName)s: %(message)s')
+    handler.setFormatter(formatter)
+    listener.start()
+    # The log output will display the thread which generated
+    # the event (the main thread) rather than the internal
+    # thread which monitors the internal queue. This is what
+    # you want to happen.
+    root.warning('Look out!')
+    listener.stop()
+
+which, when run, will produce::
+
+    MainThread: Look out!
+
+
+.. _network-logging:
+
+Sending and receiving logging events across a network
+-----------------------------------------------------
+
+Let's say you want to send logging events across a network, and handle them at
+the receiving end. A simple way of doing this is attaching a
+:class:`SocketHandler` instance to the root logger at the sending end::
+
+   import logging, logging.handlers
+
+   rootLogger = logging.getLogger('')
+   rootLogger.setLevel(logging.DEBUG)
+   socketHandler = logging.handlers.SocketHandler('localhost',
+                       logging.handlers.DEFAULT_TCP_LOGGING_PORT)
+   # don't bother with a formatter, since a socket handler sends the event as
+   # an unformatted pickle
+   rootLogger.addHandler(socketHandler)
+
+   # Now, we can log to the root logger, or any other logger. First the root...
+   logging.info('Jackdaws love my big sphinx of quartz.')
+
+   # Now, define a couple of other loggers which might represent areas in your
+   # application:
+
+   logger1 = logging.getLogger('myapp.area1')
+   logger2 = logging.getLogger('myapp.area2')
+
+   logger1.debug('Quick zephyrs blow, vexing daft Jim.')
+   logger1.info('How quickly daft jumping zebras vex.')
+   logger2.warning('Jail zesty vixen who grabbed pay from quack.')
+   logger2.error('The five boxing wizards jump quickly.')
+
+At the receiving end, you can set up a receiver using the :mod:`socketserver`
+module. Here is a basic working example::
+
+   import pickle
+   import logging
+   import logging.handlers
+   import socketserver
+   import struct
+
+
+   class LogRecordStreamHandler(socketserver.StreamRequestHandler):
+       """Handler for a streaming logging request.
+
+       This basically logs the record using whatever logging policy is
+       configured locally.
+       """
+
+       def handle(self):
+           """
+           Handle multiple requests - each expected to be a 4-byte length,
+           followed by the LogRecord in pickle format. Logs the record
+           according to whatever policy is configured locally.
+           """
+           while True:
+               chunk = self.connection.recv(4)
+               if len(chunk) < 4:
+                   break
+               slen = struct.unpack('>L', chunk)[0]
+               chunk = self.connection.recv(slen)
+               while len(chunk) < slen:
+                   chunk = chunk + self.connection.recv(slen - len(chunk))
+               obj = self.unPickle(chunk)
+               record = logging.makeLogRecord(obj)
+               self.handleLogRecord(record)
+
+       def unPickle(self, data):
+           return pickle.loads(data)
+
+       def handleLogRecord(self, record):
+           # if a name is specified, we use the named logger rather than the one
+           # implied by the record.
+           if self.server.logname is not None:
+               name = self.server.logname
+           else:
+               name = record.name
+           logger = logging.getLogger(name)
+           # N.B. EVERY record gets logged. This is because Logger.handle
+           # is normally called AFTER logger-level filtering. If you want
+           # to do filtering, do it at the client end to save wasting
+           # cycles and network bandwidth!
+           logger.handle(record)
+
+   class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):
+       """
+       Simple TCP socket-based logging receiver suitable for testing.
+       """
+
+       allow_reuse_address = 1
+
+       def __init__(self, host='localhost',
+                    port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
+                    handler=LogRecordStreamHandler):
+           socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)
+           self.abort = 0
+           self.timeout = 1
+           self.logname = None
+
+       def serve_until_stopped(self):
+           import select
+           abort = 0
+           while not abort:
+               rd, wr, ex = select.select([self.socket.fileno()],
+                                          [], [],
+                                          self.timeout)
+               if rd:
+                   self.handle_request()
+               abort = self.abort
+
+   def main():
+       logging.basicConfig(
+           format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')
+       tcpserver = LogRecordSocketReceiver()
+       print('About to start TCP server...')
+       tcpserver.serve_until_stopped()
+
+   if __name__ == '__main__':
+       main()
+
+First run the server, and then the client. On the client side, nothing is
+printed on the console; on the server side, you should see something like::
+
+   About to start TCP server...
+      59 root            INFO     Jackdaws love my big sphinx of quartz.
+      59 myapp.area1     DEBUG    Quick zephyrs blow, vexing daft Jim.
+      69 myapp.area1     INFO     How quickly daft jumping zebras vex.
+      69 myapp.area2     WARNING  Jail zesty vixen who grabbed pay from quack.
+      69 myapp.area2     ERROR    The five boxing wizards jump quickly.
+
+Note that there are some security issues with pickle in some scenarios. If
+these affect you, you can use an alternative serialization scheme by overriding
+the :meth:`makePickle` method and implementing your alternative there, as
+well as adapting the above script to use your alternative serialization.
+
+
+.. _context-info:
+
+Adding contextual information to your logging output
+----------------------------------------------------
+
+Sometimes you want logging output to contain contextual information in
+addition to the parameters passed to the logging call. For example, in a
+networked application, it may be desirable to log client-specific information
+in the log (e.g. remote client's username, or IP address). Although you could
+use the *extra* parameter to achieve this, it's not always convenient to pass
+the information in this way. While it might be tempting to create
+:class:`Logger` instances on a per-connection basis, this is not a good idea
+because these instances are not garbage collected. While this is not a problem
+in practice, when the number of :class:`Logger` instances is dependent on the
+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.
+
+
+Using LoggerAdapters to impart contextual 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.
+
+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`::
+
+    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)
+
+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
+
+
+.. _filters-contextual:
+
+Using Filters to impart contextual information
+^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
+
+You can also add contextual information to log output using a user-defined
+:class:`Filter`. ``Filter`` instances are allowed to modify the ``LogRecords``
+passed to them, including adding additional attributes which can then be output
+using a suitable format string, or if needed a custom :class:`Formatter`.
+
+For example in a web application, the request being processed (or at least,
+the interesting parts of it) can be stored in a threadlocal
+(:class:`threading.local`) variable, and then accessed from a ``Filter`` to
+add, say, information from the request - say, the remote IP address and remote
+user's username - to the ``LogRecord``, using the attribute names 'ip' and
+'user' as in the ``LoggerAdapter`` example above. In that case, the same format
+string can be used to get similar output to that shown above. Here's an example
+script::
+
+    import logging
+    from random import choice
+
+    class ContextFilter(logging.Filter):
+        """
+        This is a filter which injects contextual information into the log.
+
+        Rather than use actual contextual information, we just use random
+        data in this demo.
+        """
+
+        USERS = ['jim', 'fred', 'sheila']
+        IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']
+
+        def filter(self, record):
+
+            record.ip = choice(ContextFilter.IPS)
+            record.user = choice(ContextFilter.USERS)
+            return True
+
+    if __name__ == '__main__':
+       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 = logging.getLogger('a.b.c')
+       a2 = logging.getLogger('d.e.f')
+
+       f = ContextFilter()
+       a1.addFilter(f)
+       a2.addFilter(f)
+       a1.debug('A debug message')
+       a1.info('An info message with %s', 'some parameters')
+       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')
+
+which, when run, produces something like::
+
+    2010-09-06 22:38:15,292 a.b.c DEBUG    IP: 123.231.231.123 User: fred     A debug message
+    2010-09-06 22:38:15,300 a.b.c INFO     IP: 192.168.0.1     User: sheila   An info message with some parameters
+    2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
+    2010-09-06 22:38:15,300 d.e.f ERROR    IP: 127.0.0.1       User: jim      A message at ERROR level with 2 parameters
+    2010-09-06 22:38:15,300 d.e.f DEBUG    IP: 127.0.0.1       User: sheila   A message at DEBUG level with 2 parameters
+    2010-09-06 22:38:15,300 d.e.f ERROR    IP: 123.231.231.123 User: fred     A message at ERROR level with 2 parameters
+    2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1     User: jim      A message at CRITICAL level with 2 parameters
+    2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
+    2010-09-06 22:38:15,300 d.e.f DEBUG    IP: 192.168.0.1     User: jim      A message at DEBUG level with 2 parameters
+    2010-09-06 22:38:15,301 d.e.f ERROR    IP: 127.0.0.1       User: sheila   A message at ERROR level with 2 parameters
+    2010-09-06 22:38:15,301 d.e.f DEBUG    IP: 123.231.231.123 User: fred     A message at DEBUG level with 2 parameters
+    2010-09-06 22:38:15,301 d.e.f INFO     IP: 123.231.231.123 User: fred     A message at INFO level with 2 parameters
+
+
+.. _multiple-processes:
+
+Logging to a single file from multiple processes
+------------------------------------------------
+
+Although logging is thread-safe, and logging to a single file from multiple
+threads in a single process *is* supported, logging to a single file from
+*multiple processes* is *not* supported, because there is no standard way to
+serialize access to a single file across multiple processes in Python. If you
+need to log to a single file from multiple processes, one way of doing this is
+to have all the processes log to a :class:`SocketHandler`, and have a separate
+process which implements a socket server which reads from the socket and logs
+to file. (If you prefer, you can dedicate one thread in one of the existing
+processes to perform this function.) The following section documents this
+approach in more detail and includes a working socket receiver which can be
+used as a starting point for you to adapt in your own applications.
+
+If you are using a recent version of Python which includes the
+:mod:`multiprocessing` module, you could write your own handler which uses the
+:class:`Lock` class from this module to serialize access to the file from
+your processes. The existing :class:`FileHandler` and subclasses do not make
+use of :mod:`multiprocessing` at present, though they may do so in the future.
+Note that at present, the :mod:`multiprocessing` module does not provide
+working lock functionality on all platforms (see
+http://bugs.python.org/issue3770).
+
+.. currentmodule:: logging.handlers
+
+Alternatively, you can use a ``Queue`` and a :class:`QueueHandler` to send
+all logging events to one of the processes in your multi-process application.
+The following example script demonstrates how you can do this; in the example
+a separate listener process listens for events sent by other processes and logs
+them according to its own logging configuration. Although the example only
+demonstrates one way of doing it (for example, you may want to use a listener
+thread rather than a separate listener process - the implementation would be
+analogous) it does allow for completely different logging configurations for
+the listener and the other processes in your application, and can be used as
+the basis for code meeting your own specific requirements::
+
+    # You'll need these imports in your own code
+    import logging
+    import logging.handlers
+    import multiprocessing
+
+    # Next two import lines for this demo only
+    from random import choice, random
+    import time
+
+    #
+    # Because you'll want to define the logging configurations for listener and workers, the
+    # listener and worker process functions take a configurer parameter which is a callable
+    # for configuring logging for that process. These functions are also passed the queue,
+    # which they use for communication.
+    #
+    # In practice, you can configure the listener however you want, but note that in this
+    # simple example, the listener does not apply level or filter logic to received records.
+    # In practice, you would probably want to do ths logic in the worker processes, to avoid
+    # sending events which would be filtered out between processes.
+    #
+    # The size of the rotated files is made small so you can see the results easily.
+    def listener_configurer():
+        root = logging.getLogger()
+        h = logging.handlers.RotatingFileHandler('/tmp/mptest.log', 'a', 300, 10)
+        f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')
+        h.setFormatter(f)
+        root.addHandler(h)
+
+    # This is the listener process top-level loop: wait for logging events
+    # (LogRecords)on the queue and handle them, quit when you get a None for a
+    # LogRecord.
+    def listener_process(queue, configurer):
+        configurer()
+        while True:
+            try:
+                record = queue.get()
+                if record is None: # We send this as a sentinel to tell the listener to quit.
+                    break
+                logger = logging.getLogger(record.name)
+                logger.handle(record) # No level or filter logic applied - just do it!
+            except (KeyboardInterrupt, SystemExit):
+                raise
+            except:
+                import sys, traceback
+                print >> sys.stderr, 'Whoops! Problem:'
+                traceback.print_exc(file=sys.stderr)
+
+    # Arrays used for random selections in this demo
+
+    LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,
+              logging.ERROR, logging.CRITICAL]
+
+    LOGGERS = ['a.b.c', 'd.e.f']
+
+    MESSAGES = [
+        'Random message #1',
+        'Random message #2',
+        'Random message #3',
+    ]
+
+    # The worker configuration is done at the start of the worker process run.
+    # Note that on Windows you can't rely on fork semantics, so each process
+    # will run the logging configuration code when it starts.
+    def worker_configurer(queue):
+        h = logging.handlers.QueueHandler(queue) # Just the one handler needed
+        root = logging.getLogger()
+        root.addHandler(h)
+        root.setLevel(logging.DEBUG) # send all messages, for demo; no other level or filter logic applied.
+
+    # This is the worker process top-level loop, which just logs ten events with
+    # random intervening delays before terminating.
+    # The print messages are just so you know it's doing something!
+    def worker_process(queue, configurer):
+        configurer(queue)
+        name = multiprocessing.current_process().name
+        print('Worker started: %s' % name)
+        for i in range(10):
+            time.sleep(random())
+            logger = logging.getLogger(choice(LOGGERS))
+            level = choice(LEVELS)
+            message = choice(MESSAGES)
+            logger.log(level, message)
+        print('Worker finished: %s' % name)
+
+    # Here's where the demo gets orchestrated. Create the queue, create and start
+    # the listener, create ten workers and start them, wait for them to finish,
+    # then send a None to the queue to tell the listener to finish.
+    def main():
+        queue = multiprocessing.Queue(-1)
+        listener = multiprocessing.Process(target=listener_process,
+                                           args=(queue, listener_configurer))
+        listener.start()
+        workers = []
+        for i in range(10):
+            worker = multiprocessing.Process(target=worker_process,
+                                           args=(queue, worker_configurer))
+            workers.append(worker)
+            worker.start()
+        for w in workers:
+            w.join()
+        queue.put_nowait(None)
+        listener.join()
+
+    if __name__ == '__main__':
+        main()
+
+
+Using file rotation
+-------------------
+
+.. sectionauthor:: Doug Hellmann, Vinay Sajip (changes)
+.. (see <http://blog.doughellmann.com/2007/05/pymotw-logging.html>)
+
+Sometimes you want to let a log file grow to a certain size, then open a new
+file and log to that. You may want to keep a certain number of these files, and
+when that many files have been created, rotate the files so that the number of
+files and the size of the files both remin bounded. For this usage pattern, the
+logging package provides a :class:`RotatingFileHandler`::
+
+   import glob
+   import logging
+   import logging.handlers
+
+   LOG_FILENAME = 'logging_rotatingfile_example.out'
+
+   # Set up a specific logger with our desired output level
+   my_logger = logging.getLogger('MyLogger')
+   my_logger.setLevel(logging.DEBUG)
+
+   # Add the log message handler to the logger
+   handler = logging.handlers.RotatingFileHandler(
+                 LOG_FILENAME, maxBytes=20, backupCount=5)
+
+   my_logger.addHandler(handler)
+
+   # Log some messages
+   for i in range(20):
+       my_logger.debug('i = %d' % i)
+
+   # See what files are created
+   logfiles = glob.glob('%s*' % LOG_FILENAME)
+
+   for filename in logfiles:
+       print(filename)
+
+The result should be 6 separate files, each with part of the log history for the
+application::
+
+   logging_rotatingfile_example.out
+   logging_rotatingfile_example.out.1
+   logging_rotatingfile_example.out.2
+   logging_rotatingfile_example.out.3
+   logging_rotatingfile_example.out.4
+   logging_rotatingfile_example.out.5
+
+The most current file is always :file:`logging_rotatingfile_example.out`,
+and each time it reaches the size limit it is renamed with the suffix
+``.1``. Each of the existing backup files is renamed to increment the suffix
+(``.1`` becomes ``.2``, etc.)  and the ``.6`` file is erased.
+
+Obviously this example sets the log length much much too small as an extreme
+example.  You would want to set *maxBytes* to an appropriate value.
+
+.. _zeromq-handlers:
+
+Subclassing QueueHandler
+------------------------
+
+You can use a :class:`QueueHandler` subclass to send messages to other kinds
+of queues, for example a ZeroMQ 'publish' socket. In the example below,the
+socket is created separately and passed to the handler (as its 'queue')::
+
+    import zmq # using pyzmq, the Python binding for ZeroMQ
+    import json # for serializing records portably
+
+    ctx = zmq.Context()
+    sock = zmq.Socket(ctx, zmq.PUB) # or zmq.PUSH, or other suitable value
+    sock.bind('tcp://*:5556') # or wherever
+
+    class ZeroMQSocketHandler(QueueHandler):
+        def enqueue(self, record):
+            data = json.dumps(record.__dict__)
+            self.queue.send(data)
+
+    handler = ZeroMQSocketHandler(sock)
+
+
+Of course there are other ways of organizing this, for example passing in the
+data needed by the handler to create the socket::
+
+    class ZeroMQSocketHandler(QueueHandler):
+        def __init__(self, uri, socktype=zmq.PUB, ctx=None):
+            self.ctx = ctx or zmq.Context()
+            socket = zmq.Socket(self.ctx, socktype)
+            socket.bind(uri)
+            QueueHandler.__init__(self, socket)
+
+        def enqueue(self, record):
+            data = json.dumps(record.__dict__)
+            self.queue.send(data)
+
+        def close(self):
+            self.queue.close()
+
+
+Subclassing QueueListener
+-------------------------
+
+You can also subclass :class:`QueueListener` to get messages from other kinds
+of queues, for example a ZeroMQ 'subscribe' socket. Here's an example::
+
+    class ZeroMQSocketListener(QueueListener):
+        def __init__(self, uri, *handlers, **kwargs):
+            self.ctx = kwargs.get('ctx') or zmq.Context()
+            socket = zmq.Socket(self.ctx, zmq.SUB)
+            socket.setsockopt(zmq.SUBSCRIBE, '') # subscribe to everything
+            socket.connect(uri)
+
+        def dequeue(self):
+            msg = self.queue.recv()
+            return logging.makeLogRecord(json.loads(msg))
+
+
+