Python - Log Files: The logging Module

Log Files: The `logging` Module
	Chapter 34. File Formats: CSV, Tab, XML, Logs and Others

Log Files: The `logging` Module

Most programs need a way to write sophisticated, easy-to-control log files what contain status and debugging information. Any program that requires careful auditing will benefit from using the logging module to create an easy-to-read permanent log. Also, when we have programs with multiple modules, and need more sophisticated debugging, we'll find a need for the logging module.

There are several closely related concepts that define a log. First, your program will have a hierarchical tree of Loggers. Each Logger is used to do two things. It creates LogRecords with your messages about errors, or debugging information. It provides these LogRecords to Handlers which ignore them, write them to files or insert them into databases. Each Handler can make use of a Formatter to provide a nice, readable version of each LogRecord message. Also, you can build sophisticated Filters if you need to handle complex situations.

The default configuration gives you a single Logger, named "", which uses a StreamHandler configured to write to standard error file, stderr.

While the logging module can appear complex, it gives us a number of distinct advatages.

Multiple Loggers. We can easily create a large number of separate loggers. This helps us to manage large, complex programs. Each component of the program can have it's own, indepenent logger. We can configure the collection of loggers centrally, however, supporting sophisticated auditing and debugging which is independent of each individual component.
Hierarchy of Loggers. Each Logger instance has a name, which is a .-separated string of names. For example, 'myapp.stock', 'myapp.portfolio'. This forms a natural hierarchy of Loggers. Each child inherits the configuration from its parent, which simplifies configuration. If, for example, we have a program which does stock portfolio analysis, we might have a component which does stock prices and another component which does overall portfolio calculations. Each component, then, could have a separate Logger which uses component name. Both of these Loggers are children of the "" Logger; the configuration for the top-most Logger would apply to both children.

Some components define their own Loggers. For example SQLAlchemy, has a set of Loggers with 'sqlalchemy' as the first part of their name. You can configure all of them by using that top-level name. For specific debugging, you might alter the configuration of just one Logger, for example, 'sqlalchemy.orm.sync'.
Multiple Handlers. Each Logger can feed a number of Handlers. This allows you to assure that a single important log messages can go to multiple destinations. A common setup is to have two Handlers for log messages: a FileHandler which records everything, and a StreamHandler which writes only severe error messages to stderr.

For some kinds of applications, you may also want to add the SysLogHandler (in conjunction with a Filter) to send some messages to the operating system-maintained system log as well as the application's internal log. Another example is using the SMTPHandler to send selected log messages via email as well as to the application's log and stderr.
Level Numbers and Filters. Each LogRecord includes a message level number, and a destination Logger name (as well as the text of the message and arguments with values to insert into the message). There are a number of predefined level numbers which are used for filtering. Additionally, a Filter object can be created to filter by destination Logger name, or any other criteria.

The predefined levels are CRITICAL, ERROR, WARNING, INFO, and DEBUG; these are coded with numeric values from 50 to 10. Critical messages usually indicate a complete failure of the application, they are often the last message sent before it stops running; error messages indicate problems which are not fatal, but preclude the creation of usable results; warnings are questions or notes about the results being produced. The information messages are the standard messages to describe successful processing, and debug messages provide additional details.

By default, all Loggers will show only messages which have a level number greater than or equal to WARNING, which is generally 30. When enabling debugging, we rarely want to debug an entire application. Instead, we usually enable debugging on specific modules. We do this by changing the level of a specific Logger.

You can create additional level numbers or change the level numbers. Programmers familiar with Java, for example, might want to change the levels to SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST, using level numbers from 70 through 10.

Module-Level Functions. The following module-level functions will get a Logger that can be used for logging. Additionally, there are functions can also be used to create Handlers, Filters and Formatters that can be used to configure a Logger.

logging.getLogger( name ) → Logger

Returns a Logger with the given name. The name is a .-separated string of names (e.g., "x.y.z") If the Logger already exists, it is returned. If the Logger did not exist, it is created and returned.

