From print() to Real Logging
Leave a record instead of shouting
In this lesson
Your Units 7 and 8 scripts work. Now imagine one of them running at three in the morning on a schedule, failing, and you finding out at nine. What did it do? Which record broke it? print() cannot answer that, because its output is gone. This lesson replaces it with something that leaves a record.
Explain it like I’m 5
print() is shouting across the room. Logging is keeping a journal. One is gone the second it happens; the other is still there tomorrow.
Five levels, and what each is for
The logging module is in the standard library. Every message you log carries a level saying how much it matters:
- DEBUG, detail you want while diagnosing something. Noisy on purpose.
- INFO, normal progress: started, finished, processed 40 records.
- WARNING, something odd that did not stop the run. A skipped row.
- ERROR, an operation failed.
- CRITICAL, the program cannot continue.
The payoff is that you choose a threshold at runtime. Set it to INFO and DEBUG messages vanish; set it to DEBUG when something is wrong and they all come back. Same code, different amount of detail, nothing edited.
import logging, sys
logging.basicConfig(
level=logging.INFO,
format="%(levelname)s %(message)s",
stream=sys.stdout,
)
logging.debug("connection pool warmed") # below the threshold, not shown
logging.info("fetched 3 records")
logging.warning("2 records had no year")
logging.error("could not reach the API")
INFO fetched 3 records WARNING 2 records had no year ERROR could not reach the API
Configuring it once, properly
basicConfig() takes the settings that matter most: the threshold, the line format, and where output goes. Call it once, early, in the file you actually run.
A timestamp is worth adding immediately. Knowing a failure happened is useful; knowing it happened at 03:14 and again at 04:14 tells you it is on a schedule.
import logging
logging.basicConfig(
level=logging.INFO,
format="%(asctime)s %(levelname)-8s %(message)s",
datefmt="%Y-%m-%d %H:%M:%S",
filename="run.log", # write to a file instead of the screen
)
logging.info("run started")
# run.log now contains:
# 2026-07-27 03:14:02 INFO run started
Let logging do the formatting
Pass values as extra arguments rather than building the string yourself: logging.info("stored %d rows", count). The formatting only happens if the message is actually going to be emitted, so a DEBUG line below the threshold costs almost nothing.
There is also logging.exception(), which logs at ERROR level and includes the full traceback. Inside an except block it is almost always what you want.
import logging, sys
logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s",
stream=sys.stdout)
records = ["Dune", "Neuromancer"]
logging.info("stored %d of %d records", len(records), 3)
try:
int("nineteen")
except ValueError:
logging.error("could not parse the year")
INFO stored 2 of 3 records ERROR could not parse the year
Convert the prints to logs. Each line below has a level that fits it: routine progress is INFO, the skipped record is a WARNING, and the failure is an ERROR. The DEBUG line should not appear, because the threshold is INFO.
import logging, sys
logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s",
stream=sys.stdout, force=True)
# TODO: convert each print to the logging call that fits it
print("cache warmed") # diagnostic detail -> DEBUG
print("fetched 3 records") # routine progress -> INFO
print("1 record had no year") # odd but survivable -> WARNING
print("could not save record 7") # an operation failed -> ERRORReplace each print(...) with logging.debug/info/warning/error(...). The DEBUG call still runs, it just produces no output because the threshold is INFO.
import logging, sys
logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s",
stream=sys.stdout, force=True)
logging.debug("cache warmed")
logging.info("fetched 3 records")
logging.warning("1 record had no year")
logging.error("could not save record 7")Common mistake: Logging inside a tight loop until the file is unreadable
One line per record seems informative while the test data has five records.
Log per run, not per item: totals, and the items that were unusual. If you want per-item detail, put it at DEBUG so it is off by default.
Common mistake: Using ERROR for things that are merely interesting
Everything feels important while you are writing it.
Keep ERROR for operations that actually failed. If every line is an error, the level stops carrying information and you cannot filter on it.
Common mistake: Calling basicConfig() from a module rather than the entry point
You want logging configured wherever you happen to be logging.
Configure once in the script you run. A library that configures logging fights every application that imports it.
Common mistake: Building the message with an f-string in a hot path
f-strings are the normal way to format, so they feel natural here too.
Use logging.debug("got %s", value). With an f-string the text is built even when the message is below the threshold and gets thrown away.
The threshold is set to INFO. Which of these produces no output?
DEBUG sits below INFO, so it is filtered out. Lower the threshold to logging.DEBUG and it reappears.
What is the main advantage of logging over print() for a scheduled script?
A scheduled run has nobody watching. Logging leaves a record you can read afterwards.
Which call logs an error together with the full traceback?
logging.exception() logs at ERROR level and attaches the traceback, so it belongs inside except.
Mini exercise (medium)
Write process(records) that loops over a list of record dicts and logs as it goes: one INFO at the start naming how many it received, a WARNING for each record missing a title, and one INFO at the end with how many were kept. Return the kept records.
Your turn. Fill in the code below and press Run to test it right here, nothing to install.
import logging, sys
logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s",
stream=sys.stdout, force=True)
RECORDS = [{"title": "Dune"}, {"title": ""}, {"title": "Snow Crash"}]
def process(records):
kept = []
# TODO: INFO the received count, WARN each record with no title,
# INFO the kept total, and return the kept records
return kept
print([record["title"] for record in process(RECORDS)])Configure logging once at the top with stream=sys.stdout, force=True so the output shows here. Count the kept records as you go so the closing INFO can report both numbers.
import logging, sys
logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s",
stream=sys.stdout, force=True)
RECORDS = [{"title": "Dune"}, {"title": ""}, {"title": "Snow Crash"}]
def process(records):
logging.info("received %d records", len(records))
kept = []
for record in records:
if not record.get("title"):
logging.warning("skipping record with no title")
continue
kept.append(record)
logging.info("kept %d of %d", len(kept), len(records))
return kept
print([record["title"] for record in process(RECORDS)])