# Python Logging Cheatsheet - URL: https://karandeepsingh.ca/cheatsheets/python/python-logging/ - Author: Karandeep Singh - Published: 2025-08-14 - Tags: python, logging - Summary: My notes on Python logging done properly, covering loggers vs handlers, dictConfig, structured JSON output for CloudWatch, rotation, and the traps that produce duplicate or missing lines. Every incident I have ever worked started with someone reading a log line. Python's `logging` module is configured once, at the edge of the program, and then never thought about again — which is exactly why the traps in it bite so hard. This sheet is the configuration I actually use, plus the three behaviours (propagation, double filtering, `basicConfig` no-ops) that produce duplicate or missing lines. For the language itself see the [Python Basics & CLI Cheatsheet](https://karandeepsingh.ca/cheatsheets/python/python-basics-cli/). **tip:** One rule carries most of this sheet: **libraries get a logger, applications get handlers.** A module calls `logging.getLogger(__name__)` and nothing else. The entry point decides where the output goes. Configure handlers in a library and you take that choice away from whoever imports you. ## The Five Levels > **Docs:** [Logging levels, Python 3 docs](https://docs.python.org/3/library/logging.html#logging-levels) | Level | Value | Use it for | |-------|-------|------------| | `DEBUG` | 10 | Values you need while diagnosing; off in production | | `INFO` | 20 | Normal progress: started, deployed, finished | | `WARNING` | 30 | Surprising but handled: retry, fallback, deprecation | | `ERROR` | 40 | This operation failed; the process continues | | `CRITICAL` | 50 | The process cannot continue | `WARNING` is the default. A fresh logger with no configuration prints warnings and above to `stderr`, which is why your `INFO` lines vanish before you have configured anything. ## The Shape of Every Script ```python import logging log = logging.getLogger(__name__) # module-level, by name def deploy(env: str) -> None: log.info("deploying to %s", env) # %s, not an f-string log.debug("full config: %r", cfg) if __name__ == "__main__": # only the entry point configures logging.basicConfig( level=logging.INFO, format="%(asctime)s %(levelname)-8s %(name)s %(message)s", datefmt="%Y-%m-%dT%H:%M:%S%z", ) deploy("live") ``` `getLogger(__name__)` gives you the dotted module path (`myapp.deploy.ecs`), which is what makes per-module levels possible later. ## basicConfig, and Why It Silently Does Nothing > **Docs:** [logging.basicConfig](https://docs.python.org/3/library/logging.html#logging.basicConfig) ```python logging.basicConfig(level=logging.INFO) # ignored if handlers already exist logging.basicConfig(level=logging.INFO, force=True) # 3.8+: replace them ``` Here is the trap firing. `logging.warning()` on line 2 attaches a handler to the root logger, so the `basicConfig()` below it has nothing to do: ```python import logging logging.warning("deploy starting") # implicit basicConfig happens HERE logging.basicConfig(level=logging.DEBUG, format="%(levelname)s %(message)s") logging.debug("config loaded") # never appears logging.info("deployed") # never appears ``` ```text $ python3 deploy.py WARNING:root:deploy starting # one line. The DEBUG and INFO calls printed nothing, and the format is # still the default "LEVEL:logger:message" — basicConfig never ran. ``` **warning:** `basicConfig()` returns immediately if the root logger already has a handler. Importing a library that configures logging, or calling `logging.info()` anywhere before your setup line, attaches one — and your configuration is dropped with no error. `force=True` removes the existing handlers first. ## Loggers, Handlers, Formatters > **Docs:** [Logging HOWTO: advanced](https://docs.python.org/3/howto/logging.html#advanced-logging-tutorial) A record passes **two** level checks: the logger's, then each handler's. ```python log = logging.getLogger("deployer") log.setLevel(logging.DEBUG) # check 1 console = logging.StreamHandler() # stderr by default console.setLevel(logging.INFO) # check 2: DEBUG never reaches it fileh = logging.FileHandler("deploy.log") fileh.setLevel(logging.DEBUG) # but it does reach this one fmt = logging.Formatter("%(asctime)s %(levelname)s %(name)s %(message)s") console.setFormatter(fmt) fileh.setFormatter(fmt) log.addHandler(console) log.addHandler(fileh) ``` Set the logger to the **most verbose** level you ever want, and let each handler decide what it keeps. **Every format field worth using** | Field | Gives you | |---|---| | `%(asctime)s` | Timestamp, formatted by `datefmt` | | `%(levelname)s` | `INFO`, `ERROR`, … — pad it: `%(levelname)-8s` | | `%(name)s` | The logger's dotted name, so `myapp.deploy.ecs` | | `%(message)s` | The formatted message | | `%(filename)s` `%(lineno)d` | Where the call was made | | `%(funcName)s` `%(module)s` | Which function, which module | | `%(process)d` `%(threadName)s` | Which process, which thread | | `%(exc_text)s` | The traceback, once a handler has formatted it | ```text %(asctime)s %(levelname)-8s %(name)s %(message)s ``` ## dictConfig: the One I Actually Use > **Docs:** [logging.config.dictConfig](https://docs.python.org/3/library/logging.config.html#logging.config.dictConfig) One dictionary at startup beats a scatter of `addHandler` calls. ```python import logging.config logging.config.dictConfig({ "version": 1, "disable_existing_loggers": False, # see the trap below "formatters": { "plain": { "format": "%(asctime)s %(levelname)-8s %(name)s %(message)s", "datefmt": "%Y-%m-%dT%H:%M:%S%z", }, }, "handlers": { "console": { "class": "logging.StreamHandler", "formatter": "plain", "level": "INFO", "stream": "ext://sys.stdout", # stdout, so it is not read as an error }, }, "loggers": { "botocore": {"level": "WARNING"}, # quiet a chatty dependency "urllib3": {"level": "WARNING"}, }, "root": {"handlers": ["console"], "level": "INFO"}, }) ``` **warning:** `"disable_existing_loggers": True` is the **default**, and it switches off every logger created before this call — which, thanks to module-level `getLogger(__name__)`, means every module you have already imported. Set it to `False` unless you specifically want that. ## Exceptions and Tracebacks > **Docs:** [logging.Logger.exception](https://docs.python.org/3/library/logging.html#logging.Logger.exception) ```python try: deploy("live") except Exception: log.exception("deploy failed") # ERROR + traceback, inside except raise log.error("deploy failed", exc_info=True) # same thing, usable anywhere log.warning("retrying", exc_info=True) # traceback at another level log.error("deploy failed: %s", e) # loses the traceback entirely ``` `log.exception()` only belongs inside an `except` block. Called anywhere else it still logs at ERROR, and then tells you there was nothing to attach: ```text $ python3 oops.py ERROR deployer deploy failed NoneType: None # "NoneType: None" is the traceback it could not find. If you see this in # your logs, the except block moved and the log call did not. ``` ### Extra context on a record ```python log.info("deployed", extra={"env": "live", "replicas": 3}) # the keys become attributes on the record: %(env)s in a formatter, # or fields in a JSON formatter. "message", "asctime" and "args" are # reserved and raise KeyError if you reuse them. ``` ## Structured JSON Logs CloudWatch Logs Insights, Loki and friends all want one JSON object per line. No dependency needed: ```python import json, logging class JsonFormatter(logging.Formatter): RESERVED = set(logging.LogRecord("", 0, "", 0, "", (), None).__dict__) def format(self, record: logging.LogRecord) -> str: out = { "ts": self.formatTime(record, "%Y-%m-%dT%H:%M:%S%z"), "level": record.levelname, "logger": record.name, "msg": record.getMessage(), } if record.exc_info: out["exc"] = self.formatException(record.exc_info) # anything passed via extra= for k, v in record.__dict__.items(): if k not in self.RESERVED and not k.startswith("_"): out[k] = v return json.dumps(out, default=str) h = logging.StreamHandler() h.setFormatter(JsonFormatter()) logging.getLogger().addHandler(h) ``` `default=str` stops a stray `datetime` or `Decimal` from raising inside the logger, which would otherwise take down the call site. ## Rotation > **Docs:** [logging.handlers](https://docs.python.org/3/library/logging.handlers.html) ```python from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler RotatingFileHandler("app.log", maxBytes=10_000_000, backupCount=5) TimedRotatingFileHandler("app.log", when="midnight", backupCount=14, utc=True) ``` **info:** On a container, do not rotate at all — log to `stdout` and let the platform collect it. Rotation matters on a long-lived VM. Two processes writing one `RotatingFileHandler` will also corrupt each other's rollover; use `WatchedFileHandler` with external `logrotate` instead. ## Propagation and Duplicate Lines > **Docs:** [Logger.propagate](https://docs.python.org/3/library/logging.html#logging.Logger.propagate) A record walks **up** the dotted name to the root, hitting every handler on the way. Add a handler to both `myapp` and the root and each line prints twice. ```python log = logging.getLogger("myapp.deploy") log.propagate = False # stop here; do not also hand it to root logging.getLogger().handlers # what is actually attached logging.getLogger("botocore").level # what a dependency is set to ``` Duplicate lines are nearly always one of three things: a handler on both a child and the root, `basicConfig()` called twice, or a module adding a handler at import time. ## Capturing Warnings and Third-Party Noise ```python logging.captureWarnings(True) # warnings module -> "py.warnings" logging.getLogger("botocore").setLevel(logging.WARNING) logging.getLogger("urllib3.connectionpool").setLevel(logging.WARNING) logging.getLogger("asyncio").setLevel(logging.WARNING) ``` ## Common Pitfalls **danger:** **Logging secrets.** A request object, an env dict or a boto3 response logged at DEBUG will happily print tokens and keys into CloudWatch, where they are retained and searchable. Log the fields you need by name, never the whole object. There is more on handling them in the [Python Security Cheatsheet](https://karandeepsingh.ca/cheatsheets/python/python-security/). - **f-strings in log calls.** `log.debug(f"{expensive()}")` runs `expensive()` even when DEBUG is off. `log.debug("%s", expensive())` still evaluates the argument — only the *formatting* is deferred. For genuinely costly work, guard it: `if log.isEnabledFor(logging.DEBUG):`. ```diff # deploy.py @@ -8,7 +8,8 @@ def deploy(env: str) -> None: - log.debug(f"config: {json.dumps(cfg, indent=2)}") - log.info(f"deploying to {env}") + if log.isEnabledFor(logging.DEBUG): # skip the dumps() entirely + log.debug("config: %s", json.dumps(cfg, indent=2)) + log.info("deploying to %s", env) ``` - **`print()` in a library.** It cannot be levelled, filtered, routed or turned off by the caller. - **The root logger as the app logger.** `logging.info(...)` at module scope calls the root logger and triggers an implicit `basicConfig()`, which is what later makes *your* `basicConfig()` a no-op. - **Handlers added at import time.** Import order then decides your logging configuration. - **Levels as strings.** `setLevel("info")` raises; it is `"INFO"` or `logging.INFO`. **Question:** Pick the last ERROR your service logged. Does the line say which host, which environment and which request it came from — or only that something broke? ## Related Cheatsheets - [Python Basics & CLI Cheatsheet](https://karandeepsingh.ca/cheatsheets/python/python-basics-cli/) — the syntax underneath this - [Python Security Cheatsheet](https://karandeepsingh.ca/cheatsheets/python/python-security/) — what must never reach a log line - [Python Threading & Concurrency Cheatsheet](https://karandeepsingh.ca/cheatsheets/python/python-threading-concurrency/) — logging from threads, and why `QueueHandler` exists ## Quiz 1. Why does `logging.basicConfig()` sometimes appear to do nothing at all? a) It only works inside a function b) It is a no-op if the root logger already has a handler attached c) It requires a filename argument d) It was removed in Python 3.11 Answer: b. basicConfig() returns immediately if the root logger already has handlers. Anything that logged before your call — or a library that configured logging itself — attaches one, so your settings are silently discarded. Pass force=True (3.8+) to replace the existing handlers instead. 2. You call `logger.setLevel(logging.DEBUG)` but no DEBUG lines appear. What is the most likely cause? a) DEBUG is not a real level b) The handler has its own, higher level, and a record must pass both c) setLevel only works on the root logger d) You must restart the interpreter Answer: b. A record is filtered twice: once by the logger's level, then again by each handler's level. A logger at DEBUG feeding a handler left at WARNING produces nothing. Set both. 3. What is the correct way to record an exception with its traceback? a) logger.error(str(e)) b) logger.exception("message") inside the except block c) print(e) then logger.error() d) logger.error("message", traceback=True) Answer: b. logger.exception() logs at ERROR and attaches the active traceback automatically. It is only valid inside an except block; elsewhere use logger.error("msg", exc_info=True). 4. Why does `logger.info("deployed %s", name)` beat `logger.info(f"deployed {name}")`? a) It is the only syntax that works b) The string is only formatted if the record is actually emitted c) f-strings cannot be logged d) It produces coloured output Answer: b. With %-style arguments the interpolation happens inside the handler, so a filtered-out DEBUG line costs nothing. An f-string is built before the call, so you pay for formatting even when the line is discarded.