The content for this site available on GitHub. If you want to launch the notebooks interactively click on the binder stamp below. Binder

< Permutations and Combinations in Python | Contents | Decorators in Python >

Logging, Errors and Exceptions in Python

Purpose: To help you get comfortable with the topics outlined below

Recomended Usage

  • Run each of the cells (Shift+Enter) and edit them as necessary to solidify your understanding
  • Do any of the exercises that are relevant to helping you understand the material

Topics Covered

  • Logging
  • Errors and Exceptions

Workbook Setup

The following magics will reload all modules before executing a new line and help make sure you follow PEP8 code style.

In [1]:
%load_ext autoreload
%autoreload 2

%load_ext pycodestyle_magic
%pycodestyle_on
In [1]:
import logging

Logging

Usage and best practices for using Pythons native logging module.

Loggers, Levels, Formatters and Handlers

To get started with Python's logging module you need to understand loggers, handlers and formatters:

Loggers have levels (how severe the issue is) and handlers (that tell it where to put the information) which have formatters (which tell it how to format/display the information).

Get or create loggers

Python's native logging module is hierarchical. There is a default root logger then when you add custom loggers you are adding "children".

NOTE: The root logger (logging.root - top of the logging hierarchy) is called when methods like logging.debug() is used.

Using the root logger directly or indirectly via methods like logging.debug() is generally not recommended. Instead, create your own loggers.

In [3]:
test1_logger = logging.getLogger()
In [4]:
test1_logger  # Defaults to root logger (b/c no name specified)
Out[4]:
<RootLogger root (WARNING)>

Note: You can see the root logger has default logging level set to "WARNING"

In [5]:
# Get or create a logger named "test2"
test2_logger = logging.getLogger("test2")
In [6]:
print(test2_logger)
print(test2_logger.parent)

assert test2_logger.parent == logging.root  # The parent is the root logger
<Logger test2 (WARNING)>
<RootLogger root (WARNING)>

Hierarchal loggers use dot notation

In [23]:
# Create logger 't'
t = logging.getLogger("t")
t
Out[23]:
<Logger t (WARNING)>
In [25]:
t.parent  # the parent of 't' is root
Out[25]:
<RootLogger root (WARNING)>
In [26]:
# Create logger 'a' as sublogger of 't'
a = logging.getLogger("t.a")
a
Out[26]:
<Logger t.a (WARNING)>
In [29]:
a.parent  # 't' is the parent of 'a'
Out[29]:
<Logger t (WARNING)>
In [31]:
a.parent.parent  # Root is the parent of the parent of 'a'
Out[31]:
<RootLogger root (WARNING)>

Inspect your logger's default settings (log level and handlers)

We can check if a logger has a handler using hasHandler() and check the log level using getEffectiveLevel() (the numerical value associated with WARNING, ERROR, etc)

In [7]:
print('Handlers for {} logger? {}'
      .format(test1_logger.name, test1_logger.hasHandlers()))

print('Handlers for {} logger? {}'
      .format(test2_logger.name, test2_logger.hasHandlers()))
Handlers for root logger? False
Handlers for test2 logger? False

You can see there are no handlers for these loggers. When you try to log something without having assigned a handler, it will automatically use the default handler (console).

In [8]:
print('Level for {} logger? {}'
      .format(test1_logger.name, test1_logger.getEffectiveLevel()))

print('Level for {} logger? {}'
      .format(test2_logger.name, test2_logger.getEffectiveLevel()))
Level for root logger? 30
Level for test2 logger? 30
In [9]:
# If you log a message > WARN using root logger it will create a default handler
print(test1_logger.hasHandlers())

logging.error("test error message for root logger")

print(test1_logger.hasHandlers())
ERROR:root:test error message for root logger
False
True

Create handlers

Each handler has:

  • A formatter which adds context information to a log.

  • A log level that filters out lower level logs (ie. a log handler with INFO level will not handle DEBUG logs)

Formatter example:

"%(asctime)s — %(name)s — %(levelname)s — %(funcName)s:%(lineno)d — %(message)s"

will output

2018-02-07 19:47:41,864 - a.b.c - WARNING - <module>:1 - your log message

In [36]:
console_handler = logging.StreamHandler()
console_handler
Out[36]:
<StreamHandler stderr (NOTSET)>
In [37]:
file_handler = logging.FileHandler("filename")
file_handler
Out[37]:
<FileHandler /Users/elias/jupyter-notebooks/python3_fluency/filename (NOTSET)>

Create log messages

If the log level is lower than logger level, the log will be ignored

Basically, when you create a logger you say "show me anything above this level of severity, ignore everything else".

Here are the 6 log levels

6 Log Levels
NOTSET=0
DEBUG=10
INFO=20
WARN=30
ERROR=40
CRITICAL=50

Practical Logging Examples

Best practices

  • Configure the root logger but never use it in your code—e.g., never call a function like logging.info()

  • To use logging, make sure to create a new logger by using logging.getLogger(__name__).

Note: Logs can get...quite long. So you may want to use classes like RotatingFileHandler to rotate the file for you automatically when the file reaches a size limit or do it everyday. You may also want to look into tools like Sentry or Airbrake for really long logs like from WebApps.

