Logging, retries and failure design

Custom exceptions, logging to stderr, and retries with backoff, jitter and a deadline.

Automation that calls another service will meet failures that fix themselves (a restart, a brief overload) and failures that never will (a wrong URL, a revoked key). This lesson teaches you to tell them apart in code and act on the difference. You will define exceptions that carry that decision, log to stderr with levels and named loggers, and retry only temporary failures, with a bounded number of attempts, exponential backoff, random jitter and an overall deadline. Everything runs against a small local HTTP service that fails on purpose. The HTTP details themselves (TLS, authentication, pagination, Retry-After) belong to the next lesson.

A first draft, and what is wrong with it

Download the lesson files from the box at the top of this page and unpack them in your home directory: tar -xzf ps-errors.tar.gz creates ~/ps-errors, and every command below runs there (cd ~/ps-errors). The service the lesson calls is a few lines of http.server, bound to 127.0.0.1 only:

"""Lab HTTP service on 127.0.0.1. /flaky: 503 twice, then 200, and again.
/down: always 503. /slow: answers after 5 seconds. /drop: closes the connection without an
answer. /garbled: 200 with a body that is not JSON. Anything else: 404."""
import json
import sys
import time
from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer
 
flaky_calls = 0
 
 
class Handler(BaseHTTPRequestHandler):
    def do_GET(self):
        global flaky_calls
        if self.path == "/flaky":
            flaky_calls += 1
            if flaky_calls % 3:
                return self.reply(503, {"error": "warming up"})
            return self.reply(200, {"indicator": "203.0.113.42", "verdict": "malicious"})
        if self.path == "/down":
            return self.reply(503, {"error": "maintenance"})
        if self.path == "/drop":  # as a server that restarts in the middle of a request
            print("server: GET /drop -> connection closed, no answer", file=sys.stderr, flush=True)
            self.close_connection = True
            return None
        if self.path == "/garbled":
            return self.reply(200, b'{"indicator": "203.0.113.42", "verd')
        if self.path == "/slow":
            time.sleep(5)
            return self.reply(200, {"indicator": "203.0.113.42", "verdict": "unknown"})
        return self.reply(404, {"error": "no such endpoint"})
 
    def reply(self, status: int, body: dict | bytes) -> None:
        data = body if isinstance(body, bytes) else json.dumps(body).encode()
        try:
            self.send_response(status)
            self.send_header("Content-Type", "application/json")
            self.send_header("Content-Length", str(len(data)))
            self.end_headers()
            self.wfile.write(data)
        except OSError:
            pass  # the client stopped waiting and closed the connection
 
    def log_request(self, code="-", size="-"):
        print(f"server: GET {self.path} -> {int(code)}", file=sys.stderr, flush=True)
 
 
if __name__ == "__main__":
    port = int(sys.argv[1]) if len(sys.argv) > 1 else 18093
    server = ThreadingHTTPServer(("127.0.0.1", port), Handler)
    print(f"server: listening on http://127.0.0.1:{port}", file=sys.stderr, flush=True)
    server.serve_forever()

Handler is a class, as the functions lesson introduced them: a subclass of BaseHTTPRequestHandler that fills in do_GET(), the method the server calls for each GET request, with self.path holding the requested path. ThreadingHTTPServer handles each request in its own thread, so one slow request does not hold up the others. global flaky_calls lets the method change the module-level counter instead of creating a local variable of the same name. log_request() is overridden to write one short line per request, which lets you count attempts from the server's side. /drop and /garbled misbehave in two more ways, used at the end of the lesson. Start the server in the background with its output in server.log, and keep its process ID in server.pid so you can stop it later ($! is the PID of the last background command, as in the Bash course):

Here is a retry loop as people often write it first, and a run against a URL that does not exist:

"""First draft of a feed lookup. It has four bugs; the lesson finds them."""
import sys
import time
import urllib.request
 
url = sys.argv[1]
for attempt in range(4):
    try:
        with urllib.request.urlopen(url, timeout=1) as response:
            print(response.read().decode())
            break
    except Exception as err:
        print(f"attempt {attempt + 1} failed: {err}; sleeping {0.5 * 2 ** attempt}s")
        time.sleep(0.5 * 2 ** attempt)

