Logging in Python
Table of Contents
Python's logging module doesn't work out of the box. Try running this code and you'll see what I mean:
import logging
logging.info("Hello world")
Yep, it prints nothing.
Sure, there's `logging.basicConfig()` which sorta works (it dumps everything to stderr), but honestly, I'd rather set this up properly myself.
A Better Setup
Here's my go-to logging setup that actually makes sense. It sends info logs to stdout and error logs to stderr, plus adds decent formatting so you can actually read the output:
def remove_handlers():
logger = logging.getLogger()
for h in list(logger.handlers):
logger.removeHandler(h)
def setup_logging(filename=None, level="INFO"):
## Reset logger
remove_handlers()
logger = logging.getLogger()
formatter = logging.Formatter("%(asctime)s %(name)-12s %(levelname)-8s %(message)s")
consoleh = logging.StreamHandler(sys.stdout)
nonerror = lambda record: record.levelno != logging.ERROR
error = lambda record: record.levelno == logging.ERROR
errorh = logging.StreamHandler(sys.stderr)
errorh.setLevel(logging.ERROR)
errorh.setFormatter(formatter)
consoleh.setFormatter(formatter)
consoleh.addFilter(nonerror)
errorh.addFilter(error)
logger.addHandler(consoleh)
logger.addHandler(errorh)
logger.setLevel(level)
Why Split stdout and stderr?
The key thing here is separating error logs from info logs using filters. Without this, log aggregators (looking at you, Google Stackdriver) get confused and treat Python error logs the same as info logs. I've been burned by this more times than I care to admit.
For Notebooks and Remote Sessions
When I'm working in Jupyter notebooks or remote sessions, I prefer logging to files instead of relying on the session staying alive:
import logging
import sys
def remove_handlers():
logger = logging.getLogger()
for h in list(logger.handlers):
logger.removeHandler(h)
def file_logging(filename, level="INFO"):
## Reset logger
remove_handlers()
logger = logging.getLogger()
fh = logging.FileHandler(f"{filename}.log")
formatter = logging.Formatter("%(asctime)s %(name)-12s %(levelname)-8s %(message)s")
fh.setFormatter(formatter)
logger.addHandler(fh)
logger.setLevel(level)
Seeing It in Action
Here's what this actually looks like when you run it:
logging.info("Before setup") # This prints nothing
setup_logging()
logging.info("Logs to stdout")
file_logging("test_logs")
logging.info("Logs to test_logs.log")
Output:
$ python test.py
2023-03-11 13:06:39,551 root INFO Logs to stdout
$ cat test_logs.log
2023-03-11 13:06:39,552 root INFO Logs to test_logs.log
Much better than Python's default of "just pretend logging doesn't exist," right?
The `removehandlers()` function is important because Python's logging system loves to accumulate handlers if you call your setup function multiple times. Without it, you end up with duplicate log messages, which is super annoying when you're debugging.