Vinay Sajip | 5dbca9c | 2011-04-08 11:40:38 +0100 | [diff] [blame] | 1 | ============= |
| 2 | Logging HOWTO |
| 3 | ============= |
| 4 | |
| 5 | :Author: Vinay Sajip <vinay_sajip at red-dove dot com> |
| 6 | |
| 7 | .. _logging-basic-tutorial: |
| 8 | |
| 9 | .. currentmodule:: logging |
| 10 | |
| 11 | Basic Logging Tutorial |
| 12 | ---------------------- |
| 13 | |
| 14 | Logging is a means of tracking events that happen when some software runs. The |
| 15 | software's developer adds logging calls to their code to indicate that certain |
| 16 | events have occurred. An event is described by a descriptive message which can |
| 17 | optionally contain variable data (i.e. data that is potentially different for |
| 18 | each occurrence of the event). Events also have an importance which the |
| 19 | developer ascribes to the event; the importance can also be called the *level* |
| 20 | or *severity*. |
| 21 | |
| 22 | When to use logging |
| 23 | ^^^^^^^^^^^^^^^^^^^ |
| 24 | |
| 25 | Logging provides a set of convenience functions for simple logging usage. These |
| 26 | are :func:`debug`, :func:`info`, :func:`warning`, :func:`error` and |
| 27 | :func:`critical`. To determine when to use logging, see the table below, which |
| 28 | states, for each of a set of common tasks, the best tool to use for it. |
| 29 | |
| 30 | +-------------------------------------+--------------------------------------+ |
| 31 | | Task you want to perform | The best tool for the task | |
| 32 | +=====================================+======================================+ |
| 33 | | Display console output for ordinary | :func:`print` | |
| 34 | | usage of a command line script or | | |
| 35 | | program | | |
| 36 | +-------------------------------------+--------------------------------------+ |
| 37 | | Report events that occur during | :func:`logging.info` (or | |
| 38 | | normal operation of a program (e.g. | :func:`logging.debug` for very | |
| 39 | | for status monitoring or fault | detailed output for diagnostic | |
| 40 | | investigation) | purposes) | |
| 41 | +-------------------------------------+--------------------------------------+ |
| 42 | | Issue a warning regarding a | :func:`warnings.warn` in library | |
| 43 | | particular runtime event | code if the issue is avoidable and | |
| 44 | | | the client application should be | |
| 45 | | | modified to eliminate the warning | |
| 46 | | | | |
| 47 | | | :func:`logging.warning` if there is | |
| 48 | | | nothing the client application can do| |
| 49 | | | about the situation, but the event | |
| 50 | | | should still be noted | |
| 51 | +-------------------------------------+--------------------------------------+ |
| 52 | | Report an error regarding a | Raise an exception | |
| 53 | | particular runtime event | | |
| 54 | +-------------------------------------+--------------------------------------+ |
| 55 | | Report suppression of an error | :func:`logging.error`, | |
| 56 | | without raising an exception (e.g. | :func:`logging.exception` or | |
| 57 | | error handler in a long-running | :func:`logging.critical` as | |
| 58 | | server process) | appropriate for the specific error | |
| 59 | | | and application domain | |
| 60 | +-------------------------------------+--------------------------------------+ |
| 61 | |
| 62 | The logging functions are named after the level or severity of the events |
| 63 | they are used to track. The standard levels and their applicability are |
| 64 | described below (in increasing order of severity): |
| 65 | |
| 66 | +--------------+---------------------------------------------+ |
| 67 | | Level | When it's used | |
| 68 | +==============+=============================================+ |
| 69 | | ``DEBUG`` | Detailed information, typically of interest | |
| 70 | | | only when diagnosing problems. | |
| 71 | +--------------+---------------------------------------------+ |
| 72 | | ``INFO`` | Confirmation that things are working as | |
| 73 | | | expected. | |
| 74 | +--------------+---------------------------------------------+ |
| 75 | | ``WARNING`` | An indication that something unexpected | |
| 76 | | | happened, or indicative of some problem in | |
| 77 | | | the near future (e.g. 'disk space low'). | |
| 78 | | | The software is still working as expected. | |
| 79 | +--------------+---------------------------------------------+ |
| 80 | | ``ERROR`` | Due to a more serious problem, the software | |
| 81 | | | has not been able to perform some function. | |
| 82 | +--------------+---------------------------------------------+ |
| 83 | | ``CRITICAL`` | A serious error, indicating that the program| |
| 84 | | | itself may be unable to continue running. | |
| 85 | +--------------+---------------------------------------------+ |
| 86 | |
| 87 | The default level is ``WARNING``, which means that only events of this level |
| 88 | and above will be tracked, unless the logging package is configured to do |
| 89 | otherwise. |
| 90 | |
| 91 | Events that are tracked can be handled in different ways. The simplest way of |
| 92 | handling tracked events is to print them to the console. Another common way |
| 93 | is to write them to a disk file. |
| 94 | |
| 95 | |
| 96 | .. _howto-minimal-example: |
| 97 | |
| 98 | A simple example |
| 99 | ^^^^^^^^^^^^^^^^ |
| 100 | |
| 101 | A very simple example is:: |
| 102 | |
| 103 | import logging |
| 104 | logging.warning('Watch out!') # will print a message to the console |
| 105 | logging.info('I told you so') # will not print anything |
| 106 | |
| 107 | If you type these lines into a script and run it, you'll see:: |
| 108 | |
| 109 | WARNING:root:Watch out! |
| 110 | |
| 111 | printed out on the console. The ``INFO`` message doesn't appear because the |
| 112 | default level is ``WARNING``. The printed message includes the indication of |
| 113 | the level and the description of the event provided in the logging call, i.e. |
| 114 | 'Watch out!'. Don't worry about the 'root' part for now: it will be explained |
| 115 | later. The actual output can be formatted quite flexibly if you need that; |
| 116 | formatting options will also be explained later. |
| 117 | |
| 118 | |
| 119 | Logging to a file |
| 120 | ^^^^^^^^^^^^^^^^^ |
| 121 | |
| 122 | A very common situation is that of recording logging events in a file, so let's |
| 123 | look at that next:: |
| 124 | |
| 125 | import logging |
| 126 | logging.basicConfig(filename='example.log',level=logging.DEBUG) |
| 127 | logging.debug('This message should go to the log file') |
| 128 | logging.info('So should this') |
| 129 | logging.warning('And this, too') |
| 130 | |
| 131 | And now if we open the file and look at what we have, we should find the log |
| 132 | messages:: |
| 133 | |
| 134 | DEBUG:root:This message should go to the log file |
| 135 | INFO:root:So should this |
| 136 | WARNING:root:And this, too |
| 137 | |
| 138 | This example also shows how you can set the logging level which acts as the |
| 139 | threshold for tracking. In this case, because we set the threshold to |
| 140 | ``DEBUG``, all of the messages were printed. |
| 141 | |
| 142 | If you want to set the logging level from a command-line option such as:: |
| 143 | |
| 144 | --log=INFO |
| 145 | |
| 146 | and you have the value of the parameter passed for ``--log`` in some variable |
| 147 | *loglevel*, you can use:: |
| 148 | |
| 149 | getattr(logging, loglevel.upper()) |
| 150 | |
| 151 | to get the value which you'll pass to :func:`basicConfig` via the *level* |
| 152 | argument. You may want to error check any user input value, perhaps as in the |
| 153 | following example:: |
| 154 | |
| 155 | # assuming loglevel is bound to the string value obtained from the |
| 156 | # command line argument. Convert to upper case to allow the user to |
| 157 | # specify --log=DEBUG or --log=debug |
| 158 | numeric_level = getattr(logging, loglevel.upper(), None) |
| 159 | if not isinstance(numeric_level, int): |
| 160 | raise ValueError('Invalid log level: %s' % loglevel) |
| 161 | logging.basicConfig(level=numeric_level, ...) |
| 162 | |
| 163 | The call to :func:`basicConfig` should come *before* any calls to :func:`debug`, |
| 164 | :func:`info` etc. As it's intended as a one-off simple configuration facility, |
| 165 | only the first call will actually do anything: subsequent calls are effectively |
| 166 | no-ops. |
| 167 | |
| 168 | If you run the above script several times, the messages from successive runs |
| 169 | are appended to the file *example.log*. If you want each run to start afresh, |
| 170 | not remembering the messages from earlier runs, you can specify the *filemode* |
| 171 | argument, by changing the call in the above example to:: |
| 172 | |
| 173 | logging.basicConfig(filename='example.log', filemode='w', level=logging.DEBUG) |
| 174 | |
| 175 | The output will be the same as before, but the log file is no longer appended |
| 176 | to, so the messages from earlier runs are lost. |
| 177 | |
| 178 | |
| 179 | Logging from multiple modules |
| 180 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ |
| 181 | |
| 182 | If your program consists of multiple modules, here's an example of how you |
| 183 | could organize logging in it:: |
| 184 | |
| 185 | # myapp.py |
| 186 | import logging |
| 187 | import mylib |
| 188 | |
| 189 | def main(): |
| 190 | logging.basicConfig(filename='myapp.log', level=logging.INFO) |
| 191 | logging.info('Started') |
| 192 | mylib.do_something() |
| 193 | logging.info('Finished') |
| 194 | |
| 195 | if __name__ == '__main__': |
| 196 | main() |
| 197 | |
| 198 | :: |
| 199 | |
| 200 | # mylib.py |
| 201 | import logging |
| 202 | |
| 203 | def do_something(): |
| 204 | logging.info('Doing something') |
| 205 | |
| 206 | If you run *myapp.py*, you should see this in *myapp.log*:: |
| 207 | |
| 208 | INFO:root:Started |
| 209 | INFO:root:Doing something |
| 210 | INFO:root:Finished |
| 211 | |
| 212 | which is hopefully what you were expecting to see. You can generalize this to |
| 213 | multiple modules, using the pattern in *mylib.py*. Note that for this simple |
| 214 | usage pattern, you won't know, by looking in the log file, *where* in your |
| 215 | application your messages came from, apart from looking at the event |
| 216 | description. If you want to track the location of your messages, you'll need |
| 217 | to refer to the documentation beyond the tutorial level -- see |
| 218 | :ref:`logging-advanced-tutorial`. |
| 219 | |
| 220 | |
| 221 | Logging variable data |
| 222 | ^^^^^^^^^^^^^^^^^^^^^ |
| 223 | |
| 224 | To log variable data, use a format string for the event description message and |
| 225 | append the variable data as arguments. For example:: |
| 226 | |
| 227 | import logging |
| 228 | logging.warning('%s before you %s', 'Look', 'leap!') |
| 229 | |
| 230 | will display:: |
| 231 | |
| 232 | WARNING:root:Look before you leap! |
| 233 | |
| 234 | As you can see, merging of variable data into the event description message |
| 235 | uses the old, %-style of string formatting. This is for backwards |
| 236 | compatibility: the logging package pre-dates newer formatting options such as |
| 237 | :meth:`str.format` and :class:`string.Template`. These newer formatting |
| 238 | options *are* supported, but exploring them is outside the scope of this |
| 239 | tutorial. |
| 240 | |
| 241 | |
| 242 | Changing the format of displayed messages |
| 243 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ |
| 244 | |
| 245 | To change the format which is used to display messages, you need to |
| 246 | specify the format you want to use:: |
| 247 | |
| 248 | import logging |
| 249 | logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG) |
| 250 | logging.debug('This message should appear on the console') |
| 251 | logging.info('So should this') |
| 252 | logging.warning('And this, too') |
| 253 | |
| 254 | which would print:: |
| 255 | |
| 256 | DEBUG:This message should appear on the console |
| 257 | INFO:So should this |
| 258 | WARNING:And this, too |
| 259 | |
| 260 | Notice that the 'root' which appeared in earlier examples has disappeared. For |
| 261 | a full set of things that can appear in format strings, you can refer to the |
| 262 | documentation for :ref:`logrecord-attributes`, but for simple usage, you just |
| 263 | need the *levelname* (severity), *message* (event description, including |
| 264 | variable data) and perhaps to display when the event occurred. This is |
| 265 | described in the next section. |
| 266 | |
| 267 | |
| 268 | Displaying the date/time in messages |
| 269 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ |
| 270 | |
| 271 | To display the date and time of an event, you would place '%(asctime)s' in |
| 272 | your format string:: |
| 273 | |
| 274 | import logging |
| 275 | logging.basicConfig(format='%(asctime)s %(message)s') |
| 276 | logging.warning('is when this event was logged.') |
| 277 | |
| 278 | which should print something like this:: |
| 279 | |
| 280 | 2010-12-12 11:41:42,612 is when this event was logged. |
| 281 | |
| 282 | The default format for date/time display (shown above) is ISO8601. If you need |
| 283 | more control over the formatting of the date/time, provide a *datefmt* |
| 284 | argument to ``basicConfig``, as in this example:: |
| 285 | |
| 286 | import logging |
| 287 | logging.basicConfig(format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p') |
| 288 | logging.warning('is when this event was logged.') |
| 289 | |
| 290 | which would display something like this:: |
| 291 | |
| 292 | 12/12/2010 11:46:36 AM is when this event was logged. |
| 293 | |
| 294 | The format of the *datefmt* argument is the same as supported by |
| 295 | :func:`time.strftime`. |
| 296 | |
| 297 | |
| 298 | Next Steps |
| 299 | ^^^^^^^^^^ |
| 300 | |
| 301 | That concludes the basic tutorial. It should be enough to get you up and |
| 302 | running with logging. There's a lot more that the logging package offers, but |
| 303 | to get the best out of it, you'll need to invest a little more of your time in |
| 304 | reading the following sections. If you're ready for that, grab some of your |
| 305 | favourite beverage and carry on. |
| 306 | |
| 307 | If your logging needs are simple, then use the above examples to incorporate |
| 308 | logging into your own scripts, and if you run into problems or don't |
| 309 | understand something, please post a question on the comp.lang.python Usenet |
| 310 | group (available at http://groups.google.com/group/comp.lang.python) and you |
| 311 | should receive help before too long. |
| 312 | |
| 313 | Still here? You can carry on reading the next few sections, which provide a |
| 314 | slightly more advanced/in-depth tutorial than the basic one above. After that, |
| 315 | you can take a look at the :ref:`logging-cookbook`. |
| 316 | |
| 317 | .. _logging-advanced-tutorial: |
| 318 | |
| 319 | |
| 320 | Advanced Logging Tutorial |
| 321 | ------------------------- |
| 322 | |
| 323 | The logging library takes a modular approach and offers several categories |
| 324 | of components: loggers, handlers, filters, and formatters. |
| 325 | |
| 326 | * Loggers expose the interface that application code directly uses. |
| 327 | * Handlers send the log records (created by loggers) to the appropriate |
| 328 | destination. |
| 329 | * Filters provide a finer grained facility for determining which log records |
| 330 | to output. |
| 331 | * Formatters specify the layout of log records in the final output. |
| 332 | |
| 333 | Logging is performed by calling methods on instances of the :class:`Logger` |
| 334 | class (hereafter called :dfn:`loggers`). Each instance has a name, and they are |
| 335 | conceptually arranged in a namespace hierarchy using dots (periods) as |
| 336 | separators. For example, a logger named 'scan' is the parent of loggers |
| 337 | 'scan.text', 'scan.html' and 'scan.pdf'. Logger names can be anything you want, |
| 338 | and indicate the area of an application in which a logged message originates. |
| 339 | |
| 340 | A good convention to use when naming loggers is to use a module-level logger, |
| 341 | in each module which uses logging, named as follows:: |
| 342 | |
| 343 | logger = logging.getLogger(__name__) |
| 344 | |
| 345 | This means that logger names track the package/module hierarchy, and it's |
| 346 | intuitively obvious where events are logged just from the logger name. |
| 347 | |
| 348 | The root of the hierarchy of loggers is called the root logger. That's the |
| 349 | logger used by the functions :func:`debug`, :func:`info`, :func:`warning`, |
| 350 | :func:`error` and :func:`critical`, which just call the same-named method of |
| 351 | the root logger. The functions and the methods have the same signatures. The |
| 352 | root logger's name is printed as 'root' in the logged output. |
| 353 | |
| 354 | It is, of course, possible to log messages to different destinations. Support |
| 355 | is included in the package for writing log messages to files, HTTP GET/POST |
| 356 | locations, email via SMTP, generic sockets, or OS-specific logging mechanisms |
| 357 | such as syslog or the Windows NT event log. Destinations are served by |
| 358 | :dfn:`handler` classes. You can create your own log destination class if you |
| 359 | have special requirements not met by any of the built-in handler classes. |
| 360 | |
| 361 | By default, no destination is set for any logging messages. You can specify |
| 362 | a destination (such as console or file) by using :func:`basicConfig` as in the |
| 363 | tutorial examples. If you call the functions :func:`debug`, :func:`info`, |
| 364 | :func:`warning`, :func:`error` and :func:`critical`, they will check to see |
| 365 | if no destination is set; and if one is not set, they will set a destination |
| 366 | of the console (``sys.stderr``) and a default format for the displayed |
| 367 | message before delegating to the root logger to do the actual message output. |
| 368 | |
| 369 | The default format set by :func:`basicConfig` for messages is:: |
| 370 | |
| 371 | severity:logger name:message |
| 372 | |
| 373 | You can change this by passing a format string to :func:`basicConfig` with the |
| 374 | *format* keyword argument. For all options regarding how a format string is |
| 375 | constructed, see :ref:`formatter-objects`. |
| 376 | |
| 377 | |
| 378 | Loggers |
| 379 | ^^^^^^^ |
| 380 | |
| 381 | :class:`Logger` objects have a threefold job. First, they expose several |
| 382 | methods to application code so that applications can log messages at runtime. |
| 383 | Second, logger objects determine which log messages to act upon based upon |
| 384 | severity (the default filtering facility) or filter objects. Third, logger |
| 385 | objects pass along relevant log messages to all interested log handlers. |
| 386 | |
| 387 | The most widely used methods on logger objects fall into two categories: |
| 388 | configuration and message sending. |
| 389 | |
| 390 | These are the most common configuration methods: |
| 391 | |
| 392 | * :meth:`Logger.setLevel` specifies the lowest-severity log message a logger |
| 393 | will handle, where debug is the lowest built-in severity level and critical |
| 394 | is the highest built-in severity. For example, if the severity level is |
| 395 | INFO, the logger will handle only INFO, WARNING, ERROR, and CRITICAL messages |
| 396 | and will ignore DEBUG messages. |
| 397 | |
| 398 | * :meth:`Logger.addHandler` and :meth:`Logger.removeHandler` add and remove |
| 399 | handler objects from the logger object. Handlers are covered in more detail |
| 400 | in :ref:`handler-basic`. |
| 401 | |
| 402 | * :meth:`Logger.addFilter` and :meth:`Logger.removeFilter` add and remove filter |
| 403 | objects from the logger object. Filters are covered in more detail in |
| 404 | :ref:`filter`. |
| 405 | |
| 406 | You don't need to always call these methods on every logger you create. See the |
| 407 | last two paragraphs in this section. |
| 408 | |
| 409 | With the logger object configured, the following methods create log messages: |
| 410 | |
| 411 | * :meth:`Logger.debug`, :meth:`Logger.info`, :meth:`Logger.warning`, |
| 412 | :meth:`Logger.error`, and :meth:`Logger.critical` all create log records with |
| 413 | a message and a level that corresponds to their respective method names. The |
| 414 | message is actually a format string, which may contain the standard string |
| 415 | substitution syntax of :const:`%s`, :const:`%d`, :const:`%f`, and so on. The |
| 416 | rest of their arguments is a list of objects that correspond with the |
| 417 | substitution fields in the message. With regard to :const:`**kwargs`, the |
| 418 | logging methods care only about a keyword of :const:`exc_info` and use it to |
| 419 | determine whether to log exception information. |
| 420 | |
| 421 | * :meth:`Logger.exception` creates a log message similar to |
| 422 | :meth:`Logger.error`. The difference is that :meth:`Logger.exception` dumps a |
| 423 | stack trace along with it. Call this method only from an exception handler. |
| 424 | |
| 425 | * :meth:`Logger.log` takes a log level as an explicit argument. This is a |
| 426 | little more verbose for logging messages than using the log level convenience |
| 427 | methods listed above, but this is how to log at custom log levels. |
| 428 | |
| 429 | :func:`getLogger` returns a reference to a logger instance with the specified |
| 430 | name if it is provided, or ``root`` if not. The names are period-separated |
| 431 | hierarchical structures. Multiple calls to :func:`getLogger` with the same name |
| 432 | will return a reference to the same logger object. Loggers that are further |
| 433 | down in the hierarchical list are children of loggers higher up in the list. |
| 434 | For example, given a logger with a name of ``foo``, loggers with names of |
| 435 | ``foo.bar``, ``foo.bar.baz``, and ``foo.bam`` are all descendants of ``foo``. |
| 436 | |
| 437 | Loggers have a concept of *effective level*. If a level is not explicitly set |
| 438 | on a logger, the level of its parent is used instead as its effective level. |
| 439 | If the parent has no explicit level set, *its* parent is examined, and so on - |
| 440 | all ancestors are searched until an explicitly set level is found. The root |
| 441 | logger always has an explicit level set (``WARNING`` by default). When deciding |
| 442 | whether to process an event, the effective level of the logger is used to |
| 443 | determine whether the event is passed to the logger's handlers. |
| 444 | |
| 445 | Child loggers propagate messages up to the handlers associated with their |
| 446 | ancestor loggers. Because of this, it is unnecessary to define and configure |
| 447 | handlers for all the loggers an application uses. It is sufficient to |
| 448 | configure handlers for a top-level logger and create child loggers as needed. |
| 449 | (You can, however, turn off propagation by setting the *propagate* |
| 450 | attribute of a logger to *False*.) |
| 451 | |
| 452 | |
| 453 | .. _handler-basic: |
| 454 | |
| 455 | Handlers |
| 456 | ^^^^^^^^ |
| 457 | |
| 458 | :class:`~logging.Handler` objects are responsible for dispatching the |
| 459 | appropriate log messages (based on the log messages' severity) to the handler's |
| 460 | specified destination. Logger objects can add zero or more handler objects to |
| 461 | themselves with an :func:`addHandler` method. As an example scenario, an |
| 462 | application may want to send all log messages to a log file, all log messages |
| 463 | of error or higher to stdout, and all messages of critical to an email address. |
| 464 | This scenario requires three individual handlers where each handler is |
| 465 | responsible for sending messages of a specific severity to a specific location. |
| 466 | |
| 467 | The standard library includes quite a few handler types (see |
| 468 | :ref:`useful-handlers`); the tutorials use mainly :class:`StreamHandler` and |
| 469 | :class:`FileHandler` in its examples. |
| 470 | |
| 471 | There are very few methods in a handler for application developers to concern |
| 472 | themselves with. The only handler methods that seem relevant for application |
| 473 | developers who are using the built-in handler objects (that is, not creating |
| 474 | custom handlers) are the following configuration methods: |
| 475 | |
| 476 | * The :meth:`Handler.setLevel` method, just as in logger objects, specifies the |
| 477 | lowest severity that will be dispatched to the appropriate destination. Why |
| 478 | are there two :func:`setLevel` methods? The level set in the logger |
| 479 | determines which severity of messages it will pass to its handlers. The level |
| 480 | set in each handler determines which messages that handler will send on. |
| 481 | |
| 482 | * :func:`setFormatter` selects a Formatter object for this handler to use. |
| 483 | |
| 484 | * :func:`addFilter` and :func:`removeFilter` respectively configure and |
| 485 | deconfigure filter objects on handlers. |
| 486 | |
| 487 | Application code should not directly instantiate and use instances of |
| 488 | :class:`Handler`. Instead, the :class:`Handler` class is a base class that |
| 489 | defines the interface that all handlers should have and establishes some |
| 490 | default behavior that child classes can use (or override). |
| 491 | |
| 492 | |
| 493 | Formatters |
| 494 | ^^^^^^^^^^ |
| 495 | |
| 496 | Formatter objects configure the final order, structure, and contents of the log |
| 497 | message. Unlike the base :class:`logging.Handler` class, application code may |
| 498 | instantiate formatter classes, although you could likely subclass the formatter |
| 499 | if your application needs special behavior. The constructor takes two |
| 500 | optional arguments -- a message format string and a date format string. |
| 501 | |
| 502 | .. method:: logging.Formatter.__init__(fmt=None, datefmt=None) |
| 503 | |
| 504 | If there is no message format string, the default is to use the |
| 505 | raw message. If there is no date format string, the default date format is:: |
| 506 | |
| 507 | %Y-%m-%d %H:%M:%S |
| 508 | |
| 509 | with the milliseconds tacked on at the end. |
| 510 | |
| 511 | The message format string uses ``%(<dictionary key>)s`` styled string |
| 512 | substitution; the possible keys are documented in :ref:`logrecord-attributes`. |
| 513 | |
| 514 | The following message format string will log the time in a human-readable |
| 515 | format, the severity of the message, and the contents of the message, in that |
| 516 | order:: |
| 517 | |
| 518 | '%(asctime)s - %(levelname)s - %(message)s' |
| 519 | |
| 520 | Formatters use a user-configurable function to convert the creation time of a |
| 521 | record to a tuple. By default, :func:`time.localtime` is used; to change this |
| 522 | for a particular formatter instance, set the ``converter`` attribute of the |
| 523 | instance to a function with the same signature as :func:`time.localtime` or |
| 524 | :func:`time.gmtime`. To change it for all formatters, for example if you want |
| 525 | all logging times to be shown in GMT, set the ``converter`` attribute in the |
| 526 | Formatter class (to ``time.gmtime`` for GMT display). |
| 527 | |
| 528 | |
| 529 | Configuring Logging |
| 530 | ^^^^^^^^^^^^^^^^^^^ |
| 531 | |
| 532 | .. currentmodule:: logging.config |
| 533 | |
| 534 | Programmers can configure logging in three ways: |
| 535 | |
| 536 | 1. Creating loggers, handlers, and formatters explicitly using Python |
| 537 | code that calls the configuration methods listed above. |
| 538 | 2. Creating a logging config file and reading it using the :func:`fileConfig` |
| 539 | function. |
| 540 | 3. Creating a dictionary of configuration information and passing it |
| 541 | to the :func:`dictConfig` function. |
| 542 | |
| 543 | For the reference documentation on the last two options, see |
| 544 | :ref:`logging-config-api`. The following example configures a very simple |
| 545 | logger, a console handler, and a simple formatter using Python code:: |
| 546 | |
| 547 | import logging |
| 548 | |
| 549 | # create logger |
| 550 | logger = logging.getLogger('simple_example') |
| 551 | logger.setLevel(logging.DEBUG) |
| 552 | |
| 553 | # create console handler and set level to debug |
| 554 | ch = logging.StreamHandler() |
| 555 | ch.setLevel(logging.DEBUG) |
| 556 | |
| 557 | # create formatter |
| 558 | formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s') |
| 559 | |
| 560 | # add formatter to ch |
| 561 | ch.setFormatter(formatter) |
| 562 | |
| 563 | # add ch to logger |
| 564 | logger.addHandler(ch) |
| 565 | |
| 566 | # 'application' code |
| 567 | logger.debug('debug message') |
| 568 | logger.info('info message') |
| 569 | logger.warn('warn message') |
| 570 | logger.error('error message') |
| 571 | logger.critical('critical message') |
| 572 | |
| 573 | Running this module from the command line produces the following output:: |
| 574 | |
| 575 | $ python simple_logging_module.py |
| 576 | 2005-03-19 15:10:26,618 - simple_example - DEBUG - debug message |
| 577 | 2005-03-19 15:10:26,620 - simple_example - INFO - info message |
| 578 | 2005-03-19 15:10:26,695 - simple_example - WARNING - warn message |
| 579 | 2005-03-19 15:10:26,697 - simple_example - ERROR - error message |
| 580 | 2005-03-19 15:10:26,773 - simple_example - CRITICAL - critical message |
| 581 | |
| 582 | The following Python module creates a logger, handler, and formatter nearly |
| 583 | identical to those in the example listed above, with the only difference being |
| 584 | the names of the objects:: |
| 585 | |
| 586 | import logging |
| 587 | import logging.config |
| 588 | |
| 589 | logging.config.fileConfig('logging.conf') |
| 590 | |
| 591 | # create logger |
| 592 | logger = logging.getLogger('simpleExample') |
| 593 | |
| 594 | # 'application' code |
| 595 | logger.debug('debug message') |
| 596 | logger.info('info message') |
| 597 | logger.warn('warn message') |
| 598 | logger.error('error message') |
| 599 | logger.critical('critical message') |
| 600 | |
| 601 | Here is the logging.conf file:: |
| 602 | |
| 603 | [loggers] |
| 604 | keys=root,simpleExample |
| 605 | |
| 606 | [handlers] |
| 607 | keys=consoleHandler |
| 608 | |
| 609 | [formatters] |
| 610 | keys=simpleFormatter |
| 611 | |
| 612 | [logger_root] |
| 613 | level=DEBUG |
| 614 | handlers=consoleHandler |
| 615 | |
| 616 | [logger_simpleExample] |
| 617 | level=DEBUG |
| 618 | handlers=consoleHandler |
| 619 | qualname=simpleExample |
| 620 | propagate=0 |
| 621 | |
| 622 | [handler_consoleHandler] |
| 623 | class=StreamHandler |
| 624 | level=DEBUG |
| 625 | formatter=simpleFormatter |
| 626 | args=(sys.stdout,) |
| 627 | |
| 628 | [formatter_simpleFormatter] |
| 629 | format=%(asctime)s - %(name)s - %(levelname)s - %(message)s |
| 630 | datefmt= |
| 631 | |
| 632 | The output is nearly identical to that of the non-config-file-based example:: |
| 633 | |
| 634 | $ python simple_logging_config.py |
| 635 | 2005-03-19 15:38:55,977 - simpleExample - DEBUG - debug message |
| 636 | 2005-03-19 15:38:55,979 - simpleExample - INFO - info message |
| 637 | 2005-03-19 15:38:56,054 - simpleExample - WARNING - warn message |
| 638 | 2005-03-19 15:38:56,055 - simpleExample - ERROR - error message |
| 639 | 2005-03-19 15:38:56,130 - simpleExample - CRITICAL - critical message |
| 640 | |
| 641 | You can see that the config file approach has a few advantages over the Python |
| 642 | code approach, mainly separation of configuration and code and the ability of |
| 643 | noncoders to easily modify the logging properties. |
| 644 | |
| 645 | .. currentmodule:: logging |
| 646 | |
| 647 | Note that the class names referenced in config files need to be either relative |
| 648 | to the logging module, or absolute values which can be resolved using normal |
| 649 | import mechanisms. Thus, you could use either |
| 650 | :class:`~logging.handlers.WatchedFileHandler` (relative to the logging module) or |
| 651 | ``mypackage.mymodule.MyHandler`` (for a class defined in package ``mypackage`` |
| 652 | and module ``mymodule``, where ``mypackage`` is available on the Python import |
| 653 | path). |
| 654 | |
| 655 | In Python 2.7, a new means of configuring logging has been introduced, using |
| 656 | dictionaries to hold configuration information. This provides a superset of the |
| 657 | functionality of the config-file-based approach outlined above, and is the |
| 658 | recommended configuration method for new applications and deployments. Because |
| 659 | a Python dictionary is used to hold configuration information, and since you |
| 660 | can populate that dictionary using different means, you have more options for |
| 661 | configuration. For example, you can use a configuration file in JSON format, |
| 662 | or, if you have access to YAML processing functionality, a file in YAML |
| 663 | format, to populate the configuration dictionary. Or, of course, you can |
| 664 | construct the dictionary in Python code, receive it in pickled form over a |
| 665 | socket, or use whatever approach makes sense for your application. |
| 666 | |
| 667 | Here's an example of the same configuration as above, in YAML format for |
| 668 | the new dictionary-based approach:: |
| 669 | |
| 670 | version: 1 |
| 671 | formatters: |
| 672 | simple: |
| 673 | format: format=%(asctime)s - %(name)s - %(levelname)s - %(message)s |
| 674 | handlers: |
| 675 | console: |
| 676 | class: logging.StreamHandler |
| 677 | level: DEBUG |
| 678 | formatter: simple |
| 679 | stream: ext://sys.stdout |
| 680 | loggers: |
| 681 | simpleExample: |
| 682 | level: DEBUG |
| 683 | handlers: [console] |
| 684 | propagate: no |
| 685 | root: |
| 686 | level: DEBUG |
| 687 | handlers: [console] |
| 688 | |
| 689 | For more information about logging using a dictionary, see |
| 690 | :ref:`logging-config-api`. |
| 691 | |
| 692 | What happens if no configuration is provided |
| 693 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ |
| 694 | |
| 695 | If no logging configuration is provided, it is possible to have a situation |
| 696 | where a logging event needs to be output, but no handlers can be found to |
| 697 | output the event. The behaviour of the logging package in these |
| 698 | circumstances is dependent on the Python version. |
| 699 | |
| 700 | For Python 2.x, the behaviour is as follows: |
| 701 | |
| 702 | * If *logging.raiseExceptions* is *False* (production mode), the event is |
| 703 | silently dropped. |
| 704 | |
| 705 | * If *logging.raiseExceptions* is *True* (development mode), a message |
| 706 | 'No handlers could be found for logger X.Y.Z' is printed once. |
| 707 | |
| 708 | .. _library-config: |
| 709 | |
| 710 | Configuring Logging for a Library |
| 711 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ |
| 712 | |
| 713 | When developing a library which uses logging, you should take care to |
| 714 | document how the library uses logging - for example, the names of loggers |
| 715 | used. Some consideration also needs to be given to its logging configuration. |
| 716 | If the using application does not use logging, and library code makes logging |
| 717 | calls, then (as described in the previous section) events of severity |
| 718 | ``WARNING`` and greater will be printed to ``sys.stderr``. This is regarded as |
| 719 | the best default behaviour. |
| 720 | |
| 721 | If for some reason you *don't* want these messages printed in the absence of |
| 722 | any logging configuration, you can attach a do-nothing handler to the top-level |
| 723 | logger for your library. This avoids the message being printed, since a handler |
| 724 | will be always be found for the library's events: it just doesn't produce any |
| 725 | output. If the library user configures logging for application use, presumably |
| 726 | that configuration will add some handlers, and if levels are suitably |
| 727 | configured then logging calls made in library code will send output to those |
| 728 | handlers, as normal. |
| 729 | |
| 730 | A do-nothing handler is included in the logging package: |
| 731 | :class:`~logging.NullHandler` (since Python 2.7). An instance of this handler |
| 732 | could be added to the top-level logger of the logging namespace used by the |
| 733 | library (*if* you want to prevent your library's logged events being output to |
| 734 | ``sys.stderr`` in the absence of logging configuration). If all logging by a |
| 735 | library *foo* is done using loggers with names matching 'foo.x', 'foo.x.y', |
| 736 | etc. then the code:: |
| 737 | |
| 738 | import logging |
| 739 | logging.getLogger('foo').addHandler(logging.NullHandler()) |
| 740 | |
| 741 | should have the desired effect. If an organisation produces a number of |
| 742 | libraries, then the logger name specified can be 'orgname.foo' rather than |
| 743 | just 'foo'. |
| 744 | |
| 745 | **PLEASE NOTE:** It is strongly advised that you *do not add any handlers other |
| 746 | than* :class:`~logging.NullHandler` *to your library's loggers*. This is |
| 747 | because the configuration of handlers is the prerogative of the application |
| 748 | developer who uses your library. The application developer knows their target |
| 749 | audience and what handlers are most appropriate for their application: if you |
| 750 | add handlers 'under the hood', you might well interfere with their ability to |
| 751 | carry out unit tests and deliver logs which suit their requirements. |
| 752 | |
| 753 | |
| 754 | Logging Levels |
| 755 | -------------- |
| 756 | |
| 757 | The numeric values of logging levels are given in the following table. These are |
| 758 | primarily of interest if you want to define your own levels, and need them to |
| 759 | have specific values relative to the predefined levels. If you define a level |
| 760 | with the same numeric value, it overwrites the predefined value; the predefined |
| 761 | name is lost. |
| 762 | |
| 763 | +--------------+---------------+ |
| 764 | | Level | Numeric value | |
| 765 | +==============+===============+ |
| 766 | | ``CRITICAL`` | 50 | |
| 767 | +--------------+---------------+ |
| 768 | | ``ERROR`` | 40 | |
| 769 | +--------------+---------------+ |
| 770 | | ``WARNING`` | 30 | |
| 771 | +--------------+---------------+ |
| 772 | | ``INFO`` | 20 | |
| 773 | +--------------+---------------+ |
| 774 | | ``DEBUG`` | 10 | |
| 775 | +--------------+---------------+ |
| 776 | | ``NOTSET`` | 0 | |
| 777 | +--------------+---------------+ |
| 778 | |
| 779 | Levels can also be associated with loggers, being set either by the developer or |
| 780 | through loading a saved logging configuration. When a logging method is called |
| 781 | on a logger, the logger compares its own level with the level associated with |
| 782 | the method call. If the logger's level is higher than the method call's, no |
| 783 | logging message is actually generated. This is the basic mechanism controlling |
| 784 | the verbosity of logging output. |
| 785 | |
| 786 | Logging messages are encoded as instances of the :class:`~logging.LogRecord` |
| 787 | class. When a logger decides to actually log an event, a |
| 788 | :class:`~logging.LogRecord` instance is created from the logging message. |
| 789 | |
| 790 | Logging messages are subjected to a dispatch mechanism through the use of |
| 791 | :dfn:`handlers`, which are instances of subclasses of the :class:`Handler` |
| 792 | class. Handlers are responsible for ensuring that a logged message (in the form |
| 793 | of a :class:`LogRecord`) ends up in a particular location (or set of locations) |
| 794 | which is useful for the target audience for that message (such as end users, |
| 795 | support desk staff, system administrators, developers). Handlers are passed |
| 796 | :class:`LogRecord` instances intended for particular destinations. Each logger |
| 797 | can have zero, one or more handlers associated with it (via the |
| 798 | :meth:`~Logger.addHandler` method of :class:`Logger`). In addition to any |
| 799 | handlers directly associated with a logger, *all handlers associated with all |
| 800 | ancestors of the logger* are called to dispatch the message (unless the |
| 801 | *propagate* flag for a logger is set to a false value, at which point the |
| 802 | passing to ancestor handlers stops). |
| 803 | |
| 804 | Just as for loggers, handlers can have levels associated with them. A handler's |
| 805 | level acts as a filter in the same way as a logger's level does. If a handler |
| 806 | decides to actually dispatch an event, the :meth:`~Handler.emit` method is used |
| 807 | to send the message to its destination. Most user-defined subclasses of |
| 808 | :class:`Handler` will need to override this :meth:`~Handler.emit`. |
| 809 | |
| 810 | .. _custom-levels: |
| 811 | |
| 812 | Custom Levels |
| 813 | ^^^^^^^^^^^^^ |
| 814 | |
| 815 | Defining your own levels is possible, but should not be necessary, as the |
| 816 | existing levels have been chosen on the basis of practical experience. |
| 817 | However, if you are convinced that you need custom levels, great care should |
| 818 | be exercised when doing this, and it is possibly *a very bad idea to define |
| 819 | custom levels if you are developing a library*. That's because if multiple |
| 820 | library authors all define their own custom levels, there is a chance that |
| 821 | the logging output from such multiple libraries used together will be |
| 822 | difficult for the using developer to control and/or interpret, because a |
| 823 | given numeric value might mean different things for different libraries. |
| 824 | |
| 825 | .. _useful-handlers: |
| 826 | |
| 827 | Useful Handlers |
| 828 | --------------- |
| 829 | |
| 830 | In addition to the base :class:`Handler` class, many useful subclasses are |
| 831 | provided: |
| 832 | |
| 833 | #. :class:`StreamHandler` instances send messages to streams (file-like |
| 834 | objects). |
| 835 | |
| 836 | #. :class:`FileHandler` instances send messages to disk files. |
| 837 | |
| 838 | #. :class:`~handlers.BaseRotatingHandler` is the base class for handlers that |
| 839 | rotate log files at a certain point. It is not meant to be instantiated |
| 840 | directly. Instead, use :class:`~handlers.RotatingFileHandler` or |
| 841 | :class:`~handlers.TimedRotatingFileHandler`. |
| 842 | |
| 843 | #. :class:`~handlers.RotatingFileHandler` instances send messages to disk |
| 844 | files, with support for maximum log file sizes and log file rotation. |
| 845 | |
| 846 | #. :class:`~handlers.TimedRotatingFileHandler` instances send messages to |
| 847 | disk files, rotating the log file at certain timed intervals. |
| 848 | |
| 849 | #. :class:`~handlers.SocketHandler` instances send messages to TCP/IP |
| 850 | sockets. |
| 851 | |
| 852 | #. :class:`~handlers.DatagramHandler` instances send messages to UDP |
| 853 | sockets. |
| 854 | |
| 855 | #. :class:`~handlers.SMTPHandler` instances send messages to a designated |
| 856 | email address. |
| 857 | |
| 858 | #. :class:`~handlers.SysLogHandler` instances send messages to a Unix |
| 859 | syslog daemon, possibly on a remote machine. |
| 860 | |
| 861 | #. :class:`~handlers.NTEventLogHandler` instances send messages to a |
| 862 | Windows NT/2000/XP event log. |
| 863 | |
| 864 | #. :class:`~handlers.MemoryHandler` instances send messages to a buffer |
| 865 | in memory, which is flushed whenever specific criteria are met. |
| 866 | |
| 867 | #. :class:`~handlers.HTTPHandler` instances send messages to an HTTP |
| 868 | server using either ``GET`` or ``POST`` semantics. |
| 869 | |
| 870 | #. :class:`~handlers.WatchedFileHandler` instances watch the file they are |
| 871 | logging to. If the file changes, it is closed and reopened using the file |
| 872 | name. This handler is only useful on Unix-like systems; Windows does not |
| 873 | support the underlying mechanism used. |
| 874 | |
| 875 | #. :class:`NullHandler` instances do nothing with error messages. They are used |
| 876 | by library developers who want to use logging, but want to avoid the 'No |
| 877 | handlers could be found for logger XXX' message which can be displayed if |
| 878 | the library user has not configured logging. See :ref:`library-config` for |
| 879 | more information. |
| 880 | |
| 881 | .. versionadded:: 2.7 |
| 882 | The :class:`NullHandler` class. |
| 883 | |
| 884 | The :class:`NullHandler`, :class:`StreamHandler` and :class:`FileHandler` |
| 885 | classes are defined in the core logging package. The other handlers are |
| 886 | defined in a sub- module, :mod:`logging.handlers`. (There is also another |
| 887 | sub-module, :mod:`logging.config`, for configuration functionality.) |
| 888 | |
| 889 | Logged messages are formatted for presentation through instances of the |
| 890 | :class:`Formatter` class. They are initialized with a format string suitable for |
| 891 | use with the % operator and a dictionary. |
| 892 | |
| 893 | For formatting multiple messages in a batch, instances of |
| 894 | :class:`BufferingFormatter` can be used. In addition to the format string (which |
| 895 | is applied to each message in the batch), there is provision for header and |
| 896 | trailer format strings. |
| 897 | |
| 898 | When filtering based on logger level and/or handler level is not enough, |
| 899 | instances of :class:`Filter` can be added to both :class:`Logger` and |
| 900 | :class:`Handler` instances (through their :meth:`addFilter` method). Before |
| 901 | deciding to process a message further, both loggers and handlers consult all |
| 902 | their filters for permission. If any filter returns a false value, the message |
| 903 | is not processed further. |
| 904 | |
| 905 | The basic :class:`Filter` functionality allows filtering by specific logger |
| 906 | name. If this feature is used, messages sent to the named logger and its |
| 907 | children are allowed through the filter, and all others dropped. |
| 908 | |
| 909 | |
| 910 | .. _logging-exceptions: |
| 911 | |
| 912 | Exceptions raised during logging |
| 913 | -------------------------------- |
| 914 | |
| 915 | The logging package is designed to swallow exceptions which occur while logging |
| 916 | in production. This is so that errors which occur while handling logging events |
| 917 | - such as logging misconfiguration, network or other similar errors - do not |
| 918 | cause the application using logging to terminate prematurely. |
| 919 | |
| 920 | :class:`SystemExit` and :class:`KeyboardInterrupt` exceptions are never |
| 921 | swallowed. Other exceptions which occur during the :meth:`emit` method of a |
| 922 | :class:`Handler` subclass are passed to its :meth:`handleError` method. |
| 923 | |
| 924 | The default implementation of :meth:`handleError` in :class:`Handler` checks |
| 925 | to see if a module-level variable, :data:`raiseExceptions`, is set. If set, a |
| 926 | traceback is printed to :data:`sys.stderr`. If not set, the exception is swallowed. |
| 927 | |
| 928 | **Note:** The default value of :data:`raiseExceptions` is ``True``. This is because |
| 929 | during development, you typically want to be notified of any exceptions that |
| 930 | occur. It's advised that you set :data:`raiseExceptions` to ``False`` for production |
| 931 | usage. |
| 932 | |
| 933 | .. currentmodule:: logging |
| 934 | |
| 935 | .. _arbitrary-object-messages: |
| 936 | |
| 937 | Using arbitrary objects as messages |
| 938 | ----------------------------------- |
| 939 | |
| 940 | In the preceding sections and examples, it has been assumed that the message |
| 941 | passed when logging the event is a string. However, this is not the only |
| 942 | possibility. You can pass an arbitrary object as a message, and its |
| 943 | :meth:`__str__` method will be called when the logging system needs to convert |
| 944 | it to a string representation. In fact, if you want to, you can avoid |
| 945 | computing a string representation altogether - for example, the |
| 946 | :class:`SocketHandler` emits an event by pickling it and sending it over the |
| 947 | wire. |
| 948 | |
| 949 | |
| 950 | Optimization |
| 951 | ------------ |
| 952 | |
| 953 | Formatting of message arguments is deferred until it cannot be avoided. |
| 954 | However, computing the arguments passed to the logging method can also be |
| 955 | expensive, and you may want to avoid doing it if the logger will just throw |
| 956 | away your event. To decide what to do, you can call the :meth:`isEnabledFor` |
| 957 | method which takes a level argument and returns true if the event would be |
| 958 | created by the Logger for that level of call. You can write code like this:: |
| 959 | |
| 960 | if logger.isEnabledFor(logging.DEBUG): |
| 961 | logger.debug('Message with %s, %s', expensive_func1(), |
| 962 | expensive_func2()) |
| 963 | |
| 964 | so that if the logger's threshold is set above ``DEBUG``, the calls to |
| 965 | :func:`expensive_func1` and :func:`expensive_func2` are never made. |
| 966 | |
| 967 | There are other optimizations which can be made for specific applications which |
| 968 | need more precise control over what logging information is collected. Here's a |
| 969 | list of things you can do to avoid processing during logging which you don't |
| 970 | need: |
| 971 | |
| 972 | +-----------------------------------------------+----------------------------------------+ |
| 973 | | What you don't want to collect | How to avoid collecting it | |
| 974 | +===============================================+========================================+ |
| 975 | | Information about where calls were made from. | Set ``logging._srcfile`` to ``None``. | |
| 976 | +-----------------------------------------------+----------------------------------------+ |
| 977 | | Threading information. | Set ``logging.logThreads`` to ``0``. | |
| 978 | +-----------------------------------------------+----------------------------------------+ |
| 979 | | Process information. | Set ``logging.logProcesses`` to ``0``. | |
| 980 | +-----------------------------------------------+----------------------------------------+ |
| 981 | |
| 982 | Also note that the core logging module only includes the basic handlers. If |
| 983 | you don't import :mod:`logging.handlers` and :mod:`logging.config`, they won't |
| 984 | take up any memory. |
| 985 | |
| 986 | .. seealso:: |
| 987 | |
| 988 | Module :mod:`logging` |
| 989 | API reference for the logging module. |
| 990 | |
| 991 | Module :mod:`logging.config` |
| 992 | Configuration API for the logging module. |
| 993 | |
| 994 | Module :mod:`logging.handlers` |
| 995 | Useful handlers included with the logging module. |
| 996 | |
| 997 | :ref:`A logging cookbook <logging-cookbook>` |
| 998 | |