Logging in Python

When to use logging 

Logging provides a set of convenience functions for simple logging usage. These are debug(), info(), warning(), error() and critical(). To determine when to use logging, see the table below, which states, for each of a set of common tasks, the best tool to use for it.



The logging functions are named after the level or severity of the events they are used to track. The standard levels and their applicability are described below (in increasing order of severity):



The default level is WARNING, which means that only events of this level and above will be tracked, unless the logging package is configured to do otherwise.

Events that are tracked can be handled in different ways. The simplest way of handling tracked events is to print them to the console. Another common way is to write them to a disk file.

Advanced Logging Tutorial 

The logging library takes a modular approach and offers several categories of components: loggers, handlers, filters, and formatters.

% Loggers expose the interface that application code directly uses.

% Handlers send the log records (created by loggers) to the appropriate destination.

% Filters provide a finer grained facility for determining which log records to output.

% Formatters specify the layout of log records in the final output.

Log event information is passed between loggers, handlers, filters and formatters in a LogRecord instance.

Logging is performed by calling methods on instances of the Logger class (hereafter called loggers). Each instance has a name, and they are conceptually arranged in a namespace hierarchy using dots (periods) as separators. For example, a logger named ‘scan’ is the parent of loggers ‘scan.text’, ‘scan.html’ and ‘scan.pdf’. Logger names can be anything you want, and indicate the area of an application in which a logged message originates.

A good convention to use when naming loggers is to use a module-level logger, in each module which uses logging, named as follows:

logger = logging.getLogger(__name__) 

This means that logger names track the package/module hierarchy, and it’s intuitively obvious where events are logged just from the logger name.

The root of the hierarchy of loggers is called the root logger. That’s the logger used by the functions debug(), info(), warning(), error() and critical(), which just call the same-named method of the root logger. The functions and the methods have the same signatures. The root logger’s name is printed as ‘root’ in the logged output.

It is, of course, possible to log messages to different destinations. Support is included in the package for writing log messages to files, HTTP GET/POST locations, email via SMTP, generic sockets, queues, or OS-specific logging mechanisms such as syslog or the Windows NT event log. Destinations are served by handler classes. You can create your own log destination class if you have special requirements not met by any of the built-in handler classes.

By default, no destination is set for any logging messages. You can specify a destination (such as console or file) by using basicConfig() as in the tutorial examples. If you call the functions debug(), info(), warning(), error() and critical(), they will check to see if no destination is set; and if one is not set, they will set a destination of the console (sys.stderr) and a default format for the displayed message before delegating to the root logger to do the actual message output.

The default format set by basicConfig() for messages is:

severity:logger name:message 

You can change this by passing a format string to basicConfig() with the format keyword argument. For all options regarding how a format string is constructed, see Formatter Objects.

Logging Flow 

The flow of log event information in loggers and handlers is illustrated in the following diagram.



Loggers 

Logger objects have a threefold job. First, they expose several methods to application code so that applications can log messages at runtime. Second, logger objects determine which log messages to act upon based upon severity (the default filtering facility) or filter objects. Third, logger objects pass along relevant log messages to all interested log handlers.

The most widely used methods on logger objects fall into two categories: configuration and message sending.

These are the most common configuration methods:

% Logger.setLevel() specifies the lowest-severity log message a logger will handle, where debug is the lowest built-in severity level and critical is the highest built-in severity. For example, if the severity level is INFO, the logger will handle only INFO, WARNING, ERROR, and CRITICAL messages and will ignore DEBUG messages.

% Logger.addHandler() and Logger.removeHandler() add and remove handler objects from the logger object. Handlers are covered in more detail in Handlers.

% Logger.addFilter() and Logger.removeFilter() add and remove filter objects from the logger object. Filters are covered in more detail in Filter Objects.

You don’t need to always call these methods on every logger you create. See the last two paragraphs in this section.

With the logger object configured, the following methods create log messages:

% Logger.debug(), Logger.info(), Logger.warning(), Logger.error(), and Logger.critical() all create log records with a message and a level that corresponds to their respective method names. The message is actually a format string, which may contain the standard string substitution syntax of %s, %d, %f, and so on. The rest of their arguments is a list of objects that correspond with the substitution fields in the message. With regard to **kwargs, the logging methods care only about a keyword of exc_info and use it to determine whether to log exception information.

% Logger.exception() creates a log message similar to Logger.error(). The difference is that Logger.exception() dumps a stack trace along with it. Call this method only from an exception handler.