logging.addLevelName( lvl , levelName )

Defines (or redefines) a level number, proving a name that will be displayed for the given level number Generally, you will parallel these definitions with your own constants. For example, CONFIG=20; logging.addLevelName(CONFIG,"CONFIG")

logging.basicConfig

Configures the logging system. By default this creates a StreamHandler directed to stderr, and a default Formatter. Also, by default, all Loggers show only WARNING or higher messages. There are a number of keyword parameters that can be given to basicConfig.

filename: This keyword provides the filename used to create a FileHandler instead of a StreamHandler. The log will be written to the given file.
filemode: If a filename is given, this is the mode to open the file. By default, a file is opened with 'a', appending the log file.
format: This is the format string for the Handler that is created. A Formatter object has a format method which expects a dictionary of values; the format string uses %( key )s conversion specifications. See String Formatting with Dictionaries for more information. The dictionary provided to a Formatter is the LogRecord, which has a number of fields that can be interpolated into a log string.
datefmt: The date/time format to use for the asctime attribute of a LogRecord. This is a format string based on the time package strftime function. See Chapter 32, Dates and Times: the time and datetime Modules for more information on this format string.
level: This is the default message level for all loggers. The default is WARNING, 30.
stream: This is a stream that will be used to initialize a StreamHandler instead of a FileHandler. This is incompatible with filename . If both filename and stream are provided, stream is ignored.

Typically, you'll use this in the following form: logging.basicConfig( level=logging.INFO ).

logging.fileConfig

Configures the logging system. This will read a configuration file, which defines the loggers, handlers and formatters that will be built initially. Once the loggers are built by the configuration, then the logging.getLogger function will return one of these pre-built loggers.

logging.shutdown

Finishes logging by flushing all buffers and closing all handlers, which generally closes any internally created files and streams. An application must do this last to assure that all log messages are properly recorded in the log.

Logger Functions. The following functions are used to create a LogRecord in a Logger; a LogRecord is then processed by the Handlers associated with the Logger.

Many of these functions have essentially the same signature. They accept the text for a message as the first argument. This message can have string conversion specifications, which are filled in from the various arguments. In effect, the logger does message % ( args ) for you.

You can provide a number of argument values, or you can provide a single argument which is a dictionary. This gives us two principle methods for producing log messages.

log.info( "message %s, %d", "some string", 2 )
log.info( "message %(part1)s, %(anotherpart)d", { "part1" : "some string", "anotherpart": 2 } )

These functions also have an optional argument, exc_info , which can have either of two values. You can provide the keyword argument exc_info= sys.exc_info(). As an alternative, you can provide exc_info=True, in which case the logging module will call sys.exc_info for you.

In the following definitions, we'll assume that we've created a Logger named log.

log. ,(debug message , 〈 args 〉〈 exc_info 〉): Creates a LogRecord with level DEBUG, then processes this LogRecord on this Logger. The message is the message test; the args are the arguments which are provided to the formatting operator, %. If the exc_info keyword argument is provided, then exception information will be added to the logging message. The value of exc_info can be an exception tuple (as provided by sys.exc_info); otherwise, sys.exc_info will be called to get the exception information.
log. ,(info message , 〈 args 〉〈 exc_info 〉): Creates a LogRecord with level INFO on this logger. The positional arguments fill in the message; a single positional argument can be a dictionary. The exc_info keyword argument can provide exception information.
log. ,(warning message , 〈 args 〉〈 exc_info 〉): Creates a LogRecord with level WARNING on this logger. The positional arguments fill in the message; a single positional argument can be a dictionary. The exc_info keyword argument can provide exception information.
log. ,(error message , 〈 args 〉〈 exc_info 〉): Creates a LogRecord with level ERROR on this logger. The positional arguments fill in the message; a single positional argument can be a dictionary. The exc_info keyword argument can provide exception information.
log.(critical message , 〈 args 〉〈 exc_info 〉): Creates a LogRecord with level CRITICAL on this logger. The positional arguments fill in the message; a single positional argument can be a dictionary. The exc_info keyword argument can provide exception information.
log. log lvl message 〈 args 〉〈 exc_info 〉: Creates a LogRecord with the given lvl on this logger. The positional arguments fill in the message; a single positional argument can be a dictionary. The exc_info keyword argument can provide exception information.
log.(exception message , 〈 args 〉): Creates a LogRecord with level ERROR on this logger. The positional arguments fill in the message; a single positional argument can be a dictionary. Exception info is added to the logging message, as if the keyword parameter exc_info=True. This method should only be called from an exception handler.
log.(isEnabledFor level ): Returns True if this Logger will handle messages of this level or higher. This can be handy to prevent creating really complex debugging output that would only get ignored by the logger. This is rarely needed, and is used in the following structure: if log.isEnabledFor(logging.DEBUG): log.debug( "some complex message" ).