It took 7.6 seconds to fail, and there are four separate bugs. It retried a 404, which will be a 404 on every attempt. It slept four seconds after the last attempt, with nothing left to try. Every copy of this script waits exactly 0.5, 1, 2 and 4 seconds, so a hundred hosts that failed together retry together, in waves. And it reported the failure on stdout and exited 0, so a scheduler or a pipeline thinks it worked. except Exception adds a fifth problem, as the functions lesson showed: a typo in the code would be retried as if it were a network error.

Exceptions that carry a decision

The code that makes the request knows why it failed; the caller needs to know what to do about it. feed.py translates every low-level error into one of two exception classes:

"""Fetch JSON from the feed and sort failures into temporary and permanent ones."""
import http.client
import json
import urllib.error
import urllib.request
 
RETRYABLE_STATUS = {429, 500, 502, 503, 504}
 
 
class FeedError(Exception):
    """Base class for every failed feed lookup."""
 
 
class TemporaryFeedError(FeedError):
    """Might work later: timeouts, refused or dropped connections, 429 and 5xx answers."""
 
 
class PermanentFeedError(FeedError):
    """Fails the same way every time: other 4xx answers, a body that is not JSON."""
 
 
def get_json(url: str, timeout: float) -> dict:
    try:
        with urllib.request.urlopen(url, timeout=timeout) as response:
            body = response.read()
    except urllib.error.HTTPError as err:  # a subclass of URLError, so it comes first
        kind = TemporaryFeedError if err.code in RETRYABLE_STATUS else PermanentFeedError
        raise kind(f"HTTP {err.code} from {url}") from err
    except urllib.error.URLError as err:  # while connecting: refused, name lookup failed
        raise TemporaryFeedError(f"cannot reach {url}: {err.reason}") from err
    except TimeoutError as err:  # connected, but no answer in time
        raise TemporaryFeedError(f"no answer from {url} within {timeout:.1f}s") from err
    except (OSError, http.client.HTTPException) as err:  # the answer broke off or was not HTTP
        raise TemporaryFeedError(f"broken answer from {url}: {err!r}") from err
    try:
        return json.loads(body)
    except ValueError as err:  # JSONDecodeError, or bytes that are not UTF-8 at all
        raise PermanentFeedError(f"{url} did not return JSON: {err}") from err

class TemporaryFeedError(FeedError) defines a new exception type that is a kind of FeedError, which is a kind of Exception; the docstring is all the body it needs. A caller can catch FeedError for any failure, or one subclass to handle one kind. Temporary means "the same request may work later": a connection refused or reset while a service restarts, a timeout, 503 (Service Unavailable), 502 and 504 from a proxy, 500, and 429 (Too Many Requests). Other 4xx answers mean the request itself is wrong, and a reply that is not JSON will not become JSON on the next attempt; both are permanent.

The order of the except clauses matters. HTTPError, raised for 4xx and 5xx answers, is a subclass of URLError, so it must come first; the other way round, every 404 would be caught as "cannot reach" and retried. urlopen() wraps only the errors of connecting in URLError. Errors while it reads the answer arrive unwrapped: a timeout as the built-in TimeoutError, a connection that the server closes or resets before answering as http.client.RemoteDisconnected (a kind of ConnectionResetError, and so an OSError), and an answer that is not HTTP at all as http.client.BadStatusLine (an HTTPException, which is not an OSError). The fourth clause catches both families; TimeoutError is an OSError too, so its own clause must come before it. The body is parsed last, and ValueError covers both a body that is not JSON (JSONDecodeError is a subclass) and bytes that are not valid UTF-8. Each raise ... from err keeps the original error attached as the cause:

The chained traceback you learned to read in the functions lesson: the HTTPError from inside urllib at the top, and PermanentFeedError, the decision, at the bottom. Retrying is only safe for requests that do the same thing however often they are sent, such as this GET. A request that creates or changes something may have worked before the connection broke; retrying it needs an idempotency key, which the scripting-adv lesson on failure design covers.

Logging: stderr, levels and named loggers

The logging module gives every message a level: DEBUG, INFO, WARNING, ERROR and CRITICAL, in rising order. logging.getLogger(name) returns a logger with that name, the same object every time it is asked for. Without any configuration, this is what you get:

The INFO message vanished and the WARNING appeared as bare text. An unconfigured program shows only WARNING and above, through a fallback handler that writes the message alone to stderr; the second command sent stderr to /dev/null and nothing was left. Configure logging once, at the start of the program, with logging.basicConfig(): it sets the level, the format, and a handler that writes to stderr unless you name another stream. Modules that other code imports, such as retry.py below, only call logging.getLogger(__name__) (__name__ is the module's name, here retry) and never basicConfig(): which messages appear, and where, is the program's decision. Pass values as arguments, log.warning("attempt %d failed", n), not in an f-string: the text is only built if the message is actually emitted.

Retries with backoff, jitter and a deadline

"""Retry a call after temporary failures: bounded, with backoff, jitter and a deadline."""
import logging
import random
import time
 
log = logging.getLogger(__name__)
 
 
class GaveUp(Exception):
    """Every attempt failed, or the deadline left no time for another one."""
 
 
def retry(call, *, retry_on, attempts=4, base=0.5, cap=4.0, deadline=5.0):
    """Return call(seconds_left); retry only the exception types in retry_on."""
    start = time.monotonic()
    last_error = None
    for attempt in range(1, attempts + 1):
        left = deadline - (time.monotonic() - start)
        if left <= 0:  # a sleep can end late: never hand the call a negative timeout
            raise GaveUp(f"{deadline:.0f}s deadline reached after {attempt - 1} attempts") from last_error
        try:
            return call(left)
        except retry_on as err:
            if attempt == attempts:  # the last attempt: give up now, no sleep
                raise GaveUp(f"{attempts} attempts failed") from err
            # full jitter: a random wait between 0 and the exponential bound
            delay = random.uniform(0, min(cap, base * 2 ** (attempt - 1)))
            if delay >= deadline - (time.monotonic() - start):
                raise GaveUp(f"{deadline:.0f}s deadline reached after {attempt} attempts") from err
            log.warning("attempt %d/%d: %s; retrying in %.2fs", attempt, attempts, err, delay)
            last_error = err
            time.sleep(delay)

retry() takes the function to call and the exception types worth retrying, so it knows nothing about HTTP; the Try this section reuses it for a command. The bare * in its parameter list makes every parameter after it keyword-only, so a call must spell out retry_on=... and cannot mix up the numbers by position. The wait before attempt n+1 is exponential backoff with full jitter: a random value between 0 and base * 2 ** (n - 1), capped at cap. Backoff gives a struggling service more room with every failure; jitter spreads a hundred clients' retries across the interval instead of sending them in a wave. time.monotonic() measures elapsed time with a clock that never jumps when the system time is corrected. The deadline gives up rather than sleep past it, and the time left is passed to the call so that it can shorten its own timeout. That time is measured again at the top of every attempt: on a busy host time.sleep() can return late, and a negative timeout would make urlopen() fail with a ValueError that nobody retries or reports cleanly. On the last attempt the loop raises at once.

"""Look up one indicator on the feed and print the verdict as JSON on stdout.
 
Exit status: 0 verdict printed, 1 the request is wrong (not retried),
2 usage error, 3 the feed stayed unavailable (attempts or deadline used up).
"""
import json
import logging
import sys
 
from feed import PermanentFeedError, TemporaryFeedError, get_json
from retry import GaveUp, retry
 
log = logging.getLogger("check_feed")
TIMEOUT = 2.0  # per attempt; retry() also caps it at the time left
 
 
def main(argv: list[str]) -> int:
    verbose = "-v" in argv
    args = [arg for arg in argv if arg != "-v"]
    logging.basicConfig(  # once, in the program; library modules only call getLogger()
        level=logging.DEBUG if verbose else logging.INFO,
        format="%(asctime)s.%(msecs)03d %(levelname)s %(name)s: %(message)s",
        datefmt="%H:%M:%S",
    )
    if len(args) != 1:
        log.error("usage: check_feed.py [-v] URL")
        return 2
    url = args[0]
 
    def lookup(seconds_left: float) -> dict:
        timeout = min(TIMEOUT, seconds_left)
        log.debug("GET %s, timeout %.2fs", url, timeout)
        return get_json(url, timeout)
 
    try:
        verdict = retry(lookup, retry_on=(TemporaryFeedError,))
    except PermanentFeedError as err:
        log.error("%s (not retried)", err, exc_info=verbose)
        return 1
    except GaveUp as err:
        log.error("feed unavailable: %s; last error: %s", err, err.__cause__, exc_info=verbose)
        return 3
    print(json.dumps(verdict))
    return 0
 
 
if __name__ == "__main__":
    sys.exit(main(sys.argv[1:]))

lookup is a function defined inside main. It can use url from the enclosing function, and retry() calls it with the seconds left, which become the timeout of the request, at most two seconds. In the format string, each %(name)s is a field of the log record (the time, the level name, the logger name, the message), and %(msecs)03d adds milliseconds. err.__cause__ is the exception that raise ... from attached, here the last temporary failure. exc_info=verbose adds the full traceback chain to the log line when -v is given. The exit statuses say what to do next: 1 means fix the request, 3 means try again later; the argparse lesson makes this a documented contract.

Two 503s, two warnings with their random delays, then the verdict. With 2>/dev/null only the JSON is left: logs on stderr, data on stdout, so the tool can feed jq or another program. The server's log shows three requests for each run. Now the failures:

/down was tried four times, and the error came right after the fourth attempt, with no final wait. The three random waits can add up to 3.5 seconds at most (here 1.8), where the first draft slept 7.5 seconds. The 404 was reported once, marked "not retried", with exit status 1. A service that accepts connections and never answers is the case the deadline is for:

The DEBUG lines appear because -v lowered the level. The first two attempts each waited their full two seconds, which left about 0.66 s of the five-second budget. The second wait is a random draw of up to one second, so the ending changes from run to run: here the draw was 0.51 s and the third attempt got only the 0.14 s that was left. A draw longer than the time left makes retry() stop after 2 attempts without sleeping. Either way it gives up at the deadline instead of sleeping past it. The traceback chain from exc_info shows the whole story: the socket's TimeoutError, the TemporaryFeedError it became, and the GaveUp that ended the run. Nothing listening at all is temporary too:

Connection refused was retried with growing random delays and ended with exit status 3. A missing argument is a usage error, exit status 2, reported through the same logger. The tenacity package offers these policies as a decorator; the scripting-adv lesson on failure design covers it together with Retry-After and retry budgets across a whole job.

A dropped connection and a garbled answer

Two failures are easy to miss because they do not happen while connecting. /drop reads the request and closes the connection without a word, as a service does when it restarts in the middle of a request. Plain urlopen() shows what arrives:

RemoteDisconnected, not a URLError. Without the fourth except clause in get_json(), that traceback would end check_feed.py with exit status 1, which its contract says means "the request is wrong, do not retry". With it, the tool treats the dropped connection as temporary. /garbled answers 200 with half a JSON document:

The dropped connection was retried four times and reported as unavailable, exit status 3. The garbled body was reported once, with the parser's reason, and exit status 1: the same broken answer would come back on every attempt. Then stop the server; its log confirms the last requests arrived:

Try this

Batch jobs often signal "try again later" with exit status 75 (EX_TEMPFAIL in sysexits.h). Write retry_cmd.py COMMAND [ARG...] in ~/ps-errors: it runs the command with subprocess.run (timeout: the seconds left), raises your own TryAgainLater exception when the status is 75, and uses retry() with a 10-second deadline. It exits with the command's own status, or 75 when retries run out, and logs through logging. Verify it with flaky_job.sh from the lesson files, which keeps a run counter in .flaky_job.count, exits 75 twice and then succeeds:

#!/bin/bash
# A job that fails with 75 (EX_TEMPFAIL, "try again later") on its first two runs.
count_file=.flaky_job.count
count=$(( $(cat "$count_file" 2>/dev/null || echo 0) + 1 ))
printf '%s\n' "$count" > "$count_file"
if (( count < 3 )); then
  printf 'flaky_job: backend busy (run %s)\n' "$count" >&2
  exit 75
fi
printf 'flaky_job: done on run %s\n' "$count"

Run rm -f .flaky_job.count first. Expect two warnings, then flaky_job: done on run 3 and exit status 0. python3 retry_cmd.py sh -c "exit 2" must exit 2 at once with no warning. Then break it: retry on any non-zero status and watch the same command run four times and end with 4 attempts failed and status 75, a configuration error turned into a retry storm.

Takeaway

Translate low-level errors into exceptions that say whether a retry can help, and retry only those, a bounded number of times, with jittered exponential backoff, inside a deadline and without a final sleep. Configure logging once in the program, to stderr, and keep stdout for the data.

Related