% Logger.log() takes a log level as an explicit argument. This is a little more verbose for logging messages than using the log level convenience methods listed above, but this is how to log at custom log levels.

getLogger() returns a reference to a logger instance with the specified name if it is provided, or root if not. The names are period-separated hierarchical structures. Multiple calls to getLogger() with the same name will return a reference to the same logger object. Loggers that are further down in the hierarchical list are children of loggers higher up in the list. For example, given a logger with a name of foo, loggers with names of foo.bar, foo.bar.baz, and foo.bam are all descendants of foo.

Loggers have a concept of effective level. If a level is not explicitly set on a logger, the level of its parent is used instead as its effective level. If the parent has no explicit level set, its parent is examined, and so on - all ancestors are searched until an explicitly set level is found. The root logger always has an explicit level set (WARNING by default). When deciding whether to process an event, the effective level of the logger is used to determine whether the event is passed to the logger’s handlers.

Child loggers propagate messages up to the handlers associated with their ancestor loggers. Because of this, it is unnecessary to define and configure handlers for all the loggers an application uses. It is sufficient to configure handlers for a top-level logger and create child loggers as needed. (You can, however, turn off propagation by setting the propagate attribute of a logger to False.)

Ref: docs.python.org/3/howto 

Logging Levels 

The numeric values of logging levels are given in the following table. These are primarily of interest if you want to define your own levels, and need them to have specific values relative to the predefined levels. If you define a level with the same numeric value, it overwrites the predefined value; the predefined name is lost.



Ref 1: docs.python.org/3/library/logging
Ref 2: docs.python.org/3/howto/logging

Using logging in multiple modules 

Multiple calls to logging.getLogger('someLogger') return a reference to the same logger object. This is true not only within the same module, but also across modules as long as it is in the same Python interpreter process. It is true for references to the same object; additionally, application code can define and configure a parent logger in one module and create (but not configure) a child logger in a separate module, and all logger calls to the child will pass up to the parent. Here is a main module:

import logging
import auxiliary_module

# create logger with 'spam_application'

logger = logging.getLogger('spam_application')
logger.setLevel(logging.DEBUG)

# create file handler which logs even debug messages

fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)

# create console handler with a higher log level

ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)

# create formatter and add it to the handlers

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)

# add the handlers to the logger

logger.addHandler(fh)
logger.addHandler(ch)

logger.info('creating an instance of auxiliary_module.Auxiliary')
a = auxiliary_module.Auxiliary()
logger.info('created an instance of auxiliary_module.Auxiliary')
logger.info('calling auxiliary_module.Auxiliary.do_something')
a.do_something()
logger.info('finished auxiliary_module.Auxiliary.do_something')
logger.info('calling auxiliary_module.some_function()')
auxiliary_module.some_function()
logger.info('done with auxiliary_module.some_function()') 

Here is the auxiliary module:

import logging

# create logger
module_logger = logging.getLogger('spam_application.auxiliary')

class Auxiliary:
    def __init__(self):
        self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
        self.logger.info('creating an instance of Auxiliary')

    def do_something(self):
        self.logger.info('doing something')
        a = 1 + 1
        self.logger.info('done doing something')

def some_function():
    module_logger.info('received a call to "some_function"') 
	
The output looks like this:

2005-03-23 23:47:11,663 - spam_application - INFO -
   creating an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -
   creating an instance of Auxiliary
2005-03-23 23:47:11,665 - spam_application - INFO -
   created an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,668 - spam_application - INFO -
   calling auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -
   doing something
2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -
   done doing something
2005-03-23 23:47:11,670 - spam_application - INFO -
   finished auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,671 - spam_application - INFO -
   calling auxiliary_module.some_function()
2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -
   received a call to 'some_function'
2005-03-23 23:47:11,673 - spam_application - INFO -
   done with auxiliary_module.some_function()  
   
When we ran it:

PS C:\Users\Ashish Jain> cd .\OneDrive\Desktop\code\
PS C:\Users\Ashish Jain\OneDrive\Desktop\code> ls

    Directory: C:\Users\Ashish Jain\OneDrive\Desktop\code

Mode                LastWriteTime         Length Name
----                -------------         ------ ----
-a----         9/4/2020  11:30 PM           1126 app.py
-a----         9/4/2020  11:32 PM            518 auxiliary_module.py


PS C:\Users\Ashish Jain\OneDrive\Desktop\code> python app.py
PS C:\Users\Ashish Jain\OneDrive\Desktop\code>

