Error handling, retries & logging

Fail loudly, retry sensibly, log what happened.

Every time your automation reaches across the network, it is placing a phone call to someone who might not pick up. The reputation service you query for an IP address (Internet Protocol address, the number that identifies a machine on the network) could be down for maintenance. The connection could drop halfway through. The server could be swamped and answer four seconds late, or never answer at all. A script that assumes the call always connects, always replies, and always says something sensible is a script that runs fine on your laptop and falls over at 3 a.m. during the exact incident you wrote it for.

Making a script survive its bad days comes down to four habits, and this lesson builds each one. Catch the specific failures you expect, and let the ones you did not expect crash loudly instead of hiding. Retry a call that failed for a temporary reason, waiting a little longer before each attempt so you are not pounding on a server that is already struggling. Put a time limit on every call, so one slow server cannot freeze the whole run. And swap your scattered print() lines for real logging, so that when something breaks you are left with a timestamped record of what happened rather than a guess.

try, except, else, finally

Python's way of handling failure is the try statement, and it breaks into four parts that people mix up constantly. Cooking dinner is a fair picture of the shape. try is the attempt: you start the food on the stove, which is the step that might go wrong. except is your backup plan for one specific way it fails, like ordering takeout when the pan catches fire. else is what you do only when nothing burned: plate the meal and sit down. finally is the step you take every single time, whether dinner turns out a triumph or a disaster, which here is turning off the stove. In code, finally is where you close the file, release the lock, or note that the work is done. Here is a loader that reads an API (application programming interface) token off disk before the rest of a tool starts.

import sys
 
def load_token(path):
    try:
        with open(path) as f:
            token = f.read().strip()
    except FileNotFoundError:
        print(f"[load_token] no token file at {path}")
        raise
    else:
        print(f"[load_token] loaded token ({len(token)} chars)")
        return token
    finally:
        print("[load_token] cleanup done")
 
if __name__ == "__main__":
    try:
        token = load_token(sys.argv[1])
    except FileNotFoundError:
        print("startup aborted: no credentials")
        sys.exit(1)
    print(f"token starts with {token[:3]!r}")

Two runs, two paths. When the file exists, the except block is skipped, the else block runs and returns the token, and finally prints its cleanup line on the way out. When the file is missing, except catches the FileNotFoundError, prints a note, and then hits a bare raise, which is the re-raise: it throws the same exception onward so the caller can decide what to do. Here the caller decides the tool cannot start without credentials and exits with a non-zero status, which is why echo $? shows 1. Notice the shape of it: the low-level code adds context about what failed, and the high-level code decides how to respond. Swallowing the error at the bottom would have let the tool run on with no token, which is worse than stopping.

Catch what you can name

There is a tempting shortcut you should treat as a trap: except: with nothing after it, the bare except. It is a fishing net with no holes, and it catches everything, including the fish you needed to let swim past. The right instinct is the opposite. Name the specific exception you know how to handle, and let everything else travel up the stack. This small script shows why the difference matters.

def shutdown():
    raise SystemExit("operator asked to stop")
 
# WRONG: a bare except eats even the signals meant to stop the program
try:
    shutdown()
except:
    print("bare except swallowed the shutdown; the script keeps running")
 
# RIGHT: name the exceptions you actually handle
try:
    shutdown()
except ValueError:
    print("handled a bad value")

The first block calls shutdown(), which raises SystemExit, the exception Python uses to end a program cleanly. The bare except grabs it and prints its line, so the shutdown you asked for never happens and the script rolls on. The second block asks only about ValueError. SystemExit is not a ValueError, so it passes straight through, the program stops the way it was told to, and prints its message. The rule to carry: the widest catch you should ever write is except Exception, and only to log the problem before re-raising it. Reach for the exact exception name whenever you can.

Give your failures a name

When your own code detects a problem the built-in exceptions do not describe, define your own. A custom exception is a labeled failure. Instead of raising a generic ValueError that a caller cannot tell apart from a dozen unrelated ones, you raise FeedUnavailable, and any code calling you can catch that one thing precisely. Defining it takes a single line: a class that inherits from Exception.

class FeedUnavailable(Exception):
    """The threat feed gave no answer we can use."""
 
def get_score(ip, feed):
    if ip not in feed:
        raise FeedUnavailable(f"no data for {ip}")
    return feed[ip]
 
try:
    score = get_score("203.0.113.7", feed={})
except FeedUnavailable as err:
    print(f"triage skipped: {err}")

The caller catches your failure by name and moves on to the next indicator, instead of crashing on it or, worse, mistaking a missing lookup for a clean all-clear. A named exception is how a busy pipeline tells the difference between the feed being down and the feed saying an IP is safe.

Retry, back off, and set a timeout

A temporary failure deserves a second try. Redialing a busy phone line is the everyday version: you do not give up after one busy signal, but you also do not mash redial a hundred times a second. You wait, and you wait longer each time. That growing pause is exponential backoff, and in code it is one line: time.sleep(2 ** attempt), which waits 1 second, then 2, then 4, then 8. It matters for security, not only for manners. A tight retry loop hammering a failing service is a self-inflicted denial of service (DoS, flooding a system with more requests than it can handle), and if that service rate-limits or bans the API key your whole team shares, one runaway script blinds every tool that depends on it. Back off, and you cooperate with the server instead of attacking it.

