Logging Exceptions in Python

Posted by db on Tue 09 February 2021

The various functions of logger.debug, logger.info, logger.warning, logger.error and logger.critical were introduced in the quick-start article about logging. However, there is another useful function, the logger.exception function, that that was not covered in that article but should be mentioned because it has a very special use.

Logging during Exceptions

Like the other conveinience functions, the logger.exception function is a wrapper around the base logger.log function. The function, however, does two specific things:

  1. It logs to the error level.
  2. It includes the stack trace of the current exception from sys.exc_info().

These are useful when logging messages during an exception. For example, consider this example script:

import sys
import logging

def function():
    x = 1/ 0

def main(args=[]):
    logger = logging.getLogger(__name__)
    try:
        function()
    except Exception:
        logger.exception("Fatal error when calling function.")
        return 1
    return 0

if __name__ == '__main__':
    logging.basicConfig(format='%(asctime)s : %(name)s %(levelname)s : %(message)s', level=logging.NOTSET)
    sys.exit(main(sys.argv))

The script uses a catch-all pattern by using the base Exception object in the tr/except block. This is normally discouraged and is only used here for sake of simplicity.

Executing the example intercepts the divide by 0 and prints out the messasge along with the respective call stack and -- it's important to note it here -- resumes the execution, returning 1 instead of 0.

Running this script yeilds the following output:

$ python example.py
2021-02-09 21:34:23,560 : __main__ ERROR : Fatal error when calling function.
Traceback (most recent call last):
  File "example.py", line 10, in main
    function()
  File "example.py", line 5, in function
    x = 1/ 0
ZeroDivisionError: division by zero

The accompanying callstack appears right under the logging message, starting with Traceback and ending with the exception name, ZeroDivisionError.

Logging Exceptions at other Levels

Underneath the hood, the exception function assigns the message to the error level and sets the exc_info parameter to True. So with the parameter, we can accomplish the same thing by being more explict with the logger.error function:

try:
    function()
except Exception:
    logger.error("Fatal error when calling function.", exc_info=True)
    return 1

Running the updated script yields the same output:

$ python example.py
2021-02-09 21:42:23,560 : __main__ ERROR : Fatal error when calling function.
Traceback (most recent call last):
  File "example.py", line 10, in main
    function()
  File "example.py", line 5, in function
    x = 1/ 0
ZeroDivisionError: division by zero

The exc_info is a key word argument of the base log function so using it is not restricted to just the error function. The parameter is available to all convenience functions and can be used to log the message and callstack to any other level, like info, for example:

try:
    function()
except Exception:
    logger.info("Handled exception when calling function.", exc_info=True)

Executing the script changes nothing -- except that the message is now emitted at the info level instead of the more severe error level.

$ python example.py
2021-02-09 21:59:40,506 : __main__ INFO : Handled exception when calling function.
Traceback (most recent call last):
  File "example.py", line 10, in main
    function()
  File "example.py", line 5, in function
    x = 1/ 0
ZeroDivisionError: division by zero

Using this technique really should be done in special cases. It's still best to use the exception method to log exception classtacks on the error level. Callstacks are rather synonymous with applications crashes, so dumping a callstack at a client-visible level, like info or warning will end up confusing the user. In the cases where the application is handling expected exceptions, it's probably simpler for everybody for the application to use the regular logging functions skip the callstack.

tags: python, logging