PS C:\Users\Ashish Jain\OneDrive\Desktop\code> ls

    Directory: C:\Users\Ashish Jain\OneDrive\Desktop\code

Mode                LastWriteTime         Length Name
----                -------------         ------ ----
d-----         9/4/2020  11:36 PM                __pycache__
-a----         9/4/2020  11:30 PM           1126 app.py
-a----         9/4/2020  11:32 PM            518 auxiliary_module.py
-a----         9/4/2020  11:36 PM            988 spam.log 

Contents of spam.log:

2020-09-04 23:36:37,281 - spam_application - INFO - creating an instance of auxiliary_module.Auxiliary
2020-09-04 23:36:37,281 - spam_application.auxiliary.Auxiliary - INFO - creating an instance of Auxiliary
2020-09-04 23:36:37,281 - spam_application - INFO - created an instance of auxiliary_module.Auxiliary
2020-09-04 23:36:37,281 - spam_application - INFO - calling auxiliary_module.Auxiliary.do_something
2020-09-04 23:36:37,281 - spam_application.auxiliary.Auxiliary - INFO - doing something
2020-09-04 23:36:37,281 - spam_application.auxiliary.Auxiliary - INFO - done doing something
2020-09-04 23:36:37,281 - spam_application - INFO - finished auxiliary_module.Auxiliary.do_something
2020-09-04 23:36:37,281 - spam_application - INFO - calling auxiliary_module.some_function()
2020-09-04 23:36:37,281 - spam_application.auxiliary - INFO - received a call to "some_function"
2020-09-04 23:36:37,281 - spam_application - INFO - done with auxiliary_module.some_function() 

Ref for above example: howto/logging-cookbook

A second example:

PS C:\Users\Ashish Jain> cd .\OneDrive\Desktop\code2\
PS C:\Users\Ashish Jain\OneDrive\Desktop\code2> ls

    Directory: C:\Users\Ashish Jain\OneDrive\Desktop\code2

Mode                LastWriteTime         Length Name
----                -------------         ------ ----
-a----         9/4/2020  11:49 PM           1072 app.py
-a----         9/4/2020  11:49 PM            325 submodule.py 

File "app.py":
# app.py (runs when application starts)


import logging

import logging.config # This is required. Otherwise, you get error: AttributeError: module 'logging' has no attribute 'config'

import os.path

import submodule as sm

def main():
    logging_config = {
        'version': 1,
        'disable_existing_loggers': False,
        'formatters': {
            'standard': {
                'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
            },
        },
        'handlers': {
            'default_handler': {
                'class': 'logging.FileHandler',
                'level': 'DEBUG',
                'formatter': 'standard',

                #'filename': os.path.join('logs', 'application.log'),
                'filename': 'application.log',

                'encoding': 'utf8'
            },
        },
        'loggers': {
            '': {
                'handlers': ['default_handler'],
                'level': 'DEBUG',
                'propagate': False
            }
        }
    }

    logging.config.dictConfig(logging_config)
    logger = logging.getLogger(__name__)
    logger.info("Application started.") 
    sm.do_something()

if __name__ == '__main__':
    main() 


File "submodule.py" has code:
import logging

# define top level module logger
logger = logging.getLogger(__name__)

def do_something():
    
    logger.info('Something happended.')
    
    try:
        logger.info("In 'try'.")

    except Exception as e:
        logger.exception(e)
        logger.exception('Something broke.') 
    
Run...

PS C:\Users\Ashish Jain\OneDrive\Desktop\code2> python .\app.py
PS C:\Users\Ashish Jain\OneDrive\Desktop\code2> ls

    Directory: C:\Users\Ashish Jain\OneDrive\Desktop\code2

Mode                LastWriteTime         Length Name
----                -------------         ------ ----
d-----         9/4/2020  11:50 PM                __pycache__
-a----         9/4/2020  11:52 PM           1259 app.py
-a----         9/4/2020  11:52 PM            180 application.log
-a----         9/4/2020  11:49 PM            325 submodule.py

PS C:\Users\Ashish Jain\OneDrive\Desktop\code2> 

Logs in file "application.log":

2020-09-04 23:52:00,208 [INFO] __main__: Application started.
2020-09-04 23:52:00,208 [INFO] submodule: Something happended.
2020-09-04 23:52:00,208 [INFO] submodule: In 'try'. 

Ref for second example: stackoverflow 

References

% realpython.com/python-logging
% Python/2 Logging
% Toptal - Python Logging
% docs.python-guide.org/writing/logging
% machinelearningplus
% zetcode
% tutorialspoint