Logging documentation reorganised.
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))
+
+
+