Backoff handles a call that fails fast. The nastier failure is a call that does not fail at all: it goes quiet and hangs. A retry loop cannot rescue you from that, because a hung call never raises the exception your retry depends on. Every call needs a deadline. The requests library takes a timeout= argument; a subprocess you launch takes one too. Here is an external scanner that decides to run forever, kept on a two-second leash.

import subprocess
 
# Run an external scanner, but never let it hang the pipeline.
try:
    subprocess.run(
        ["sleep", "30"],       # stand-in for a slow external scanner
        timeout=2,
        check=True,
    )
except subprocess.TimeoutExpired:
    print("scanner exceeded its 2s budget; killed it and moving on")

After two seconds, subprocess.run kills the child and raises TimeoutExpired, your handler catches it, and the run moves on instead of stalling until someone notices the dashboard went cold. If hand-writing retry loops wears thin, the tenacity library packages the whole pattern behind a decorator: how long to wait, how the wait grows, how many attempts, and which exceptions count as worth retrying. It gives the same behavior as the loop you are about to write, minus the bookkeeping, at the cost of one more dependency to vet.

from tenacity import (retry, stop_after_attempt,
                      wait_exponential, retry_if_exception_type)
 
@retry(
    retry=retry_if_exception_type(TimeoutError),
    wait=wait_exponential(multiplier=1, max=30),
    stop=stop_after_attempt(4),
    reraise=True,   # raise the real error after the last try, not RetryError
)
def query_feed(ip):
    ...   # the same call, without the hand-written for/sleep loop

Stop printing, start logging

print() is a sticky note. It tells you something right now and carries no date, no severity, and no way to turn it down when the noise gets loud. The logging module in Python's standard library is the ship's log instead: every line is stamped with the time and a level, and you can make the whole thing quieter or louder without touching a single message. The levels run from calm to alarmed: DEBUG (fine detail for chasing a bug), INFO (normal progress), WARNING (something looks off but the run continues), and ERROR (something failed). You set a threshold, and anything below it stays silent.

One detail earns its keep for automation. logging writes to standard error (stderr, the stream meant for diagnostics) by default, which leaves standard output (stdout, the stream meant for real results) clean for your actual data. That separation is what lets a teammate pipe your tool into another program and receive only the findings, while your log chatter goes to the terminal or a file. Set the format once with a timestamp, and every line documents itself.

import logging
import sys
 
logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s  %(levelname)-8s %(message)s",
    datefmt="%H:%M:%S",
    stream=sys.stderr,
)
log = logging.getLogger("triage")
 
log.debug("opening connection to feed")   # below INFO: never printed
log.info("feed reachable")
log.warning("feed answered slowly")
log.error("feed returned no data")

The DEBUG line never printed, because the threshold was set to INFO. Lower it to logging.DEBUG when you need the detail, then put it back. The timestamp, the padded level name, and the message all come from that one format string, so every line across your whole tool lines up and sorts cleanly. That %(levelname)-8s pads the level to eight characters, which is why the columns stay straight whether the word is INFO or WARNING.

Putting it together: a call that retries and logs

Here is the whole shape in one function. It defines a named exception for the failure that matters, retries a flaky call with exponential backoff, logs every attempt so you can reconstruct what happened after the fact, and keeps the real answer on stdout. The query_feed stand-in times out twice and then answers on the third try, which is exactly the ragged pattern a real network hands you.

import logging
import sys
import time
 
logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s  %(levelname)-8s %(name)s: %(message)s",
    datefmt="%H:%M:%S",
    stream=sys.stderr,          # logs to stderr; data stays on stdout
)
log = logging.getLogger("iptriage")
 
 
class FeedUnavailable(Exception):
    """The threat feed gave no answer after every retry."""
 
 
def query_feed(ip):
    """Stand-in network call: times out the first two times, then answers."""
    query_feed.calls += 1
    if query_feed.calls < 3:
        raise TimeoutError("read timed out")
    return {"ip": ip, "score": 100}
query_feed.calls = 0
 
 
def check_ip(ip, attempts=4):
    for attempt in range(attempts):
        try:
            data = query_feed(ip)
        except TimeoutError as err:
            wait = 2 ** attempt
            log.warning("attempt %d/%d failed (%s); retrying in %ds",
                        attempt + 1, attempts, err, wait)
            time.sleep(wait)
        else:
            log.info("attempt %d/%d ok: %s scored %d",
                     attempt + 1, attempts, ip, data["score"])
            return data
    raise FeedUnavailable(f"{ip}: no answer after {attempts} attempts")
 
 
if __name__ == "__main__":
    result = check_ip("203.0.113.7")
    print(result["score"])       # the only thing on stdout

Read the timestamps: the first retry waits one second, the second waits two, so the third attempt lands three seconds after the first. Two WARNING lines record the failures, one INFO line records the success, and the only thing on standard output is the number 100. Prove that last part by throwing the logs away and keeping the data, which is what a downstream program in a pipe would see.

Send stderr to a log collector and let stdout flow into the next stage of your pipeline, and this one function behaves the same whether you run it by hand or a scheduler runs it at midnight with nobody watching the terminal. Those logs become the only witness you have to what actually ran, which is why they were worth the care.

Related