Log what your program did, so you can find out later

A script you watch can tell you things with print. A script that runs while you are away cannot. When it does something you did not expect, the only account of what happened is the one it wrote down as it went.

Python's logging module is print with three things added. Every message has a level, from DEBUG for detail up to ERROR for something that went wrong. Every message can carry the time. And messages can go to more than one place, each place choosing how much it wants to hear.

The script sets up one logger with two handlers. The screen gets INFO and above. A file gets everything, with the time on each line. It then works through three invented rows, one of which is bad, and afterwards prints what the file holds so you can see the difference.

One rule above all: never log a key, a password or a token. A log file gets copied, attached and pasted into places a secret must never go.

The code

# Log what your program did, so that you can find out afterwards.
# No broker, no account, no internet. The rows are invented.
import logging
import sys

log = logging.getLogger("journal")
log.setLevel(logging.DEBUG)

# One handler for the screen: only what a person needs to see.
to_screen = logging.StreamHandler(sys.stdout)
to_screen.setLevel(logging.INFO)
to_screen.setFormatter(logging.Formatter("%(levelname)s %(message)s"))
log.addHandler(to_screen)

# One handler for a file: everything, with the time, for reading later.
to_file = logging.FileHandler("run.log", mode="w")
to_file.setLevel(logging.DEBUG)
to_file.setFormatter(logging.Formatter("%(asctime)s %(levelname)s %(name)s %(message)s"))
log.addHandler(to_file)

rows = [
    {"reference": "MOCK001", "profit": "31.48"},
    {"reference": "MOCK002", "profit": "n/a"},
    {"reference": "MOCK003", "profit": "-12.90"},
]

log.info("Run started with %d rows", len(rows))
total = 0.0
used = 0
for row in rows:
    log.debug("Reading %s", row["reference"])
    try:
        total += float(row["profit"])
        used += 1
    except ValueError:
        log.warning("Skipped %s: profit is not a number: %r", row["reference"], row["profit"])

if used < len(rows):
    log.error("Only %d of %d rows were used, so the total is incomplete", used, len(rows))
log.info("Run finished. Total %.2f from %d rows", total, used)

# Close the file, then look at what it holds. It has the DEBUG lines the screen did not show.
logging.shutdown()
with open("run.log") as f:
    lines = f.read().splitlines()
print("run.log holds", len(lines), "lines")
for line in lines:
    print("  in the file:", line.split(" ", 2)[2])      # the line without its date and time

What you should see

INFO Run started with 3 rows
WARNING Skipped MOCK002: profit is not a number: 'n/a'
ERROR Only 2 of 3 rows were used, so the total is incomplete
INFO Run finished. Total 18.58 from 2 rows
run.log holds 7 lines
  in the file: INFO journal Run started with 3 rows
  in the file: DEBUG journal Reading MOCK001
  in the file: DEBUG journal Reading MOCK002
  in the file: WARNING journal Skipped MOCK002: profit is not a number: 'n/a'
  in the file: DEBUG journal Reading MOCK003
  in the file: ERROR journal Only 2 of 3 rows were used, so the total is incomplete
  in the file: INFO journal Run finished. Total 18.58 from 2 rows

Run with Python 3.12 on Windows. No network and no account.

Check yourself

Answer each question from the code above before you open it. The answers were written from the script on this page and what it printed.

Exercise

Let the screen show the DEBUG lines too, by changing the level on the screen handler, and run it again.

INFO Run started with 3 rows
DEBUG Reading MOCK001
DEBUG Reading MOCK002
WARNING Skipped MOCK002: profit is not a number: 'n/a'
DEBUG Reading MOCK003
ERROR Only 2 of 3 rows were used, so the total is incomplete
INFO Run finished. Total 18.58 from 2 rows
run.log holds 7 lines
  in the file: INFO journal Run started with 3 rows
  in the file: DEBUG journal Reading MOCK001
  in the file: DEBUG journal Reading MOCK002
  in the file: WARNING journal Skipped MOCK002: profit is not a number: 'n/a'
  in the file: DEBUG journal Reading MOCK003
  in the file: ERROR journal Only 2 of 3 rows were used, so the total is incomplete
  in the file: INFO journal Run finished. Total 18.58 from 2 rows

# Exercise solution: the lesson script with the one change the exercise asks for.
# Log what your program did, so that you can find out afterwards.
# No broker, no account, no internet. The rows are invented.
import logging
import sys

log = logging.getLogger("journal")
log.setLevel(logging.DEBUG)

# One handler for the screen: only what a person needs to see.
to_screen = logging.StreamHandler(sys.stdout)
to_screen.setLevel(logging.DEBUG)
to_screen.setFormatter(logging.Formatter("%(levelname)s %(message)s"))
log.addHandler(to_screen)

# One handler for a file: everything, with the time, for reading later.
to_file = logging.FileHandler("run.log", mode="w")
to_file.setLevel(logging.DEBUG)
to_file.setFormatter(logging.Formatter("%(asctime)s %(levelname)s %(name)s %(message)s"))
log.addHandler(to_file)

rows = [
    {"reference": "MOCK001", "profit": "31.48"},
    {"reference": "MOCK002", "profit": "n/a"},
    {"reference": "MOCK003", "profit": "-12.90"},
]

log.info("Run started with %d rows", len(rows))
total = 0.0
used = 0
for row in rows:
    log.debug("Reading %s", row["reference"])
    try:
        total += float(row["profit"])
        used += 1
    except ValueError:
        log.warning("Skipped %s: profit is not a number: %r", row["reference"], row["profit"])

if used < len(rows):
    log.error("Only %d of %d rows were used, so the total is incomplete", used, len(rows))
log.info("Run finished. Total %.2f from %d rows", total, used)

# Close the file, then look at what it holds. It has the DEBUG lines the screen did not show.
logging.shutdown()
with open("run.log") as f:
    lines = f.read().splitlines()
print("run.log holds", len(lines), "lines")
for line in lines:
    print("  in the file:", line.split(" ", 2)[2])      # the line without its date and time

Your progress

Next: Log your API calls

Your marks are kept in this browser only, in its local storage. They are not sent anywhere, there is no account, and they will not follow you to another browser or device. To remove them, use Clear my progress on the learning track page, or clear this site's data in your browser's settings. Marking needs JavaScript. With scripts off the track reads the same, without the ticks.

This browser refused to store anything for this page, so marks cannot be kept here.

Where this sits in the path

Stage 4 of 4: Building things that survive. Failure, limits, repeated orders, logs, settings, tests and backtests that do not fool you: what separates a script from a tool.

1. 21Retry and backoff
2. 22Stay under a rate limit
3. 23Handle an error reply
4. 24Idempotent orders
5. 25Log what happenedYou are here
6. 26Log your API calls
7. 27Backtest an idea
8. 28The look ahead mistake
9. 29Settings from environment
10. 30Test with saved replies
11. 31A command line tool
12. EndThe capstone project

The whole path, every stage