These functions are used to configure a Logger. Generally, you'll configure Loggers using the module level basicConfig and fileConfig functions. However, in some specialized circumstances (like unit testing), you may want finer control without the overhead of a configuration file. In the following definitions, we'll assume that we've created a Logger named log.

log. propagate: When True, all the parents of a given Logger must also handle the message. This assures consistency for audit purposes. When False, the parents will not handle the message. A False value might be used for keeping debugging messages separate from other messages. By default this is a True value.
log.(setLevel level ): Sets the level for this Logger; messages less severe are ignored. Messages of this severity or higher are handled. The special value of logging.NOTSET indicates that this Logger inherits the setting from the parent. The root logger has a default value of logging.WARNING.
log. getEffectiveLevel → number: Gets the level for this Logger. If this Logger has a setting of logging.NOTSET (the default for all Loggers) then it inherits the level from its parent.
log.(addFilter filter ): Adds the given Filter object to this Logger.
log.(removeFilter filter ): Removes the given Filter object from this Logger.
log. addHandler: Adds the given Handler object to this Logger.
log. removeHander: Removes the given Handler object from this Logger.

There are also some functions which would be used if you were creating your own subclass of Logger for more specialized logging purposes. These methods include log.filter, log.handle and log.findCaller.

Using the Logger. Generally, there are a number of ways of using a Logger. In a module that is part of a larger application, we will get an instance of a Logger, and trust that it was configured correctly by the overall application. In the top-level application we may both configure and use a Logger.

This example shows a simple module file which uses a Logger.

Example 34.4. logmodule.py

import logging, sys

log= logging.getLogger('logmodule')

def someFunc( a, b ):
    log.debug( "someFunc( %d, %d )", a, b )
    try:
        return 2*int(a) + int(b)
    except ValueError, e:
        log.warning( "ValueError in someFunc( %r, %r )", a, b, exc_info=True )

def mainFunc( *args ):
    log.info( "Starting mainFunc" )
    z= someFunc( args[0], args[1] )
    print z
    log.info( "Ending mainFunc" )

if __name__ == "__main__":
    logging.fileConfig( "logmodule_log.init" )
    mainFunc( sys.argv[1:] )

	We import the `logging` module and the `sys` module.
	We ask the logging module to create a `Logger` with the given name. We do this through a factory function to assure that the logger is configured correctly. The logging module actually keeps a pool of `Logger`s, and will assure that there is only one instance of each named `Logger`.
	This function has a debugging message and a warning message. This is typical of most function definitions. Ordinarily, the debug message will not show up in the log; we can only see it if we provide a configuration which sets the log level to `DEBUG` for the root logger or the `logmodule` `Logger`.
	This function has a pair of informational messages. This is typical of "main" functions which drive an overall application program. Applications which have several logical steps might have informational messages for each step. Since informational messages are lower level than warnings, these don't show up by default; however, the main program that uses this module will often set the overall level to logging.INFO to enable informational messages.


XML Files: The `xml.minidom` and `xml.sax` Modules		File Format Exercises