Example 1: Logging w/ default handler and formatter

In [38]:
logger = logging.getLogger(__name__)

print(logger)
print('hasHandlers? {}'.format(logger.hasHandlers()))
print('getEffectiveLevel? {}'.format(logger.getEffectiveLevel()))
<Logger __main__ (WARNING)>
hasHandlers? True
getEffectiveLevel? 30
In [40]:
# Debug and info messages should be ignored because our log level is WARNING
logger.debug('my DEBUG message')
logger.info('my INFO message')
logger.warning('my WARNING message')
logger.error('my ERROR message')
logger.critical('my CRITICAL message')
WARNING:__main__:my WARNING message
ERROR:__main__:my ERROR message
CRITICAL:__main__:my CRITICAL message

Example 2: Logging w/ custom handler and formatter

In [10]:
# Get or create a logger
logger = logging.getLogger(__name__)

# Set log level
logger.setLevel(logging.DEBUG)

# Define file handler and set formatter
file_handler = logging.FileHandler('logfile.log')
format_str = '%(asctime)s : %(levelname)s : %(name)s : %(message)s'
formatter = logging.Formatter(format_str)
file_handler.setFormatter(formatter)

# Add file handler to logger
logger.addHandler(file_handler)
In [11]:
logger.debug('A debug message')
logger.info('An info message')
logger.warning('Something is not right.')
logger.error('A Major error has happened.')
logger.critical('Fatal error. Cannot continue')
DEBUG:__main__:A debug message
INFO:__main__:An info message
WARNING:__main__:Something is not right.
ERROR:__main__:A Major error has happened.
CRITICAL:__main__:Fatal error. Cannot continue

We can checkout the log file that was just created.

Notice the format for the log file vs the console output is different, that is because its being handled by a different handler. The default console handler and the log file handler we just created.

In [12]:
!cat logfile.log
2019-11-17 13:04:07,452 : DEBUG : __main__ : A debug message
2019-11-17 13:04:07,453 : INFO : __main__ : An info message
2019-11-17 13:04:07,454 : WARNING : __main__ : Something is not right.
2019-11-17 13:04:07,458 : ERROR : __main__ : A Major error has happened.
2019-11-17 13:04:07,460 : CRITICAL : __main__ : Fatal error. Cannot continue
2019-11-17 13:08:42,216 : ERROR : __main__ : Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-110-0b146286ffa0>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero
2019-11-17 13:08:42,218 : ERROR : __main__ : Divide 10 / 0 = None
2019-11-17 13:09:45,936 : ERROR : __main__ : Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-110-0b146286ffa0>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero
2019-11-18 12:46:34,170 : DEBUG : __main__ : A debug message
2019-11-18 12:46:34,170 : DEBUG : __main__ : A debug message
2019-11-18 12:46:34,170 : DEBUG : __main__ : A debug message
2019-11-18 12:46:34,170 : DEBUG : __main__ : A debug message
2019-11-18 12:46:34,173 : INFO : __main__ : An info message
2019-11-18 12:46:34,173 : INFO : __main__ : An info message
2019-11-18 12:46:34,173 : INFO : __main__ : An info message
2019-11-18 12:46:34,173 : INFO : __main__ : An info message
2019-11-18 12:46:34,174 : WARNING : __main__ : Something is not right.
2019-11-18 12:46:34,174 : WARNING : __main__ : Something is not right.
2019-11-18 12:46:34,174 : WARNING : __main__ : Something is not right.
2019-11-18 12:46:34,174 : WARNING : __main__ : Something is not right.
2019-11-18 12:46:34,175 : ERROR : __main__ : A Major error has happened.
2019-11-18 12:46:34,175 : ERROR : __main__ : A Major error has happened.
2019-11-18 12:46:34,175 : ERROR : __main__ : A Major error has happened.
2019-11-18 12:46:34,175 : ERROR : __main__ : A Major error has happened.
2019-11-18 12:46:34,176 : CRITICAL : __main__ : Fatal error. Cannot continue
2019-11-18 12:46:34,176 : CRITICAL : __main__ : Fatal error. Cannot continue
2019-11-18 12:46:34,176 : CRITICAL : __main__ : Fatal error. Cannot continue
2019-11-18 12:46:34,176 : CRITICAL : __main__ : Fatal error. Cannot continue
2019-11-18 12:48:07,287 : ERROR : __main__ : Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-49-b3de6ac2c9d7>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero
2019-11-18 12:48:07,287 : ERROR : __main__ : Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-49-b3de6ac2c9d7>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero
2019-11-18 12:48:07,287 : ERROR : __main__ : Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-49-b3de6ac2c9d7>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero
2019-11-18 12:48:07,287 : ERROR : __main__ : Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-49-b3de6ac2c9d7>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero
2019-11-18 12:48:12,473 : ERROR : __main__ : Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-49-b3de6ac2c9d7>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero
2019-11-18 12:48:12,473 : ERROR : __main__ : Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-49-b3de6ac2c9d7>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero
2019-11-18 12:48:12,473 : ERROR : __main__ : Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-49-b3de6ac2c9d7>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero
2019-11-18 12:48:12,473 : ERROR : __main__ : Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-49-b3de6ac2c9d7>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero
2019-11-25 13:18:20,161 : DEBUG : __main__ : A debug message
2019-11-25 13:18:20,165 : INFO : __main__ : An info message
2019-11-25 13:18:20,166 : WARNING : __main__ : Something is not right.
2019-11-25 13:18:20,167 : ERROR : __main__ : A Major error has happened.
2019-11-25 13:18:20,167 : CRITICAL : __main__ : Fatal error. Cannot continue

