Don't print it, log it!

Write your Python the lumberjack's way - with logging!

github.com/GenevieveBuckley/pyconau-2019-talk

Hi, I'm Genevieve

  • I'm a scientific programmer
  • Data science for biomedical research
  • @GenevieveBuckley / @DataNerdery

Resources

Introducing logging

The logging module is part of the Python standard library

In [1]:
import logging
print('Success: logging imported!')
Success: logging imported!

Advantages over print()

  1. You can log to file and the terminal simultaneously
  2. You can easily change how verbose the output is
  3. If you log user input and exceptions, you can reproduce issues later

How to use logging

A simple example

In [2]:
import logging
import importlib          # this line only needed in ipython/jupyter
importlib.reload(logging) # this line only needed in ipython/jupyter

logging.basicConfig(
    format="%(asctime)s %(levelname)s %(message)s",
    level=logging.DEBUG,
    handlers=[logging.StreamHandler()]
    )

# See the docs: https://docs.python.org/3/library/logging.html
In [3]:
# There are different levels of logging
# Adjust level=logging.DEBUG to level=logging.ERROR and see what happens
logging.debug("Debugging information logged.")
logging.info("Useful information logged.")
logging.warning("Warning message logged.")
logging.error("Error message logged.")
logging.critical("Critical error message logged.")
2019-08-03 17:01:36,282 DEBUG Debugging information logged.
2019-08-03 17:01:36,287 INFO Useful information logged.
2019-08-03 17:01:36,292 WARNING Warning message logged.
2019-08-03 17:01:36,296 ERROR Error message logged.
2019-08-03 17:01:36,298 CRITICAL Critical error message logged.
In [4]:
import logging
import importlib          # this line only needed in ipython/jupyter
importlib.reload(logging) # this line only needed in ipython/jupyter

logging.basicConfig(
    format="%(asctime)s %(levelname)s %(message)s",
    level=logging.ERROR,  # <-- change the log level to error & higher
    handlers=[logging.StreamHandler()]
    )

# See the docs: https://docs.python.org/3/library/logging.html
In [5]:
# Let's see that again, now we have set the log level to error and above
logging.debug("Debugging information logged.")
logging.info("Useful information logged.")
logging.warning("Warning message logged.")
logging.error("Error message logged.")
logging.critical("Critical error message logged.")
2019-08-03 17:02:08,914 ERROR Error message logged.
2019-08-03 17:02:08,919 CRITICAL Critical error message logged.

Log to file and the terminal simultaneously

In [6]:
import logging
import importlib          # this line only needed in ipython/jupyter
importlib.reload(logging) # this line only needed in ipython/jupyter

log_filename = 'logfile_demo.log'

logging.basicConfig(
    format="%(asctime)s %(levelname)s %(message)s",
    level=logging.DEBUG,
    # Multiple handlers can be added to your logging configuration.
    # By default log messages are appended to the file if it exists already
    handlers=[
        logging.FileHandler(log_filename),
        logging.StreamHandler(),
    ])
In [7]:
logging.debug("Debugging information logged.")
logging.info("Useful information logged.")
logging.warning("Warning message logged.")
logging.error("Error message logged.")
logging.critical("Critical error message logged.")
2019-08-03 17:02:39,822 DEBUG Debugging information logged.
2019-08-03 17:02:39,825 INFO Useful information logged.
2019-08-03 17:02:39,828 WARNING Warning message logged.
2019-08-03 17:02:39,830 ERROR Error message logged.
2019-08-03 17:02:39,834 CRITICAL Critical error message logged.

Now let's see what's written to the log file

In [8]:
!cat logfile_demo.log
2019-08-03 17:02:39,822 DEBUG Debugging information logged.
2019-08-03 17:02:39,825 INFO Useful information logged.
2019-08-03 17:02:39,828 WARNING Warning message logged.
2019-08-03 17:02:39,830 ERROR Error message logged.
2019-08-03 17:02:39,834 CRITICAL Critical error message logged.

If a log file already exists, new logging messages are APPENDED by default (but you can change this with filemode).

If you want to log different priority levels to file vs the terminal, you can do that too. See the logging cookbook for an example.

Logging exceptions

In [ ]:
try:
    x = 1 / 0
except ZeroDivisionError as e:
    logging.exception('ZeroDivisionError: %s', e)

Logging uncaught exceptions

We can use sys.excepthook to capture the traceback of uncaught exceptions.*

*This is not an excuse to not catch and handle exceptions. But in the rare event of an unanticipated and uncaught exception, we still want to have all the information.

Logging uncaught exceptions

We can use sys.excepthook to capture the traceback of uncaught exceptions.*

You can read more about why it's always a good idea to log the full traceback here in 'The most diabolical python antipattern' at realpython.com

In [ ]:
# WARNING: You cannot override sys.excepthook in ipython/jupyter
# Please see the standalone file example_3.py for full working example
import sys
import traceback

def _exception_handler(error_type, error_value, error_traceback):
    """Log all uncaught exceptions at runtime with sys.excepthook"""
    logging.exception("Uncaught exception {} {}".format(
        str(error_type), str(error_value)))
    tb = traceback.format_exception(
        error_type, error_value, error_traceback)
    traceback_string = ''
    for ln in tb:
        traceback_string += ln
    logging.exception(traceback_string)

sys.excepthook = _exception_handler

Traps for the unwary

logging is different in ipython/jupyter

If you're in ipython/jupyter and want to use logging's basicConfig() we need to reload the module in the same cell.

If you want to configure logging specifically for a jupyter notebook, you can read more about that at https://www.dataquest.io/blog/advanced-jupyter-notebooks-tutorial/

Remember to ignore logs with git

Tell git to ignore log file outputs. Handy hint: using a .log suffix instead of .txt for all your log files makes this easy.

Just add this line your .gitignore:

*.log

Avoid namespace collisions

Do not name your file logging.py

It's never a good idea to give your python files the same name as a python library - this will cause namespace collisions. You can read more about the name shadowing trap in Nick Coghlan's Python Notes.

Don't print it, log it!

Slides and code: github.com/GenevieveBuckley/pyconau-2019-talk

@GenevieveBuckley