Logging, Not Printing

A program says two kinds of things. There’s its output, the report someone asked for. And there are diagnostics: “reading messy.log”, “skipped line 5”, “stored 6 records”. Until now both have gone through print, into the same stream, mixed together.

That stops working the moment someone uses the tool for real. They run logan server.log > report.txt and find the file full of “skipped line” messages. Or they want to see what the tool is doing while debugging, and then turn that off again without editing code. The logging module solves both.

The basics

A logger Python

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s: %(message)s",
                    force=True)             # force: see the note below

logger = logging.getLogger("logan.store")

logger.debug("not shown: DEBUG is below the INFO threshold")
logger.info("stored %d new record(s)", 6)
logger.warning("skipped line %d: %s", 5, "bad timestamp")
try:
    1 / 0
except ZeroDivisionError:
    logger.exception("couldn't build the summary")   # ERROR, plus the traceback

print("The report itself still goes to stdout.")

The log lines appear in a different colour from the print. They go to stderr, the standard error stream, while print writes to stdout. A shell redirect like > report.txt captures stdout only, so the report goes in the file and the diagnostics stay on the screen.

The pieces:

logging.getLogger(name) gets a named logger. Each module gets its own, with logger = logging.getLogger(__name__), so every message says where it came from.
Levels say how much a message matters: DEBUG, INFO, WARNING, ERROR, CRITICAL. These are the same five as the analyzer’s Level enum, with the same numbers, 10 to 50. That’s why Day 5 chose them.
basicConfig sets up the root logger: the lowest level to show, where to write, and the format. Anything below the level is discarded cheaply.
Arguments, not f-strings: logger.info("stored %d", n) formats the message only if it’s actually going to be shown. It also keeps the message’s template the same every time, which log search tools rely on.
logger.exception(...), inside an except, logs at ERROR and includes the traceback.

Why force=True on this page

All the playgrounds on a page share one Python, so logging set up in one run is still set up in the next. force=True replaces any earlier setup, which makes each playground start fresh. In a normal program, which starts once and configures logging once, you don’t need it. The bug hunt below shows what happens without it.

Who configures logging

Here’s the rule that keeps logging manageable: modules log, programs configure.

store.py, analyzer.py and friends only ever call logging.getLogger(__name__) and log through it. They never call basicConfig, never choose a level, never decide where output goes.
The entry point, cli.py, configures logging once, at startup, based on its command line: -v means INFO, otherwise WARNING.

Libraries follow the same rule. It’s why you can use sqlite3 or urllib and never see their internal messages unless you ask for them.

Bug hunt: the -v that did nothing

The command line’s main configures logging from its verbose flag. The quiet run is right. The verbose run should add an INFO line, “reading messy.log”, and doesn’t:

Quiet, then verbose Python

import logging

logging.root.handlers.clear()               # start from a brand-new logging setup,
logging.root.setLevel(logging.WARNING)      # as a freshly started program would

logger = logging.getLogger("logan")


def main(verbose):
    logging.basicConfig(level=logging.INFO if verbose else logging.WARNING,
                        format="%(levelname)s %(name)s: %(message)s")
    logger.info("reading messy.log")
    logger.warning("skipped line 5")
    print("...the report...")


print("--- logan messy.log")
main(verbose=False)
print("--- logan messy.log -v")
main(verbose=True)

Reproduce. Swap the two calls, so the verbose run goes first. Now both runs show the INFO line. Whichever call comes first decides for both.

Inspect. Check the logging state after each call. Add this after each main(...):

print("root level:", logging.getLevelName(logging.root.level), logging.root.handlers)

After the verbose call, the root level is still WARNING.

Before you open this, find out why the second call changed nothing. The documentation for basicConfig is fair game. Read the reveal either way: there are two fixes, for two different situations.

The diagnosis and the fix (read it either way)

Narrow. The documentation for basicConfig has the answer: it does nothing if the root logger already has a handler. The first call added one. The second call, with its new level, was silently ignored. That’s a deliberate design, so that a library calling basicConfig by mistake can’t override the program’s own setup. But it means basicConfig only works the first time.

Pin it. Test that a verbose run logs progress, after a quiet one:

def test_verbose_logs_progress(self):
    self.assertNotIn("stored 6", run("messy.log")[2])
    self.assertIn("stored 6 new record(s)", run("messy.log", "-v")[2])

Fix. There are two good fixes, for two situations:

In a program that configures logging once at startup, which is the normal case, make sure it really is once. Call basicConfig in the entry point only, never in library code.
When the same process calls main more than once, as tests do, pass force=True. It removes the existing handlers first, so the new configuration takes effect. cli.py does this, and its tests put the old setup back after each call, so they can’t leak into one another.

Your turn

Exercise

Replace the prints

import_logs mixes its result with its diagnostics. Change it so that:

“reading …” is logged at INFO on the importer logger,
an empty file is logged at WARNING as ”… is empty”,
the only thing printed to stdout is the final result line.

The tests use assertLogs, which captures a logger’s messages during a with block, whatever logging setup is active, and checks them as "LEVEL:logger:message" strings.

import io
import logging
import sys
import unittest
from contextlib import redirect_stdout

logger = logging.getLogger("importer")


def import_logs(files):
    """files maps a file name to its lines. Prints a one-line result."""
    total = 0
    for name, lines in files.items():
        print(f"reading {name}")
        if not lines:
            print(f"warning: {name} is empty")
            continue
        total += len(lines)
    print(f"{total} lines from {len(files)} files")
    return total


FILES = {"a.log": ["x", "y"], "b.log": [], "c.log": ["z", "z", "z"]}


class TestImportLogs(unittest.TestCase):
    def test_stdout_is_only_the_result(self):
        out = io.StringIO()
        with redirect_stdout(out):
            import_logs(FILES)
        self.assertEqual(out.getvalue(), "5 lines from 3 files\n")

    def test_progress_is_logged_at_info(self):
        with self.assertLogs("importer", level="INFO") as logs:
            import_logs(FILES)
        self.assertIn("INFO:importer:reading a.log", logs.output)

    def test_an_empty_file_is_a_warning(self):
        with self.assertLogs("importer", level="WARNING") as logs:
            import_logs(FILES)
        self.assertEqual(logs.output, ["WARNING:importer:b.log is empty"])


suite = unittest.defaultTestLoader.loadTestsFromTestCase(TestImportLogs)
unittest.TextTestRunner(stream=sys.stdout, verbosity=2).run(suite)

Hint 1: the idea

Two audiences, two channels. The result line is the program’s output — what someone ran it to get — so it stays a print. “reading …” and ”… is empty” are diagnostics, so they go through the importer logger at the level that says how much they matter. The level now carries “warning”, so the message doesn’t need to.

Hint 2: a first step

The starter already defines logger. Replace the “reading” print with logger.info(...) and run: the INFO test should pass while the others still fail. Then do the same for the empty-file warning, and check that nothing but the result reaches stdout.

Show one solution

def import_logs(files):
    """files maps a file name to its lines. Prints a one-line result."""
    total = 0
    for name, lines in files.items():
        logger.info("reading %s", name)
        if not lines:
            logger.warning("%s is empty", name)
            continue
        total += len(lines)
    print(f"{total} lines from {len(files)} files")
    return total

The warning: prefix is gone from the message, because the level now carries that information. The format decides how it’s shown.

The result stays a print. It’s the program’s output, what someone ran it to get. Logging it would send it to stderr, and import_logs ... > result.txt would produce an empty file.

You may see “b.log is empty” in red above the test results. It doesn’t come from the assertLogs tests: for the length of its block, assertLogs swaps the logger’s handlers for its own and stops messages travelling on to the root logger, so it captures them instead of letting them out. The red line comes from test_stdout_is_only_the_result, which calls import_logs with no assertLogs around it. Its warning goes through whatever logging setup is active. And with no setup at all, Python still prints warnings and worse to stderr, using a fallback called the “last resort” handler. That’s why a forgotten basicConfig loses your INFO messages but never your warnings.

What you can now do

Log through a named logger per module, at a level that says how much each message matters.
Keep a program’s output on stdout and its diagnostics on stderr.
Configure logging once, in the entry point, and know why basicConfig ignores a second call.
Test log messages with assertLogs.

Next: the command line itself.