< Back to Blog

Python Logging Done Right: The Setup That Tells You Exactly What Your Bot Did

TL;DR / Key Takeaways

  • Python's default logging setup is nearly useless for production bots. You need rotating file handlers, a structured formatter, and level discipline.
  • logger.debug and logger.info are not interchangeable. Using them wrong turns your log file into noise you cannot search.
  • Structured log lines with consistent prefixes (TRADE, SKIP, SIGNAL, ERROR) let you grep your way to an answer in seconds after a bad trade.
  • The Predict & Profit Weather Bot and Econ Bot both ship with this exact logging setup so you can see every decision the bot made, including the trades it rejected.

My first production bot used print() statements. Everywhere. I would watch it run in a terminal, see green lines scrolling past, and feel confident. Then it ran overnight on the VPS and I woke up to an empty screen and no idea what happened.

Logging is not complicated. But the default Python setup is almost deliberately unhelpful, and most tutorials show you logging.basicConfig() and call it a day. That is fine for a script you run once. It is useless for a bot running 24 hours a day that needs to tell you exactly what it did at 3:47 AM on a Tuesday.

Here is the actual setup I use.

The Problem With basicConfig

logging.basicConfig(level=logging.INFO) writes to stdout. The format is a timestamp, the log level, the logger name, and the message. No rotation, no file output by default, no structure. The moment your bot runs as a systemd service, stdout goes to journald, which has its own retention policy, and good luck grepping through it a week later.

Even when you add a filename to basicConfig, you get one file that grows forever. A bot running daily will produce megabytes of logs per week. You will eventually have a 2GB log file and grep will take 40 seconds.

The other problem is that most people use logging.info() for everything because that is what the tutorials show. When something goes wrong, your log file is 90% noise and 10% the thing you actually needed to see.

The Setup I Use

This is the actual logging initialization from the Predict & Profit bots, cleaned up for clarity:

import logging
import logging.handlers
import os
from datetime import datetime

def setup_logger(name: str, log_dir: str = "logs", level: int = logging.DEBUG) -> logging.Logger:
    """
    Configure a named logger with rotating file handler and console handler.
    Returns the logger. Call this once at bot startup.
    """
    os.makedirs(log_dir, exist_ok=True)

    log_filename = os.path.join(log_dir, f"{name}.log")

    logger = logging.getLogger(name)
    logger.setLevel(level)

    # Prevent duplicate handlers if setup_logger is called more than once
    if logger.handlers:
        return logger

    # Formatter: timestamp, level, module, message
    fmt = logging.Formatter(
        fmt="%(asctime)s | %(levelname)-8s | %(module)-20s | %(message)s",
        datefmt="%Y-%m-%d %H:%M:%S"
    )

    # Rotating file handler: 5MB per file, keep 10 backups
    file_handler = logging.handlers.RotatingFileHandler(
        filename=log_filename,
        maxBytes=5 * 1024 * 1024,
        backupCount=10,
        encoding="utf-8"
    )
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(fmt)

    # Console handler: INFO and above only, so the terminal is not buried
    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.INFO)
    console_handler.setFormatter(fmt)

    logger.addHandler(file_handler)
    logger.addHandler(console_handler)

    return logger

Call it once at the top of your main entry point:

logger = setup_logger("weather_bot")
logger.info("Bot started. Version 2.1.")

Everywhere else in the codebase you just do logging.getLogger("weather_bot") and you get the same configured logger. No need to pass the logger object around.

Level Discipline

This is where most people make the mistake. They use logger.info() for everything because it feels like the right level for "stuff that happened." Then they have a 10,000-line log file and they need to find why the bot skipped a trade at 2 AM and they are scrolling forever.

Here is how I use the levels:

DEBUG: Everything. Every API call. Every response. Every score computed. Every conditional branch that matters. This goes to the file only, never to the console. When something breaks, DEBUG is how you reconstruct it step by step.

logger.debug(f"SIGNAL | Cleveland Fed nowcast: {nowcast_prob:.4f} | market_price: {market_price:.4f}")
logger.debug(f"SIGNAL | FRED gas nudge: {gas_nudge:+.4f} | FRED oil nudge: {oil_nudge:+.4f}")
logger.debug(f"SCORE | composite_edge: {edge:.4f} | threshold: {self.min_edge}")

INFO: Decisions and outcomes. The bot decided something. A trade fired. A trade was skipped with a reason. A position closed. A cycle completed. This is what you read in the terminal when you are watching it run.

logger.info(f"TRADE | market={ticker} | side={side} | contracts={n} | price={price:.2f} | edge={edge:.4f}")
logger.info(f"SKIP  | market={ticker} | reason=score_below_threshold | score={score:.4f} | min={self.min_score}")
logger.info(f"CLOSE | market={ticker} | reason=early_exit | entry={entry_price:.2f} | exit={exit_price:.2f}")

WARNING: Something unexpected happened but the bot kept running. An API call took longer than expected. A data source returned a null. The bot fell back to cached data.

logger.warning(f"FRED outage detected. Falling back to 6-hour cache. source=gas_prices")
logger.warning(f"AIGEFS member {member_id} missing. Continuing with {available_members} members.")

ERROR: The bot caught an exception and cannot proceed with this cycle or this trade. Log the full traceback. Do not swallow errors silently.