Example 3: Logging an exception/error (div by 0)

In [13]:
# Create or get the logger
my_logger = logging.getLogger(__name__)

# Set log level
my_logger.setLevel(logging.INFO)


# Define function
def divide(x, y):
    try:
        out = x / y
    except ZeroDivisionError:
        my_logger.exception("Division by zero problem")
    else:
        return out
In [14]:
divide(10, 0)
ERROR:__main__:Division by zero problem
Traceback (most recent call last):
  File "<ipython-input-13-93bdd46699a6>", line 11, in divide
    out = x / y
ZeroDivisionError: division by zero

Errors and Exceptions

Raising and handling default and custom exceptions

Check out how try statements work in the docs if you need some more background.

Basic try-except

In [2]:
try:
    # Pretend you wrote some code here that threw a ValueError
    raise ValueError()
except ValueError:
    print("Oops!  That was no valid number.  Try again...")
Oops!  That was no valid number.  Try again...

Raise exception

In [3]:
# Raise an exception with custom message
raise ValueError("custom message")
---------------------------------------------------------------------------
ValueError                                Traceback (most recent call last)
<ipython-input-3-558a6c8cd86b> in <module>
      1 # Raise an exception with custom message
----> 2 raise ValueError("custom message")

ValueError: custom message

Define custom exceptions

This example is directly from the docs

In [5]:
class Error(Exception):
    """Base class for exceptions in this module."""
    pass

class InputError(Error):
    """Exception raised for errors in the input.

    Attributes:
        expression -- input expression in which the error occurred
        message -- explanation of the error
    """

    def __init__(self, expression, message):
        self.expression = expression
        self.message = message

class TransitionError(Error):
    """Raised when an operation attempts a state transition that's not
    allowed.

    Attributes:
        previous -- state at beginning of transition
        next -- attempted new state
        message -- explanation of why the specific transition is not allowed
    """

    def __init__(self, previous, next, message):
        self.previous = previous
        self.next = next
        self.message = message

Catchall Wildcard

The last except in the code below will catch anything that wasn't an OSError or ValueError.

Note: Carefull using wildcard catchalls so you don't mask the real programming error. As a general rule try and be as specific as possible and pass the error if up the chain if necessary.

In [15]:
import sys
In [120]:
try:
    f = open('myfile.txt')
    s = f.readline()
    i = int(s.strip())
except OSError as err:
    print("OS error: {0}".format(err))
except ValueError:
    print("Could not convert data to an integer.")
except:
    print("Unexpected error:", sys.exc_info()[0])
    raise
OS error: [Errno 2] No such file or directory: 'myfile.txt'

You can see because there is no file called 'myfile.txt' for you to open an OSError exception is thrown.

Finally is always executed

In [121]:
try:
    raise KeyboardInterrupt
finally:
    print('Goodbye, world!')
Goodbye, world!
---------------------------------------------------------------------------
KeyboardInterrupt                         Traceback (most recent call last)
<ipython-input-121-ca8991ac7661> in <module>
      1 try:
----> 2     raise KeyboardInterrupt
      3 finally:
      4     print('Goodbye, world!')

KeyboardInterrupt: 

Else is executed IFF try works

In [128]:
# Else is executed
try:
    print("trying worked")
except OSError:
    print('inside OSError')
else:
    print("inside else")
finally:
    print("inside finally")
trying worked
inside else
inside finally
In [127]:
# Else isn't executed
try:
    raise OSError("some OS error")
except (OSError, RuntimeError, TypeError):
    print('inside OSError')
else:
    print("inside else")
finally:
    print("inside finally")
inside OSError
inside finally

Troubleshooting Tips

If you run into issues running any of the code in this notebook, check your version of Python and Jupyter against mine below

import sys
print(sys.version)
3.7.6 (default, Dec 31 2019, 17:12:14) 
[Clang 11.0.0 (clang-1100.0.33.16)]
!jupyter --version
jupyter core     : 4.6.1
jupyter-notebook : 6.0.2
qtconsole        : not installed
ipython          : 7.9.0
ipykernel        : 5.1.3
jupyter client   : 5.3.4
jupyter lab      : 1.2.3
nbconvert        : 5.6.1
ipywidgets       : not installed
nbformat         : 4.4.0
traitlets        : 4.3.3
In [7]:
# import sys
# print(sys.version)
In [6]:
# !jupyter --version


< Permutations and Combinations in Python | Contents | Decorators in Python >