1539 lines
59 KiB
ReStructuredText
1539 lines
59 KiB
ReStructuredText
.. _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.
|
|
|
|
.. currentmodule:: logging
|
|
|
|
Using logging in multiple modules
|
|
---------------------------------
|
|
|
|
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()
|
|
|
|
Logging from multiple threads
|
|
-----------------------------
|
|
|
|
Logging from multiple threads requires no special effort. The following example
|
|
shows logging from the main (initIal) thread and another thread::
|
|
|
|
import logging
|
|
import threading
|
|
import time
|
|
|
|
def worker(arg):
|
|
while not arg['stop']:
|
|
logging.debug('Hi from myfunc')
|
|
time.sleep(0.5)
|
|
|
|
def main():
|
|
logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')
|
|
info = {'stop': False}
|
|
thread = threading.Thread(target=worker, args=(info,))
|
|
thread.start()
|
|
while True:
|
|
try:
|
|
logging.debug('Hello from main')
|
|
time.sleep(0.75)
|
|
except KeyboardInterrupt:
|
|
info['stop'] = True
|
|
break
|
|
thread.join()
|
|
|
|
if __name__ == '__main__':
|
|
main()
|
|
|
|
When run, the script should print something like the following::
|
|
|
|
0 Thread-1 Hi from myfunc
|
|
3 MainThread Hello from main
|
|
505 Thread-1 Hi from myfunc
|
|
755 MainThread Hello from main
|
|
1007 Thread-1 Hi from myfunc
|
|
1507 MainThread Hello from main
|
|
1508 Thread-1 Hi from myfunc
|
|
2010 Thread-1 Hi from myfunc
|
|
2258 MainThread Hello from main
|
|
2512 Thread-1 Hi from myfunc
|
|
3009 MainThread Hello from main
|
|
3013 Thread-1 Hi from myfunc
|
|
3515 Thread-1 Hi from myfunc
|
|
3761 MainThread Hello from main
|
|
4017 Thread-1 Hi from myfunc
|
|
4513 MainThread Hello from main
|
|
4518 Thread-1 Hi from myfunc
|
|
|
|
This shows the logging output interspersed as one might expect. This approach
|
|
works for more threads than shown here, of course.
|
|
|
|
Multiple handlers and formatters
|
|
--------------------------------
|
|
|
|
Loggers are plain Python objects. The :meth:`~Logger.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
|
|
|
|
with open(sys.argv[1], 'rb') as f:
|
|
data_to_send = f.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')
|
|
|
|
|
|
.. _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:`~handlers.SocketHandler.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
|
|
----------------------------------------------------
|
|
|
|
.. currentmodule:: logging
|
|
|
|
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:`~LoggerAdapter.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:`~LoggerAdapter.process` to do what you need. Here is a simple example::
|
|
|
|
class CustomAdapter(logging.LoggerAdapter):
|
|
"""
|
|
This example adapter expects the passed in dict-like object to have a
|
|
'connid' key, whose value in brackets is prepended to the log message.
|
|
"""
|
|
def process(self, msg, kwargs):
|
|
return '[%s] %s' % (self.extra['connid'], msg), kwargs
|
|
|
|
which you can use like this::
|
|
|
|
logger = logging.getLogger(__name__)
|
|
adapter = CustomAdapter(logger, {'connid': some_conn_id})
|
|
|
|
Then any events that you log to the adapter will have the value of
|
|
``some_conn_id`` prepended to the log messages.
|
|
|
|
Using objects other than dicts to pass contextual information
|
|
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
|
|
|
|
You don't need to pass an actual dict to a :class:`LoggerAdapter` - you could
|
|
pass an instance of a class which implements ``__getitem__`` and ``__iter__`` so
|
|
that it looks like a dict to logging. This would be useful if you want to
|
|
generate values dynamically (whereas the values in a dict would be constant).
|
|
|
|
|
|
.. _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)
|
|
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:`~handlers.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.)
|
|
:ref:`This section <network-logging>` 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:`~multiprocessing.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
|
|
https://bugs.python.org/issue3770).
|
|
|
|
|
|
Using file rotation
|
|
-------------------
|
|
|
|
.. sectionauthor:: Doug Hellmann, Vinay Sajip (changes)
|
|
.. (see <https://pymotw.com/3/logging/>)
|
|
|
|
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 remain bounded. For this usage pattern, the
|
|
logging package provides a :class:`~handlers.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 too small as an extreme
|
|
example. You would want to set *maxBytes* to an appropriate value.
|
|
|
|
An example dictionary-based configuration
|
|
-----------------------------------------
|
|
|
|
Below is an example of a logging configuration dictionary - it's taken from
|
|
the `documentation on the Django project <https://docs.djangoproject.com/en/1.9/topics/logging/#configuring-logging>`_.
|
|
This dictionary is passed to :func:`~config.dictConfig` to put the configuration into effect::
|
|
|
|
LOGGING = {
|
|
'version': 1,
|
|
'disable_existing_loggers': True,
|
|
'formatters': {
|
|
'verbose': {
|
|
'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
|
|
},
|
|
'simple': {
|
|
'format': '%(levelname)s %(message)s'
|
|
},
|
|
},
|
|
'filters': {
|
|
'special': {
|
|
'()': 'project.logging.SpecialFilter',
|
|
'foo': 'bar',
|
|
}
|
|
},
|
|
'handlers': {
|
|
'null': {
|
|
'level':'DEBUG',
|
|
'class':'django.utils.log.NullHandler',
|
|
},
|
|
'console':{
|
|
'level':'DEBUG',
|
|
'class':'logging.StreamHandler',
|
|
'formatter': 'simple'
|
|
},
|
|
'mail_admins': {
|
|
'level': 'ERROR',
|
|
'class': 'django.utils.log.AdminEmailHandler',
|
|
'filters': ['special']
|
|
}
|
|
},
|
|
'loggers': {
|
|
'django': {
|
|
'handlers':['null'],
|
|
'propagate': True,
|
|
'level':'INFO',
|
|
},
|
|
'django.request': {
|
|
'handlers': ['mail_admins'],
|
|
'level': 'ERROR',
|
|
'propagate': False,
|
|
},
|
|
'myproject.custom': {
|
|
'handlers': ['console', 'mail_admins'],
|
|
'level': 'INFO',
|
|
'filters': ['special']
|
|
}
|
|
}
|
|
}
|
|
|
|
For more information about this configuration, you can see the `relevant
|
|
section <https://docs.djangoproject.com/en/1.9/topics/logging/#configuring-logging>`_
|
|
of the Django documentation.
|
|
|
|
Inserting a BOM into messages sent to a SysLogHandler
|
|
-----------------------------------------------------
|
|
|
|
`RFC 5424 <https://tools.ietf.org/html/rfc5424>`_ requires that a
|
|
Unicode message be sent to a syslog daemon as a set of bytes which have the
|
|
following structure: an optional pure-ASCII component, followed by a UTF-8 Byte
|
|
Order Mark (BOM), followed by Unicode encoded using UTF-8. (See the `relevant
|
|
section of the specification <https://tools.ietf.org/html/rfc5424#section-6>`_.)
|
|
|
|
In Python 2.6 and 2.7, code was added to
|
|
:class:`~logging.handlers.SysLogHandler` to insert a BOM into the message, but
|
|
unfortunately, it was implemented incorrectly, with the BOM appearing at the
|
|
beginning of the message and hence not allowing any pure-ASCII component to
|
|
appear before it.
|
|
|
|
As this behaviour is broken, the incorrect BOM insertion code is being removed
|
|
from Python 2.7.4 and later. However, it is not being replaced, and if you
|
|
want to produce RFC 5424-compliant messages which include a BOM, an optional
|
|
pure-ASCII sequence before it and arbitrary Unicode after it, encoded using
|
|
UTF-8, then you need to do the following:
|
|
|
|
#. Attach a :class:`~logging.Formatter` instance to your
|
|
:class:`~logging.handlers.SysLogHandler` instance, with a format string
|
|
such as::
|
|
|
|
u'ASCII section\ufeffUnicode section'
|
|
|
|
The Unicode code point ``u'\ufeff'``, when encoded using UTF-8, will be
|
|
encoded as a UTF-8 BOM -- the byte-string ``'\xef\xbb\xbf'``.
|
|
|
|
#. Replace the ASCII section with whatever placeholders you like, but make sure
|
|
that the data that appears in there after substitution is always ASCII (that
|
|
way, it will remain unchanged after UTF-8 encoding).
|
|
|
|
#. Replace the Unicode section with whatever placeholders you like; if the data
|
|
which appears there after substitution contains characters outside the ASCII
|
|
range, that's fine -- it will be encoded using UTF-8.
|
|
|
|
If the formatted message is Unicode, it *will* be encoded using UTF-8 encoding
|
|
by ``SysLogHandler``. If you follow the above rules, you should be able to
|
|
produce RFC 5424-compliant messages. If you don't, logging may not complain,
|
|
but your messages will not be RFC 5424-compliant, and your syslog daemon may
|
|
complain.
|
|
|
|
|
|
Implementing structured logging
|
|
-------------------------------
|
|
|
|
Although most logging messages are intended for reading by humans, and thus not
|
|
readily machine-parseable, there might be circumstances where you want to output
|
|
messages in a structured format which *is* capable of being parsed by a program
|
|
(without needing complex regular expressions to parse the log message). This is
|
|
straightforward to achieve using the logging package. There are a number of
|
|
ways in which this could be achieved, but the following is a simple approach
|
|
which uses JSON to serialise the event in a machine-parseable manner::
|
|
|
|
import json
|
|
import logging
|
|
|
|
class StructuredMessage(object):
|
|
def __init__(self, message, **kwargs):
|
|
self.message = message
|
|
self.kwargs = kwargs
|
|
|
|
def __str__(self):
|
|
return '%s >>> %s' % (self.message, json.dumps(self.kwargs))
|
|
|
|
_ = StructuredMessage # optional, to improve readability
|
|
|
|
logging.basicConfig(level=logging.INFO, format='%(message)s')
|
|
logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))
|
|
|
|
If the above script is run, it prints::
|
|
|
|
message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}
|
|
|
|
Note that the order of items might be different according to the version of
|
|
Python used.
|
|
|
|
If you need more specialised processing, you can use a custom JSON encoder,
|
|
as in the following complete example::
|
|
|
|
from __future__ import unicode_literals
|
|
|
|
import json
|
|
import logging
|
|
|
|
# This next bit is to ensure the script runs unchanged on 2.x and 3.x
|
|
try:
|
|
unicode
|
|
except NameError:
|
|
unicode = str
|
|
|
|
class Encoder(json.JSONEncoder):
|
|
def default(self, o):
|
|
if isinstance(o, set):
|
|
return tuple(o)
|
|
elif isinstance(o, unicode):
|
|
return o.encode('unicode_escape').decode('ascii')
|
|
return super(Encoder, self).default(o)
|
|
|
|
class StructuredMessage(object):
|
|
def __init__(self, message, **kwargs):
|
|
self.message = message
|
|
self.kwargs = kwargs
|
|
|
|
def __str__(self):
|
|
s = Encoder().encode(self.kwargs)
|
|
return '%s >>> %s' % (self.message, s)
|
|
|
|
_ = StructuredMessage # optional, to improve readability
|
|
|
|
def main():
|
|
logging.basicConfig(level=logging.INFO, format='%(message)s')
|
|
logging.info(_('message 1', set_value=set([1, 2, 3]), snowman='\u2603'))
|
|
|
|
if __name__ == '__main__':
|
|
main()
|
|
|
|
When the above script is run, it prints::
|
|
|
|
message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}
|
|
|
|
Note that the order of items might be different according to the version of
|
|
Python used.
|
|
|
|
|
|
.. _custom-handlers:
|
|
|
|
.. currentmodule:: logging.config
|
|
|
|
Customizing handlers with :func:`dictConfig`
|
|
--------------------------------------------
|
|
|
|
There are times when you want to customize logging handlers in particular ways,
|
|
and if you use :func:`dictConfig` you may be able to do this without
|
|
subclassing. As an example, consider that you may want to set the ownership of a
|
|
log file. On POSIX, this is easily done using :func:`os.chown`, but the file
|
|
handlers in the stdlib don't offer built-in support. You can customize handler
|
|
creation using a plain function such as::
|
|
|
|
def owned_file_handler(filename, mode='a', encoding=None, owner=None):
|
|
if owner:
|
|
import os, pwd, grp
|
|
# convert user and group names to uid and gid
|
|
uid = pwd.getpwnam(owner[0]).pw_uid
|
|
gid = grp.getgrnam(owner[1]).gr_gid
|
|
owner = (uid, gid)
|
|
if not os.path.exists(filename):
|
|
open(filename, 'a').close()
|
|
os.chown(filename, *owner)
|
|
return logging.FileHandler(filename, mode, encoding)
|
|
|
|
You can then specify, in a logging configuration passed to :func:`dictConfig`,
|
|
that a logging handler be created by calling this function::
|
|
|
|
LOGGING = {
|
|
'version': 1,
|
|
'disable_existing_loggers': False,
|
|
'formatters': {
|
|
'default': {
|
|
'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
|
|
},
|
|
},
|
|
'handlers': {
|
|
'file':{
|
|
# The values below are popped from this dictionary and
|
|
# used to create the handler, set the handler's level and
|
|
# its formatter.
|
|
'()': owned_file_handler,
|
|
'level':'DEBUG',
|
|
'formatter': 'default',
|
|
# The values below are passed to the handler creator callable
|
|
# as keyword arguments.
|
|
'owner': ['pulse', 'pulse'],
|
|
'filename': 'chowntest.log',
|
|
'mode': 'w',
|
|
'encoding': 'utf-8',
|
|
},
|
|
},
|
|
'root': {
|
|
'handlers': ['file'],
|
|
'level': 'DEBUG',
|
|
},
|
|
}
|
|
|
|
In this example I am setting the ownership using the ``pulse`` user and group,
|
|
just for the purposes of illustration. Putting it together into a working
|
|
script, ``chowntest.py``::
|
|
|
|
import logging, logging.config, os, shutil
|
|
|
|
def owned_file_handler(filename, mode='a', encoding=None, owner=None):
|
|
if owner:
|
|
if not os.path.exists(filename):
|
|
open(filename, 'a').close()
|
|
shutil.chown(filename, *owner)
|
|
return logging.FileHandler(filename, mode, encoding)
|
|
|
|
LOGGING = {
|
|
'version': 1,
|
|
'disable_existing_loggers': False,
|
|
'formatters': {
|
|
'default': {
|
|
'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
|
|
},
|
|
},
|
|
'handlers': {
|
|
'file':{
|
|
# The values below are popped from this dictionary and
|
|
# used to create the handler, set the handler's level and
|
|
# its formatter.
|
|
'()': owned_file_handler,
|
|
'level':'DEBUG',
|
|
'formatter': 'default',
|
|
# The values below are passed to the handler creator callable
|
|
# as keyword arguments.
|
|
'owner': ['pulse', 'pulse'],
|
|
'filename': 'chowntest.log',
|
|
'mode': 'w',
|
|
'encoding': 'utf-8',
|
|
},
|
|
},
|
|
'root': {
|
|
'handlers': ['file'],
|
|
'level': 'DEBUG',
|
|
},
|
|
}
|
|
|
|
logging.config.dictConfig(LOGGING)
|
|
logger = logging.getLogger('mylogger')
|
|
logger.debug('A debug message')
|
|
|
|
To run this, you will probably need to run as ``root``:
|
|
|
|
.. code-block:: shell-session
|
|
|
|
$ sudo python3.3 chowntest.py
|
|
$ cat chowntest.log
|
|
2013-11-05 09:34:51,128 DEBUG mylogger A debug message
|
|
$ ls -l chowntest.log
|
|
-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log
|
|
|
|
Note that this example uses Python 3.3 because that's where :func:`shutil.chown`
|
|
makes an appearance. This approach should work with any Python version that
|
|
supports :func:`dictConfig` - namely, Python 2.7, 3.2 or later. With pre-3.3
|
|
versions, you would need to implement the actual ownership change using e.g.
|
|
:func:`os.chown`.
|
|
|
|
In practice, the handler-creating function may be in a utility module somewhere
|
|
in your project. Instead of the line in the configuration::
|
|
|
|
'()': owned_file_handler,
|
|
|
|
you could use e.g.::
|
|
|
|
'()': 'ext://project.util.owned_file_handler',
|
|
|
|
where ``project.util`` can be replaced with the actual name of the package
|
|
where the function resides. In the above working script, using
|
|
``'ext://__main__.owned_file_handler'`` should work. Here, the actual callable
|
|
is resolved by :func:`dictConfig` from the ``ext://`` specification.
|
|
|
|
This example hopefully also points the way to how you could implement other
|
|
types of file change - e.g. setting specific POSIX permission bits - in the
|
|
same way, using :func:`os.chmod`.
|
|
|
|
Of course, the approach could also be extended to types of handler other than a
|
|
:class:`~logging.FileHandler` - for example, one of the rotating file handlers,
|
|
or a different type of handler altogether.
|
|
|
|
|
|
.. _filters-dictconfig:
|
|
|
|
Configuring filters with :func:`dictConfig`
|
|
-------------------------------------------
|
|
|
|
You *can* configure filters using :func:`~logging.config.dictConfig`, though it
|
|
might not be obvious at first glance how to do it (hence this recipe). Since
|
|
:class:`~logging.Filter` is the only filter class included in the standard
|
|
library, and it is unlikely to cater to many requirements (it's only there as a
|
|
base class), you will typically need to define your own :class:`~logging.Filter`
|
|
subclass with an overridden :meth:`~logging.Filter.filter` method. To do this,
|
|
specify the ``()`` key in the configuration dictionary for the filter,
|
|
specifying a callable which will be used to create the filter (a class is the
|
|
most obvious, but you can provide any callable which returns a
|
|
:class:`~logging.Filter` instance). Here is a complete example::
|
|
|
|
import logging
|
|
import logging.config
|
|
import sys
|
|
|
|
class MyFilter(logging.Filter):
|
|
def __init__(self, param=None):
|
|
self.param = param
|
|
|
|
def filter(self, record):
|
|
if self.param is None:
|
|
allow = True
|
|
else:
|
|
allow = self.param not in record.msg
|
|
if allow:
|
|
record.msg = 'changed: ' + record.msg
|
|
return allow
|
|
|
|
LOGGING = {
|
|
'version': 1,
|
|
'filters': {
|
|
'myfilter': {
|
|
'()': MyFilter,
|
|
'param': 'noshow',
|
|
}
|
|
},
|
|
'handlers': {
|
|
'console': {
|
|
'class': 'logging.StreamHandler',
|
|
'filters': ['myfilter']
|
|
}
|
|
},
|
|
'root': {
|
|
'level': 'DEBUG',
|
|
'handlers': ['console']
|
|
},
|
|
}
|
|
|
|
if __name__ == '__main__':
|
|
logging.config.dictConfig(LOGGING)
|
|
logging.debug('hello')
|
|
logging.debug('hello - noshow')
|
|
|
|
This example shows how you can pass configuration data to the callable which
|
|
constructs the instance, in the form of keyword parameters. When run, the above
|
|
script will print::
|
|
|
|
changed: hello
|
|
|
|
which shows that the filter is working as configured.
|
|
|
|
A couple of extra points to note:
|
|
|
|
* If you can't refer to the callable directly in the configuration (e.g. if it
|
|
lives in a different module, and you can't import it directly where the
|
|
configuration dictionary is), you can use the form ``ext://...`` as described
|
|
in :ref:`logging-config-dict-externalobj`. For example, you could have used
|
|
the text ``'ext://__main__.MyFilter'`` instead of ``MyFilter`` in the above
|
|
example.
|
|
|
|
* As well as for filters, this technique can also be used to configure custom
|
|
handlers and formatters. See :ref:`logging-config-dict-userdef` for more
|
|
information on how logging supports using user-defined objects in its
|
|
configuration, and see the other cookbook recipe :ref:`custom-handlers` above.
|
|
|
|
|
|
.. _custom-format-exception:
|
|
|
|
Customized exception formatting
|
|
-------------------------------
|
|
|
|
There might be times when you want to do customized exception formatting - for
|
|
argument's sake, let's say you want exactly one line per logged event, even
|
|
when exception information is present. You can do this with a custom formatter
|
|
class, as shown in the following example::
|
|
|
|
import logging
|
|
|
|
class OneLineExceptionFormatter(logging.Formatter):
|
|
def formatException(self, exc_info):
|
|
"""
|
|
Format an exception so that it prints on a single line.
|
|
"""
|
|
result = super(OneLineExceptionFormatter, self).formatException(exc_info)
|
|
return repr(result) # or format into one line however you want to
|
|
|
|
def format(self, record):
|
|
s = super(OneLineExceptionFormatter, self).format(record)
|
|
if record.exc_text:
|
|
s = s.replace('\n', '') + '|'
|
|
return s
|
|
|
|
def configure_logging():
|
|
fh = logging.FileHandler('output.txt', 'w')
|
|
f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',
|
|
'%d/%m/%Y %H:%M:%S')
|
|
fh.setFormatter(f)
|
|
root = logging.getLogger()
|
|
root.setLevel(logging.DEBUG)
|
|
root.addHandler(fh)
|
|
|
|
def main():
|
|
configure_logging()
|
|
logging.info('Sample message')
|
|
try:
|
|
x = 1 / 0
|
|
except ZeroDivisionError as e:
|
|
logging.exception('ZeroDivisionError: %s', e)
|
|
|
|
if __name__ == '__main__':
|
|
main()
|
|
|
|
When run, this produces a file with exactly two lines::
|
|
|
|
28/01/2015 07:21:23|INFO|Sample message|
|
|
28/01/2015 07:21:23|ERROR|ZeroDivisionError: integer division or modulo by zero|'Traceback (most recent call last):\n File "logtest7.py", line 30, in main\n x = 1 / 0\nZeroDivisionError: integer division or modulo by zero'|
|
|
|
|
While the above treatment is simplistic, it points the way to how exception
|
|
information can be formatted to your liking. The :mod:`traceback` module may be
|
|
helpful for more specialized needs.
|
|
|
|
.. _spoken-messages:
|
|
|
|
Speaking logging messages
|
|
-------------------------
|
|
|
|
There might be situations when it is desirable to have logging messages rendered
|
|
in an audible rather than a visible format. This is easy to do if you have
|
|
text-to-speech (TTS) functionality available in your system, even if it doesn't have
|
|
a Python binding. Most TTS systems have a command line program you can run, and
|
|
this can be invoked from a handler using :mod:`subprocess`. It's assumed here
|
|
that TTS command line programs won't expect to interact with users or take a
|
|
long time to complete, and that the frequency of logged messages will be not so
|
|
high as to swamp the user with messages, and that it's acceptable to have the
|
|
messages spoken one at a time rather than concurrently, The example implementation
|
|
below waits for one message to be spoken before the next is processed, and this
|
|
might cause other handlers to be kept waiting. Here is a short example showing
|
|
the approach, which assumes that the ``espeak`` TTS package is available::
|
|
|
|
import logging
|
|
import subprocess
|
|
import sys
|
|
|
|
class TTSHandler(logging.Handler):
|
|
def emit(self, record):
|
|
msg = self.format(record)
|
|
# Speak slowly in a female English voice
|
|
cmd = ['espeak', '-s150', '-ven+f3', msg]
|
|
p = subprocess.Popen(cmd, stdout=subprocess.PIPE,
|
|
stderr=subprocess.STDOUT)
|
|
# wait for the program to finish
|
|
p.communicate()
|
|
|
|
def configure_logging():
|
|
h = TTSHandler()
|
|
root = logging.getLogger()
|
|
root.addHandler(h)
|
|
# the default formatter just returns the message
|
|
root.setLevel(logging.DEBUG)
|
|
|
|
def main():
|
|
logging.info('Hello')
|
|
logging.debug('Goodbye')
|
|
|
|
if __name__ == '__main__':
|
|
configure_logging()
|
|
sys.exit(main())
|
|
|
|
When run, this script should say "Hello" and then "Goodbye" in a female voice.
|
|
|
|
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 at 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):
|
|
...
|
|
|
|
|
|
.. _utc-formatting:
|
|
|
|
Formatting times using UTC (GMT) via configuration
|
|
--------------------------------------------------
|
|
|
|
Sometimes you want to format times using UTC, which can be done using a class
|
|
such as `UTCFormatter`, shown below::
|
|
|
|
import logging
|
|
import time
|
|
|
|
class UTCFormatter(logging.Formatter):
|
|
converter = time.gmtime
|
|
|
|
and you can then use the ``UTCFormatter`` in your code instead of
|
|
:class:`~logging.Formatter`. If you want to do that via configuration, you can
|
|
use the :func:`~logging.config.dictConfig` API with an approach illustrated by
|
|
the following complete example::
|
|
|
|
import logging
|
|
import logging.config
|
|
import time
|
|
|
|
class UTCFormatter(logging.Formatter):
|
|
converter = time.gmtime
|
|
|
|
LOGGING = {
|
|
'version': 1,
|
|
'disable_existing_loggers': False,
|
|
'formatters': {
|
|
'utc': {
|
|
'()': UTCFormatter,
|
|
'format': '%(asctime)s %(message)s',
|
|
},
|
|
'local': {
|
|
'format': '%(asctime)s %(message)s',
|
|
}
|
|
},
|
|
'handlers': {
|
|
'console1': {
|
|
'class': 'logging.StreamHandler',
|
|
'formatter': 'utc',
|
|
},
|
|
'console2': {
|
|
'class': 'logging.StreamHandler',
|
|
'formatter': 'local',
|
|
},
|
|
},
|
|
'root': {
|
|
'handlers': ['console1', 'console2'],
|
|
}
|
|
}
|
|
|
|
if __name__ == '__main__':
|
|
logging.config.dictConfig(LOGGING)
|
|
logging.warning('The local time is %s', time.asctime())
|
|
|
|
When this script is run, it should print something like::
|
|
|
|
2015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 2015
|
|
2015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 2015
|
|
|
|
showing how the time is formatted both as local time and UTC, one for each
|
|
handler.
|
|
|
|
|
|
.. _context-manager:
|
|
|
|
Using a context manager for selective logging
|
|
---------------------------------------------
|
|
|
|
There are times when it would be useful to temporarily change the logging
|
|
configuration and revert it back after doing something. For this, a context
|
|
manager is the most obvious way of saving and restoring the logging context.
|
|
Here is a simple example of such a context manager, which allows you to
|
|
optionally change the logging level and add a logging handler purely in the
|
|
scope of the context manager::
|
|
|
|
import logging
|
|
import sys
|
|
|
|
class LoggingContext(object):
|
|
def __init__(self, logger, level=None, handler=None, close=True):
|
|
self.logger = logger
|
|
self.level = level
|
|
self.handler = handler
|
|
self.close = close
|
|
|
|
def __enter__(self):
|
|
if self.level is not None:
|
|
self.old_level = self.logger.level
|
|
self.logger.setLevel(self.level)
|
|
if self.handler:
|
|
self.logger.addHandler(self.handler)
|
|
|
|
def __exit__(self, et, ev, tb):
|
|
if self.level is not None:
|
|
self.logger.setLevel(self.old_level)
|
|
if self.handler:
|
|
self.logger.removeHandler(self.handler)
|
|
if self.handler and self.close:
|
|
self.handler.close()
|
|
# implicit return of None => don't swallow exceptions
|
|
|
|
If you specify a level value, the logger's level is set to that value in the
|
|
scope of the with block covered by the context manager. If you specify a
|
|
handler, it is added to the logger on entry to the block and removed on exit
|
|
from the block. You can also ask the manager to close the handler for you on
|
|
block exit - you could do this if you don't need the handler any more.
|
|
|
|
To illustrate how it works, we can add the following block of code to the
|
|
above::
|
|
|
|
if __name__ == '__main__':
|
|
logger = logging.getLogger('foo')
|
|
logger.addHandler(logging.StreamHandler())
|
|
logger.setLevel(logging.INFO)
|
|
logger.info('1. This should appear just once on stderr.')
|
|
logger.debug('2. This should not appear.')
|
|
with LoggingContext(logger, level=logging.DEBUG):
|
|
logger.debug('3. This should appear once on stderr.')
|
|
logger.debug('4. This should not appear.')
|
|
h = logging.StreamHandler(sys.stdout)
|
|
with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):
|
|
logger.debug('5. This should appear twice - once on stderr and once on stdout.')
|
|
logger.info('6. This should appear just once on stderr.')
|
|
logger.debug('7. This should not appear.')
|
|
|
|
We initially set the logger's level to ``INFO``, so message #1 appears and
|
|
message #2 doesn't. We then change the level to ``DEBUG`` temporarily in the
|
|
following ``with`` block, and so message #3 appears. After the block exits, the
|
|
logger's level is restored to ``INFO`` and so message #4 doesn't appear. In the
|
|
next ``with`` block, we set the level to ``DEBUG`` again but also add a handler
|
|
writing to ``sys.stdout``. Thus, message #5 appears twice on the console (once
|
|
via ``stderr`` and once via ``stdout``). After the ``with`` statement's
|
|
completion, the status is as it was before so message #6 appears (like message
|
|
#1) whereas message #7 doesn't (just like message #2).
|
|
|
|
If we run the resulting script, the result is as follows:
|
|
|
|
.. code-block:: shell-session
|
|
|
|
$ python logctx.py
|
|
1. This should appear just once on stderr.
|
|
3. This should appear once on stderr.
|
|
5. This should appear twice - once on stderr and once on stdout.
|
|
5. This should appear twice - once on stderr and once on stdout.
|
|
6. This should appear just once on stderr.
|
|
|
|
If we run it again, but pipe ``stderr`` to ``/dev/null``, we see the following,
|
|
which is the only message written to ``stdout``:
|
|
|
|
.. code-block:: shell-session
|
|
|
|
$ python logctx.py 2>/dev/null
|
|
5. This should appear twice - once on stderr and once on stdout.
|
|
|
|
Once again, but piping ``stdout`` to ``/dev/null``, we get:
|
|
|
|
.. code-block:: shell-session
|
|
|
|
$ python logctx.py >/dev/null
|
|
1. This should appear just once on stderr.
|
|
3. This should appear once on stderr.
|
|
5. This should appear twice - once on stderr and once on stdout.
|
|
6. This should appear just once on stderr.
|
|
|
|
In this case, the message #5 printed to ``stdout`` doesn't appear, as expected.
|
|
|
|
Of course, the approach described here can be generalised, for example to attach
|
|
logging filters temporarily. Note that the above code works in Python 2 as well
|
|
as Python 3.
|