Vinay Sajip | 5dbca9c | 2011-04-08 11:40:38 +0100 | [diff] [blame] | 1 | .. _logging-cookbook: |
| 2 | |
| 3 | ================ |
| 4 | Logging Cookbook |
| 5 | ================ |
| 6 | |
| 7 | :Author: Vinay Sajip <vinay_sajip at red-dove dot com> |
| 8 | |
| 9 | This page contains a number of recipes related to logging, which have been found |
| 10 | useful in the past. |
| 11 | |
| 12 | .. currentmodule:: logging |
| 13 | |
| 14 | Using logging in multiple modules |
| 15 | --------------------------------- |
| 16 | |
| 17 | Multiple calls to ``logging.getLogger('someLogger')`` return a reference to the |
| 18 | same logger object. This is true not only within the same module, but also |
| 19 | across modules as long as it is in the same Python interpreter process. It is |
| 20 | true for references to the same object; additionally, application code can |
| 21 | define and configure a parent logger in one module and create (but not |
| 22 | configure) a child logger in a separate module, and all logger calls to the |
| 23 | child will pass up to the parent. Here is a main module:: |
| 24 | |
| 25 | import logging |
| 26 | import auxiliary_module |
| 27 | |
| 28 | # create logger with 'spam_application' |
| 29 | logger = logging.getLogger('spam_application') |
| 30 | logger.setLevel(logging.DEBUG) |
| 31 | # create file handler which logs even debug messages |
| 32 | fh = logging.FileHandler('spam.log') |
| 33 | fh.setLevel(logging.DEBUG) |
| 34 | # create console handler with a higher log level |
| 35 | ch = logging.StreamHandler() |
| 36 | ch.setLevel(logging.ERROR) |
| 37 | # create formatter and add it to the handlers |
| 38 | formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s') |
| 39 | fh.setFormatter(formatter) |
| 40 | ch.setFormatter(formatter) |
| 41 | # add the handlers to the logger |
| 42 | logger.addHandler(fh) |
| 43 | logger.addHandler(ch) |
| 44 | |
| 45 | logger.info('creating an instance of auxiliary_module.Auxiliary') |
| 46 | a = auxiliary_module.Auxiliary() |
| 47 | logger.info('created an instance of auxiliary_module.Auxiliary') |
| 48 | logger.info('calling auxiliary_module.Auxiliary.do_something') |
| 49 | a.do_something() |
| 50 | logger.info('finished auxiliary_module.Auxiliary.do_something') |
| 51 | logger.info('calling auxiliary_module.some_function()') |
| 52 | auxiliary_module.some_function() |
| 53 | logger.info('done with auxiliary_module.some_function()') |
| 54 | |
| 55 | Here is the auxiliary module:: |
| 56 | |
| 57 | import logging |
| 58 | |
| 59 | # create logger |
| 60 | module_logger = logging.getLogger('spam_application.auxiliary') |
| 61 | |
| 62 | class Auxiliary: |
| 63 | def __init__(self): |
| 64 | self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary') |
| 65 | self.logger.info('creating an instance of Auxiliary') |
| 66 | def do_something(self): |
| 67 | self.logger.info('doing something') |
| 68 | a = 1 + 1 |
| 69 | self.logger.info('done doing something') |
| 70 | |
| 71 | def some_function(): |
| 72 | module_logger.info('received a call to "some_function"') |
| 73 | |
| 74 | The output looks like this:: |
| 75 | |
| 76 | 2005-03-23 23:47:11,663 - spam_application - INFO - |
| 77 | creating an instance of auxiliary_module.Auxiliary |
| 78 | 2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO - |
| 79 | creating an instance of Auxiliary |
| 80 | 2005-03-23 23:47:11,665 - spam_application - INFO - |
| 81 | created an instance of auxiliary_module.Auxiliary |
| 82 | 2005-03-23 23:47:11,668 - spam_application - INFO - |
| 83 | calling auxiliary_module.Auxiliary.do_something |
| 84 | 2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO - |
| 85 | doing something |
| 86 | 2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO - |
| 87 | done doing something |
| 88 | 2005-03-23 23:47:11,670 - spam_application - INFO - |
| 89 | finished auxiliary_module.Auxiliary.do_something |
| 90 | 2005-03-23 23:47:11,671 - spam_application - INFO - |
| 91 | calling auxiliary_module.some_function() |
| 92 | 2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO - |
| 93 | received a call to 'some_function' |
| 94 | 2005-03-23 23:47:11,673 - spam_application - INFO - |
| 95 | done with auxiliary_module.some_function() |
| 96 | |
| 97 | Multiple handlers and formatters |
| 98 | -------------------------------- |
| 99 | |
| 100 | Loggers are plain Python objects. The :func:`addHandler` method has no minimum |
| 101 | or maximum quota for the number of handlers you may add. Sometimes it will be |
| 102 | beneficial for an application to log all messages of all severities to a text |
| 103 | file while simultaneously logging errors or above to the console. To set this |
| 104 | up, simply configure the appropriate handlers. The logging calls in the |
| 105 | application code will remain unchanged. Here is a slight modification to the |
| 106 | previous simple module-based configuration example:: |
| 107 | |
| 108 | import logging |
| 109 | |
| 110 | logger = logging.getLogger('simple_example') |
| 111 | logger.setLevel(logging.DEBUG) |
| 112 | # create file handler which logs even debug messages |
| 113 | fh = logging.FileHandler('spam.log') |
| 114 | fh.setLevel(logging.DEBUG) |
| 115 | # create console handler with a higher log level |
| 116 | ch = logging.StreamHandler() |
| 117 | ch.setLevel(logging.ERROR) |
| 118 | # create formatter and add it to the handlers |
| 119 | formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s') |
| 120 | ch.setFormatter(formatter) |
| 121 | fh.setFormatter(formatter) |
| 122 | # add the handlers to logger |
| 123 | logger.addHandler(ch) |
| 124 | logger.addHandler(fh) |
| 125 | |
| 126 | # 'application' code |
| 127 | logger.debug('debug message') |
| 128 | logger.info('info message') |
| 129 | logger.warn('warn message') |
| 130 | logger.error('error message') |
| 131 | logger.critical('critical message') |
| 132 | |
| 133 | Notice that the 'application' code does not care about multiple handlers. All |
| 134 | that changed was the addition and configuration of a new handler named *fh*. |
| 135 | |
| 136 | The ability to create new handlers with higher- or lower-severity filters can be |
| 137 | very helpful when writing and testing an application. Instead of using many |
| 138 | ``print`` statements for debugging, use ``logger.debug``: Unlike the print |
| 139 | statements, which you will have to delete or comment out later, the logger.debug |
| 140 | statements can remain intact in the source code and remain dormant until you |
| 141 | need them again. At that time, the only change that needs to happen is to |
| 142 | modify the severity level of the logger and/or handler to debug. |
| 143 | |
| 144 | .. _multiple-destinations: |
| 145 | |
| 146 | Logging to multiple destinations |
| 147 | -------------------------------- |
| 148 | |
| 149 | Let's say you want to log to console and file with different message formats and |
| 150 | in differing circumstances. Say you want to log messages with levels of DEBUG |
| 151 | and higher to file, and those messages at level INFO and higher to the console. |
| 152 | Let's also assume that the file should contain timestamps, but the console |
| 153 | messages should not. Here's how you can achieve this:: |
| 154 | |
| 155 | import logging |
| 156 | |
| 157 | # set up logging to file - see previous section for more details |
| 158 | logging.basicConfig(level=logging.DEBUG, |
| 159 | format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s', |
| 160 | datefmt='%m-%d %H:%M', |
| 161 | filename='/temp/myapp.log', |
| 162 | filemode='w') |
| 163 | # define a Handler which writes INFO messages or higher to the sys.stderr |
| 164 | console = logging.StreamHandler() |
| 165 | console.setLevel(logging.INFO) |
| 166 | # set a format which is simpler for console use |
| 167 | formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s') |
| 168 | # tell the handler to use this format |
| 169 | console.setFormatter(formatter) |
| 170 | # add the handler to the root logger |
| 171 | logging.getLogger('').addHandler(console) |
| 172 | |
| 173 | # Now, we can log to the root logger, or any other logger. First the root... |
| 174 | logging.info('Jackdaws love my big sphinx of quartz.') |
| 175 | |
| 176 | # Now, define a couple of other loggers which might represent areas in your |
| 177 | # application: |
| 178 | |
| 179 | logger1 = logging.getLogger('myapp.area1') |
| 180 | logger2 = logging.getLogger('myapp.area2') |
| 181 | |
| 182 | logger1.debug('Quick zephyrs blow, vexing daft Jim.') |
| 183 | logger1.info('How quickly daft jumping zebras vex.') |
| 184 | logger2.warning('Jail zesty vixen who grabbed pay from quack.') |
| 185 | logger2.error('The five boxing wizards jump quickly.') |
| 186 | |
| 187 | When you run this, on the console you will see :: |
| 188 | |
| 189 | root : INFO Jackdaws love my big sphinx of quartz. |
| 190 | myapp.area1 : INFO How quickly daft jumping zebras vex. |
| 191 | myapp.area2 : WARNING Jail zesty vixen who grabbed pay from quack. |
| 192 | myapp.area2 : ERROR The five boxing wizards jump quickly. |
| 193 | |
| 194 | and in the file you will see something like :: |
| 195 | |
| 196 | 10-22 22:19 root INFO Jackdaws love my big sphinx of quartz. |
| 197 | 10-22 22:19 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim. |
| 198 | 10-22 22:19 myapp.area1 INFO How quickly daft jumping zebras vex. |
| 199 | 10-22 22:19 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack. |
| 200 | 10-22 22:19 myapp.area2 ERROR The five boxing wizards jump quickly. |
| 201 | |
| 202 | As you can see, the DEBUG message only shows up in the file. The other messages |
| 203 | are sent to both destinations. |
| 204 | |
| 205 | This example uses console and file handlers, but you can use any number and |
| 206 | combination of handlers you choose. |
| 207 | |
| 208 | |
| 209 | Configuration server example |
| 210 | ---------------------------- |
| 211 | |
| 212 | Here is an example of a module using the logging configuration server:: |
| 213 | |
| 214 | import logging |
| 215 | import logging.config |
| 216 | import time |
| 217 | import os |
| 218 | |
| 219 | # read initial config file |
| 220 | logging.config.fileConfig('logging.conf') |
| 221 | |
| 222 | # create and start listener on port 9999 |
| 223 | t = logging.config.listen(9999) |
| 224 | t.start() |
| 225 | |
| 226 | logger = logging.getLogger('simpleExample') |
| 227 | |
| 228 | try: |
| 229 | # loop through logging calls to see the difference |
| 230 | # new configurations make, until Ctrl+C is pressed |
| 231 | while True: |
| 232 | logger.debug('debug message') |
| 233 | logger.info('info message') |
| 234 | logger.warn('warn message') |
| 235 | logger.error('error message') |
| 236 | logger.critical('critical message') |
| 237 | time.sleep(5) |
| 238 | except KeyboardInterrupt: |
| 239 | # cleanup |
| 240 | logging.config.stopListening() |
| 241 | t.join() |
| 242 | |
| 243 | And here is a script that takes a filename and sends that file to the server, |
| 244 | properly preceded with the binary-encoded length, as the new logging |
| 245 | configuration:: |
| 246 | |
| 247 | #!/usr/bin/env python |
| 248 | import socket, sys, struct |
| 249 | |
| 250 | with open(sys.argv[1], 'rb') as f: |
| 251 | data_to_send = f.read() |
| 252 | |
| 253 | HOST = 'localhost' |
| 254 | PORT = 9999 |
| 255 | s = socket.socket(socket.AF_INET, socket.SOCK_STREAM) |
| 256 | print('connecting...') |
| 257 | s.connect((HOST, PORT)) |
| 258 | print('sending config...') |
| 259 | s.send(struct.pack('>L', len(data_to_send))) |
| 260 | s.send(data_to_send) |
| 261 | s.close() |
| 262 | print('complete') |
| 263 | |
| 264 | |
| 265 | .. _network-logging: |
| 266 | |
| 267 | Sending and receiving logging events across a network |
| 268 | ----------------------------------------------------- |
| 269 | |
| 270 | Let's say you want to send logging events across a network, and handle them at |
| 271 | the receiving end. A simple way of doing this is attaching a |
| 272 | :class:`SocketHandler` instance to the root logger at the sending end:: |
| 273 | |
| 274 | import logging, logging.handlers |
| 275 | |
| 276 | rootLogger = logging.getLogger('') |
| 277 | rootLogger.setLevel(logging.DEBUG) |
| 278 | socketHandler = logging.handlers.SocketHandler('localhost', |
| 279 | logging.handlers.DEFAULT_TCP_LOGGING_PORT) |
| 280 | # don't bother with a formatter, since a socket handler sends the event as |
| 281 | # an unformatted pickle |
| 282 | rootLogger.addHandler(socketHandler) |
| 283 | |
| 284 | # Now, we can log to the root logger, or any other logger. First the root... |
| 285 | logging.info('Jackdaws love my big sphinx of quartz.') |
| 286 | |
| 287 | # Now, define a couple of other loggers which might represent areas in your |
| 288 | # application: |
| 289 | |
| 290 | logger1 = logging.getLogger('myapp.area1') |
| 291 | logger2 = logging.getLogger('myapp.area2') |
| 292 | |
| 293 | logger1.debug('Quick zephyrs blow, vexing daft Jim.') |
| 294 | logger1.info('How quickly daft jumping zebras vex.') |
| 295 | logger2.warning('Jail zesty vixen who grabbed pay from quack.') |
| 296 | logger2.error('The five boxing wizards jump quickly.') |
| 297 | |
| 298 | At the receiving end, you can set up a receiver using the :mod:`socketserver` |
| 299 | module. Here is a basic working example:: |
| 300 | |
| 301 | import pickle |
| 302 | import logging |
| 303 | import logging.handlers |
| 304 | import socketserver |
| 305 | import struct |
| 306 | |
| 307 | |
| 308 | class LogRecordStreamHandler(socketserver.StreamRequestHandler): |
| 309 | """Handler for a streaming logging request. |
| 310 | |
| 311 | This basically logs the record using whatever logging policy is |
| 312 | configured locally. |
| 313 | """ |
| 314 | |
| 315 | def handle(self): |
| 316 | """ |
| 317 | Handle multiple requests - each expected to be a 4-byte length, |
| 318 | followed by the LogRecord in pickle format. Logs the record |
| 319 | according to whatever policy is configured locally. |
| 320 | """ |
| 321 | while True: |
| 322 | chunk = self.connection.recv(4) |
| 323 | if len(chunk) < 4: |
| 324 | break |
| 325 | slen = struct.unpack('>L', chunk)[0] |
| 326 | chunk = self.connection.recv(slen) |
| 327 | while len(chunk) < slen: |
| 328 | chunk = chunk + self.connection.recv(slen - len(chunk)) |
| 329 | obj = self.unPickle(chunk) |
| 330 | record = logging.makeLogRecord(obj) |
| 331 | self.handleLogRecord(record) |
| 332 | |
| 333 | def unPickle(self, data): |
| 334 | return pickle.loads(data) |
| 335 | |
| 336 | def handleLogRecord(self, record): |
| 337 | # if a name is specified, we use the named logger rather than the one |
| 338 | # implied by the record. |
| 339 | if self.server.logname is not None: |
| 340 | name = self.server.logname |
| 341 | else: |
| 342 | name = record.name |
| 343 | logger = logging.getLogger(name) |
| 344 | # N.B. EVERY record gets logged. This is because Logger.handle |
| 345 | # is normally called AFTER logger-level filtering. If you want |
| 346 | # to do filtering, do it at the client end to save wasting |
| 347 | # cycles and network bandwidth! |
| 348 | logger.handle(record) |
| 349 | |
| 350 | class LogRecordSocketReceiver(socketserver.ThreadingTCPServer): |
| 351 | """ |
| 352 | Simple TCP socket-based logging receiver suitable for testing. |
| 353 | """ |
| 354 | |
| 355 | allow_reuse_address = 1 |
| 356 | |
| 357 | def __init__(self, host='localhost', |
| 358 | port=logging.handlers.DEFAULT_TCP_LOGGING_PORT, |
| 359 | handler=LogRecordStreamHandler): |
| 360 | socketserver.ThreadingTCPServer.__init__(self, (host, port), handler) |
| 361 | self.abort = 0 |
| 362 | self.timeout = 1 |
| 363 | self.logname = None |
| 364 | |
| 365 | def serve_until_stopped(self): |
| 366 | import select |
| 367 | abort = 0 |
| 368 | while not abort: |
| 369 | rd, wr, ex = select.select([self.socket.fileno()], |
| 370 | [], [], |
| 371 | self.timeout) |
| 372 | if rd: |
| 373 | self.handle_request() |
| 374 | abort = self.abort |
| 375 | |
| 376 | def main(): |
| 377 | logging.basicConfig( |
| 378 | format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s') |
| 379 | tcpserver = LogRecordSocketReceiver() |
| 380 | print('About to start TCP server...') |
| 381 | tcpserver.serve_until_stopped() |
| 382 | |
| 383 | if __name__ == '__main__': |
| 384 | main() |
| 385 | |
| 386 | First run the server, and then the client. On the client side, nothing is |
| 387 | printed on the console; on the server side, you should see something like:: |
| 388 | |
| 389 | About to start TCP server... |
| 390 | 59 root INFO Jackdaws love my big sphinx of quartz. |
| 391 | 59 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim. |
| 392 | 69 myapp.area1 INFO How quickly daft jumping zebras vex. |
| 393 | 69 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack. |
| 394 | 69 myapp.area2 ERROR The five boxing wizards jump quickly. |
| 395 | |
| 396 | Note that there are some security issues with pickle in some scenarios. If |
| 397 | these affect you, you can use an alternative serialization scheme by overriding |
| 398 | the :meth:`makePickle` method and implementing your alternative there, as |
| 399 | well as adapting the above script to use your alternative serialization. |
| 400 | |
| 401 | |
| 402 | .. _context-info: |
| 403 | |
| 404 | Adding contextual information to your logging output |
| 405 | ---------------------------------------------------- |
| 406 | |
| 407 | Sometimes you want logging output to contain contextual information in |
| 408 | addition to the parameters passed to the logging call. For example, in a |
| 409 | networked application, it may be desirable to log client-specific information |
| 410 | in the log (e.g. remote client's username, or IP address). Although you could |
| 411 | use the *extra* parameter to achieve this, it's not always convenient to pass |
| 412 | the information in this way. While it might be tempting to create |
| 413 | :class:`Logger` instances on a per-connection basis, this is not a good idea |
| 414 | because these instances are not garbage collected. While this is not a problem |
| 415 | in practice, when the number of :class:`Logger` instances is dependent on the |
| 416 | level of granularity you want to use in logging an application, it could |
| 417 | be hard to manage if the number of :class:`Logger` instances becomes |
| 418 | effectively unbounded. |
| 419 | |
| 420 | |
| 421 | Using LoggerAdapters to impart contextual information |
| 422 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ |
| 423 | |
| 424 | An easy way in which you can pass contextual information to be output along |
| 425 | with logging event information is to use the :class:`LoggerAdapter` class. |
| 426 | This class is designed to look like a :class:`Logger`, so that you can call |
| 427 | :meth:`debug`, :meth:`info`, :meth:`warning`, :meth:`error`, |
| 428 | :meth:`exception`, :meth:`critical` and :meth:`log`. These methods have the |
| 429 | same signatures as their counterparts in :class:`Logger`, so you can use the |
| 430 | two types of instances interchangeably. |
| 431 | |
| 432 | When you create an instance of :class:`LoggerAdapter`, you pass it a |
| 433 | :class:`Logger` instance and a dict-like object which contains your contextual |
| 434 | information. When you call one of the logging methods on an instance of |
| 435 | :class:`LoggerAdapter`, it delegates the call to the underlying instance of |
| 436 | :class:`Logger` passed to its constructor, and arranges to pass the contextual |
| 437 | information in the delegated call. Here's a snippet from the code of |
| 438 | :class:`LoggerAdapter`:: |
| 439 | |
| 440 | def debug(self, msg, *args, **kwargs): |
| 441 | """ |
| 442 | Delegate a debug call to the underlying logger, after adding |
| 443 | contextual information from this adapter instance. |
| 444 | """ |
| 445 | msg, kwargs = self.process(msg, kwargs) |
| 446 | self.logger.debug(msg, *args, **kwargs) |
| 447 | |
| 448 | The :meth:`process` method of :class:`LoggerAdapter` is where the contextual |
| 449 | information is added to the logging output. It's passed the message and |
| 450 | keyword arguments of the logging call, and it passes back (potentially) |
| 451 | modified versions of these to use in the call to the underlying logger. The |
| 452 | default implementation of this method leaves the message alone, but inserts |
| 453 | an 'extra' key in the keyword argument whose value is the dict-like object |
| 454 | passed to the constructor. Of course, if you had passed an 'extra' keyword |
| 455 | argument in the call to the adapter, it will be silently overwritten. |
| 456 | |
| 457 | The advantage of using 'extra' is that the values in the dict-like object are |
| 458 | merged into the :class:`LogRecord` instance's __dict__, allowing you to use |
| 459 | customized strings with your :class:`Formatter` instances which know about |
| 460 | the keys of the dict-like object. If you need a different method, e.g. if you |
| 461 | want to prepend or append the contextual information to the message string, |
| 462 | you just need to subclass :class:`LoggerAdapter` and override :meth:`process` |
| 463 | to do what you need. Here's an example script which uses this class, which |
| 464 | also illustrates what dict-like behaviour is needed from an arbitrary |
| 465 | 'dict-like' object for use in the constructor:: |
| 466 | |
| 467 | import logging |
| 468 | |
| 469 | class ConnInfo: |
| 470 | """ |
| 471 | An example class which shows how an arbitrary class can be used as |
| 472 | the 'extra' context information repository passed to a LoggerAdapter. |
| 473 | """ |
| 474 | |
| 475 | def __getitem__(self, name): |
| 476 | """ |
| 477 | To allow this instance to look like a dict. |
| 478 | """ |
| 479 | from random import choice |
| 480 | if name == 'ip': |
| 481 | result = choice(['127.0.0.1', '192.168.0.1']) |
| 482 | elif name == 'user': |
| 483 | result = choice(['jim', 'fred', 'sheila']) |
| 484 | else: |
| 485 | result = self.__dict__.get(name, '?') |
| 486 | return result |
| 487 | |
| 488 | def __iter__(self): |
| 489 | """ |
| 490 | To allow iteration over keys, which will be merged into |
| 491 | the LogRecord dict before formatting and output. |
| 492 | """ |
| 493 | keys = ['ip', 'user'] |
| 494 | keys.extend(self.__dict__.keys()) |
| 495 | return keys.__iter__() |
| 496 | |
| 497 | if __name__ == '__main__': |
| 498 | from random import choice |
| 499 | levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL) |
| 500 | a1 = logging.LoggerAdapter(logging.getLogger('a.b.c'), |
| 501 | { 'ip' : '123.231.231.123', 'user' : 'sheila' }) |
| 502 | logging.basicConfig(level=logging.DEBUG, |
| 503 | format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s') |
| 504 | a1.debug('A debug message') |
| 505 | a1.info('An info message with %s', 'some parameters') |
| 506 | a2 = logging.LoggerAdapter(logging.getLogger('d.e.f'), ConnInfo()) |
| 507 | for x in range(10): |
| 508 | lvl = choice(levels) |
| 509 | lvlname = logging.getLevelName(lvl) |
| 510 | a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters') |
| 511 | |
| 512 | When this script is run, the output should look something like this:: |
| 513 | |
| 514 | 2008-01-18 14:49:54,023 a.b.c DEBUG IP: 123.231.231.123 User: sheila A debug message |
| 515 | 2008-01-18 14:49:54,023 a.b.c INFO IP: 123.231.231.123 User: sheila An info message with some parameters |
| 516 | 2008-01-18 14:49:54,023 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters |
| 517 | 2008-01-18 14:49:54,033 d.e.f INFO IP: 192.168.0.1 User: jim A message at INFO level with 2 parameters |
| 518 | 2008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: sheila A message at WARNING level with 2 parameters |
| 519 | 2008-01-18 14:49:54,033 d.e.f ERROR IP: 127.0.0.1 User: fred A message at ERROR level with 2 parameters |
| 520 | 2008-01-18 14:49:54,033 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters |
| 521 | 2008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: sheila A message at WARNING level with 2 parameters |
| 522 | 2008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: jim A message at WARNING level with 2 parameters |
| 523 | 2008-01-18 14:49:54,033 d.e.f INFO IP: 192.168.0.1 User: fred A message at INFO level with 2 parameters |
| 524 | 2008-01-18 14:49:54,033 d.e.f WARNING IP: 192.168.0.1 User: sheila A message at WARNING level with 2 parameters |
| 525 | 2008-01-18 14:49:54,033 d.e.f WARNING IP: 127.0.0.1 User: jim A message at WARNING level with 2 parameters |
| 526 | |
| 527 | |
| 528 | .. _filters-contextual: |
| 529 | |
| 530 | Using Filters to impart contextual information |
| 531 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ |
| 532 | |
| 533 | You can also add contextual information to log output using a user-defined |
| 534 | :class:`Filter`. ``Filter`` instances are allowed to modify the ``LogRecords`` |
| 535 | passed to them, including adding additional attributes which can then be output |
| 536 | using a suitable format string, or if needed a custom :class:`Formatter`. |
| 537 | |
| 538 | For example in a web application, the request being processed (or at least, |
| 539 | the interesting parts of it) can be stored in a threadlocal |
| 540 | (:class:`threading.local`) variable, and then accessed from a ``Filter`` to |
| 541 | add, say, information from the request - say, the remote IP address and remote |
| 542 | user's username - to the ``LogRecord``, using the attribute names 'ip' and |
| 543 | 'user' as in the ``LoggerAdapter`` example above. In that case, the same format |
| 544 | string can be used to get similar output to that shown above. Here's an example |
| 545 | script:: |
| 546 | |
| 547 | import logging |
| 548 | from random import choice |
| 549 | |
| 550 | class ContextFilter(logging.Filter): |
| 551 | """ |
| 552 | This is a filter which injects contextual information into the log. |
| 553 | |
| 554 | Rather than use actual contextual information, we just use random |
| 555 | data in this demo. |
| 556 | """ |
| 557 | |
| 558 | USERS = ['jim', 'fred', 'sheila'] |
| 559 | IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1'] |
| 560 | |
| 561 | def filter(self, record): |
| 562 | |
| 563 | record.ip = choice(ContextFilter.IPS) |
| 564 | record.user = choice(ContextFilter.USERS) |
| 565 | return True |
| 566 | |
| 567 | if __name__ == '__main__': |
| 568 | levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL) |
| 569 | logging.basicConfig(level=logging.DEBUG, |
| 570 | format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s') |
| 571 | a1 = logging.getLogger('a.b.c') |
| 572 | a2 = logging.getLogger('d.e.f') |
| 573 | |
| 574 | f = ContextFilter() |
| 575 | a1.addFilter(f) |
| 576 | a2.addFilter(f) |
| 577 | a1.debug('A debug message') |
| 578 | a1.info('An info message with %s', 'some parameters') |
| 579 | for x in range(10): |
| 580 | lvl = choice(levels) |
| 581 | lvlname = logging.getLevelName(lvl) |
| 582 | a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters') |
| 583 | |
| 584 | which, when run, produces something like:: |
| 585 | |
| 586 | 2010-09-06 22:38:15,292 a.b.c DEBUG IP: 123.231.231.123 User: fred A debug message |
| 587 | 2010-09-06 22:38:15,300 a.b.c INFO IP: 192.168.0.1 User: sheila An info message with some parameters |
| 588 | 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 |
| 589 | 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 |
| 590 | 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 |
| 591 | 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 |
| 592 | 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 |
| 593 | 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 |
| 594 | 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 |
| 595 | 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 |
| 596 | 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 |
| 597 | 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 |
| 598 | |
| 599 | |
| 600 | .. _multiple-processes: |
| 601 | |
| 602 | Logging to a single file from multiple processes |
| 603 | ------------------------------------------------ |
| 604 | |
| 605 | Although logging is thread-safe, and logging to a single file from multiple |
| 606 | threads in a single process *is* supported, logging to a single file from |
| 607 | *multiple processes* is *not* supported, because there is no standard way to |
| 608 | serialize access to a single file across multiple processes in Python. If you |
| 609 | need to log to a single file from multiple processes, one way of doing this is |
| 610 | to have all the processes log to a :class:`SocketHandler`, and have a separate |
| 611 | process which implements a socket server which reads from the socket and logs |
| 612 | to file. (If you prefer, you can dedicate one thread in one of the existing |
| 613 | processes to perform this function.) The following section documents this |
| 614 | approach in more detail and includes a working socket receiver which can be |
| 615 | used as a starting point for you to adapt in your own applications. |
| 616 | |
| 617 | If you are using a recent version of Python which includes the |
| 618 | :mod:`multiprocessing` module, you could write your own handler which uses the |
| 619 | :class:`Lock` class from this module to serialize access to the file from |
| 620 | your processes. The existing :class:`FileHandler` and subclasses do not make |
| 621 | use of :mod:`multiprocessing` at present, though they may do so in the future. |
| 622 | Note that at present, the :mod:`multiprocessing` module does not provide |
| 623 | working lock functionality on all platforms (see |
| 624 | http://bugs.python.org/issue3770). |
| 625 | |
| 626 | .. currentmodule:: logging.handlers |
| 627 | |
| 628 | |
| 629 | Using file rotation |
| 630 | ------------------- |
| 631 | |
| 632 | .. sectionauthor:: Doug Hellmann, Vinay Sajip (changes) |
| 633 | .. (see <http://blog.doughellmann.com/2007/05/pymotw-logging.html>) |
| 634 | |
| 635 | Sometimes you want to let a log file grow to a certain size, then open a new |
| 636 | file and log to that. You may want to keep a certain number of these files, and |
| 637 | when that many files have been created, rotate the files so that the number of |
| 638 | files and the size of the files both remain bounded. For this usage pattern, the |
| 639 | logging package provides a :class:`RotatingFileHandler`:: |
| 640 | |
| 641 | import glob |
| 642 | import logging |
| 643 | import logging.handlers |
| 644 | |
| 645 | LOG_FILENAME = 'logging_rotatingfile_example.out' |
| 646 | |
| 647 | # Set up a specific logger with our desired output level |
| 648 | my_logger = logging.getLogger('MyLogger') |
| 649 | my_logger.setLevel(logging.DEBUG) |
| 650 | |
| 651 | # Add the log message handler to the logger |
| 652 | handler = logging.handlers.RotatingFileHandler( |
| 653 | LOG_FILENAME, maxBytes=20, backupCount=5) |
| 654 | |
| 655 | my_logger.addHandler(handler) |
| 656 | |
| 657 | # Log some messages |
| 658 | for i in range(20): |
| 659 | my_logger.debug('i = %d' % i) |
| 660 | |
| 661 | # See what files are created |
| 662 | logfiles = glob.glob('%s*' % LOG_FILENAME) |
| 663 | |
| 664 | for filename in logfiles: |
| 665 | print(filename) |
| 666 | |
| 667 | The result should be 6 separate files, each with part of the log history for the |
| 668 | application:: |
| 669 | |
| 670 | logging_rotatingfile_example.out |
| 671 | logging_rotatingfile_example.out.1 |
| 672 | logging_rotatingfile_example.out.2 |
| 673 | logging_rotatingfile_example.out.3 |
| 674 | logging_rotatingfile_example.out.4 |
| 675 | logging_rotatingfile_example.out.5 |
| 676 | |
| 677 | The most current file is always :file:`logging_rotatingfile_example.out`, |
| 678 | and each time it reaches the size limit it is renamed with the suffix |
| 679 | ``.1``. Each of the existing backup files is renamed to increment the suffix |
| 680 | (``.1`` becomes ``.2``, etc.) and the ``.6`` file is erased. |
| 681 | |
| 682 | Obviously this example sets the log length much much too small as an extreme |
| 683 | example. You would want to set *maxBytes* to an appropriate value. |
| 684 | |