1.. _logging-cookbook:
2
3================
4Logging Cookbook
5================
6
7:Author: Vinay Sajip <vinay_sajip at red-dove dot com>
8
9This page contains a number of recipes related to logging, which have been found
10useful in the past. For links to tutorial and reference information, please see
11:ref:`cookbook-ref-links`.
12
13.. currentmodule:: logging
14
15Using logging in multiple modules
16---------------------------------
17
18Multiple calls to ``logging.getLogger('someLogger')`` return a reference to the
19same logger object.  This is true not only within the same module, but also
20across modules as long as it is in the same Python interpreter process.  It is
21true for references to the same object; additionally, application code can
22define and configure a parent logger in one module and create (but not
23configure) a child logger in a separate module, and all logger calls to the
24child will pass up to the parent.  Here is a main module::
25
26    import logging
27    import auxiliary_module
28
29    # create logger with 'spam_application'
30    logger = logging.getLogger('spam_application')
31    logger.setLevel(logging.DEBUG)
32    # create file handler which logs even debug messages
33    fh = logging.FileHandler('spam.log')
34    fh.setLevel(logging.DEBUG)
35    # create console handler with a higher log level
36    ch = logging.StreamHandler()
37    ch.setLevel(logging.ERROR)
38    # create formatter and add it to the handlers
39    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
40    fh.setFormatter(formatter)
41    ch.setFormatter(formatter)
42    # add the handlers to the logger
43    logger.addHandler(fh)
44    logger.addHandler(ch)
45
46    logger.info('creating an instance of auxiliary_module.Auxiliary')
47    a = auxiliary_module.Auxiliary()
48    logger.info('created an instance of auxiliary_module.Auxiliary')
49    logger.info('calling auxiliary_module.Auxiliary.do_something')
50    a.do_something()
51    logger.info('finished auxiliary_module.Auxiliary.do_something')
52    logger.info('calling auxiliary_module.some_function()')
53    auxiliary_module.some_function()
54    logger.info('done with auxiliary_module.some_function()')
55
56Here is the auxiliary module::
57
58    import logging
59
60    # create logger
61    module_logger = logging.getLogger('spam_application.auxiliary')
62
63    class Auxiliary:
64        def __init__(self):
65            self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
66            self.logger.info('creating an instance of Auxiliary')
67
68        def do_something(self):
69            self.logger.info('doing something')
70            a = 1 + 1
71            self.logger.info('done doing something')
72
73    def some_function():
74        module_logger.info('received a call to "some_function"')
75
76The output looks like this:
77
78.. code-block:: none
79
80    2005-03-23 23:47:11,663 - spam_application - INFO -
81       creating an instance of auxiliary_module.Auxiliary
82    2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -
83       creating an instance of Auxiliary
84    2005-03-23 23:47:11,665 - spam_application - INFO -
85       created an instance of auxiliary_module.Auxiliary
86    2005-03-23 23:47:11,668 - spam_application - INFO -
87       calling auxiliary_module.Auxiliary.do_something
88    2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -
89       doing something
90    2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -
91       done doing something
92    2005-03-23 23:47:11,670 - spam_application - INFO -
93       finished auxiliary_module.Auxiliary.do_something
94    2005-03-23 23:47:11,671 - spam_application - INFO -
95       calling auxiliary_module.some_function()
96    2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -
97       received a call to 'some_function'
98    2005-03-23 23:47:11,673 - spam_application - INFO -
99       done with auxiliary_module.some_function()
100
101Logging from multiple threads
102-----------------------------
103
104Logging from multiple threads requires no special effort. The following example
105shows logging from the main (initial) thread and another thread::
106
107    import logging
108    import threading
109    import time
110
111    def worker(arg):
112        while not arg['stop']:
113            logging.debug('Hi from myfunc')
114            time.sleep(0.5)
115
116    def main():
117        logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')
118        info = {'stop': False}
119        thread = threading.Thread(target=worker, args=(info,))
120        thread.start()
121        while True:
122            try:
123                logging.debug('Hello from main')
124                time.sleep(0.75)
125            except KeyboardInterrupt:
126                info['stop'] = True
127                break
128        thread.join()
129
130    if __name__ == '__main__':
131        main()
132
133When run, the script should print something like the following:
134
135.. code-block:: none
136
137     0 Thread-1 Hi from myfunc
138     3 MainThread Hello from main
139   505 Thread-1 Hi from myfunc
140   755 MainThread Hello from main
141  1007 Thread-1 Hi from myfunc
142  1507 MainThread Hello from main
143  1508 Thread-1 Hi from myfunc
144  2010 Thread-1 Hi from myfunc
145  2258 MainThread Hello from main
146  2512 Thread-1 Hi from myfunc
147  3009 MainThread Hello from main
148  3013 Thread-1 Hi from myfunc
149  3515 Thread-1 Hi from myfunc
150  3761 MainThread Hello from main
151  4017 Thread-1 Hi from myfunc
152  4513 MainThread Hello from main
153  4518 Thread-1 Hi from myfunc
154
155This shows the logging output interspersed as one might expect. This approach
156works for more threads than shown here, of course.
157
158Multiple handlers and formatters
159--------------------------------
160
161Loggers are plain Python objects.  The :meth:`~Logger.addHandler` method has no
162minimum or maximum quota for the number of handlers you may add.  Sometimes it
163will be beneficial for an application to log all messages of all severities to a
164text file while simultaneously logging errors or above to the console.  To set
165this up, simply configure the appropriate handlers.  The logging calls in the
166application code will remain unchanged.  Here is a slight modification to the
167previous simple module-based configuration example::
168
169    import logging
170
171    logger = logging.getLogger('simple_example')
172    logger.setLevel(logging.DEBUG)
173    # create file handler which logs even debug messages
174    fh = logging.FileHandler('spam.log')
175    fh.setLevel(logging.DEBUG)
176    # create console handler with a higher log level
177    ch = logging.StreamHandler()
178    ch.setLevel(logging.ERROR)
179    # create formatter and add it to the handlers
180    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
181    ch.setFormatter(formatter)
182    fh.setFormatter(formatter)
183    # add the handlers to logger
184    logger.addHandler(ch)
185    logger.addHandler(fh)
186
187    # 'application' code
188    logger.debug('debug message')
189    logger.info('info message')
190    logger.warning('warn message')
191    logger.error('error message')
192    logger.critical('critical message')
193
194Notice that the 'application' code does not care about multiple handlers.  All
195that changed was the addition and configuration of a new handler named *fh*.
196
197The ability to create new handlers with higher- or lower-severity filters can be
198very helpful when writing and testing an application.  Instead of using many
199``print`` statements for debugging, use ``logger.debug``: Unlike the print
200statements, which you will have to delete or comment out later, the logger.debug
201statements can remain intact in the source code and remain dormant until you
202need them again.  At that time, the only change that needs to happen is to
203modify the severity level of the logger and/or handler to debug.
204
205.. _multiple-destinations:
206
207Logging to multiple destinations
208--------------------------------
209
210Let's say you want to log to console and file with different message formats and
211in differing circumstances. Say you want to log messages with levels of DEBUG
212and higher to file, and those messages at level INFO and higher to the console.
213Let's also assume that the file should contain timestamps, but the console
214messages should not. Here's how you can achieve this::
215
216   import logging
217
218   # set up logging to file - see previous section for more details
219   logging.basicConfig(level=logging.DEBUG,
220                       format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
221                       datefmt='%m-%d %H:%M',
222                       filename='/tmp/myapp.log',
223                       filemode='w')
224   # define a Handler which writes INFO messages or higher to the sys.stderr
225   console = logging.StreamHandler()
226   console.setLevel(logging.INFO)
227   # set a format which is simpler for console use
228   formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
229   # tell the handler to use this format
230   console.setFormatter(formatter)
231   # add the handler to the root logger
232   logging.getLogger('').addHandler(console)
233
234   # Now, we can log to the root logger, or any other logger. First the root...
235   logging.info('Jackdaws love my big sphinx of quartz.')
236
237   # Now, define a couple of other loggers which might represent areas in your
238   # application:
239
240   logger1 = logging.getLogger('myapp.area1')
241   logger2 = logging.getLogger('myapp.area2')
242
243   logger1.debug('Quick zephyrs blow, vexing daft Jim.')
244   logger1.info('How quickly daft jumping zebras vex.')
245   logger2.warning('Jail zesty vixen who grabbed pay from quack.')
246   logger2.error('The five boxing wizards jump quickly.')
247
248When you run this, on the console you will see
249
250.. code-block:: none
251
252   root        : INFO     Jackdaws love my big sphinx of quartz.
253   myapp.area1 : INFO     How quickly daft jumping zebras vex.
254   myapp.area2 : WARNING  Jail zesty vixen who grabbed pay from quack.
255   myapp.area2 : ERROR    The five boxing wizards jump quickly.
256
257and in the file you will see something like
258
259.. code-block:: none
260
261   10-22 22:19 root         INFO     Jackdaws love my big sphinx of quartz.
262   10-22 22:19 myapp.area1  DEBUG    Quick zephyrs blow, vexing daft Jim.
263   10-22 22:19 myapp.area1  INFO     How quickly daft jumping zebras vex.
264   10-22 22:19 myapp.area2  WARNING  Jail zesty vixen who grabbed pay from quack.
265   10-22 22:19 myapp.area2  ERROR    The five boxing wizards jump quickly.
266
267As you can see, the DEBUG message only shows up in the file. The other messages
268are sent to both destinations.
269
270This example uses console and file handlers, but you can use any number and
271combination of handlers you choose.
272
273Note that the above choice of log filename ``/tmp/myapp.log`` implies use of a
274standard location for temporary files on POSIX systems. On Windows, you may need to
275choose a different directory name for the log - just ensure that the directory exists
276and that you have the permissions to create and update files in it.
277
278
279.. _custom-level-handling:
280
281Custom handling of levels
282-------------------------
283
284Sometimes, you might want to do something slightly different from the standard
285handling of levels in handlers, where all levels above a threshold get
286processed by a handler. To do this, you need to use filters. Let's look at a
287scenario where you want to arrange things as follows:
288
289* Send messages of severity ``INFO`` and ``WARNING`` to ``sys.stdout``
290* Send messages of severity ``ERROR`` and above to ``sys.stderr``
291* Send messages of severity ``DEBUG`` and above to file ``app.log``
292
293Suppose you configure logging with the following JSON:
294
295.. code-block:: json
296
297    {
298        "version": 1,
299        "disable_existing_loggers": false,
300        "formatters": {
301            "simple": {
302                "format": "%(levelname)-8s - %(message)s"
303            }
304        },
305        "handlers": {
306            "stdout": {
307                "class": "logging.StreamHandler",
308                "level": "INFO",
309                "formatter": "simple",
310                "stream": "ext://sys.stdout"
311            },
312            "stderr": {
313                "class": "logging.StreamHandler",
314                "level": "ERROR",
315                "formatter": "simple",
316                "stream": "ext://sys.stderr"
317            },
318            "file": {
319                "class": "logging.FileHandler",
320                "formatter": "simple",
321                "filename": "app.log",
322                "mode": "w"
323            }
324        },
325        "root": {
326            "level": "DEBUG",
327            "handlers": [
328                "stderr",
329                "stdout",
330                "file"
331            ]
332        }
333    }
334
335This configuration does *almost* what we want, except that ``sys.stdout`` would
336show messages of severity ``ERROR`` and above as well as ``INFO`` and
337``WARNING`` messages. To prevent this, we can set up a filter which excludes
338those messages and add it to the relevant handler. This can be configured by
339adding a ``filters`` section parallel to ``formatters`` and ``handlers``:
340
341.. code-block:: json
342
343    {
344        "filters": {
345            "warnings_and_below": {
346                "()" : "__main__.filter_maker",
347                "level": "WARNING"
348            }
349        }
350    }
351
352and changing the section on the ``stdout`` handler to add it:
353
354.. code-block:: json
355
356    {
357        "stdout": {
358            "class": "logging.StreamHandler",
359            "level": "INFO",
360            "formatter": "simple",
361            "stream": "ext://sys.stdout",
362            "filters": ["warnings_and_below"]
363        }
364    }
365
366A filter is just a function, so we can define the ``filter_maker`` (a factory
367function) as follows:
368
369.. code-block:: python
370
371    def filter_maker(level):
372        level = getattr(logging, level)
373
374        def filter(record):
375            return record.levelno <= level
376
377        return filter
378
379This converts the string argument passed in to a numeric level, and returns a
380function which only returns ``True`` if the level of the passed in record is
381at or below the specified level. Note that in this example I have defined the
382``filter_maker`` in a test script ``main.py`` that I run from the command line,
383so its module will be ``__main__`` - hence the ``__main__.filter_maker`` in the
384filter configuration. You will need to change that if you define it in a
385different module.
386
387With the filter added, we can run ``main.py``, which in full is:
388
389.. code-block:: python
390
391    import json
392    import logging
393    import logging.config
394
395    CONFIG = '''
396    {
397        "version": 1,
398        "disable_existing_loggers": false,
399        "formatters": {
400            "simple": {
401                "format": "%(levelname)-8s - %(message)s"
402            }
403        },
404        "filters": {
405            "warnings_and_below": {
406                "()" : "__main__.filter_maker",
407                "level": "WARNING"
408            }
409        },
410        "handlers": {
411            "stdout": {
412                "class": "logging.StreamHandler",
413                "level": "INFO",
414                "formatter": "simple",
415                "stream": "ext://sys.stdout",
416                "filters": ["warnings_and_below"]
417            },
418            "stderr": {
419                "class": "logging.StreamHandler",
420                "level": "ERROR",
421                "formatter": "simple",
422                "stream": "ext://sys.stderr"
423            },
424            "file": {
425                "class": "logging.FileHandler",
426                "formatter": "simple",
427                "filename": "app.log",
428                "mode": "w"
429            }
430        },
431        "root": {
432            "level": "DEBUG",
433            "handlers": [
434                "stderr",
435                "stdout",
436                "file"
437            ]
438        }
439    }
440    '''
441
442    def filter_maker(level):
443        level = getattr(logging, level)
444
445        def filter(record):
446            return record.levelno <= level
447
448        return filter
449
450    logging.config.dictConfig(json.loads(CONFIG))
451    logging.debug('A DEBUG message')
452    logging.info('An INFO message')
453    logging.warning('A WARNING message')
454    logging.error('An ERROR message')
455    logging.critical('A CRITICAL message')
456
457And after running it like this:
458
459.. code-block:: shell
460
461    python main.py 2>stderr.log >stdout.log
462
463We can see the results are as expected:
464
465.. code-block:: shell
466
467    $ more *.log
468    ::::::::::::::
469    app.log
470    ::::::::::::::
471    DEBUG    - A DEBUG message
472    INFO     - An INFO message
473    WARNING  - A WARNING message
474    ERROR    - An ERROR message
475    CRITICAL - A CRITICAL message
476    ::::::::::::::
477    stderr.log
478    ::::::::::::::
479    ERROR    - An ERROR message
480    CRITICAL - A CRITICAL message
481    ::::::::::::::
482    stdout.log
483    ::::::::::::::
484    INFO     - An INFO message
485    WARNING  - A WARNING message
486
487
488Configuration server example
489----------------------------
490
491Here is an example of a module using the logging configuration server::
492
493    import logging
494    import logging.config
495    import time
496    import os
497
498    # read initial config file
499    logging.config.fileConfig('logging.conf')
500
501    # create and start listener on port 9999
502    t = logging.config.listen(9999)
503    t.start()
504
505    logger = logging.getLogger('simpleExample')
506
507    try:
508        # loop through logging calls to see the difference
509        # new configurations make, until Ctrl+C is pressed
510        while True:
511            logger.debug('debug message')
512            logger.info('info message')
513            logger.warning('warn message')
514            logger.error('error message')
515            logger.critical('critical message')
516            time.sleep(5)
517    except KeyboardInterrupt:
518        # cleanup
519        logging.config.stopListening()
520        t.join()
521
522And here is a script that takes a filename and sends that file to the server,
523properly preceded with the binary-encoded length, as the new logging
524configuration::
525
526    #!/usr/bin/env python
527    import socket, sys, struct
528
529    with open(sys.argv[1], 'rb') as f:
530        data_to_send = f.read()
531
532    HOST = 'localhost'
533    PORT = 9999
534    s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
535    print('connecting...')
536    s.connect((HOST, PORT))
537    print('sending config...')
538    s.send(struct.pack('>L', len(data_to_send)))
539    s.send(data_to_send)
540    s.close()
541    print('complete')
542
543
544.. _blocking-handlers:
545
546Dealing with handlers that block
547--------------------------------
548
549.. currentmodule:: logging.handlers
550
551Sometimes you have to get your logging handlers to do their work without
552blocking the thread you're logging from. This is common in web applications,
553though of course it also occurs in other scenarios.
554
555A common culprit which demonstrates sluggish behaviour is the
556:class:`SMTPHandler`: sending emails can take a long time, for a
557number of reasons outside the developer's control (for example, a poorly
558performing mail or network infrastructure). But almost any network-based
559handler can block: Even a :class:`SocketHandler` operation may do a
560DNS query under the hood which is too slow (and this query can be deep in the
561socket library code, below the Python layer, and outside your control).
562
563One solution is to use a two-part approach. For the first part, attach only a
564:class:`QueueHandler` to those loggers which are accessed from
565performance-critical threads. They simply write to their queue, which can be
566sized to a large enough capacity or initialized with no upper bound to their
567size. The write to the queue will typically be accepted quickly, though you
568will probably need to catch the :exc:`queue.Full` exception as a precaution
569in your code. If you are a library developer who has performance-critical
570threads in their code, be sure to document this (together with a suggestion to
571attach only ``QueueHandlers`` to your loggers) for the benefit of other
572developers who will use your code.
573
574The second part of the solution is :class:`QueueListener`, which has been
575designed as the counterpart to :class:`QueueHandler`.  A
576:class:`QueueListener` is very simple: it's passed a queue and some handlers,
577and it fires up an internal thread which listens to its queue for LogRecords
578sent from ``QueueHandlers`` (or any other source of ``LogRecords``, for that
579matter). The ``LogRecords`` are removed from the queue and passed to the
580handlers for processing.
581
582The advantage of having a separate :class:`QueueListener` class is that you
583can use the same instance to service multiple ``QueueHandlers``. This is more
584resource-friendly than, say, having threaded versions of the existing handler
585classes, which would eat up one thread per handler for no particular benefit.
586
587An example of using these two classes follows (imports omitted)::
588
589    que = queue.Queue(-1)  # no limit on size
590    queue_handler = QueueHandler(que)
591    handler = logging.StreamHandler()
592    listener = QueueListener(que, handler)
593    root = logging.getLogger()
594    root.addHandler(queue_handler)
595    formatter = logging.Formatter('%(threadName)s: %(message)s')
596    handler.setFormatter(formatter)
597    listener.start()
598    # The log output will display the thread which generated
599    # the event (the main thread) rather than the internal
600    # thread which monitors the internal queue. This is what
601    # you want to happen.
602    root.warning('Look out!')
603    listener.stop()
604
605which, when run, will produce:
606
607.. code-block:: none
608
609    MainThread: Look out!
610
611.. note:: Although the earlier discussion wasn't specifically talking about
612   async code, but rather about slow logging handlers, it should be noted that
613   when logging from async code, network and even file handlers could lead to
614   problems (blocking the event loop) because some logging is done from
615   :mod:`asyncio` internals. It might be best, if any async code is used in an
616   application, to use the above approach for logging, so that any blocking code
617   runs only in the ``QueueListener`` thread.
618
619.. versionchanged:: 3.5
620   Prior to Python 3.5, the :class:`QueueListener` always passed every message
621   received from the queue to every handler it was initialized with. (This was
622   because it was assumed that level filtering was all done on the other side,
623   where the queue is filled.) From 3.5 onwards, this behaviour can be changed
624   by passing a keyword argument ``respect_handler_level=True`` to the
625   listener's constructor. When this is done, the listener compares the level
626   of each message with the handler's level, and only passes a message to a
627   handler if it's appropriate to do so.
628
629.. _network-logging:
630
631Sending and receiving logging events across a network
632-----------------------------------------------------
633
634Let's say you want to send logging events across a network, and handle them at
635the receiving end. A simple way of doing this is attaching a
636:class:`SocketHandler` instance to the root logger at the sending end::
637
638   import logging, logging.handlers
639
640   rootLogger = logging.getLogger('')
641   rootLogger.setLevel(logging.DEBUG)
642   socketHandler = logging.handlers.SocketHandler('localhost',
643                       logging.handlers.DEFAULT_TCP_LOGGING_PORT)
644   # don't bother with a formatter, since a socket handler sends the event as
645   # an unformatted pickle
646   rootLogger.addHandler(socketHandler)
647
648   # Now, we can log to the root logger, or any other logger. First the root...
649   logging.info('Jackdaws love my big sphinx of quartz.')
650
651   # Now, define a couple of other loggers which might represent areas in your
652   # application:
653
654   logger1 = logging.getLogger('myapp.area1')
655   logger2 = logging.getLogger('myapp.area2')
656
657   logger1.debug('Quick zephyrs blow, vexing daft Jim.')
658   logger1.info('How quickly daft jumping zebras vex.')
659   logger2.warning('Jail zesty vixen who grabbed pay from quack.')
660   logger2.error('The five boxing wizards jump quickly.')
661
662At the receiving end, you can set up a receiver using the :mod:`socketserver`
663module. Here is a basic working example::
664
665   import pickle
666   import logging
667   import logging.handlers
668   import socketserver
669   import struct
670
671
672   class LogRecordStreamHandler(socketserver.StreamRequestHandler):
673       """Handler for a streaming logging request.
674
675       This basically logs the record using whatever logging policy is
676       configured locally.
677       """
678
679       def handle(self):
680           """
681           Handle multiple requests - each expected to be a 4-byte length,
682           followed by the LogRecord in pickle format. Logs the record
683           according to whatever policy is configured locally.
684           """
685           while True:
686               chunk = self.connection.recv(4)
687               if len(chunk) < 4:
688                   break
689               slen = struct.unpack('>L', chunk)[0]
690               chunk = self.connection.recv(slen)
691               while len(chunk) < slen:
692                   chunk = chunk + self.connection.recv(slen - len(chunk))
693               obj = self.unPickle(chunk)
694               record = logging.makeLogRecord(obj)
695               self.handleLogRecord(record)
696
697       def unPickle(self, data):
698           return pickle.loads(data)
699
700       def handleLogRecord(self, record):
701           # if a name is specified, we use the named logger rather than the one
702           # implied by the record.
703           if self.server.logname is not None:
704               name = self.server.logname
705           else:
706               name = record.name
707           logger = logging.getLogger(name)
708           # N.B. EVERY record gets logged. This is because Logger.handle
709           # is normally called AFTER logger-level filtering. If you want
710           # to do filtering, do it at the client end to save wasting
711           # cycles and network bandwidth!
712           logger.handle(record)
713
714   class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):
715       """
716       Simple TCP socket-based logging receiver suitable for testing.
717       """
718
719       allow_reuse_address = True
720
721       def __init__(self, host='localhost',
722                    port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
723                    handler=LogRecordStreamHandler):
724           socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)
725           self.abort = 0
726           self.timeout = 1
727           self.logname = None
728
729       def serve_until_stopped(self):
730           import select
731           abort = 0
732           while not abort:
733               rd, wr, ex = select.select([self.socket.fileno()],
734                                          [], [],
735                                          self.timeout)
736               if rd:
737                   self.handle_request()
738               abort = self.abort
739
740   def main():
741       logging.basicConfig(
742           format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')
743       tcpserver = LogRecordSocketReceiver()
744       print('About to start TCP server...')
745       tcpserver.serve_until_stopped()
746
747   if __name__ == '__main__':
748       main()
749
750First run the server, and then the client. On the client side, nothing is
751printed on the console; on the server side, you should see something like:
752
753.. code-block:: none
754
755   About to start TCP server...
756      59 root            INFO     Jackdaws love my big sphinx of quartz.
757      59 myapp.area1     DEBUG    Quick zephyrs blow, vexing daft Jim.
758      69 myapp.area1     INFO     How quickly daft jumping zebras vex.
759      69 myapp.area2     WARNING  Jail zesty vixen who grabbed pay from quack.
760      69 myapp.area2     ERROR    The five boxing wizards jump quickly.
761
762Note that there are some security issues with pickle in some scenarios. If
763these affect you, you can use an alternative serialization scheme by overriding
764the :meth:`~handlers.SocketHandler.makePickle` method and implementing your
765alternative there, as well as adapting the above script to use your alternative
766serialization.
767
768
769Running a logging socket listener in production
770^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
771
772.. _socket-listener-gist: https://gist.github.com/vsajip/4b227eeec43817465ca835ca66f75e2b
773
774To run a logging listener in production, you may need to use a
775process-management tool such as `Supervisor <http://supervisord.org/>`_.
776`Here is a Gist <socket-listener-gist_>`__
777which provides the bare-bones files to run the above functionality using
778Supervisor. It consists of the following files:
779
780+-------------------------+----------------------------------------------------+
781| File                    | Purpose                                            |
782+=========================+====================================================+
783| :file:`prepare.sh`      | A Bash script to prepare the environment for       |
784|                         | testing                                            |
785+-------------------------+----------------------------------------------------+
786| :file:`supervisor.conf` | The Supervisor configuration file, which has       |
787|                         | entries for the listener and a multi-process web   |
788|                         | application                                        |
789+-------------------------+----------------------------------------------------+
790| :file:`ensure_app.sh`   | A Bash script to ensure that Supervisor is running |
791|                         | with the above configuration                       |
792+-------------------------+----------------------------------------------------+
793| :file:`log_listener.py` | The socket listener program which receives log     |
794|                         | events and records them to a file                  |
795+-------------------------+----------------------------------------------------+
796| :file:`main.py`         | A simple web application which performs logging    |
797|                         | via a socket connected to the listener             |
798+-------------------------+----------------------------------------------------+
799| :file:`webapp.json`     | A JSON configuration file for the web application  |
800+-------------------------+----------------------------------------------------+
801| :file:`client.py`       | A Python script to exercise the web application    |
802+-------------------------+----------------------------------------------------+
803
804The web application uses `Gunicorn <https://gunicorn.org/>`_, which is a
805popular web application server that starts multiple worker processes to handle
806requests. This example setup shows how the workers can write to the same log file
807without conflicting with one another --- they all go through the socket listener.
808
809To test these files, do the following in a POSIX environment:
810
811#. Download `the Gist <socket-listener-gist_>`__
812   as a ZIP archive using the :guilabel:`Download ZIP` button.
813
814#. Unzip the above files from the archive into a scratch directory.
815
816#. In the scratch directory, run ``bash prepare.sh`` to get things ready.
817   This creates a :file:`run` subdirectory to contain Supervisor-related and
818   log files, and a :file:`venv` subdirectory to contain a virtual environment
819   into which ``bottle``, ``gunicorn`` and ``supervisor`` are installed.
820
821#. Run ``bash ensure_app.sh`` to ensure that Supervisor is running with
822   the above configuration.
823
824#. Run ``venv/bin/python client.py`` to exercise the web application,
825   which will lead to records being written to the log.
826
827#. Inspect the log files in the :file:`run` subdirectory. You should see the
828   most recent log lines in files matching the pattern :file:`app.log*`. They won't be in
829   any particular order, since they have been handled concurrently by different
830   worker processes in a non-deterministic way.
831
832#. You can shut down the listener and the web application by running
833   ``venv/bin/supervisorctl -c supervisor.conf shutdown``.
834
835You may need to tweak the configuration files in the unlikely event that the
836configured ports clash with something else in your test environment.
837
838.. _context-info:
839
840Adding contextual information to your logging output
841----------------------------------------------------
842
843Sometimes you want logging output to contain contextual information in
844addition to the parameters passed to the logging call. For example, in a
845networked application, it may be desirable to log client-specific information
846in the log (e.g. remote client's username, or IP address). Although you could
847use the *extra* parameter to achieve this, it's not always convenient to pass
848the information in this way. While it might be tempting to create
849:class:`Logger` instances on a per-connection basis, this is not a good idea
850because these instances are not garbage collected. While this is not a problem
851in practice, when the number of :class:`Logger` instances is dependent on the
852level of granularity you want to use in logging an application, it could
853be hard to manage if the number of :class:`Logger` instances becomes
854effectively unbounded.
855
856
857Using LoggerAdapters to impart contextual information
858^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
859
860An easy way in which you can pass contextual information to be output along
861with logging event information is to use the :class:`LoggerAdapter` class.
862This class is designed to look like a :class:`Logger`, so that you can call
863:meth:`debug`, :meth:`info`, :meth:`warning`, :meth:`error`,
864:meth:`exception`, :meth:`critical` and :meth:`log`. These methods have the
865same signatures as their counterparts in :class:`Logger`, so you can use the
866two types of instances interchangeably.
867
868When you create an instance of :class:`LoggerAdapter`, you pass it a
869:class:`Logger` instance and a dict-like object which contains your contextual
870information. When you call one of the logging methods on an instance of
871:class:`LoggerAdapter`, it delegates the call to the underlying instance of
872:class:`Logger` passed to its constructor, and arranges to pass the contextual
873information in the delegated call. Here's a snippet from the code of
874:class:`LoggerAdapter`::
875
876    def debug(self, msg, /, *args, **kwargs):
877        """
878        Delegate a debug call to the underlying logger, after adding
879        contextual information from this adapter instance.
880        """
881        msg, kwargs = self.process(msg, kwargs)
882        self.logger.debug(msg, *args, **kwargs)
883
884The :meth:`~LoggerAdapter.process` method of :class:`LoggerAdapter` is where the
885contextual information is added to the logging output. It's passed the message
886and keyword arguments of the logging call, and it passes back (potentially)
887modified versions of these to use in the call to the underlying logger. The
888default implementation of this method leaves the message alone, but inserts
889an 'extra' key in the keyword argument whose value is the dict-like object
890passed to the constructor. Of course, if you had passed an 'extra' keyword
891argument in the call to the adapter, it will be silently overwritten.
892
893The advantage of using 'extra' is that the values in the dict-like object are
894merged into the :class:`LogRecord` instance's __dict__, allowing you to use
895customized strings with your :class:`Formatter` instances which know about
896the keys of the dict-like object. If you need a different method, e.g. if you
897want to prepend or append the contextual information to the message string,
898you just need to subclass :class:`LoggerAdapter` and override
899:meth:`~LoggerAdapter.process` to do what you need. Here is a simple example::
900
901    class CustomAdapter(logging.LoggerAdapter):
902        """
903        This example adapter expects the passed in dict-like object to have a
904        'connid' key, whose value in brackets is prepended to the log message.
905        """
906        def process(self, msg, kwargs):
907            return '[%s] %s' % (self.extra['connid'], msg), kwargs
908
909which you can use like this::
910
911    logger = logging.getLogger(__name__)
912    adapter = CustomAdapter(logger, {'connid': some_conn_id})
913
914Then any events that you log to the adapter will have the value of
915``some_conn_id`` prepended to the log messages.
916
917Using objects other than dicts to pass contextual information
918~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
919
920You don't need to pass an actual dict to a :class:`LoggerAdapter` - you could
921pass an instance of a class which implements ``__getitem__`` and ``__iter__`` so
922that it looks like a dict to logging. This would be useful if you want to
923generate values dynamically (whereas the values in a dict would be constant).
924
925
926.. _filters-contextual:
927
928Using Filters to impart contextual information
929^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
930
931You can also add contextual information to log output using a user-defined
932:class:`Filter`. ``Filter`` instances are allowed to modify the ``LogRecords``
933passed to them, including adding additional attributes which can then be output
934using a suitable format string, or if needed a custom :class:`Formatter`.
935
936For example in a web application, the request being processed (or at least,
937the interesting parts of it) can be stored in a threadlocal
938(:class:`threading.local`) variable, and then accessed from a ``Filter`` to
939add, say, information from the request - say, the remote IP address and remote
940user's username - to the ``LogRecord``, using the attribute names 'ip' and
941'user' as in the ``LoggerAdapter`` example above. In that case, the same format
942string can be used to get similar output to that shown above. Here's an example
943script::
944
945    import logging
946    from random import choice
947
948    class ContextFilter(logging.Filter):
949        """
950        This is a filter which injects contextual information into the log.
951
952        Rather than use actual contextual information, we just use random
953        data in this demo.
954        """
955
956        USERS = ['jim', 'fred', 'sheila']
957        IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']
958
959        def filter(self, record):
960
961            record.ip = choice(ContextFilter.IPS)
962            record.user = choice(ContextFilter.USERS)
963            return True
964
965    if __name__ == '__main__':
966        levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
967        logging.basicConfig(level=logging.DEBUG,
968                            format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')
969        a1 = logging.getLogger('a.b.c')
970        a2 = logging.getLogger('d.e.f')
971
972        f = ContextFilter()
973        a1.addFilter(f)
974        a2.addFilter(f)
975        a1.debug('A debug message')
976        a1.info('An info message with %s', 'some parameters')
977        for x in range(10):
978            lvl = choice(levels)
979            lvlname = logging.getLevelName(lvl)
980            a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')
981
982which, when run, produces something like:
983
984.. code-block:: none
985
986    2010-09-06 22:38:15,292 a.b.c DEBUG    IP: 123.231.231.123 User: fred     A debug message
987    2010-09-06 22:38:15,300 a.b.c INFO     IP: 192.168.0.1     User: sheila   An info message with some parameters
988    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
989    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
990    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
991    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
992    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
993    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
994    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
995    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
996    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
997    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
998
999Use of ``contextvars``
1000----------------------
1001
1002Since Python 3.7, the :mod:`contextvars` module has provided context-local storage
1003which works for both :mod:`threading` and :mod:`asyncio` processing needs. This type
1004of storage may thus be generally preferable to thread-locals. The following example
1005shows how, in a multi-threaded environment, logs can populated with contextual
1006information such as, for example, request attributes handled by web applications.
1007
1008For the purposes of illustration, say that you have different web applications, each
1009independent of the other but running in the same Python process and using a library
1010common to them. How can each of these applications have their own log, where all
1011logging messages from the library (and other request processing code) are directed to
1012the appropriate application's log file, while including in the log additional
1013contextual information such as client IP, HTTP request method and client username?
1014
1015Let's assume that the library can be simulated by the following code:
1016
1017.. code-block:: python
1018
1019    # webapplib.py
1020    import logging
1021    import time
1022
1023    logger = logging.getLogger(__name__)
1024
1025    def useful():
1026        # Just a representative event logged from the library
1027        logger.debug('Hello from webapplib!')
1028        # Just sleep for a bit so other threads get to run
1029        time.sleep(0.01)
1030
1031We can simulate the multiple web applications by means of two simple classes,
1032``Request`` and ``WebApp``. These simulate how real threaded web applications work -
1033each request is handled by a thread:
1034
1035.. code-block:: python
1036
1037    # main.py
1038    import argparse
1039    from contextvars import ContextVar
1040    import logging
1041    import os
1042    from random import choice
1043    import threading
1044    import webapplib
1045
1046    logger = logging.getLogger(__name__)
1047    root = logging.getLogger()
1048    root.setLevel(logging.DEBUG)
1049
1050    class Request:
1051        """
1052        A simple dummy request class which just holds dummy HTTP request method,
1053        client IP address and client username
1054        """
1055        def __init__(self, method, ip, user):
1056            self.method = method
1057            self.ip = ip
1058            self.user = user
1059
1060    # A dummy set of requests which will be used in the simulation - we'll just pick
1061    # from this list randomly. Note that all GET requests are from 192.168.2.XXX
1062    # addresses, whereas POST requests are from 192.16.3.XXX addresses. Three users
1063    # are represented in the sample requests.
1064
1065    REQUESTS = [
1066        Request('GET', '192.168.2.20', 'jim'),
1067        Request('POST', '192.168.3.20', 'fred'),
1068        Request('GET', '192.168.2.21', 'sheila'),
1069        Request('POST', '192.168.3.21', 'jim'),
1070        Request('GET', '192.168.2.22', 'fred'),
1071        Request('POST', '192.168.3.22', 'sheila'),
1072    ]
1073
1074    # Note that the format string includes references to request context information
1075    # such as HTTP method, client IP and username
1076
1077    formatter = logging.Formatter('%(threadName)-11s %(appName)s %(name)-9s %(user)-6s %(ip)s %(method)-4s %(message)s')
1078
1079    # Create our context variables. These will be filled at the start of request
1080    # processing, and used in the logging that happens during that processing
1081
1082    ctx_request = ContextVar('request')
1083    ctx_appname = ContextVar('appname')
1084
1085    class InjectingFilter(logging.Filter):
1086        """
1087        A filter which injects context-specific information into logs and ensures
1088        that only information for a specific webapp is included in its log
1089        """
1090        def __init__(self, app):
1091            self.app = app
1092
1093        def filter(self, record):
1094            request = ctx_request.get()
1095            record.method = request.method
1096            record.ip = request.ip
1097            record.user = request.user
1098            record.appName = appName = ctx_appname.get()
1099            return appName == self.app.name
1100
1101    class WebApp:
1102        """
1103        A dummy web application class which has its own handler and filter for a
1104        webapp-specific log.
1105        """
1106        def __init__(self, name):
1107            self.name = name
1108            handler = logging.FileHandler(name + '.log', 'w')
1109            f = InjectingFilter(self)
1110            handler.setFormatter(formatter)
1111            handler.addFilter(f)
1112            root.addHandler(handler)
1113            self.num_requests = 0
1114
1115        def process_request(self, request):
1116            """
1117            This is the dummy method for processing a request. It's called on a
1118            different thread for every request. We store the context information into
1119            the context vars before doing anything else.
1120            """
1121            ctx_request.set(request)
1122            ctx_appname.set(self.name)
1123            self.num_requests += 1
1124            logger.debug('Request processing started')
1125            webapplib.useful()
1126            logger.debug('Request processing finished')
1127
1128    def main():
1129        fn = os.path.splitext(os.path.basename(__file__))[0]
1130        adhf = argparse.ArgumentDefaultsHelpFormatter
1131        ap = argparse.ArgumentParser(formatter_class=adhf, prog=fn,
1132                                     description='Simulate a couple of web '
1133                                                 'applications handling some '
1134                                                 'requests, showing how request '
1135                                                 'context can be used to '
1136                                                 'populate logs')
1137        aa = ap.add_argument
1138        aa('--count', '-c', type=int, default=100, help='How many requests to simulate')
1139        options = ap.parse_args()
1140
1141        # Create the dummy webapps and put them in a list which we can use to select
1142        # from randomly
1143        app1 = WebApp('app1')
1144        app2 = WebApp('app2')
1145        apps = [app1, app2]
1146        threads = []
1147        # Add a common handler which will capture all events
1148        handler = logging.FileHandler('app.log', 'w')
1149        handler.setFormatter(formatter)
1150        root.addHandler(handler)
1151
1152        # Generate calls to process requests
1153        for i in range(options.count):
1154            try:
1155                # Pick an app at random and a request for it to process
1156                app = choice(apps)
1157                request = choice(REQUESTS)
1158                # Process the request in its own thread
1159                t = threading.Thread(target=app.process_request, args=(request,))
1160                threads.append(t)
1161                t.start()
1162            except KeyboardInterrupt:
1163                break
1164
1165        # Wait for the threads to terminate
1166        for t in threads:
1167            t.join()
1168
1169        for app in apps:
1170            print('%s processed %s requests' % (app.name, app.num_requests))
1171
1172    if __name__ == '__main__':
1173        main()
1174
1175If you run the above, you should find that roughly half the requests go
1176into :file:`app1.log` and the rest into :file:`app2.log`, and the all the requests are
1177logged to :file:`app.log`. Each webapp-specific log will contain only log entries for
1178only that webapp, and the request information will be displayed consistently in the
1179log (i.e. the information in each dummy request will always appear together in a log
1180line). This is illustrated by the following shell output:
1181
1182.. code-block:: shell
1183
1184    ~/logging-contextual-webapp$ python main.py
1185    app1 processed 51 requests
1186    app2 processed 49 requests
1187    ~/logging-contextual-webapp$ wc -l *.log
1188      153 app1.log
1189      147 app2.log
1190      300 app.log
1191      600 total
1192    ~/logging-contextual-webapp$ head -3 app1.log
1193    Thread-3 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
1194    Thread-3 (process_request) app1 webapplib jim    192.168.3.21 POST Hello from webapplib!
1195    Thread-5 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
1196    ~/logging-contextual-webapp$ head -3 app2.log
1197    Thread-1 (process_request) app2 __main__  sheila 192.168.2.21 GET  Request processing started
1198    Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET  Hello from webapplib!
1199    Thread-2 (process_request) app2 __main__  jim    192.168.2.20 GET  Request processing started
1200    ~/logging-contextual-webapp$ head app.log
1201    Thread-1 (process_request) app2 __main__  sheila 192.168.2.21 GET  Request processing started
1202    Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET  Hello from webapplib!
1203    Thread-2 (process_request) app2 __main__  jim    192.168.2.20 GET  Request processing started
1204    Thread-3 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
1205    Thread-2 (process_request) app2 webapplib jim    192.168.2.20 GET  Hello from webapplib!
1206    Thread-3 (process_request) app1 webapplib jim    192.168.3.21 POST Hello from webapplib!
1207    Thread-4 (process_request) app2 __main__  fred   192.168.2.22 GET  Request processing started
1208    Thread-5 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
1209    Thread-4 (process_request) app2 webapplib fred   192.168.2.22 GET  Hello from webapplib!
1210    Thread-6 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
1211    ~/logging-contextual-webapp$ grep app1 app1.log | wc -l
1212    153
1213    ~/logging-contextual-webapp$ grep app2 app2.log | wc -l
1214    147
1215    ~/logging-contextual-webapp$ grep app1 app.log | wc -l
1216    153
1217    ~/logging-contextual-webapp$ grep app2 app.log | wc -l
1218    147
1219
1220
1221Imparting contextual information in handlers
1222--------------------------------------------
1223
1224Each :class:`~Handler` has its own chain of filters.
1225If you want to add contextual information to a :class:`LogRecord` without leaking
1226it to other handlers, you can use a filter that returns
1227a new :class:`~LogRecord` instead of modifying it in-place, as shown in the following script::
1228
1229    import copy
1230    import logging
1231
1232    def filter(record: logging.LogRecord):
1233        record = copy.copy(record)
1234        record.user = 'jim'
1235        return record
1236
1237    if __name__ == '__main__':
1238        logger = logging.getLogger()
1239        logger.setLevel(logging.INFO)
1240        handler = logging.StreamHandler()
1241        formatter = logging.Formatter('%(message)s from %(user)-8s')
1242        handler.setFormatter(formatter)
1243        handler.addFilter(filter)
1244        logger.addHandler(handler)
1245
1246        logger.info('A log message')
1247
1248.. _multiple-processes:
1249
1250Logging to a single file from multiple processes
1251------------------------------------------------
1252
1253Although logging is thread-safe, and logging to a single file from multiple
1254threads in a single process *is* supported, logging to a single file from
1255*multiple processes* is *not* supported, because there is no standard way to
1256serialize access to a single file across multiple processes in Python. If you
1257need to log to a single file from multiple processes, one way of doing this is
1258to have all the processes log to a :class:`~handlers.SocketHandler`, and have a
1259separate process which implements a socket server which reads from the socket
1260and logs to file. (If you prefer, you can dedicate one thread in one of the
1261existing processes to perform this function.)
1262:ref:`This section <network-logging>` documents this approach in more detail and
1263includes a working socket receiver which can be used as a starting point for you
1264to adapt in your own applications.
1265
1266You could also write your own handler which uses the :class:`~multiprocessing.Lock`
1267class from the :mod:`multiprocessing` module to serialize access to the
1268file from your processes. The existing :class:`FileHandler` and subclasses do
1269not make use of :mod:`multiprocessing` at present, though they may do so in the
1270future. Note that at present, the :mod:`multiprocessing` module does not provide
1271working lock functionality on all platforms (see
1272https://bugs.python.org/issue3770).
1273
1274.. currentmodule:: logging.handlers
1275
1276Alternatively, you can use a ``Queue`` and a :class:`QueueHandler` to send
1277all logging events to one of the processes in your multi-process application.
1278The following example script demonstrates how you can do this; in the example
1279a separate listener process listens for events sent by other processes and logs
1280them according to its own logging configuration. Although the example only
1281demonstrates one way of doing it (for example, you may want to use a listener
1282thread rather than a separate listener process -- the implementation would be
1283analogous) it does allow for completely different logging configurations for
1284the listener and the other processes in your application, and can be used as
1285the basis for code meeting your own specific requirements::
1286
1287    # You'll need these imports in your own code
1288    import logging
1289    import logging.handlers
1290    import multiprocessing
1291
1292    # Next two import lines for this demo only
1293    from random import choice, random
1294    import time
1295
1296    #
1297    # Because you'll want to define the logging configurations for listener and workers, the
1298    # listener and worker process functions take a configurer parameter which is a callable
1299    # for configuring logging for that process. These functions are also passed the queue,
1300    # which they use for communication.
1301    #
1302    # In practice, you can configure the listener however you want, but note that in this
1303    # simple example, the listener does not apply level or filter logic to received records.
1304    # In practice, you would probably want to do this logic in the worker processes, to avoid
1305    # sending events which would be filtered out between processes.
1306    #
1307    # The size of the rotated files is made small so you can see the results easily.
1308    def listener_configurer():
1309        root = logging.getLogger()
1310        h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)
1311        f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')
1312        h.setFormatter(f)
1313        root.addHandler(h)
1314
1315    # This is the listener process top-level loop: wait for logging events
1316    # (LogRecords)on the queue and handle them, quit when you get a None for a
1317    # LogRecord.
1318    def listener_process(queue, configurer):
1319        configurer()
1320        while True:
1321            try:
1322                record = queue.get()
1323                if record is None:  # We send this as a sentinel to tell the listener to quit.
1324                    break
1325                logger = logging.getLogger(record.name)
1326                logger.handle(record)  # No level or filter logic applied - just do it!
1327            except Exception:
1328                import sys, traceback
1329                print('Whoops! Problem:', file=sys.stderr)
1330                traceback.print_exc(file=sys.stderr)
1331
1332    # Arrays used for random selections in this demo
1333
1334    LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,
1335              logging.ERROR, logging.CRITICAL]
1336
1337    LOGGERS = ['a.b.c', 'd.e.f']
1338
1339    MESSAGES = [
1340        'Random message #1',
1341        'Random message #2',
1342        'Random message #3',
1343    ]
1344
1345    # The worker configuration is done at the start of the worker process run.
1346    # Note that on Windows you can't rely on fork semantics, so each process
1347    # will run the logging configuration code when it starts.
1348    def worker_configurer(queue):
1349        h = logging.handlers.QueueHandler(queue)  # Just the one handler needed
1350        root = logging.getLogger()
1351        root.addHandler(h)
1352        # send all messages, for demo; no other level or filter logic applied.
1353        root.setLevel(logging.DEBUG)
1354
1355    # This is the worker process top-level loop, which just logs ten events with
1356    # random intervening delays before terminating.
1357    # The print messages are just so you know it's doing something!
1358    def worker_process(queue, configurer):
1359        configurer(queue)
1360        name = multiprocessing.current_process().name
1361        print('Worker started: %s' % name)
1362        for i in range(10):
1363            time.sleep(random())
1364            logger = logging.getLogger(choice(LOGGERS))
1365            level = choice(LEVELS)
1366            message = choice(MESSAGES)
1367            logger.log(level, message)
1368        print('Worker finished: %s' % name)
1369
1370    # Here's where the demo gets orchestrated. Create the queue, create and start
1371    # the listener, create ten workers and start them, wait for them to finish,
1372    # then send a None to the queue to tell the listener to finish.
1373    def main():
1374        queue = multiprocessing.Queue(-1)
1375        listener = multiprocessing.Process(target=listener_process,
1376                                           args=(queue, listener_configurer))
1377        listener.start()
1378        workers = []
1379        for i in range(10):
1380            worker = multiprocessing.Process(target=worker_process,
1381                                             args=(queue, worker_configurer))
1382            workers.append(worker)
1383            worker.start()
1384        for w in workers:
1385            w.join()
1386        queue.put_nowait(None)
1387        listener.join()
1388
1389    if __name__ == '__main__':
1390        main()
1391
1392A variant of the above script keeps the logging in the main process, in a
1393separate thread::
1394
1395    import logging
1396    import logging.config
1397    import logging.handlers
1398    from multiprocessing import Process, Queue
1399    import random
1400    import threading
1401    import time
1402
1403    def logger_thread(q):
1404        while True:
1405            record = q.get()
1406            if record is None:
1407                break
1408            logger = logging.getLogger(record.name)
1409            logger.handle(record)
1410
1411
1412    def worker_process(q):
1413        qh = logging.handlers.QueueHandler(q)
1414        root = logging.getLogger()
1415        root.setLevel(logging.DEBUG)
1416        root.addHandler(qh)
1417        levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
1418                  logging.CRITICAL]
1419        loggers = ['foo', 'foo.bar', 'foo.bar.baz',
1420                   'spam', 'spam.ham', 'spam.ham.eggs']
1421        for i in range(100):
1422            lvl = random.choice(levels)
1423            logger = logging.getLogger(random.choice(loggers))
1424            logger.log(lvl, 'Message no. %d', i)
1425
1426    if __name__ == '__main__':
1427        q = Queue()
1428        d = {
1429            'version': 1,
1430            'formatters': {
1431                'detailed': {
1432                    'class': 'logging.Formatter',
1433                    'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
1434                }
1435            },
1436            'handlers': {
1437                'console': {
1438                    'class': 'logging.StreamHandler',
1439                    'level': 'INFO',
1440                },
1441                'file': {
1442                    'class': 'logging.FileHandler',
1443                    'filename': 'mplog.log',
1444                    'mode': 'w',
1445                    'formatter': 'detailed',
1446                },
1447                'foofile': {
1448                    'class': 'logging.FileHandler',
1449                    'filename': 'mplog-foo.log',
1450                    'mode': 'w',
1451                    'formatter': 'detailed',
1452                },
1453                'errors': {
1454                    'class': 'logging.FileHandler',
1455                    'filename': 'mplog-errors.log',
1456                    'mode': 'w',
1457                    'level': 'ERROR',
1458                    'formatter': 'detailed',
1459                },
1460            },
1461            'loggers': {
1462                'foo': {
1463                    'handlers': ['foofile']
1464                }
1465            },
1466            'root': {
1467                'level': 'DEBUG',
1468                'handlers': ['console', 'file', 'errors']
1469            },
1470        }
1471        workers = []
1472        for i in range(5):
1473            wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))
1474            workers.append(wp)
1475            wp.start()
1476        logging.config.dictConfig(d)
1477        lp = threading.Thread(target=logger_thread, args=(q,))
1478        lp.start()
1479        # At this point, the main process could do some useful work of its own
1480        # Once it's done that, it can wait for the workers to terminate...
1481        for wp in workers:
1482            wp.join()
1483        # And now tell the logging thread to finish up, too
1484        q.put(None)
1485        lp.join()
1486
1487This variant shows how you can e.g. apply configuration for particular loggers
1488- e.g. the ``foo`` logger has a special handler which stores all events in the
1489``foo`` subsystem in a file ``mplog-foo.log``. This will be used by the logging
1490machinery in the main process (even though the logging events are generated in
1491the worker processes) to direct the messages to the appropriate destinations.
1492
1493Using concurrent.futures.ProcessPoolExecutor
1494^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
1495
1496If you want to use :class:`concurrent.futures.ProcessPoolExecutor` to start
1497your worker processes, you need to create the queue slightly differently.
1498Instead of
1499
1500.. code-block:: python
1501
1502   queue = multiprocessing.Queue(-1)
1503
1504you should use
1505
1506.. code-block:: python
1507
1508   queue = multiprocessing.Manager().Queue(-1)  # also works with the examples above
1509
1510and you can then replace the worker creation from this::
1511
1512    workers = []
1513    for i in range(10):
1514        worker = multiprocessing.Process(target=worker_process,
1515                                         args=(queue, worker_configurer))
1516        workers.append(worker)
1517        worker.start()
1518    for w in workers:
1519        w.join()
1520
1521to this (remembering to first import :mod:`concurrent.futures`)::
1522
1523    with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:
1524        for i in range(10):
1525            executor.submit(worker_process, queue, worker_configurer)
1526
1527Deploying Web applications using Gunicorn and uWSGI
1528^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
1529
1530When deploying Web applications using `Gunicorn <https://gunicorn.org/>`_ or `uWSGI
1531<https://uwsgi-docs.readthedocs.io/en/latest/>`_ (or similar), multiple worker
1532processes are created to handle client requests. In such environments, avoid creating
1533file-based handlers directly in your web application. Instead, use a
1534:class:`SocketHandler` to log from the web application to a listener in a separate
1535process. This can be set up using a process management tool such as Supervisor - see
1536`Running a logging socket listener in production`_ for more details.
1537
1538
1539Using file rotation
1540-------------------
1541
1542.. sectionauthor:: Doug Hellmann, Vinay Sajip (changes)
1543.. (see <https://pymotw.com/3/logging/>)
1544
1545Sometimes you want to let a log file grow to a certain size, then open a new
1546file and log to that. You may want to keep a certain number of these files, and
1547when that many files have been created, rotate the files so that the number of
1548files and the size of the files both remain bounded. For this usage pattern, the
1549logging package provides a :class:`~handlers.RotatingFileHandler`::
1550
1551   import glob
1552   import logging
1553   import logging.handlers
1554
1555   LOG_FILENAME = 'logging_rotatingfile_example.out'
1556
1557   # Set up a specific logger with our desired output level
1558   my_logger = logging.getLogger('MyLogger')
1559   my_logger.setLevel(logging.DEBUG)
1560
1561   # Add the log message handler to the logger
1562   handler = logging.handlers.RotatingFileHandler(
1563                 LOG_FILENAME, maxBytes=20, backupCount=5)
1564
1565   my_logger.addHandler(handler)
1566
1567   # Log some messages
1568   for i in range(20):
1569       my_logger.debug('i = %d' % i)
1570
1571   # See what files are created
1572   logfiles = glob.glob('%s*' % LOG_FILENAME)
1573
1574   for filename in logfiles:
1575       print(filename)
1576
1577The result should be 6 separate files, each with part of the log history for the
1578application:
1579
1580.. code-block:: none
1581
1582   logging_rotatingfile_example.out
1583   logging_rotatingfile_example.out.1
1584   logging_rotatingfile_example.out.2
1585   logging_rotatingfile_example.out.3
1586   logging_rotatingfile_example.out.4
1587   logging_rotatingfile_example.out.5
1588
1589The most current file is always :file:`logging_rotatingfile_example.out`,
1590and each time it reaches the size limit it is renamed with the suffix
1591``.1``. Each of the existing backup files is renamed to increment the suffix
1592(``.1`` becomes ``.2``, etc.)  and the ``.6`` file is erased.
1593
1594Obviously this example sets the log length much too small as an extreme
1595example.  You would want to set *maxBytes* to an appropriate value.
1596
1597.. _format-styles:
1598
1599Use of alternative formatting styles
1600------------------------------------
1601
1602When logging was added to the Python standard library, the only way of
1603formatting messages with variable content was to use the %-formatting
1604method. Since then, Python has gained two new formatting approaches:
1605:class:`string.Template` (added in Python 2.4) and :meth:`str.format`
1606(added in Python 2.6).
1607
1608Logging (as of 3.2) provides improved support for these two additional
1609formatting styles. The :class:`Formatter` class been enhanced to take an
1610additional, optional keyword parameter named ``style``. This defaults to
1611``'%'``, but other possible values are ``'{'`` and ``'$'``, which correspond
1612to the other two formatting styles. Backwards compatibility is maintained by
1613default (as you would expect), but by explicitly specifying a style parameter,
1614you get the ability to specify format strings which work with
1615:meth:`str.format` or :class:`string.Template`. Here's an example console
1616session to show the possibilities:
1617
1618.. code-block:: pycon
1619
1620    >>> import logging
1621    >>> root = logging.getLogger()
1622    >>> root.setLevel(logging.DEBUG)
1623    >>> handler = logging.StreamHandler()
1624    >>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',
1625    ...                        style='{')
1626    >>> handler.setFormatter(bf)
1627    >>> root.addHandler(handler)
1628    >>> logger = logging.getLogger('foo.bar')
1629    >>> logger.debug('This is a DEBUG message')
1630    2010-10-28 15:11:55,341 foo.bar DEBUG    This is a DEBUG message
1631    >>> logger.critical('This is a CRITICAL message')
1632    2010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message
1633    >>> df = logging.Formatter('$asctime $name ${levelname} $message',
1634    ...                        style='$')
1635    >>> handler.setFormatter(df)
1636    >>> logger.debug('This is a DEBUG message')
1637    2010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message
1638    >>> logger.critical('This is a CRITICAL message')
1639    2010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message
1640    >>>
1641
1642Note that the formatting of logging messages for final output to logs is
1643completely independent of how an individual logging message is constructed.
1644That can still use %-formatting, as shown here::
1645
1646    >>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')
1647    2010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message
1648    >>>
1649
1650Logging calls (``logger.debug()``, ``logger.info()`` etc.) only take
1651positional parameters for the actual logging message itself, with keyword
1652parameters used only for determining options for how to handle the actual
1653logging call (e.g. the ``exc_info`` keyword parameter to indicate that
1654traceback information should be logged, or the ``extra`` keyword parameter
1655to indicate additional contextual information to be added to the log). So
1656you cannot directly make logging calls using :meth:`str.format` or
1657:class:`string.Template` syntax, because internally the logging package
1658uses %-formatting to merge the format string and the variable arguments.
1659There would be no changing this while preserving backward compatibility, since
1660all logging calls which are out there in existing code will be using %-format
1661strings.
1662
1663There is, however, a way that you can use {}- and $- formatting to construct
1664your individual log messages. Recall that for a message you can use an
1665arbitrary object as a message format string, and that the logging package will
1666call ``str()`` on that object to get the actual format string. Consider the
1667following two classes::
1668
1669    class BraceMessage:
1670        def __init__(self, fmt, /, *args, **kwargs):
1671            self.fmt = fmt
1672            self.args = args
1673            self.kwargs = kwargs
1674
1675        def __str__(self):
1676            return self.fmt.format(*self.args, **self.kwargs)
1677
1678    class DollarMessage:
1679        def __init__(self, fmt, /, **kwargs):
1680            self.fmt = fmt
1681            self.kwargs = kwargs
1682
1683        def __str__(self):
1684            from string import Template
1685            return Template(self.fmt).substitute(**self.kwargs)
1686
1687Either of these can be used in place of a format string, to allow {}- or
1688$-formatting to be used to build the actual "message" part which appears in the
1689formatted log output in place of "%(message)s" or "{message}" or "$message".
1690It's a little unwieldy to use the class names whenever you want to log
1691something, but it's quite palatable if you use an alias such as __ (double
1692underscore --- not to be confused with _, the single underscore used as a
1693synonym/alias for :func:`gettext.gettext` or its brethren).
1694
1695The above classes are not included in Python, though they're easy enough to
1696copy and paste into your own code. They can be used as follows (assuming that
1697they're declared in a module called ``wherever``):
1698
1699.. code-block:: pycon
1700
1701    >>> from wherever import BraceMessage as __
1702    >>> print(__('Message with {0} {name}', 2, name='placeholders'))
1703    Message with 2 placeholders
1704    >>> class Point: pass
1705    ...
1706    >>> p = Point()
1707    >>> p.x = 0.5
1708    >>> p.y = 0.5
1709    >>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',
1710    ...       point=p))
1711    Message with coordinates: (0.50, 0.50)
1712    >>> from wherever import DollarMessage as __
1713    >>> print(__('Message with $num $what', num=2, what='placeholders'))
1714    Message with 2 placeholders
1715    >>>
1716
1717While the above examples use ``print()`` to show how the formatting works, you
1718would of course use ``logger.debug()`` or similar to actually log using this
1719approach.
1720
1721One thing to note is that you pay no significant performance penalty with this
1722approach: the actual formatting happens not when you make the logging call, but
1723when (and if) the logged message is actually about to be output to a log by a
1724handler. So the only slightly unusual thing which might trip you up is that the
1725parentheses go around the format string and the arguments, not just the format
1726string. That's because the __ notation is just syntax sugar for a constructor
1727call to one of the XXXMessage classes.
1728
1729If you prefer, you can use a :class:`LoggerAdapter` to achieve a similar effect
1730to the above, as in the following example::
1731
1732    import logging
1733
1734    class Message:
1735        def __init__(self, fmt, args):
1736            self.fmt = fmt
1737            self.args = args
1738
1739        def __str__(self):
1740            return self.fmt.format(*self.args)
1741
1742    class StyleAdapter(logging.LoggerAdapter):
1743        def __init__(self, logger, extra=None):
1744            super().__init__(logger, extra or {})
1745
1746        def log(self, level, msg, /, *args, **kwargs):
1747            if self.isEnabledFor(level):
1748                msg, kwargs = self.process(msg, kwargs)
1749                self.logger._log(level, Message(msg, args), (), **kwargs)
1750
1751    logger = StyleAdapter(logging.getLogger(__name__))
1752
1753    def main():
1754        logger.debug('Hello, {}', 'world!')
1755
1756    if __name__ == '__main__':
1757        logging.basicConfig(level=logging.DEBUG)
1758        main()
1759
1760The above script should log the message ``Hello, world!`` when run with
1761Python 3.2 or later.
1762
1763
1764.. currentmodule:: logging
1765
1766.. _custom-logrecord:
1767
1768Customizing ``LogRecord``
1769-------------------------
1770
1771Every logging event is represented by a :class:`LogRecord` instance.
1772When an event is logged and not filtered out by a logger's level, a
1773:class:`LogRecord` is created, populated with information about the event and
1774then passed to the handlers for that logger (and its ancestors, up to and
1775including the logger where further propagation up the hierarchy is disabled).
1776Before Python 3.2, there were only two places where this creation was done:
1777
1778* :meth:`Logger.makeRecord`, which is called in the normal process of
1779  logging an event. This invoked :class:`LogRecord` directly to create an
1780  instance.
1781* :func:`makeLogRecord`, which is called with a dictionary containing
1782  attributes to be added to the LogRecord. This is typically invoked when a
1783  suitable dictionary has been received over the network (e.g. in pickle form
1784  via a :class:`~handlers.SocketHandler`, or in JSON form via an
1785  :class:`~handlers.HTTPHandler`).
1786
1787This has usually meant that if you need to do anything special with a
1788:class:`LogRecord`, you've had to do one of the following.
1789
1790* Create your own :class:`Logger` subclass, which overrides
1791  :meth:`Logger.makeRecord`, and set it using :func:`~logging.setLoggerClass`
1792  before any loggers that you care about are instantiated.
1793* Add a :class:`Filter` to a logger or handler, which does the
1794  necessary special manipulation you need when its
1795  :meth:`~Filter.filter` method is called.
1796
1797The first approach would be a little unwieldy in the scenario where (say)
1798several different libraries wanted to do different things. Each would attempt
1799to set its own :class:`Logger` subclass, and the one which did this last would
1800win.
1801
1802The second approach works reasonably well for many cases, but does not allow
1803you to e.g. use a specialized subclass of :class:`LogRecord`. Library
1804developers can set a suitable filter on their loggers, but they would have to
1805remember to do this every time they introduced a new logger (which they would
1806do simply by adding new packages or modules and doing ::
1807
1808   logger = logging.getLogger(__name__)
1809
1810at module level). It's probably one too many things to think about. Developers
1811could also add the filter to a :class:`~logging.NullHandler` attached to their
1812top-level logger, but this would not be invoked if an application developer
1813attached a handler to a lower-level library logger --- so output from that
1814handler would not reflect the intentions of the library developer.
1815
1816In Python 3.2 and later, :class:`~logging.LogRecord` creation is done through a
1817factory, which you can specify. The factory is just a callable you can set with
1818:func:`~logging.setLogRecordFactory`, and interrogate with
1819:func:`~logging.getLogRecordFactory`. The factory is invoked with the same
1820signature as the :class:`~logging.LogRecord` constructor, as :class:`LogRecord`
1821is the default setting for the factory.
1822
1823This approach allows a custom factory to control all aspects of LogRecord
1824creation. For example, you could return a subclass, or just add some additional
1825attributes to the record once created, using a pattern similar to this::
1826
1827    old_factory = logging.getLogRecordFactory()
1828
1829    def record_factory(*args, **kwargs):
1830        record = old_factory(*args, **kwargs)
1831        record.custom_attribute = 0xdecafbad
1832        return record
1833
1834    logging.setLogRecordFactory(record_factory)
1835
1836This pattern allows different libraries to chain factories together, and as
1837long as they don't overwrite each other's attributes or unintentionally
1838overwrite the attributes provided as standard, there should be no surprises.
1839However, it should be borne in mind that each link in the chain adds run-time
1840overhead to all logging operations, and the technique should only be used when
1841the use of a :class:`Filter` does not provide the desired result.
1842
1843
1844.. _zeromq-handlers:
1845
1846Subclassing QueueHandler - a ZeroMQ example
1847-------------------------------------------
1848
1849You can use a :class:`QueueHandler` subclass to send messages to other kinds
1850of queues, for example a ZeroMQ 'publish' socket. In the example below,the
1851socket is created separately and passed to the handler (as its 'queue')::
1852
1853    import zmq   # using pyzmq, the Python binding for ZeroMQ
1854    import json  # for serializing records portably
1855
1856    ctx = zmq.Context()
1857    sock = zmq.Socket(ctx, zmq.PUB)  # or zmq.PUSH, or other suitable value
1858    sock.bind('tcp://*:5556')        # or wherever
1859
1860    class ZeroMQSocketHandler(QueueHandler):
1861        def enqueue(self, record):
1862            self.queue.send_json(record.__dict__)
1863
1864
1865    handler = ZeroMQSocketHandler(sock)
1866
1867
1868Of course there are other ways of organizing this, for example passing in the
1869data needed by the handler to create the socket::
1870
1871    class ZeroMQSocketHandler(QueueHandler):
1872        def __init__(self, uri, socktype=zmq.PUB, ctx=None):
1873            self.ctx = ctx or zmq.Context()
1874            socket = zmq.Socket(self.ctx, socktype)
1875            socket.bind(uri)
1876            super().__init__(socket)
1877
1878        def enqueue(self, record):
1879            self.queue.send_json(record.__dict__)
1880
1881        def close(self):
1882            self.queue.close()
1883
1884
1885Subclassing QueueListener - a ZeroMQ example
1886--------------------------------------------
1887
1888You can also subclass :class:`QueueListener` to get messages from other kinds
1889of queues, for example a ZeroMQ 'subscribe' socket. Here's an example::
1890
1891    class ZeroMQSocketListener(QueueListener):
1892        def __init__(self, uri, /, *handlers, **kwargs):
1893            self.ctx = kwargs.get('ctx') or zmq.Context()
1894            socket = zmq.Socket(self.ctx, zmq.SUB)
1895            socket.setsockopt_string(zmq.SUBSCRIBE, '')  # subscribe to everything
1896            socket.connect(uri)
1897            super().__init__(socket, *handlers, **kwargs)
1898
1899        def dequeue(self):
1900            msg = self.queue.recv_json()
1901            return logging.makeLogRecord(msg)
1902
1903
1904.. seealso::
1905
1906   Module :mod:`logging`
1907      API reference for the logging module.
1908
1909   Module :mod:`logging.config`
1910      Configuration API for the logging module.
1911
1912   Module :mod:`logging.handlers`
1913      Useful handlers included with the logging module.
1914
1915   :ref:`A basic logging tutorial <logging-basic-tutorial>`
1916
1917   :ref:`A more advanced logging tutorial <logging-advanced-tutorial>`
1918
1919
1920An example dictionary-based configuration
1921-----------------------------------------
1922
1923Below is an example of a logging configuration dictionary - it's taken from
1924the `documentation on the Django project <https://docs.djangoproject.com/en/stable/topics/logging/#configuring-logging>`_.
1925This dictionary is passed to :func:`~config.dictConfig` to put the configuration into effect::
1926
1927    LOGGING = {
1928        'version': 1,
1929        'disable_existing_loggers': True,
1930        'formatters': {
1931            'verbose': {
1932                'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
1933            },
1934            'simple': {
1935                'format': '%(levelname)s %(message)s'
1936            },
1937        },
1938        'filters': {
1939            'special': {
1940                '()': 'project.logging.SpecialFilter',
1941                'foo': 'bar',
1942            }
1943        },
1944        'handlers': {
1945            'null': {
1946                'level':'DEBUG',
1947                'class':'django.utils.log.NullHandler',
1948            },
1949            'console':{
1950                'level':'DEBUG',
1951                'class':'logging.StreamHandler',
1952                'formatter': 'simple'
1953            },
1954            'mail_admins': {
1955                'level': 'ERROR',
1956                'class': 'django.utils.log.AdminEmailHandler',
1957                'filters': ['special']
1958            }
1959        },
1960        'loggers': {
1961            'django': {
1962                'handlers':['null'],
1963                'propagate': True,
1964                'level':'INFO',
1965            },
1966            'django.request': {
1967                'handlers': ['mail_admins'],
1968                'level': 'ERROR',
1969                'propagate': False,
1970            },
1971            'myproject.custom': {
1972                'handlers': ['console', 'mail_admins'],
1973                'level': 'INFO',
1974                'filters': ['special']
1975            }
1976        }
1977    }
1978
1979For more information about this configuration, you can see the `relevant
1980section <https://docs.djangoproject.com/en/stable/topics/logging/#configuring-logging>`_
1981of the Django documentation.
1982
1983.. _cookbook-rotator-namer:
1984
1985Using a rotator and namer to customize log rotation processing
1986--------------------------------------------------------------
1987
1988An example of how you can define a namer and rotator is given in the following
1989runnable script, which shows gzip compression of the log file::
1990
1991    import gzip
1992    import logging
1993    import logging.handlers
1994    import os
1995    import shutil
1996
1997    def namer(name):
1998        return name + ".gz"
1999
2000    def rotator(source, dest):
2001        with open(source, 'rb') as f_in:
2002            with gzip.open(dest, 'wb') as f_out:
2003                shutil.copyfileobj(f_in, f_out)
2004        os.remove(source)
2005
2006
2007    rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)
2008    rh.rotator = rotator
2009    rh.namer = namer
2010
2011    root = logging.getLogger()
2012    root.setLevel(logging.INFO)
2013    root.addHandler(rh)
2014    f = logging.Formatter('%(asctime)s %(message)s')
2015    rh.setFormatter(f)
2016    for i in range(1000):
2017        root.info(f'Message no. {i + 1}')
2018
2019After running this, you will see six new files, five of which are compressed:
2020
2021.. code-block:: shell-session
2022
2023    $ ls rotated.log*
2024    rotated.log       rotated.log.2.gz  rotated.log.4.gz
2025    rotated.log.1.gz  rotated.log.3.gz  rotated.log.5.gz
2026    $ zcat rotated.log.1.gz
2027    2023-01-20 02:28:17,767 Message no. 996
2028    2023-01-20 02:28:17,767 Message no. 997
2029    2023-01-20 02:28:17,767 Message no. 998
2030
2031A more elaborate multiprocessing example
2032----------------------------------------
2033
2034The following working example shows how logging can be used with multiprocessing
2035using configuration files. The configurations are fairly simple, but serve to
2036illustrate how more complex ones could be implemented in a real multiprocessing
2037scenario.
2038
2039In the example, the main process spawns a listener process and some worker
2040processes. Each of the main process, the listener and the workers have three
2041separate configurations (the workers all share the same configuration). We can
2042see logging in the main process, how the workers log to a QueueHandler and how
2043the listener implements a QueueListener and a more complex logging
2044configuration, and arranges to dispatch events received via the queue to the
2045handlers specified in the configuration. Note that these configurations are
2046purely illustrative, but you should be able to adapt this example to your own
2047scenario.
2048
2049Here's the script - the docstrings and the comments hopefully explain how it
2050works::
2051
2052    import logging
2053    import logging.config
2054    import logging.handlers
2055    from multiprocessing import Process, Queue, Event, current_process
2056    import os
2057    import random
2058    import time
2059
2060    class MyHandler:
2061        """
2062        A simple handler for logging events. It runs in the listener process and
2063        dispatches events to loggers based on the name in the received record,
2064        which then get dispatched, by the logging system, to the handlers
2065        configured for those loggers.
2066        """
2067
2068        def handle(self, record):
2069            if record.name == "root":
2070                logger = logging.getLogger()
2071            else:
2072                logger = logging.getLogger(record.name)
2073
2074            if logger.isEnabledFor(record.levelno):
2075                # The process name is transformed just to show that it's the listener
2076                # doing the logging to files and console
2077                record.processName = '%s (for %s)' % (current_process().name, record.processName)
2078                logger.handle(record)
2079
2080    def listener_process(q, stop_event, config):
2081        """
2082        This could be done in the main process, but is just done in a separate
2083        process for illustrative purposes.
2084
2085        This initialises logging according to the specified configuration,
2086        starts the listener and waits for the main process to signal completion
2087        via the event. The listener is then stopped, and the process exits.
2088        """
2089        logging.config.dictConfig(config)
2090        listener = logging.handlers.QueueListener(q, MyHandler())
2091        listener.start()
2092        if os.name == 'posix':
2093            # On POSIX, the setup logger will have been configured in the
2094            # parent process, but should have been disabled following the
2095            # dictConfig call.
2096            # On Windows, since fork isn't used, the setup logger won't
2097            # exist in the child, so it would be created and the message
2098            # would appear - hence the "if posix" clause.
2099            logger = logging.getLogger('setup')
2100            logger.critical('Should not appear, because of disabled logger ...')
2101        stop_event.wait()
2102        listener.stop()
2103
2104    def worker_process(config):
2105        """
2106        A number of these are spawned for the purpose of illustration. In
2107        practice, they could be a heterogeneous bunch of processes rather than
2108        ones which are identical to each other.
2109
2110        This initialises logging according to the specified configuration,
2111        and logs a hundred messages with random levels to randomly selected
2112        loggers.
2113
2114        A small sleep is added to allow other processes a chance to run. This
2115        is not strictly needed, but it mixes the output from the different
2116        processes a bit more than if it's left out.
2117        """
2118        logging.config.dictConfig(config)
2119        levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
2120                  logging.CRITICAL]
2121        loggers = ['foo', 'foo.bar', 'foo.bar.baz',
2122                   'spam', 'spam.ham', 'spam.ham.eggs']
2123        if os.name == 'posix':
2124            # On POSIX, the setup logger will have been configured in the
2125            # parent process, but should have been disabled following the
2126            # dictConfig call.
2127            # On Windows, since fork isn't used, the setup logger won't
2128            # exist in the child, so it would be created and the message
2129            # would appear - hence the "if posix" clause.
2130            logger = logging.getLogger('setup')
2131            logger.critical('Should not appear, because of disabled logger ...')
2132        for i in range(100):
2133            lvl = random.choice(levels)
2134            logger = logging.getLogger(random.choice(loggers))
2135            logger.log(lvl, 'Message no. %d', i)
2136            time.sleep(0.01)
2137
2138    def main():
2139        q = Queue()
2140        # The main process gets a simple configuration which prints to the console.
2141        config_initial = {
2142            'version': 1,
2143            'handlers': {
2144                'console': {
2145                    'class': 'logging.StreamHandler',
2146                    'level': 'INFO'
2147                }
2148            },
2149            'root': {
2150                'handlers': ['console'],
2151                'level': 'DEBUG'
2152            }
2153        }
2154        # The worker process configuration is just a QueueHandler attached to the
2155        # root logger, which allows all messages to be sent to the queue.
2156        # We disable existing loggers to disable the "setup" logger used in the
2157        # parent process. This is needed on POSIX because the logger will
2158        # be there in the child following a fork().
2159        config_worker = {
2160            'version': 1,
2161            'disable_existing_loggers': True,
2162            'handlers': {
2163                'queue': {
2164                    'class': 'logging.handlers.QueueHandler',
2165                    'queue': q
2166                }
2167            },
2168            'root': {
2169                'handlers': ['queue'],
2170                'level': 'DEBUG'
2171            }
2172        }
2173        # The listener process configuration shows that the full flexibility of
2174        # logging configuration is available to dispatch events to handlers however
2175        # you want.
2176        # We disable existing loggers to disable the "setup" logger used in the
2177        # parent process. This is needed on POSIX because the logger will
2178        # be there in the child following a fork().
2179        config_listener = {
2180            'version': 1,
2181            'disable_existing_loggers': True,
2182            'formatters': {
2183                'detailed': {
2184                    'class': 'logging.Formatter',
2185                    'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
2186                },
2187                'simple': {
2188                    'class': 'logging.Formatter',
2189                    'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
2190                }
2191            },
2192            'handlers': {
2193                'console': {
2194                    'class': 'logging.StreamHandler',
2195                    'formatter': 'simple',
2196                    'level': 'INFO'
2197                },
2198                'file': {
2199                    'class': 'logging.FileHandler',
2200                    'filename': 'mplog.log',
2201                    'mode': 'w',
2202                    'formatter': 'detailed'
2203                },
2204                'foofile': {
2205                    'class': 'logging.FileHandler',
2206                    'filename': 'mplog-foo.log',
2207                    'mode': 'w',
2208                    'formatter': 'detailed'
2209                },
2210                'errors': {
2211                    'class': 'logging.FileHandler',
2212                    'filename': 'mplog-errors.log',
2213                    'mode': 'w',
2214                    'formatter': 'detailed',
2215                    'level': 'ERROR'
2216                }
2217            },
2218            'loggers': {
2219                'foo': {
2220                    'handlers': ['foofile']
2221                }
2222            },
2223            'root': {
2224                'handlers': ['console', 'file', 'errors'],
2225                'level': 'DEBUG'
2226            }
2227        }
2228        # Log some initial events, just to show that logging in the parent works
2229        # normally.
2230        logging.config.dictConfig(config_initial)
2231        logger = logging.getLogger('setup')
2232        logger.info('About to create workers ...')
2233        workers = []
2234        for i in range(5):
2235            wp = Process(target=worker_process, name='worker %d' % (i + 1),
2236                         args=(config_worker,))
2237            workers.append(wp)
2238            wp.start()
2239            logger.info('Started worker: %s', wp.name)
2240        logger.info('About to create listener ...')
2241        stop_event = Event()
2242        lp = Process(target=listener_process, name='listener',
2243                     args=(q, stop_event, config_listener))
2244        lp.start()
2245        logger.info('Started listener')
2246        # We now hang around for the workers to finish their work.
2247        for wp in workers:
2248            wp.join()
2249        # Workers all done, listening can now stop.
2250        # Logging in the parent still works normally.
2251        logger.info('Telling listener to stop ...')
2252        stop_event.set()
2253        lp.join()
2254        logger.info('All done.')
2255
2256    if __name__ == '__main__':
2257        main()
2258
2259
2260Inserting a BOM into messages sent to a SysLogHandler
2261-----------------------------------------------------
2262
2263:rfc:`5424` requires that a
2264Unicode message be sent to a syslog daemon as a set of bytes which have the
2265following structure: an optional pure-ASCII component, followed by a UTF-8 Byte
2266Order Mark (BOM), followed by Unicode encoded using UTF-8. (See the
2267:rfc:`relevant section of the specification <5424#section-6>`.)
2268
2269In Python 3.1, code was added to
2270:class:`~logging.handlers.SysLogHandler` to insert a BOM into the message, but
2271unfortunately, it was implemented incorrectly, with the BOM appearing at the
2272beginning of the message and hence not allowing any pure-ASCII component to
2273appear before it.
2274
2275As this behaviour is broken, the incorrect BOM insertion code is being removed
2276from Python 3.2.4 and later. However, it is not being replaced, and if you
2277want to produce :rfc:`5424`-compliant messages which include a BOM, an optional
2278pure-ASCII sequence before it and arbitrary Unicode after it, encoded using
2279UTF-8, then you need to do the following:
2280
2281#. Attach a :class:`~logging.Formatter` instance to your
2282   :class:`~logging.handlers.SysLogHandler` instance, with a format string
2283   such as::
2284
2285      'ASCII section\ufeffUnicode section'
2286
2287   The Unicode code point U+FEFF, when encoded using UTF-8, will be
2288   encoded as a UTF-8 BOM -- the byte-string ``b'\xef\xbb\xbf'``.
2289
2290#. Replace the ASCII section with whatever placeholders you like, but make sure
2291   that the data that appears in there after substitution is always ASCII (that
2292   way, it will remain unchanged after UTF-8 encoding).
2293
2294#. Replace the Unicode section with whatever placeholders you like; if the data
2295   which appears there after substitution contains characters outside the ASCII
2296   range, that's fine -- it will be encoded using UTF-8.
2297
2298The formatted message *will* be encoded using UTF-8 encoding by
2299``SysLogHandler``. If you follow the above rules, you should be able to produce
2300:rfc:`5424`-compliant messages. If you don't, logging may not complain, but your
2301messages will not be RFC 5424-compliant, and your syslog daemon may complain.
2302
2303
2304Implementing structured logging
2305-------------------------------
2306
2307Although most logging messages are intended for reading by humans, and thus not
2308readily machine-parseable, there might be circumstances where you want to output
2309messages in a structured format which *is* capable of being parsed by a program
2310(without needing complex regular expressions to parse the log message). This is
2311straightforward to achieve using the logging package. There are a number of
2312ways in which this could be achieved, but the following is a simple approach
2313which uses JSON to serialise the event in a machine-parseable manner::
2314
2315    import json
2316    import logging
2317
2318    class StructuredMessage:
2319        def __init__(self, message, /, **kwargs):
2320            self.message = message
2321            self.kwargs = kwargs
2322
2323        def __str__(self):
2324            return '%s >>> %s' % (self.message, json.dumps(self.kwargs))
2325
2326    _ = StructuredMessage   # optional, to improve readability
2327
2328    logging.basicConfig(level=logging.INFO, format='%(message)s')
2329    logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))
2330
2331If the above script is run, it prints:
2332
2333.. code-block:: none
2334
2335    message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}
2336
2337Note that the order of items might be different according to the version of
2338Python used.
2339
2340If you need more specialised processing, you can use a custom JSON encoder,
2341as in the following complete example::
2342
2343    import json
2344    import logging
2345
2346
2347    class Encoder(json.JSONEncoder):
2348        def default(self, o):
2349            if isinstance(o, set):
2350                return tuple(o)
2351            elif isinstance(o, str):
2352                return o.encode('unicode_escape').decode('ascii')
2353            return super().default(o)
2354
2355    class StructuredMessage:
2356        def __init__(self, message, /, **kwargs):
2357            self.message = message
2358            self.kwargs = kwargs
2359
2360        def __str__(self):
2361            s = Encoder().encode(self.kwargs)
2362            return '%s >>> %s' % (self.message, s)
2363
2364    _ = StructuredMessage   # optional, to improve readability
2365
2366    def main():
2367        logging.basicConfig(level=logging.INFO, format='%(message)s')
2368        logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))
2369
2370    if __name__ == '__main__':
2371        main()
2372
2373When the above script is run, it prints:
2374
2375.. code-block:: none
2376
2377    message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}
2378
2379Note that the order of items might be different according to the version of
2380Python used.
2381
2382
2383.. _custom-handlers:
2384
2385.. currentmodule:: logging.config
2386
2387Customizing handlers with :func:`dictConfig`
2388--------------------------------------------
2389
2390There are times when you want to customize logging handlers in particular ways,
2391and if you use :func:`dictConfig` you may be able to do this without
2392subclassing. As an example, consider that you may want to set the ownership of a
2393log file. On POSIX, this is easily done using :func:`shutil.chown`, but the file
2394handlers in the stdlib don't offer built-in support. You can customize handler
2395creation using a plain function such as::
2396
2397    def owned_file_handler(filename, mode='a', encoding=None, owner=None):
2398        if owner:
2399            if not os.path.exists(filename):
2400                open(filename, 'a').close()
2401            shutil.chown(filename, *owner)
2402        return logging.FileHandler(filename, mode, encoding)
2403
2404You can then specify, in a logging configuration passed to :func:`dictConfig`,
2405that a logging handler be created by calling this function::
2406
2407    LOGGING = {
2408        'version': 1,
2409        'disable_existing_loggers': False,
2410        'formatters': {
2411            'default': {
2412                'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
2413            },
2414        },
2415        'handlers': {
2416            'file':{
2417                # The values below are popped from this dictionary and
2418                # used to create the handler, set the handler's level and
2419                # its formatter.
2420                '()': owned_file_handler,
2421                'level':'DEBUG',
2422                'formatter': 'default',
2423                # The values below are passed to the handler creator callable
2424                # as keyword arguments.
2425                'owner': ['pulse', 'pulse'],
2426                'filename': 'chowntest.log',
2427                'mode': 'w',
2428                'encoding': 'utf-8',
2429            },
2430        },
2431        'root': {
2432            'handlers': ['file'],
2433            'level': 'DEBUG',
2434        },
2435    }
2436
2437In this example I am setting the ownership using the ``pulse`` user and group,
2438just for the purposes of illustration. Putting it together into a working
2439script, ``chowntest.py``::
2440
2441    import logging, logging.config, os, shutil
2442
2443    def owned_file_handler(filename, mode='a', encoding=None, owner=None):
2444        if owner:
2445            if not os.path.exists(filename):
2446                open(filename, 'a').close()
2447            shutil.chown(filename, *owner)
2448        return logging.FileHandler(filename, mode, encoding)
2449
2450    LOGGING = {
2451        'version': 1,
2452        'disable_existing_loggers': False,
2453        'formatters': {
2454            'default': {
2455                'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
2456            },
2457        },
2458        'handlers': {
2459            'file':{
2460                # The values below are popped from this dictionary and
2461                # used to create the handler, set the handler's level and
2462                # its formatter.
2463                '()': owned_file_handler,
2464                'level':'DEBUG',
2465                'formatter': 'default',
2466                # The values below are passed to the handler creator callable
2467                # as keyword arguments.
2468                'owner': ['pulse', 'pulse'],
2469                'filename': 'chowntest.log',
2470                'mode': 'w',
2471                'encoding': 'utf-8',
2472            },
2473        },
2474        'root': {
2475            'handlers': ['file'],
2476            'level': 'DEBUG',
2477        },
2478    }
2479
2480    logging.config.dictConfig(LOGGING)
2481    logger = logging.getLogger('mylogger')
2482    logger.debug('A debug message')
2483
2484To run this, you will probably need to run as ``root``:
2485
2486.. code-block:: shell-session
2487
2488    $ sudo python3.3 chowntest.py
2489    $ cat chowntest.log
2490    2013-11-05 09:34:51,128 DEBUG mylogger A debug message
2491    $ ls -l chowntest.log
2492    -rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log
2493
2494Note that this example uses Python 3.3 because that's where :func:`shutil.chown`
2495makes an appearance. This approach should work with any Python version that
2496supports :func:`dictConfig` - namely, Python 2.7, 3.2 or later. With pre-3.3
2497versions, you would need to implement the actual ownership change using e.g.
2498:func:`os.chown`.
2499
2500In practice, the handler-creating function may be in a utility module somewhere
2501in your project. Instead of the line in the configuration::
2502
2503    '()': owned_file_handler,
2504
2505you could use e.g.::
2506
2507    '()': 'ext://project.util.owned_file_handler',
2508
2509where ``project.util`` can be replaced with the actual name of the package
2510where the function resides. In the above working script, using
2511``'ext://__main__.owned_file_handler'`` should work. Here, the actual callable
2512is resolved by :func:`dictConfig` from the ``ext://`` specification.
2513
2514This example hopefully also points the way to how you could implement other
2515types of file change - e.g. setting specific POSIX permission bits - in the
2516same way, using :func:`os.chmod`.
2517
2518Of course, the approach could also be extended to types of handler other than a
2519:class:`~logging.FileHandler` - for example, one of the rotating file handlers,
2520or a different type of handler altogether.
2521
2522
2523.. currentmodule:: logging
2524
2525.. _formatting-styles:
2526
2527Using particular formatting styles throughout your application
2528--------------------------------------------------------------
2529
2530In Python 3.2, the :class:`~logging.Formatter` gained a ``style`` keyword
2531parameter which, while defaulting to ``%`` for backward compatibility, allowed
2532the specification of ``{`` or ``$`` to support the formatting approaches
2533supported by :meth:`str.format` and :class:`string.Template`. Note that this
2534governs the formatting of logging messages for final output to logs, and is
2535completely orthogonal to how an individual logging message is constructed.
2536
2537Logging calls (:meth:`~Logger.debug`, :meth:`~Logger.info` etc.) only take
2538positional parameters for the actual logging message itself, with keyword
2539parameters used only for determining options for how to handle the logging call
2540(e.g. the ``exc_info`` keyword parameter to indicate that traceback information
2541should be logged, or the ``extra`` keyword parameter to indicate additional
2542contextual information to be added to the log). So you cannot directly make
2543logging calls using :meth:`str.format` or :class:`string.Template` syntax,
2544because internally the logging package uses %-formatting to merge the format
2545string and the variable arguments. There would be no changing this while preserving
2546backward compatibility, since all logging calls which are out there in existing
2547code will be using %-format strings.
2548
2549There have been suggestions to associate format styles with specific loggers,
2550but that approach also runs into backward compatibility problems because any
2551existing code could be using a given logger name and using %-formatting.
2552
2553For logging to work interoperably between any third-party libraries and your
2554code, decisions about formatting need to be made at the level of the
2555individual logging call. This opens up a couple of ways in which alternative
2556formatting styles can be accommodated.
2557
2558
2559Using LogRecord factories
2560^^^^^^^^^^^^^^^^^^^^^^^^^
2561
2562In Python 3.2, along with the :class:`~logging.Formatter` changes mentioned
2563above, the logging package gained the ability to allow users to set their own
2564:class:`LogRecord` subclasses, using the :func:`setLogRecordFactory` function.
2565You can use this to set your own subclass of :class:`LogRecord`, which does the
2566Right Thing by overriding the :meth:`~LogRecord.getMessage` method. The base
2567class implementation of this method is where the ``msg % args`` formatting
2568happens, and where you can substitute your alternate formatting; however, you
2569should be careful to support all formatting styles and allow %-formatting as
2570the default, to ensure interoperability with other code. Care should also be
2571taken to call ``str(self.msg)``, just as the base implementation does.
2572
2573Refer to the reference documentation on :func:`setLogRecordFactory` and
2574:class:`LogRecord` for more information.
2575
2576
2577Using custom message objects
2578^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2579
2580There is another, perhaps simpler way that you can use {}- and $- formatting to
2581construct your individual log messages. You may recall (from
2582:ref:`arbitrary-object-messages`) that when logging you can use an arbitrary
2583object as a message format string, and that the logging package will call
2584:func:`str` on that object to get the actual format string. Consider the
2585following two classes::
2586
2587    class BraceMessage:
2588        def __init__(self, fmt, /, *args, **kwargs):
2589            self.fmt = fmt
2590            self.args = args
2591            self.kwargs = kwargs
2592
2593        def __str__(self):
2594            return self.fmt.format(*self.args, **self.kwargs)
2595
2596    class DollarMessage:
2597        def __init__(self, fmt, /, **kwargs):
2598            self.fmt = fmt
2599            self.kwargs = kwargs
2600
2601        def __str__(self):
2602            from string import Template
2603            return Template(self.fmt).substitute(**self.kwargs)
2604
2605Either of these can be used in place of a format string, to allow {}- or
2606$-formatting to be used to build the actual "message" part which appears in the
2607formatted log output in place of “%(message)s” or “{message}” or “$message”.
2608If you find it a little unwieldy to use the class names whenever you want to log
2609something, you can make it more palatable if you use an alias such as ``M`` or
2610``_`` for the message (or perhaps ``__``, if you are using ``_`` for
2611localization).
2612
2613Examples of this approach are given below. Firstly, formatting with
2614:meth:`str.format`::
2615
2616    >>> __ = BraceMessage
2617    >>> print(__('Message with {0} {1}', 2, 'placeholders'))
2618    Message with 2 placeholders
2619    >>> class Point: pass
2620    ...
2621    >>> p = Point()
2622    >>> p.x = 0.5
2623    >>> p.y = 0.5
2624    >>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))
2625    Message with coordinates: (0.50, 0.50)
2626
2627Secondly, formatting with :class:`string.Template`::
2628
2629    >>> __ = DollarMessage
2630    >>> print(__('Message with $num $what', num=2, what='placeholders'))
2631    Message with 2 placeholders
2632    >>>
2633
2634One thing to note is that you pay no significant performance penalty with this
2635approach: the actual formatting happens not when you make the logging call, but
2636when (and if) the logged message is actually about to be output to a log by a
2637handler. So the only slightly unusual thing which might trip you up is that the
2638parentheses go around the format string and the arguments, not just the format
2639string. That’s because the __ notation is just syntax sugar for a constructor
2640call to one of the ``XXXMessage`` classes shown above.
2641
2642
2643.. _filters-dictconfig:
2644
2645.. currentmodule:: logging.config
2646
2647Configuring filters with :func:`dictConfig`
2648-------------------------------------------
2649
2650You *can* configure filters using :func:`~logging.config.dictConfig`, though it
2651might not be obvious at first glance how to do it (hence this recipe). Since
2652:class:`~logging.Filter` is the only filter class included in the standard
2653library, and it is unlikely to cater to many requirements (it's only there as a
2654base class), you will typically need to define your own :class:`~logging.Filter`
2655subclass with an overridden :meth:`~logging.Filter.filter` method. To do this,
2656specify the ``()`` key in the configuration dictionary for the filter,
2657specifying a callable which will be used to create the filter (a class is the
2658most obvious, but you can provide any callable which returns a
2659:class:`~logging.Filter` instance). Here is a complete example::
2660
2661    import logging
2662    import logging.config
2663    import sys
2664
2665    class MyFilter(logging.Filter):
2666        def __init__(self, param=None):
2667            self.param = param
2668
2669        def filter(self, record):
2670            if self.param is None:
2671                allow = True
2672            else:
2673                allow = self.param not in record.msg
2674            if allow:
2675                record.msg = 'changed: ' + record.msg
2676            return allow
2677
2678    LOGGING = {
2679        'version': 1,
2680        'filters': {
2681            'myfilter': {
2682                '()': MyFilter,
2683                'param': 'noshow',
2684            }
2685        },
2686        'handlers': {
2687            'console': {
2688                'class': 'logging.StreamHandler',
2689                'filters': ['myfilter']
2690            }
2691        },
2692        'root': {
2693            'level': 'DEBUG',
2694            'handlers': ['console']
2695        },
2696    }
2697
2698    if __name__ == '__main__':
2699        logging.config.dictConfig(LOGGING)
2700        logging.debug('hello')
2701        logging.debug('hello - noshow')
2702
2703This example shows how you can pass configuration data to the callable which
2704constructs the instance, in the form of keyword parameters. When run, the above
2705script will print:
2706
2707.. code-block:: none
2708
2709    changed: hello
2710
2711which shows that the filter is working as configured.
2712
2713A couple of extra points to note:
2714
2715* If you can't refer to the callable directly in the configuration (e.g. if it
2716  lives in a different module, and you can't import it directly where the
2717  configuration dictionary is), you can use the form ``ext://...`` as described
2718  in :ref:`logging-config-dict-externalobj`. For example, you could have used
2719  the text ``'ext://__main__.MyFilter'`` instead of ``MyFilter`` in the above
2720  example.
2721
2722* As well as for filters, this technique can also be used to configure custom
2723  handlers and formatters. See :ref:`logging-config-dict-userdef` for more
2724  information on how logging supports using user-defined objects in its
2725  configuration, and see the other cookbook recipe :ref:`custom-handlers` above.
2726
2727
2728.. _custom-format-exception:
2729
2730Customized exception formatting
2731-------------------------------
2732
2733There might be times when you want to do customized exception formatting - for
2734argument's sake, let's say you want exactly one line per logged event, even
2735when exception information is present. You can do this with a custom formatter
2736class, as shown in the following example::
2737
2738    import logging
2739
2740    class OneLineExceptionFormatter(logging.Formatter):
2741        def formatException(self, exc_info):
2742            """
2743            Format an exception so that it prints on a single line.
2744            """
2745            result = super().formatException(exc_info)
2746            return repr(result)  # or format into one line however you want to
2747
2748        def format(self, record):
2749            s = super().format(record)
2750            if record.exc_text:
2751                s = s.replace('\n', '') + '|'
2752            return s
2753
2754    def configure_logging():
2755        fh = logging.FileHandler('output.txt', 'w')
2756        f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',
2757                                      '%d/%m/%Y %H:%M:%S')
2758        fh.setFormatter(f)
2759        root = logging.getLogger()
2760        root.setLevel(logging.DEBUG)
2761        root.addHandler(fh)
2762
2763    def main():
2764        configure_logging()
2765        logging.info('Sample message')
2766        try:
2767            x = 1 / 0
2768        except ZeroDivisionError as e:
2769            logging.exception('ZeroDivisionError: %s', e)
2770
2771    if __name__ == '__main__':
2772        main()
2773
2774When run, this produces a file with exactly two lines:
2775
2776.. code-block:: none
2777
2778    28/01/2015 07:21:23|INFO|Sample message|
2779    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'|
2780
2781While the above treatment is simplistic, it points the way to how exception
2782information can be formatted to your liking. The :mod:`traceback` module may be
2783helpful for more specialized needs.
2784
2785.. _spoken-messages:
2786
2787Speaking logging messages
2788-------------------------
2789
2790There might be situations when it is desirable to have logging messages rendered
2791in an audible rather than a visible format. This is easy to do if you have
2792text-to-speech (TTS) functionality available in your system, even if it doesn't have
2793a Python binding. Most TTS systems have a command line program you can run, and
2794this can be invoked from a handler using :mod:`subprocess`. It's assumed here
2795that TTS command line programs won't expect to interact with users or take a
2796long time to complete, and that the frequency of logged messages will be not so
2797high as to swamp the user with messages, and that it's acceptable to have the
2798messages spoken one at a time rather than concurrently, The example implementation
2799below waits for one message to be spoken before the next is processed, and this
2800might cause other handlers to be kept waiting. Here is a short example showing
2801the approach, which assumes that the ``espeak`` TTS package is available::
2802
2803    import logging
2804    import subprocess
2805    import sys
2806
2807    class TTSHandler(logging.Handler):
2808        def emit(self, record):
2809            msg = self.format(record)
2810            # Speak slowly in a female English voice
2811            cmd = ['espeak', '-s150', '-ven+f3', msg]
2812            p = subprocess.Popen(cmd, stdout=subprocess.PIPE,
2813                                 stderr=subprocess.STDOUT)
2814            # wait for the program to finish
2815            p.communicate()
2816
2817    def configure_logging():
2818        h = TTSHandler()
2819        root = logging.getLogger()
2820        root.addHandler(h)
2821        # the default formatter just returns the message
2822        root.setLevel(logging.DEBUG)
2823
2824    def main():
2825        logging.info('Hello')
2826        logging.debug('Goodbye')
2827
2828    if __name__ == '__main__':
2829        configure_logging()
2830        sys.exit(main())
2831
2832When run, this script should say "Hello" and then "Goodbye" in a female voice.
2833
2834The above approach can, of course, be adapted to other TTS systems and even
2835other systems altogether which can process messages via external programs run
2836from a command line.
2837
2838
2839.. _buffered-logging:
2840
2841Buffering logging messages and outputting them conditionally
2842------------------------------------------------------------
2843
2844There might be situations where you want to log messages in a temporary area
2845and only output them if a certain condition occurs. For example, you may want to
2846start logging debug events in a function, and if the function completes without
2847errors, you don't want to clutter the log with the collected debug information,
2848but if there is an error, you want all the debug information to be output as well
2849as the error.
2850
2851Here is an example which shows how you could do this using a decorator for your
2852functions where you want logging to behave this way. It makes use of the
2853:class:`logging.handlers.MemoryHandler`, which allows buffering of logged events
2854until some condition occurs, at which point the buffered events are ``flushed``
2855- passed to another handler (the ``target`` handler) for processing. By default,
2856the ``MemoryHandler`` flushed when its buffer gets filled up or an event whose
2857level is greater than or equal to a specified threshold is seen. You can use this
2858recipe with a more specialised subclass of ``MemoryHandler`` if you want custom
2859flushing behavior.
2860
2861The example script has a simple function, ``foo``, which just cycles through
2862all the logging levels, writing to ``sys.stderr`` to say what level it's about
2863to log at, and then actually logging a message at that level. You can pass a
2864parameter to ``foo`` which, if true, will log at ERROR and CRITICAL levels -
2865otherwise, it only logs at DEBUG, INFO and WARNING levels.
2866
2867The script just arranges to decorate ``foo`` with a decorator which will do the
2868conditional logging that's required. The decorator takes a logger as a parameter
2869and attaches a memory handler for the duration of the call to the decorated
2870function. The decorator can be additionally parameterised using a target handler,
2871a level at which flushing should occur, and a capacity for the buffer (number of
2872records buffered). These default to a :class:`~logging.StreamHandler` which
2873writes to ``sys.stderr``, ``logging.ERROR`` and ``100`` respectively.
2874
2875Here's the script::
2876
2877    import logging
2878    from logging.handlers import MemoryHandler
2879    import sys
2880
2881    logger = logging.getLogger(__name__)
2882    logger.addHandler(logging.NullHandler())
2883
2884    def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):
2885        if target_handler is None:
2886            target_handler = logging.StreamHandler()
2887        if flush_level is None:
2888            flush_level = logging.ERROR
2889        if capacity is None:
2890            capacity = 100
2891        handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)
2892
2893        def decorator(fn):
2894            def wrapper(*args, **kwargs):
2895                logger.addHandler(handler)
2896                try:
2897                    return fn(*args, **kwargs)
2898                except Exception:
2899                    logger.exception('call failed')
2900                    raise
2901                finally:
2902                    super(MemoryHandler, handler).flush()
2903                    logger.removeHandler(handler)
2904            return wrapper
2905
2906        return decorator
2907
2908    def write_line(s):
2909        sys.stderr.write('%s\n' % s)
2910
2911    def foo(fail=False):
2912        write_line('about to log at DEBUG ...')
2913        logger.debug('Actually logged at DEBUG')
2914        write_line('about to log at INFO ...')
2915        logger.info('Actually logged at INFO')
2916        write_line('about to log at WARNING ...')
2917        logger.warning('Actually logged at WARNING')
2918        if fail:
2919            write_line('about to log at ERROR ...')
2920            logger.error('Actually logged at ERROR')
2921            write_line('about to log at CRITICAL ...')
2922            logger.critical('Actually logged at CRITICAL')
2923        return fail
2924
2925    decorated_foo = log_if_errors(logger)(foo)
2926
2927    if __name__ == '__main__':
2928        logger.setLevel(logging.DEBUG)
2929        write_line('Calling undecorated foo with False')
2930        assert not foo(False)
2931        write_line('Calling undecorated foo with True')
2932        assert foo(True)
2933        write_line('Calling decorated foo with False')
2934        assert not decorated_foo(False)
2935        write_line('Calling decorated foo with True')
2936        assert decorated_foo(True)
2937
2938When this script is run, the following output should be observed:
2939
2940.. code-block:: none
2941
2942    Calling undecorated foo with False
2943    about to log at DEBUG ...
2944    about to log at INFO ...
2945    about to log at WARNING ...
2946    Calling undecorated foo with True
2947    about to log at DEBUG ...
2948    about to log at INFO ...
2949    about to log at WARNING ...
2950    about to log at ERROR ...
2951    about to log at CRITICAL ...
2952    Calling decorated foo with False
2953    about to log at DEBUG ...
2954    about to log at INFO ...
2955    about to log at WARNING ...
2956    Calling decorated foo with True
2957    about to log at DEBUG ...
2958    about to log at INFO ...
2959    about to log at WARNING ...
2960    about to log at ERROR ...
2961    Actually logged at DEBUG
2962    Actually logged at INFO
2963    Actually logged at WARNING
2964    Actually logged at ERROR
2965    about to log at CRITICAL ...
2966    Actually logged at CRITICAL
2967
2968As you can see, actual logging output only occurs when an event is logged whose
2969severity is ERROR or greater, but in that case, any previous events at lower
2970severities are also logged.
2971
2972You can of course use the conventional means of decoration::
2973
2974    @log_if_errors(logger)
2975    def foo(fail=False):
2976        ...
2977
2978
2979.. _buffered-smtp:
2980
2981Sending logging messages to email, with buffering
2982-------------------------------------------------
2983
2984To illustrate how you can send log messages via email, so that a set number of
2985messages are sent per email, you can subclass
2986:class:`~logging.handlers.BufferingHandler`. In the following  example, which you can
2987adapt to suit your specific needs, a simple test harness is provided which allows you
2988to run the script with command line arguments specifying what you typically need to
2989send things via SMTP. (Run the downloaded script with the ``-h`` argument to see the
2990required and optional arguments.)
2991
2992.. code-block:: python
2993
2994    import logging
2995    import logging.handlers
2996    import smtplib
2997
2998    class BufferingSMTPHandler(logging.handlers.BufferingHandler):
2999        def __init__(self, mailhost, port, username, password, fromaddr, toaddrs,
3000                     subject, capacity):
3001            logging.handlers.BufferingHandler.__init__(self, capacity)
3002            self.mailhost = mailhost
3003            self.mailport = port
3004            self.username = username
3005            self.password = password
3006            self.fromaddr = fromaddr
3007            if isinstance(toaddrs, str):
3008                toaddrs = [toaddrs]
3009            self.toaddrs = toaddrs
3010            self.subject = subject
3011            self.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s"))
3012
3013        def flush(self):
3014            if len(self.buffer) > 0:
3015                try:
3016                    smtp = smtplib.SMTP(self.mailhost, self.mailport)
3017                    smtp.starttls()
3018                    smtp.login(self.username, self.password)
3019                    msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\n\r\n" % (self.fromaddr, ','.join(self.toaddrs), self.subject)
3020                    for record in self.buffer:
3021                        s = self.format(record)
3022                        msg = msg + s + "\r\n"
3023                    smtp.sendmail(self.fromaddr, self.toaddrs, msg)
3024                    smtp.quit()
3025                except Exception:
3026                    if logging.raiseExceptions:
3027                        raise
3028                self.buffer = []
3029
3030    if __name__ == '__main__':
3031        import argparse
3032
3033        ap = argparse.ArgumentParser()
3034        aa = ap.add_argument
3035        aa('host', metavar='HOST', help='SMTP server')
3036        aa('--port', '-p', type=int, default=587, help='SMTP port')
3037        aa('user', metavar='USER', help='SMTP username')
3038        aa('password', metavar='PASSWORD', help='SMTP password')
3039        aa('to', metavar='TO', help='Addressee for emails')
3040        aa('sender', metavar='SENDER', help='Sender email address')
3041        aa('--subject', '-s',
3042           default='Test Logging email from Python logging module (buffering)',
3043           help='Subject of email')
3044        options = ap.parse_args()
3045        logger = logging.getLogger()
3046        logger.setLevel(logging.DEBUG)
3047        h = BufferingSMTPHandler(options.host, options.port, options.user,
3048                                 options.password, options.sender,
3049                                 options.to, options.subject, 10)
3050        logger.addHandler(h)
3051        for i in range(102):
3052            logger.info("Info index = %d", i)
3053        h.flush()
3054        h.close()
3055
3056If you run this script and your SMTP server is correctly set up, you should find that
3057it sends eleven emails to the addressee you specify. The first ten emails will each
3058have ten log messages, and the eleventh will have two messages. That makes up 102
3059messages as specified in the script.
3060
3061.. _utc-formatting:
3062
3063Formatting times using UTC (GMT) via configuration
3064--------------------------------------------------
3065
3066Sometimes you want to format times using UTC, which can be done using a class
3067such as ``UTCFormatter``, shown below::
3068
3069    import logging
3070    import time
3071
3072    class UTCFormatter(logging.Formatter):
3073        converter = time.gmtime
3074
3075and you can then use the ``UTCFormatter`` in your code instead of
3076:class:`~logging.Formatter`. If you want to do that via configuration, you can
3077use the :func:`~logging.config.dictConfig` API with an approach illustrated by
3078the following complete example::
3079
3080    import logging
3081    import logging.config
3082    import time
3083
3084    class UTCFormatter(logging.Formatter):
3085        converter = time.gmtime
3086
3087    LOGGING = {
3088        'version': 1,
3089        'disable_existing_loggers': False,
3090        'formatters': {
3091            'utc': {
3092                '()': UTCFormatter,
3093                'format': '%(asctime)s %(message)s',
3094            },
3095            'local': {
3096                'format': '%(asctime)s %(message)s',
3097            }
3098        },
3099        'handlers': {
3100            'console1': {
3101                'class': 'logging.StreamHandler',
3102                'formatter': 'utc',
3103            },
3104            'console2': {
3105                'class': 'logging.StreamHandler',
3106                'formatter': 'local',
3107            },
3108        },
3109        'root': {
3110            'handlers': ['console1', 'console2'],
3111       }
3112    }
3113
3114    if __name__ == '__main__':
3115        logging.config.dictConfig(LOGGING)
3116        logging.warning('The local time is %s', time.asctime())
3117
3118When this script is run, it should print something like:
3119
3120.. code-block:: none
3121
3122    2015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 2015
3123    2015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 2015
3124
3125showing how the time is formatted both as local time and UTC, one for each
3126handler.
3127
3128
3129.. _context-manager:
3130
3131Using a context manager for selective logging
3132---------------------------------------------
3133
3134There are times when it would be useful to temporarily change the logging
3135configuration and revert it back after doing something. For this, a context
3136manager is the most obvious way of saving and restoring the logging context.
3137Here is a simple example of such a context manager, which allows you to
3138optionally change the logging level and add a logging handler purely in the
3139scope of the context manager::
3140
3141    import logging
3142    import sys
3143
3144    class LoggingContext:
3145        def __init__(self, logger, level=None, handler=None, close=True):
3146            self.logger = logger
3147            self.level = level
3148            self.handler = handler
3149            self.close = close
3150
3151        def __enter__(self):
3152            if self.level is not None:
3153                self.old_level = self.logger.level
3154                self.logger.setLevel(self.level)
3155            if self.handler:
3156                self.logger.addHandler(self.handler)
3157
3158        def __exit__(self, et, ev, tb):
3159            if self.level is not None:
3160                self.logger.setLevel(self.old_level)
3161            if self.handler:
3162                self.logger.removeHandler(self.handler)
3163            if self.handler and self.close:
3164                self.handler.close()
3165            # implicit return of None => don't swallow exceptions
3166
3167If you specify a level value, the logger's level is set to that value in the
3168scope of the with block covered by the context manager. If you specify a
3169handler, it is added to the logger on entry to the block and removed on exit
3170from the block. You can also ask the manager to close the handler for you on
3171block exit - you could do this if you don't need the handler any more.
3172
3173To illustrate how it works, we can add the following block of code to the
3174above::
3175
3176    if __name__ == '__main__':
3177        logger = logging.getLogger('foo')
3178        logger.addHandler(logging.StreamHandler())
3179        logger.setLevel(logging.INFO)
3180        logger.info('1. This should appear just once on stderr.')
3181        logger.debug('2. This should not appear.')
3182        with LoggingContext(logger, level=logging.DEBUG):
3183            logger.debug('3. This should appear once on stderr.')
3184        logger.debug('4. This should not appear.')
3185        h = logging.StreamHandler(sys.stdout)
3186        with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):
3187            logger.debug('5. This should appear twice - once on stderr and once on stdout.')
3188        logger.info('6. This should appear just once on stderr.')
3189        logger.debug('7. This should not appear.')
3190
3191We initially set the logger's level to ``INFO``, so message #1 appears and
3192message #2 doesn't. We then change the level to ``DEBUG`` temporarily in the
3193following ``with`` block, and so message #3 appears. After the block exits, the
3194logger's level is restored to ``INFO`` and so message #4 doesn't appear. In the
3195next ``with`` block, we set the level to ``DEBUG`` again but also add a handler
3196writing to ``sys.stdout``. Thus, message #5 appears twice on the console (once
3197via ``stderr`` and once via ``stdout``). After the ``with`` statement's
3198completion, the status is as it was before so message #6 appears (like message
3199#1) whereas message #7 doesn't (just like message #2).
3200
3201If we run the resulting script, the result is as follows:
3202
3203.. code-block:: shell-session
3204
3205    $ python logctx.py
3206    1. This should appear just once on stderr.
3207    3. This should appear once on stderr.
3208    5. This should appear twice - once on stderr and once on stdout.
3209    5. This should appear twice - once on stderr and once on stdout.
3210    6. This should appear just once on stderr.
3211
3212If we run it again, but pipe ``stderr`` to ``/dev/null``, we see the following,
3213which is the only message written to ``stdout``:
3214
3215.. code-block:: shell-session
3216
3217    $ python logctx.py 2>/dev/null
3218    5. This should appear twice - once on stderr and once on stdout.
3219
3220Once again, but piping ``stdout`` to ``/dev/null``, we get:
3221
3222.. code-block:: shell-session
3223
3224    $ python logctx.py >/dev/null
3225    1. This should appear just once on stderr.
3226    3. This should appear once on stderr.
3227    5. This should appear twice - once on stderr and once on stdout.
3228    6. This should appear just once on stderr.
3229
3230In this case, the message #5 printed to ``stdout`` doesn't appear, as expected.
3231
3232Of course, the approach described here can be generalised, for example to attach
3233logging filters temporarily. Note that the above code works in Python 2 as well
3234as Python 3.
3235
3236
3237.. _starter-template:
3238
3239A CLI application starter template
3240----------------------------------
3241
3242Here's an example which shows how you can:
3243
3244* Use a logging level based on command-line arguments
3245* Dispatch to multiple subcommands in separate files, all logging at the same
3246  level in a consistent way
3247* Make use of simple, minimal configuration
3248
3249Suppose we have a command-line application whose job is to stop, start or
3250restart some services. This could be organised for the purposes of illustration
3251as a file ``app.py`` that is the main script for the application, with individual
3252commands implemented in ``start.py``, ``stop.py`` and ``restart.py``. Suppose
3253further that we want to control the verbosity of the application via a
3254command-line argument, defaulting to ``logging.INFO``. Here's one way that
3255``app.py`` could be written::
3256
3257    import argparse
3258    import importlib
3259    import logging
3260    import os
3261    import sys
3262
3263    def main(args=None):
3264        scriptname = os.path.basename(__file__)
3265        parser = argparse.ArgumentParser(scriptname)
3266        levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')
3267        parser.add_argument('--log-level', default='INFO', choices=levels)
3268        subparsers = parser.add_subparsers(dest='command',
3269                                           help='Available commands:')
3270        start_cmd = subparsers.add_parser('start', help='Start a service')
3271        start_cmd.add_argument('name', metavar='NAME',
3272                               help='Name of service to start')
3273        stop_cmd = subparsers.add_parser('stop',
3274                                         help='Stop one or more services')
3275        stop_cmd.add_argument('names', metavar='NAME', nargs='+',
3276                              help='Name of service to stop')
3277        restart_cmd = subparsers.add_parser('restart',
3278                                            help='Restart one or more services')
3279        restart_cmd.add_argument('names', metavar='NAME', nargs='+',
3280                                 help='Name of service to restart')
3281        options = parser.parse_args()
3282        # the code to dispatch commands could all be in this file. For the purposes
3283        # of illustration only, we implement each command in a separate module.
3284        try:
3285            mod = importlib.import_module(options.command)
3286            cmd = getattr(mod, 'command')
3287        except (ImportError, AttributeError):
3288            print('Unable to find the code for command \'%s\'' % options.command)
3289            return 1
3290        # Could get fancy here and load configuration from file or dictionary
3291        logging.basicConfig(level=options.log_level,
3292                            format='%(levelname)s %(name)s %(message)s')
3293        cmd(options)
3294
3295    if __name__ == '__main__':
3296        sys.exit(main())
3297
3298And the ``start``, ``stop`` and ``restart`` commands can be implemented in
3299separate modules, like so for starting::
3300
3301    # start.py
3302    import logging
3303
3304    logger = logging.getLogger(__name__)
3305
3306    def command(options):
3307        logger.debug('About to start %s', options.name)
3308        # actually do the command processing here ...
3309        logger.info('Started the \'%s\' service.', options.name)
3310
3311and thus for stopping::
3312
3313    # stop.py
3314    import logging
3315
3316    logger = logging.getLogger(__name__)
3317
3318    def command(options):
3319        n = len(options.names)
3320        if n == 1:
3321            plural = ''
3322            services = '\'%s\'' % options.names[0]
3323        else:
3324            plural = 's'
3325            services = ', '.join('\'%s\'' % name for name in options.names)
3326            i = services.rfind(', ')
3327            services = services[:i] + ' and ' + services[i + 2:]
3328        logger.debug('About to stop %s', services)
3329        # actually do the command processing here ...
3330        logger.info('Stopped the %s service%s.', services, plural)
3331
3332and similarly for restarting::
3333
3334    # restart.py
3335    import logging
3336
3337    logger = logging.getLogger(__name__)
3338
3339    def command(options):
3340        n = len(options.names)
3341        if n == 1:
3342            plural = ''
3343            services = '\'%s\'' % options.names[0]
3344        else:
3345            plural = 's'
3346            services = ', '.join('\'%s\'' % name for name in options.names)
3347            i = services.rfind(', ')
3348            services = services[:i] + ' and ' + services[i + 2:]
3349        logger.debug('About to restart %s', services)
3350        # actually do the command processing here ...
3351        logger.info('Restarted the %s service%s.', services, plural)
3352
3353If we run this application with the default log level, we get output like this:
3354
3355.. code-block:: shell-session
3356
3357    $ python app.py start foo
3358    INFO start Started the 'foo' service.
3359
3360    $ python app.py stop foo bar
3361    INFO stop Stopped the 'foo' and 'bar' services.
3362
3363    $ python app.py restart foo bar baz
3364    INFO restart Restarted the 'foo', 'bar' and 'baz' services.
3365
3366The first word is the logging level, and the second word is the module or
3367package name of the place where the event was logged.
3368
3369If we change the logging level, then we can change the information sent to the
3370log. For example, if we want more information:
3371
3372.. code-block:: shell-session
3373
3374    $ python app.py --log-level DEBUG start foo
3375    DEBUG start About to start foo
3376    INFO start Started the 'foo' service.
3377
3378    $ python app.py --log-level DEBUG stop foo bar
3379    DEBUG stop About to stop 'foo' and 'bar'
3380    INFO stop Stopped the 'foo' and 'bar' services.
3381
3382    $ python app.py --log-level DEBUG restart foo bar baz
3383    DEBUG restart About to restart 'foo', 'bar' and 'baz'
3384    INFO restart Restarted the 'foo', 'bar' and 'baz' services.
3385
3386And if we want less:
3387
3388.. code-block:: shell-session
3389
3390    $ python app.py --log-level WARNING start foo
3391    $ python app.py --log-level WARNING stop foo bar
3392    $ python app.py --log-level WARNING restart foo bar baz
3393
3394In this case, the commands don't print anything to the console, since nothing
3395at ``WARNING`` level or above is logged by them.
3396
3397.. _qt-gui:
3398
3399A Qt GUI for logging
3400--------------------
3401
3402A question that comes up from time to time is about how to log to a GUI
3403application. The `Qt <https://www.qt.io/>`_ framework is a popular
3404cross-platform UI framework with Python bindings using `PySide2
3405<https://pypi.org/project/PySide2/>`_ or `PyQt5
3406<https://pypi.org/project/PyQt5/>`_ libraries.
3407
3408The following example shows how to log to a Qt GUI. This introduces a simple
3409``QtHandler`` class which takes a callable, which should be a slot in the main
3410thread that does GUI updates. A worker thread is also created to show how you
3411can log to the GUI from both the UI itself (via a button for manual logging)
3412as well as a worker thread doing work in the background (here, just logging
3413messages at random levels with random short delays in between).
3414
3415The worker thread is implemented using Qt's ``QThread`` class rather than the
3416:mod:`threading` module, as there are circumstances where one has to use
3417``QThread``, which offers better integration with other ``Qt`` components.
3418
3419The code should work with recent releases of either ``PySide2`` or ``PyQt5``.
3420You should be able to adapt the approach to earlier versions of Qt. Please
3421refer to the comments in the code snippet for more detailed information.
3422
3423.. code-block:: python3
3424
3425    import datetime
3426    import logging
3427    import random
3428    import sys
3429    import time
3430
3431    # Deal with minor differences between PySide2 and PyQt5
3432    try:
3433        from PySide2 import QtCore, QtGui, QtWidgets
3434        Signal = QtCore.Signal
3435        Slot = QtCore.Slot
3436    except ImportError:
3437        from PyQt5 import QtCore, QtGui, QtWidgets
3438        Signal = QtCore.pyqtSignal
3439        Slot = QtCore.pyqtSlot
3440
3441
3442    logger = logging.getLogger(__name__)
3443
3444
3445    #
3446    # Signals need to be contained in a QObject or subclass in order to be correctly
3447    # initialized.
3448    #
3449    class Signaller(QtCore.QObject):
3450        signal = Signal(str, logging.LogRecord)
3451
3452    #
3453    # Output to a Qt GUI is only supposed to happen on the main thread. So, this
3454    # handler is designed to take a slot function which is set up to run in the main
3455    # thread. In this example, the function takes a string argument which is a
3456    # formatted log message, and the log record which generated it. The formatted
3457    # string is just a convenience - you could format a string for output any way
3458    # you like in the slot function itself.
3459    #
3460    # You specify the slot function to do whatever GUI updates you want. The handler
3461    # doesn't know or care about specific UI elements.
3462    #
3463    class QtHandler(logging.Handler):
3464        def __init__(self, slotfunc, *args, **kwargs):
3465            super().__init__(*args, **kwargs)
3466            self.signaller = Signaller()
3467            self.signaller.signal.connect(slotfunc)
3468
3469        def emit(self, record):
3470            s = self.format(record)
3471            self.signaller.signal.emit(s, record)
3472
3473    #
3474    # This example uses QThreads, which means that the threads at the Python level
3475    # are named something like "Dummy-1". The function below gets the Qt name of the
3476    # current thread.
3477    #
3478    def ctname():
3479        return QtCore.QThread.currentThread().objectName()
3480
3481
3482    #
3483    # Used to generate random levels for logging.
3484    #
3485    LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
3486              logging.CRITICAL)
3487
3488    #
3489    # This worker class represents work that is done in a thread separate to the
3490    # main thread. The way the thread is kicked off to do work is via a button press
3491    # that connects to a slot in the worker.
3492    #
3493    # Because the default threadName value in the LogRecord isn't much use, we add
3494    # a qThreadName which contains the QThread name as computed above, and pass that
3495    # value in an "extra" dictionary which is used to update the LogRecord with the
3496    # QThread name.
3497    #
3498    # This example worker just outputs messages sequentially, interspersed with
3499    # random delays of the order of a few seconds.
3500    #
3501    class Worker(QtCore.QObject):
3502        @Slot()
3503        def start(self):
3504            extra = {'qThreadName': ctname() }
3505            logger.debug('Started work', extra=extra)
3506            i = 1
3507            # Let the thread run until interrupted. This allows reasonably clean
3508            # thread termination.
3509            while not QtCore.QThread.currentThread().isInterruptionRequested():
3510                delay = 0.5 + random.random() * 2
3511                time.sleep(delay)
3512                level = random.choice(LEVELS)
3513                logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)
3514                i += 1
3515
3516    #
3517    # Implement a simple UI for this cookbook example. This contains:
3518    #
3519    # * A read-only text edit window which holds formatted log messages
3520    # * A button to start work and log stuff in a separate thread
3521    # * A button to log something from the main thread
3522    # * A button to clear the log window
3523    #
3524    class Window(QtWidgets.QWidget):
3525
3526        COLORS = {
3527            logging.DEBUG: 'black',
3528            logging.INFO: 'blue',
3529            logging.WARNING: 'orange',
3530            logging.ERROR: 'red',
3531            logging.CRITICAL: 'purple',
3532        }
3533
3534        def __init__(self, app):
3535            super().__init__()
3536            self.app = app
3537            self.textedit = te = QtWidgets.QPlainTextEdit(self)
3538            # Set whatever the default monospace font is for the platform
3539            f = QtGui.QFont('nosuchfont')
3540            f.setStyleHint(f.Monospace)
3541            te.setFont(f)
3542            te.setReadOnly(True)
3543            PB = QtWidgets.QPushButton
3544            self.work_button = PB('Start background work', self)
3545            self.log_button = PB('Log a message at a random level', self)
3546            self.clear_button = PB('Clear log window', self)
3547            self.handler = h = QtHandler(self.update_status)
3548            # Remember to use qThreadName rather than threadName in the format string.
3549            fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'
3550            formatter = logging.Formatter(fs)
3551            h.setFormatter(formatter)
3552            logger.addHandler(h)
3553            # Set up to terminate the QThread when we exit
3554            app.aboutToQuit.connect(self.force_quit)
3555
3556            # Lay out all the widgets
3557            layout = QtWidgets.QVBoxLayout(self)
3558            layout.addWidget(te)
3559            layout.addWidget(self.work_button)
3560            layout.addWidget(self.log_button)
3561            layout.addWidget(self.clear_button)
3562            self.setFixedSize(900, 400)
3563
3564            # Connect the non-worker slots and signals
3565            self.log_button.clicked.connect(self.manual_update)
3566            self.clear_button.clicked.connect(self.clear_display)
3567
3568            # Start a new worker thread and connect the slots for the worker
3569            self.start_thread()
3570            self.work_button.clicked.connect(self.worker.start)
3571            # Once started, the button should be disabled
3572            self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))
3573
3574        def start_thread(self):
3575            self.worker = Worker()
3576            self.worker_thread = QtCore.QThread()
3577            self.worker.setObjectName('Worker')
3578            self.worker_thread.setObjectName('WorkerThread')  # for qThreadName
3579            self.worker.moveToThread(self.worker_thread)
3580            # This will start an event loop in the worker thread
3581            self.worker_thread.start()
3582
3583        def kill_thread(self):
3584            # Just tell the worker to stop, then tell it to quit and wait for that
3585            # to happen
3586            self.worker_thread.requestInterruption()
3587            if self.worker_thread.isRunning():
3588                self.worker_thread.quit()
3589                self.worker_thread.wait()
3590            else:
3591                print('worker has already exited.')
3592
3593        def force_quit(self):
3594            # For use when the window is closed
3595            if self.worker_thread.isRunning():
3596                self.kill_thread()
3597
3598        # The functions below update the UI and run in the main thread because
3599        # that's where the slots are set up
3600
3601        @Slot(str, logging.LogRecord)
3602        def update_status(self, status, record):
3603            color = self.COLORS.get(record.levelno, 'black')
3604            s = '<pre><font color="%s">%s</font></pre>' % (color, status)
3605            self.textedit.appendHtml(s)
3606
3607        @Slot()
3608        def manual_update(self):
3609            # This function uses the formatted message passed in, but also uses
3610            # information from the record to format the message in an appropriate
3611            # color according to its severity (level).
3612            level = random.choice(LEVELS)
3613            extra = {'qThreadName': ctname() }
3614            logger.log(level, 'Manually logged!', extra=extra)
3615
3616        @Slot()
3617        def clear_display(self):
3618            self.textedit.clear()
3619
3620
3621    def main():
3622        QtCore.QThread.currentThread().setObjectName('MainThread')
3623        logging.getLogger().setLevel(logging.DEBUG)
3624        app = QtWidgets.QApplication(sys.argv)
3625        example = Window(app)
3626        example.show()
3627        sys.exit(app.exec_())
3628
3629    if __name__=='__main__':
3630        main()
3631
3632Logging to syslog with RFC5424 support
3633--------------------------------------
3634
3635Although :rfc:`5424` dates from 2009, most syslog servers are configured by detault to
3636use the older :rfc:`3164`, which hails from 2001. When ``logging`` was added to Python
3637in 2003, it supported the earlier (and only existing) protocol at the time. Since
3638RFC5424 came out, as there has not been widespread deployment of it in syslog
3639servers, the :class:`~logging.handlers.SysLogHandler` functionality has not been
3640updated.
3641
3642RFC 5424 contains some useful features such as support for structured data, and if you
3643need to be able to log to a syslog server with support for it, you can do so with a
3644subclassed handler which looks something like this::
3645
3646    import datetime
3647    import logging.handlers
3648    import re
3649    import socket
3650    import time
3651
3652    class SysLogHandler5424(logging.handlers.SysLogHandler):
3653
3654        tz_offset = re.compile(r'([+-]\d{2})(\d{2})$')
3655        escaped = re.compile(r'([\]"\\])')
3656
3657        def __init__(self, *args, **kwargs):
3658            self.msgid = kwargs.pop('msgid', None)
3659            self.appname = kwargs.pop('appname', None)
3660            super().__init__(*args, **kwargs)
3661
3662        def format(self, record):
3663            version = 1
3664            asctime = datetime.datetime.fromtimestamp(record.created).isoformat()
3665            m = self.tz_offset.match(time.strftime('%z'))
3666            has_offset = False
3667            if m and time.timezone:
3668                hrs, mins = m.groups()
3669                if int(hrs) or int(mins):
3670                    has_offset = True
3671            if not has_offset:
3672                asctime += 'Z'
3673            else:
3674                asctime += f'{hrs}:{mins}'
3675            try:
3676                hostname = socket.gethostname()
3677            except Exception:
3678                hostname = '-'
3679            appname = self.appname or '-'
3680            procid = record.process
3681            msgid = '-'
3682            msg = super().format(record)
3683            sdata = '-'
3684            if hasattr(record, 'structured_data'):
3685                sd = record.structured_data
3686                # This should be a dict where the keys are SD-ID and the value is a
3687                # dict mapping PARAM-NAME to PARAM-VALUE (refer to the RFC for what these
3688                # mean)
3689                # There's no error checking here - it's purely for illustration, and you
3690                # can adapt this code for use in production environments
3691                parts = []
3692
3693                def replacer(m):
3694                    g = m.groups()
3695                    return '\\' + g[0]
3696
3697                for sdid, dv in sd.items():
3698                    part = f'[{sdid}'
3699                    for k, v in dv.items():
3700                        s = str(v)
3701                        s = self.escaped.sub(replacer, s)
3702                        part += f' {k}="{s}"'
3703                    part += ']'
3704                    parts.append(part)
3705                sdata = ''.join(parts)
3706            return f'{version} {asctime} {hostname} {appname} {procid} {msgid} {sdata} {msg}'
3707
3708You'll need to be familiar with RFC 5424 to fully understand the above code, and it
3709may be that you have slightly different needs (e.g. for how you pass structural data
3710to the log). Nevertheless, the above should be adaptable to your speciric needs. With
3711the above handler, you'd pass structured data using something like this::
3712
3713    sd = {
3714        'foo@12345': {'bar': 'baz', 'baz': 'bozz', 'fizz': r'buzz'},
3715        'foo@54321': {'rab': 'baz', 'zab': 'bozz', 'zzif': r'buzz'}
3716    }
3717    extra = {'structured_data': sd}
3718    i = 1
3719    logger.debug('Message %d', i, extra=extra)
3720
3721How to treat a logger like an output stream
3722-------------------------------------------
3723
3724Sometimes, you need to interface to a third-party API which expects a file-like
3725object to write to, but you want to direct the API's output to a logger. You
3726can do this using a class which wraps a logger with a file-like API.
3727Here's a short script illustrating such a class:
3728
3729.. code-block:: python
3730
3731    import logging
3732
3733    class LoggerWriter:
3734        def __init__(self, logger, level):
3735            self.logger = logger
3736            self.level = level
3737
3738        def write(self, message):
3739            if message != '\n':  # avoid printing bare newlines, if you like
3740                self.logger.log(self.level, message)
3741
3742        def flush(self):
3743            # doesn't actually do anything, but might be expected of a file-like
3744            # object - so optional depending on your situation
3745            pass
3746
3747        def close(self):
3748            # doesn't actually do anything, but might be expected of a file-like
3749            # object - so optional depending on your situation. You might want
3750            # to set a flag so that later calls to write raise an exception
3751            pass
3752
3753    def main():
3754        logging.basicConfig(level=logging.DEBUG)
3755        logger = logging.getLogger('demo')
3756        info_fp = LoggerWriter(logger, logging.INFO)
3757        debug_fp = LoggerWriter(logger, logging.DEBUG)
3758        print('An INFO message', file=info_fp)
3759        print('A DEBUG message', file=debug_fp)
3760
3761    if __name__ == "__main__":
3762        main()
3763
3764When this script is run, it prints
3765
3766.. code-block:: text
3767
3768    INFO:demo:An INFO message
3769    DEBUG:demo:A DEBUG message
3770
3771You could also use ``LoggerWriter`` to redirect ``sys.stdout`` and
3772``sys.stderr`` by doing something like this:
3773
3774.. code-block:: python
3775
3776    import sys
3777
3778    sys.stdout = LoggerWriter(logger, logging.INFO)
3779    sys.stderr = LoggerWriter(logger, logging.WARNING)
3780
3781You should do this *after* configuring logging for your needs. In the above
3782example, the :func:`~logging.basicConfig` call does this (using the
3783``sys.stderr`` value *before* it is overwritten by a ``LoggerWriter``
3784instance). Then, you'd get this kind of result:
3785
3786.. code-block:: pycon
3787
3788    >>> print('Foo')
3789    INFO:demo:Foo
3790    >>> print('Bar', file=sys.stderr)
3791    WARNING:demo:Bar
3792    >>>
3793
3794Of course, the examples above show output according to the format used by
3795:func:`~logging.basicConfig`, but you can use a different formatter when you
3796configure logging.
3797
3798Note that with the above scheme, you are somewhat at the mercy of buffering and
3799the sequence of write calls which you are intercepting. For example, with the
3800definition of ``LoggerWriter`` above, if you have the snippet
3801
3802.. code-block:: python
3803
3804    sys.stderr = LoggerWriter(logger, logging.WARNING)
3805    1 / 0
3806
3807then running the script results in
3808
3809.. code-block:: text
3810
3811    WARNING:demo:Traceback (most recent call last):
3812
3813    WARNING:demo:  File "/home/runner/cookbook-loggerwriter/test.py", line 53, in <module>
3814
3815    WARNING:demo:
3816    WARNING:demo:main()
3817    WARNING:demo:  File "/home/runner/cookbook-loggerwriter/test.py", line 49, in main
3818
3819    WARNING:demo:
3820    WARNING:demo:1 / 0
3821    WARNING:demo:ZeroDivisionError
3822    WARNING:demo::
3823    WARNING:demo:division by zero
3824
3825As you can see, this output isn't ideal. That's because the underlying code
3826which writes to ``sys.stderr`` makes mutiple writes, each of which results in a
3827separate logged line (for example, the last three lines above). To get around
3828this problem, you need to buffer things and only output log lines when newlines
3829are seen. Let's use a slghtly better implementation of ``LoggerWriter``:
3830
3831.. code-block:: python
3832
3833    class BufferingLoggerWriter(LoggerWriter):
3834        def __init__(self, logger, level):
3835            super().__init__(logger, level)
3836            self.buffer = ''
3837
3838        def write(self, message):
3839            if '\n' not in message:
3840                self.buffer += message
3841            else:
3842                parts = message.split('\n')
3843                if self.buffer:
3844                    s = self.buffer + parts.pop(0)
3845                    self.logger.log(self.level, s)
3846                self.buffer = parts.pop()
3847                for part in parts:
3848                    self.logger.log(self.level, part)
3849
3850This just buffers up stuff until a newline is seen, and then logs complete
3851lines. With this approach, you get better output:
3852
3853.. code-block:: text
3854
3855    WARNING:demo:Traceback (most recent call last):
3856    WARNING:demo:  File "/home/runner/cookbook-loggerwriter/main.py", line 55, in <module>
3857    WARNING:demo:    main()
3858    WARNING:demo:  File "/home/runner/cookbook-loggerwriter/main.py", line 52, in main
3859    WARNING:demo:    1/0
3860    WARNING:demo:ZeroDivisionError: division by zero
3861
3862
3863.. patterns-to-avoid:
3864
3865Patterns to avoid
3866-----------------
3867
3868Although the preceding sections have described ways of doing things you might
3869need to do or deal with, it is worth mentioning some usage patterns which are
3870*unhelpful*, and which should therefore be avoided in most cases. The following
3871sections are in no particular order.
3872
3873Opening the same log file multiple times
3874^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
3875
3876On Windows, you will generally not be able to open the same file multiple times
3877as this will lead to a "file is in use by another process" error. However, on
3878POSIX platforms you'll not get any errors if you open the same file multiple
3879times. This could be done accidentally, for example by:
3880
3881* Adding a file handler more than once which references the same file (e.g. by
3882  a copy/paste/forget-to-change error).
3883
3884* Opening two files that look different, as they have different names, but are
3885  the same because one is a symbolic link to the other.
3886
3887* Forking a process, following which both parent and child have a reference to
3888  the same file. This might be through use of the :mod:`multiprocessing` module,
3889  for example.
3890
3891Opening a file multiple times might *appear* to work most of the time, but can
3892lead to a number of problems in practice:
3893
3894* Logging output can be garbled because multiple threads or processes try to
3895  write to the same file. Although logging guards against concurrent use of the
3896  same handler instance by multiple threads, there is no such protection if
3897  concurrent writes are attempted by two different threads using two different
3898  handler instances which happen to point to the same file.
3899
3900* An attempt to delete a file (e.g. during file rotation) silently fails,
3901  because there is another reference pointing to it. This can lead to confusion
3902  and wasted debugging time - log entries end up in unexpected places, or are
3903  lost altogether. Or a file that was supposed to be moved remains in place,
3904  and grows in size unexpectedly despite size-based rotation being supposedly
3905  in place.
3906
3907Use the techniques outlined in :ref:`multiple-processes` to circumvent such
3908issues.
3909
3910Using loggers as attributes in a class or passing them as parameters
3911^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
3912
3913While there might be unusual cases where you'll need to do this, in general
3914there is no point because loggers are singletons. Code can always access a
3915given logger instance by name using ``logging.getLogger(name)``, so passing
3916instances around and holding them as instance attributes is pointless. Note
3917that in other languages such as Java and C#, loggers are often static class
3918attributes. However, this pattern doesn't make sense in Python, where the
3919module (and not the class) is the unit of software decomposition.
3920
3921Adding handlers other than :class:`NullHandler` to a logger in a library
3922^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
3923
3924Configuring logging by adding handlers, formatters and filters is the
3925responsibility of the application developer, not the library developer. If you
3926are maintaining a library, ensure that you don't add handlers to any of your
3927loggers other than a :class:`~logging.NullHandler` instance.
3928
3929Creating a lot of loggers
3930^^^^^^^^^^^^^^^^^^^^^^^^^
3931
3932Loggers are singletons that are never freed during a script execution, and so
3933creating lots of loggers will use up memory which can't then be freed. Rather
3934than create a logger per e.g. file processed or network connection made, use
3935the :ref:`existing mechanisms <context-info>` for passing contextual
3936information into your logs and restrict the loggers created to those describing
3937areas within your application (generally modules, but occasionally slightly
3938more fine-grained than that).
3939
3940.. _cookbook-ref-links:
3941
3942Other resources
3943---------------
3944
3945.. seealso::
3946
3947   Module :mod:`logging`
3948      API reference for the logging module.
3949
3950   Module :mod:`logging.config`
3951      Configuration API for the logging module.
3952
3953   Module :mod:`logging.handlers`
3954      Useful handlers included with the logging module.
3955
3956   :ref:`Basic Tutorial <logging-basic-tutorial>`
3957
3958   :ref:`Advanced Tutorial <logging-advanced-tutorial>`
3959