CertGrid CertGrid
Hands-on Lab·Python Automation for IT

Python Logging for Unattended Scripts

`print` is fine while you are watching. A script that runs at 3am needs a level you can turn up without editing it, a timestamp, the module the message came from, and output on stderr so it does not corrupt whatever is reading stdout. That is `logging`, in about four lines of setup - plus one widely repeated claim about lazy formatting that this guide takes apart with two captures.

Scripting Foundations Guide 6 of 39 Beginner

Written against the versions above. `logging` has been stable for many releases. The one behaviour worth pinning: with no configuration at all, a message at WARNING or above still appears - the `lastResort` handler, present since Python 3.2.

Everything on this page runs on the control node. Any machine with Python 3 will do.
Server NameIP AddressOSRolesCPURAMHDD
RUNNER01192.168.0.27Ubuntu 26.04 LTSControl node - every script in this path runs here2 Core4 GB50 GB

Before you start

  1. print goes to stdout, logging goes to stderr

    That difference is the first reason to switch, and it is easiest to see by throwing each stream away in turn.

    bash Example session 
    cat > ~/auto/streams.py <<'PY'import loggingimport sys logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s") print("this is print")logging.info("this is logging")PYpython3 ~/auto/streams.pyINFO this is loggingthis is printpython3 ~/auto/streams.py 2>/dev/nullthis is printpython3 ~/auto/streams.py 1>/dev/nullINFO this is logging

    Expected resultBoth lines; then only the print; then only the log line.

    Success conditionYou know which stream each one uses.

  2. The five levels, and the threshold

    DEBUG, INFO, WARNING, ERROR, CRITICAL, in that order. basicConfig(level=...) sets the threshold and anything below it is dropped - so the same script says three different amounts.

    bash Example session 
    cat > ~/auto/levels.py <<'PY'import loggingimport sys level = sys.argv[1] if len(sys.argv) > 1 else "INFO"logging.basicConfig(level=getattr(logging, level), format="%(levelname)-8s %(message)s")log = logging.getLogger("demo") log.debug("the value was %r", {"host": "web01"})log.info("checked 2 hosts")log.warning("disk at 91%%")log.error("host unreachable")log.critical("giving up")PYpython3 ~/auto/levels.py INFOINFO     checked 2 hostsWARNING  disk at 91%%ERROR    host unreachableCRITICAL giving uppython3 ~/auto/levels.py DEBUGDEBUG    the value was {'host': 'web01'}INFO     checked 2 hostsWARNING  disk at 91%%ERROR    host unreachableCRITICAL giving uppython3 ~/auto/levels.py WARNINGWARNING  disk at 91%%ERROR    host unreachableCRITICAL giving up

    Expected resultFour lines at INFO, five at DEBUG, three at WARNING.

    Success conditionYou can change how much a script says without editing it.

  3. With no configuration at all

    Worth knowing, because it explains a script that logs less than you expected. With no basicConfig, the default threshold is WARNING.

    bash Example session 
    cat > ~/auto/noconfig.py <<'PY'import logging log = logging.getLogger("demo")log.info("an info message")log.warning("a warning")log.error("an error")PYpython3 ~/auto/noconfig.pya warningan error

    Expected resultThe warning and the error appear; the info call produces nothing.

    Success conditionYou know why your log.info calls are silent.

  4. The format string is where the useful part is

    The default format is bare. For anything unattended you want a timestamp, the level, which logger it came from, and where in the code - and it is one argument.

    bash Example session 
    cat > ~/auto/format.py <<'PY'import logging logging.basicConfig(    level=logging.INFO,    format="%(asctime)s %(levelname)-8s %(name)s %(filename)s:%(lineno)d %(message)s",    datefmt="%Y-%m-%d %H:%M:%S",) log = logging.getLogger("diskcheck")log.info("checked %d host(s)", 2)log.warning("%s is at %d%%", "web01", 91)PYpython3 ~/auto/format.py2026-08-24 03:33:59 INFO     diskcheck format.py:10 checked 2 host(s)2026-08-24 03:33:59 WARNING  diskcheck format.py:11 web01 is at 91%

    Expected resultTimestamped lines with the level, logger name, filename and line number.

    Success conditionYour log lines say when, how bad, and where from.

  5. Percent-style against an f-string

    The usual advice is "use log.debug("x %s", val) rather than an f-string, because it is lazy". Half of that is true. Here is the half that is not: expensive() is an ordinary argument and gets evaluated either way.

    bash Example session 
    cat > ~/auto/lazy.py <<'PY'import logging logging.basicConfig(level=logging.WARNING, format="%(levelname)s %(message)s")log = logging.getLogger("demo") calls = {"n": 0}  def expensive():    calls["n"] += 1    return "computed"  log.debug("percent style: %s", expensive())print("after percent style, expensive() was called", calls["n"], "time(s)") log.debug(f"f-string: {expensive()}")print("after the f-string,  expensive() was called", calls["n"], "time(s)")PYpython3 ~/auto/lazy.pyafter percent style, expensive() was called 1 time(s)after the f-string,  expensive() was called 2 time(s)

    Expected resultexpensive() called 1 time after the percent-style call, and 2 after the f-string - even though the level is WARNING and neither line was logged.

    Success conditionYou know that percent-style does not skip your function call.

  6. What is actually deferred is the rendering

    Same experiment, with the cost moved from *producing* the value to *rendering* it - an object whose __str__ is expensive.

    Now the difference shows.

    bash Example session 
    cat > ~/auto/lazy2.py <<'PY'import logging logging.basicConfig(level=logging.WARNING, format="%(levelname)s %(message)s")log = logging.getLogger("demo") calls = {"str": 0}  class Expensive:    def __str__(self):        calls["str"] += 1        return "the expensive rendering"  obj = Expensive() log.debug("percent style: %s", obj)print("percent style -> __str__ called", calls["str"], "time(s)") log.debug(f"f-string: {obj}")print("f-string      -> __str__ called", calls["str"], "time(s)") log.warning("above the threshold: %s", obj)print("and when it IS logged, __str__ called", calls["str"], "time(s)")PYpython3 ~/auto/lazy2.pyWARNING above the threshold: the expensive renderingpercent style -> __str__ called 0 time(s)f-string      -> __str__ called 1 time(s)and when it IS logged, __str__ called 2 time(s)

    Expected result__str__ called 0 times for percent-style, 1 for the f-string, and a second time when the message really is logged.

    Success conditionYou can state precisely what percent-style saves.

  7. Writing to a file as well as the terminal

    handlers= takes a list, and each handler is a destination. Two of them means the same records go to both.

    bash Example session 
    cat > ~/auto/tofile.py <<'PY'import loggingfrom pathlib import Path logfile = Path.home() / "auto" / "run.log" logging.basicConfig(    level=logging.INFO,    format="%(asctime)s %(levelname)-8s %(message)s",    handlers=[logging.FileHandler(logfile), logging.StreamHandler()],) log = logging.getLogger("job")log.info("starting")log.warning("one host was slow")log.info("done")PYpython3 ~/auto/tofile.py2026-08-24 03:34:00,837 INFO     starting2026-08-24 03:34:00,837 WARNING  one host was slow2026-08-24 03:34:00,837 INFO     donecat ~/auto/run.log2026-08-24 03:34:00,837 INFO     starting2026-08-24 03:34:00,837 WARNING  one host was slow2026-08-24 03:34:00,837 INFO     done

    Expected resultThree lines on the terminal and the same three in run.log.

    Success conditionYou can keep a log after the terminal has gone.

  8. The traceback, kept

    log.error records your message. log.exception records the message and the traceback, and is only valid inside an except block.

    bash Example session 
    cat > ~/auto/withtb.py <<'PY'import logging logging.basicConfig(level=logging.INFO, format="%(levelname)-8s %(message)s")log = logging.getLogger("job") try:    int("not a number")except ValueError:    log.error("could not parse the count")    log.exception("the same failure, with the traceback")PYpython3 ~/auto/withtb.pyERROR    could not parse the countERROR    the same failure, with the tracebackTraceback (most recent call last):  File "/home/sysadmin/auto/withtb.py", line 7, in <module>    int("not a number")    ~~~^^^^^^^^^^^^^^^^ValueError: invalid literal for int() with base 10: 'not a number'

    Expected resultOne bare ERROR line, then the same level of line followed by the full traceback.

    Success conditionYou can log a failure without losing where it came from.

  9. One logger per module, named for the module

    logging.getLogger(__name__) at the top of every file. The names then form a hierarchy that matches your imports, and each one can be turned up or down independently.

    bash Example session 
    mkdir -p ~/auto/pkg && cat > ~/auto/pkg/collect.py <<'PY'import logging log = logging.getLogger(__name__)  def run():    log.info("collecting")PYcat > ~/auto/pkg/main.py <<'PY'import logging import collect logging.basicConfig(level=logging.DEBUG, format="%(name)-10s %(levelname)-8s %(message)s")log = logging.getLogger(__name__) log.info("starting up")collect.run()logging.getLogger("collect").setLevel(logging.WARNING)log.info("turned collect down to WARNING")collect.run()log.info("finished")PYcd ~/auto/pkg && python3 main.py__main__   INFO     starting upcollect    INFO     collecting__main__   INFO     turned collect down to WARNING__main__   INFO     finished

    Expected result__main__ and collect labelling their own lines - and after collect is set to WARNING, its info call produces nothing while __main__ carries on.

    Success conditionYou can silence one noisy module without touching the rest.

Troubleshooting

Official sources

← All Python Automation guides