try:
    response = self.kalshi_client.get_positions()
except Exception as e:
    logger.error(f"Position fetch failed. Skipping cycle. error={e}", exc_info=True)
    return

exc_info=True on an ERROR call logs the full stack trace automatically. You do not need to format it yourself.

Structured Prefixes

This is the single most useful thing I added. Every log line in the bot starts with a keyword prefix in a fixed field. TRADE, SKIP, SIGNAL, SCORE, CLOSE, BLOCK, ERROR. Whatever makes sense for the domain.

The reason is grep. When the bot runs 20 cycles a day across two bots and you need to find every trade that fired in the last 48 hours:

grep "^2026-05-17.*TRADE" logs/weather_bot.log

Done in milliseconds. No parsing. No log aggregation tool required. Just structured plain text.

When you need to see why the bot skipped everything on a particular morning:

grep "SKIP" logs/weather_bot.log | grep "2026-05-15 09"

You get every skip in that hour with the reason code attached. If the reason is always score_below_threshold and the score is always 0.23 when your minimum is 0.55, you now know exactly what happened. The models disagreed that morning. The bot did exactly what it was supposed to do.

The ENSEMBLE_COMPARE Line

In the Weather Bot, every trade candidate produces one ENSEMBLE_COMPARE log line that shows what each model thought. This was added specifically so I could debug disagreements after the fact.

logger.debug(
    f"ENSEMBLE_COMPARE | market={ticker} | "
    f"GFS={gfs_prob:.3f} | AIGEFS={aigefs_prob:.3f} | "
    f"IFS={ifs_prob:.3f} | AIFS={aifs_prob:.3f} | "
    f"weighted={weighted_prob:.3f} | market_price={market_price:.3f} | "
    f"edge={edge:.3f} | agreement={agreement_count}/4"
)

At DEBUG level this goes to the file but not the terminal. After a bad trade you open the log, grep for ENSEMBLE_COMPARE, and you can see that GFS said 0.72, AIGEFS said 0.68, IFS said 0.31, and AIFS said 0.28. Two models thought yes, two thought no. The agreement filter correctly blocked that trade. Or it did not, and now you know why.

Searching After a Bad Trade

Here is the actual workflow when something goes wrong.

First, find the trade in the file:

grep "TRADE" logs/weather_bot.log | grep "KNYC_HIGH_ABOVE_72"

Get the timestamp from that line. Then extract the 5 minutes before it:

grep "2026-05-14 14:3[2-7]" logs/weather_bot.log | grep "KNYC_HIGH_ABOVE_72"

That gives you the full decision trail for that market in that window. SIGNAL lines show what the models were saying. SCORE lines show what the composite said. ENSEMBLE_COMPARE shows whether the models agreed. TRADE shows what fired and at what price.

If you used print() everywhere, you have none of this. The terminal buffer is gone. The systemd journal might have some of it. You are guessing.

One More Thing: Log the Config at Startup

Every time the bot starts, log the active configuration. Not sensitive values, but the threshold values that determine behavior.

logger.info(f"CONFIG | min_price={cfg.min_price} | min_confidence={cfg.min_confidence} | "
            f"min_edge={cfg.min_ensemble_edge} | min_agreement={cfg.min_agreement} | "
            f"early_exit_threshold={cfg.early_exit_threshold}")

When I changed --min-price from 0.02 to 0.40 and the bot stopped trading for three days, this one line told me immediately that the new threshold was loaded. I was not chasing a code bug. The config was the answer.

The Full Pattern in 50 Lines

If you want to just copy the pattern and adapt it, here it is end to end:

import logging
import logging.handlers
import os

def setup_logger(name, log_dir="logs"):
    os.makedirs(log_dir, exist_ok=True)
    logger = logging.getLogger(name)
    logger.setLevel(logging.DEBUG)
    if logger.handlers:
        return logger
    fmt = logging.Formatter(
        "%(asctime)s | %(levelname)-8s | %(module)-20s | %(message)s",
        datefmt="%Y-%m-%d %H:%M:%S"
    )
    fh = logging.handlers.RotatingFileHandler(
        os.path.join(log_dir, f"{name}.log"),
        maxBytes=5_000_000, backupCount=10, encoding="utf-8"
    )
    fh.setLevel(logging.DEBUG)
    fh.setFormatter(fmt)
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)
    ch.setFormatter(fmt)
    logger.addHandler(fh)
    logger.addHandler(ch)
    return logger

# Usage
logger = setup_logger("my_bot")
logger.info("STARTUP | bot=my_bot | version=1.0")
logger.debug("DEBUG details here, file only")
logger.warning("Something unexpected but non-fatal")
logger.error("Something broke", exc_info=True)

That is it. Rotating files, console filter, structured format, full tracebacks on errors. This runs on my Ubuntu VPS as a systemd service, produces about 2MB of logs per day across both bots, and lets me answer any question about bot behavior in under 60 seconds.

Good logging is not glamorous. Nobody buys a trading bot because the log format is clean. But when a position goes wrong at 4 AM and you are trying to figure out what happened over coffee the next morning, you will be very glad you set this up before the bot went live.

The Predict & Profit bots ship with this exact setup already in place. Every decision, every skip, every signal value goes to the log. The first thing I tell buyers who have questions about behavior: open the log and grep for the market ticker.