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