Logging & Debugging: Beyond print()

print is fine for quick debugging. The logging module is for seeing what a running program does over time. The difference matters when your script becomes a service: print has no levels, no way to silence one module, no timestamps, no rotation, and no way to send output to a file or a log aggregator. Usually you discover that you need these things in the middle of a production problem.

This lesson covers how the pieces fit together (loggers, handlers, formatters, levels), the setup pattern for production, structured logging for log aggregators, a few debugging tools that work better than adding print calls everywhere, and the mistakes behind the common "my logs are duplicated" and "my logs are missing" problems.

1. How It Works: Four Pieces

The logging module has four separate parts. Once you see what each part does, the API is much less confusing.

Loggers: named channels. Code calls logger.info(...). By convention every module does logger = logging.getLogger(__name__) at the top, giving each module its own logger named after its dotted path.
Handlers: destinations. A handler routes log records to stderr, a file, syslog, a network socket, or an email. A logger can have multiple handlers.
Formatters: how each record turns into a string (or a JSON object). Attached to handlers, not loggers.
Levels: filters. DEBUG < INFO < WARNING < ERROR < CRITICAL. They are set on loggers and handlers, and a record has to pass both.

Records flow: module code → logger → (level filter) → handlers → (level filter) → formatter → destination. Once you know this order, it is clear where each setting belongs.

2. Levels: Use Them Right

Five levels, in order:

Level	Use for
`DEBUG`	Detailed diagnostic information: variable values, "entered function"
`INFO`	Normal events: "started", "processed 200 rows"
`WARNING`	Unusual, but the program recovered: "retry succeeded after 2 attempts"
`ERROR`	An operation failed: request returned 500, job aborted
`CRITICAL`	The system is broken: disk full, can't reach database

The most common mistake is using ERROR too often. If the code is checking whether a user exists, "User not found" is INFO at most. It is an expected result, not an error. Keep ERROR for things that really failed and probably need a person to look at them.

In production you typically run at INFO and drop to DEBUG only when investigating. That's why module-level loggers and per-module levels matter: you can turn myapp.payments up to DEBUG without also getting every DEBUG message from myapp.cache.

3. Basic Setup: `logging.basicConfig`

For a single-file script, one call is enough:

python

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(name)s: %(message)s",
)

logger = logging.getLogger(__name__)
logger.info("started")
logger.warning("disk at %d%%", 92)

basicConfig attaches a StreamHandler (writes to stderr) with the formatter you supplied to the root logger. Every other logger inherits from root by default, so every module's logger.info(...) is now formatted and printed.

Caveats:

basicConfig is a no-op if the root logger already has handlers. Call it once, at the entry point.
It's fine for scripts and quick experiments. In a library, do not call basicConfig. Let the application that uses the library configure logging.

4. Real Setup: Module-Level Loggers

Every real module starts with the same two lines:

python

# payments.py
import logging
logger = logging.getLogger(__name__)        # → "myapp.payments" if module is myapp.payments

def charge(user, amount):
    logger.info("charging user %s amount=%s", user.id, amount)
    ...

Three benefits:

The log line shows myapp.payments as the source, so you can search, filter or route logs by module.
The application can turn this module's level up or down on its own: logging.getLogger("myapp.payments").setLevel(logging.DEBUG).
Your library doesn't impose handlers on the consumer. If they never configure logging, only warnings and errors are printed, which is the right default for a library.

Configure handlers exactly once, in the entry point (main.py, manage.py, wsgi.py). If you configure logging in two places, the handlers are added twice and you'll see every log line twice. See Common Mistakes, item 2.

5. Handlers: Where Records Go

The standard library includes everything you need:

python

import logging
from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler

# Stderr (the default)
console = logging.StreamHandler()

# Plain file: grows forever (don't use it in production without rotation)
plain = logging.FileHandler("app.log", encoding="utf-8")

# Rotate by size: 10 MB per file, keep 5 old files
rotating = RotatingFileHandler("app.log", maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8")

# Rotate by time: a new file each midnight, keep 14 days
daily = TimedRotatingFileHandler("app.log", when="midnight", backupCount=14, encoding="utf-8")

RotatingFileHandler starts a new file when the current one reaches maxBytes. Older files are renamed app.log.1, app.log.2, etc., and anything past backupCount is deleted. TimedRotatingFileHandler does the same on a time interval.

Always use rotation in production. A file that never rotates fills the disk sooner or later, and a full disk can stop the whole server.

6. Formatters: What Each Line Shows

Formatters define the shape of each log line. The format string uses %-style fields:

python

import logging

fmt = logging.Formatter(
    "%(asctime)s %(levelname)-8s %(name)s %(filename)s:%(lineno)d - %(message)s"
)

h = logging.StreamHandler()
h.setFormatter(fmt)
logging.getLogger().addHandler(h)

The fields you'll use most:

Field	What it gives you
`%(asctime)s`	Timestamp
`%(levelname)s`	`INFO`, `WARNING`, ...
`%(name)s`	Logger name (i.e. `__name__`)
`%(message)s`	The actual log message
`%(filename)s`	Source file
`%(lineno)d`	Line number
`%(funcName)s`	Function that emitted the log
`%(process)d`	Process ID
`%(threadName)s`	Thread name

Include the file name and line number in your format. When you search production logs for the cause of a problem, the source location tells you where to look.

7. Lazy Formatting: The `%s` Habit

These two calls look the same, but one does extra work:

python

logger.info("user %s did %s", user, action)         # lazy: builds the text only if INFO is enabled
logger.info(f"user {user} did {action}")            # eager: builds the text now, even if it is filtered out

+ setup added so this can run · defines user, action, logger

# Lightweight mock for objects whose attributes/methods aren't critical
class _AutoMock:
    def __init__(self, name='mock'): self._name = name
    def __getattr__(self, k): return _AutoMock(self._name + '.' + k)
    def __call__(self, *a, **kw):
        print('-> ' + self._name + '() called')
        return _AutoMock(self._name + '()')
    def __repr__(self): return '<mock ' + self._name + '>'
    def __str__(self): return '<mock ' + self._name + '>'
    def __bool__(self): return True
    def __iter__(self): return iter([])
    def __len__(self): return 0
    def __getitem__(self, k): return _AutoMock(self._name + '[...]')
    def __setitem__(self, k, v): pass
    def __enter__(self): return self
    def __exit__(self, *a): return False
    async def __aenter__(self): return self
    async def __aexit__(self, *a): return False
    def __add__(self, o): return self
    def __radd__(self, o): return self
    def __sub__(self, o): return self
    def __mul__(self, o): return self
    def __rmul__(self, o): return self
    def __truediv__(self, o): return self
    def __eq__(self, o): return isinstance(o, _AutoMock)
    def __hash__(self): return hash(self._name)
    def __lt__(self, o): return True
    def __le__(self, o): return True
    def __gt__(self, o): return False
    def __ge__(self, o): return False
    def __mro_entries__(self, bases): return (object,)

user = _AutoMock('user')
action = _AutoMock('action')
logger = _AutoMock('logger')

If INFO is below the current level, the lazy form skips the string interpolation entirely. The f-string form has already built the message before logger.info decides to drop it. For code that runs very often, such as DEBUG calls inside tight loops, the difference is measurable.

For expensive log calls, you can also check the level first:

python

if logger.isEnabledFor(logging.DEBUG):
    logger.debug("state: %s", expensive_repr(big_object))

+ setup added so this can run · defines logger, logging, expensive_repr, big_object

# Lightweight mock for objects whose attributes/methods aren't critical
class _AutoMock:
    def __init__(self, name='mock'): self._name = name
    def __getattr__(self, k): return _AutoMock(self._name + '.' + k)
    def __call__(self, *a, **kw):
        print('-> ' + self._name + '() called')
        return _AutoMock(self._name + '()')
    def __repr__(self): return '<mock ' + self._name + '>'
    def __str__(self): return '<mock ' + self._name + '>'
    def __bool__(self): return True
    def __iter__(self): return iter([])
    def __len__(self): return 0
    def __getitem__(self, k): return _AutoMock(self._name + '[...]')
    def __setitem__(self, k, v): pass
    def __enter__(self): return self
    def __exit__(self, *a): return False
    async def __aenter__(self): return self
    async def __aexit__(self, *a): return False
    def __add__(self, o): return self
    def __radd__(self, o): return self
    def __sub__(self, o): return self
    def __mul__(self, o): return self
    def __rmul__(self, o): return self
    def __truediv__(self, o): return self
    def __eq__(self, o): return isinstance(o, _AutoMock)
    def __hash__(self): return hash(self._name)
    def __lt__(self, o): return True
    def __le__(self, o): return True
    def __gt__(self, o): return False
    def __ge__(self, o): return False
    def __mro_entries__(self, bases): return (object,)

logger = _AutoMock('logger')
logging = _AutoMock('logging')
def expensive_repr(*_a, **_kw):
    print('-> expensive_repr() called')
    return _AutoMock('expensive_repr()')
big_object = _AutoMock('big_object')

As a default: f-strings are fine for log calls that run rarely, but the %s form is the right default for library code and anything in a loop.

8. `logger.exception`: Always Use It Inside `except`

The right way to log an exception:

python

try:
    risky()
except Exception:
    logger.exception("risky() failed")           # includes the full traceback

+ setup added so this can run · defines risky, logger

# Lightweight mock for objects whose attributes/methods aren't critical
class _AutoMock:
    def __init__(self, name='mock'): self._name = name
    def __getattr__(self, k): return _AutoMock(self._name + '.' + k)
    def __call__(self, *a, **kw):
        print('-> ' + self._name + '() called')
        return _AutoMock(self._name + '()')
    def __repr__(self): return '<mock ' + self._name + '>'
    def __str__(self): return '<mock ' + self._name + '>'
    def __bool__(self): return True
    def __iter__(self): return iter([])
    def __len__(self): return 0
    def __getitem__(self, k): return _AutoMock(self._name + '[...]')
    def __setitem__(self, k, v): pass
    def __enter__(self): return self
    def __exit__(self, *a): return False
    async def __aenter__(self): return self
    async def __aexit__(self, *a): return False
    def __add__(self, o): return self
    def __radd__(self, o): return self
    def __sub__(self, o): return self
    def __mul__(self, o): return self
    def __rmul__(self, o): return self
    def __truediv__(self, o): return self
    def __eq__(self, o): return isinstance(o, _AutoMock)
    def __hash__(self): return hash(self._name)
    def __lt__(self, o): return True
    def __le__(self, o): return True
    def __gt__(self, o): return False
    def __ge__(self, o): return False
    def __mro_entries__(self, bases): return (object,)

def risky(*_a, **_kw):
    print('-> risky() called')
    return _AutoMock('risky()')
logger = _AutoMock('logger')

logger.exception(msg) is the same as logger.error(msg, exc_info=True): it logs at ERROR level and adds the formatted traceback. The traceback is the part that tells you where the failure came from, and print(e) or logger.error(str(e)) throws it away.

This is one of the most useful methods in the logging API. Use it in every except block that catches an exception without re-raising it. See exceptions Section 8 for more.

9. Production Pattern: `dictConfig`

For real apps, configuring handlers in code becomes long and hard to manage. logging.config.dictConfig takes a single dict that describes everything:

python

import logging.config

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "standard": {
            "format": "%(asctime)s %(levelname)-8s %(name)s: %(message)s",
        },
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "level": "INFO",
            "formatter": "standard",
        },
        "file": {
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "logs/app.log",
            "maxBytes": 10_000_000,
            "backupCount": 5,
            "level": "DEBUG",
            "formatter": "standard",
            "encoding": "utf-8",
        },
    },
    "loggers": {
        "": {                                       # root logger
            "handlers": ["console", "file"],
            "level": "DEBUG",
        },
        "urllib3": {"level": "WARNING"},            # hide the many messages from this dependency
        "boto3": {"level": "WARNING"},
    },
}

import os
os.makedirs("logs", exist_ok=True)               # the file handler won't create the folder
logging.config.dictConfig(LOGGING)

That same dict can come from a YAML or JSON file via yaml.safe_load / json.load. The dict form is the production standard. It describes the setup instead of building it step by step, it supports every feature, and frameworks such as Django use the same format.

10. Structured Logging: JSON for Aggregators

Log aggregators (Datadog, ELK, Loki, CloudWatch) want structured records, not free-form text. The simplest approach that works with the stdlib logging module is python-json-logger:

python

# pip install python-json-logger
from pythonjsonlogger.json import JsonFormatter

handler = logging.StreamHandler()
handler.setFormatter(JsonFormatter("%(asctime)s %(levelname)s %(name)s %(message)s"))

logger = logging.getLogger("myapp")
logger.setLevel(logging.INFO)
logger.addHandler(handler)
logger.info("user logged in", extra={"user_id": 42, "ip": "10.0.0.1"})

+ setup added so this can run · re-runs 5 earlier blocks on this page first

# Lightweight mock for objects whose attributes/methods aren't critical
class _AutoMock:
    def __init__(self, name='mock'): self._name = name
    def __getattr__(self, k): return _AutoMock(self._name + '.' + k)
    def __call__(self, *a, **kw):
        print('-> ' + self._name + '() called')
        return _AutoMock(self._name + '()')
    def __repr__(self): return '<mock ' + self._name + '>'
    def __str__(self): return '<mock ' + self._name + '>'
    def __bool__(self): return True
    def __iter__(self): return iter([])
    def __len__(self): return 0
    def __getitem__(self, k): return _AutoMock(self._name + '[...]')
    def __setitem__(self, k, v): pass
    def __enter__(self): return self
    def __exit__(self, *a): return False
    async def __aenter__(self): return self
    async def __aexit__(self, *a): return False
    def __add__(self, o): return self
    def __radd__(self, o): return self
    def __sub__(self, o): return self
    def __mul__(self, o): return self
    def __rmul__(self, o): return self
    def __truediv__(self, o): return self
    def __eq__(self, o): return isinstance(o, _AutoMock)
    def __hash__(self): return hash(self._name)
    def __lt__(self, o): return True
    def __le__(self, o): return True
    def __gt__(self, o): return False
    def __ge__(self, o): return False
    def __mro_entries__(self, bases): return (object,)

logging = _AutoMock('logging')

# Earlier blocks on this page that this one builds on, re-run quietly first.
try:
    import logging
    from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler
    import logging.config
    import os
except Exception:
    pass
_pm_earlier = [
    'import logging\n\nlogging.basicConfig(\n    level=logging.INFO,\n    format="%(asctime)s %(levelname)s %(name)s: %(message)s",\n)\n\nlogger = logging.getLogger(__name__)\nlogger.info("started")\nlogger.warning("disk at %d%%", 92)',
    '# payments.py\nimport logging\nlogger = logging.getLogger(__name__)        # → "myapp.payments" if module is myapp.payments\n\ndef charge(user, amount):\n    logger.info("charging user %s amount=%s", user.id, amount)\n    ...',
    'import logging\nfrom logging.handlers import RotatingFileHandler, TimedRotatingFileHandler\n\n# Stderr (the default)\nconsole = logging.StreamHandler()\n\n# Plain file: grows forever (don\'t use it in production without rotation)\nplain = logging.FileHandler("app.log", encoding="utf-8")\n\n# Rotate by size: 10 MB per file, keep 5 old files\nrotating = RotatingFileHandler("app.log", maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8")\n\n# Rotate by time: a new file each midnight, keep 14 days\ndaily = TimedRotatingFileHandler("app.log", when="midnight", backupCount=14, encoding="utf-8")',
    'import logging\n\nfmt = logging.Formatter(\n    "%(asctime)s %(levelname)-8s %(name)s %(filename)s:%(lineno)d - %(message)s"\n)\n\nh = logging.StreamHandler()\nh.setFormatter(fmt)\nlogging.getLogger().addHandler(h)',
    'import logging.config\n\nLOGGING = {\n    "version": 1,\n    "disable_existing_loggers": False,\n    "formatters": {\n        "standard": {\n            "format": "%(asctime)s %(levelname)-8s %(name)s: %(message)s",\n        },\n    },\n    "handlers": {\n        "console": {\n            "class": "logging.StreamHandler",\n            "level": "INFO",\n            "formatter": "standard",\n        },\n        "file": {\n            "class": "logging.handlers.RotatingFileHandler",\n            "filename": "logs/app.log",\n            "maxBytes": 10_000_000,\n            "backupCount": 5,\n            "level": "DEBUG",\n            "formatter": "standard",\n            "encoding": "utf-8",\n        },\n    },\n    "loggers": {\n        "": {                                       # root logger\n            "handlers": ["console", "file"],\n            "level": "DEBUG",\n        },\n        "urllib3": {"level": "WARNING"},            # hide the many messages from this dependency\n        "boto3": {"level": "WARNING"},\n    },\n}\n\nimport os\nos.makedirs("logs", exist_ok=True)               # the file handler won\'t create the folder\nlogging.config.dictConfig(LOGGING)',
]
def _pm_run_earlier(_srcs, _g):
    import sys as _s, io as _io, warnings as _w
    for _src in _srcs:
        _o, _e = _s.stdout, _s.stderr
        _s.stdout = _s.stderr = _io.StringIO()
        try:
            with _w.catch_warnings():
                _w.simplefilter('ignore')
                exec(compile(_src, '<earlier block>', 'exec'), _g)
        except (Exception, SystemExit):
            pass
        finally:
            _s.stdout, _s.stderr = _o, _e
    if 'matplotlib.pyplot' in _s.modules:
        _s.modules['matplotlib.pyplot'].close('all')   # their plots belong to their own blocks
_pm_run_earlier(_pm_earlier, globals())
del _pm_earlier, _pm_run_earlier

Output:

json

{"asctime": "2026-05-14 09:30:00,123", "levelname": "INFO", "name": "myapp",
 "message": "user logged in", "user_id": 42, "ip": "10.0.0.1"}

The extra= dict gets merged into the JSON record. The aggregator indexes those fields, so you can query "all user_id=42 events in the last hour" without grepping text.

For more features (context binding, processors, async support), use structlog. The ideas are the same, and many people find its API easier to use.

11. Per-Module Levels and Quietening Dependencies

Third-party libraries can produce a lot of log messages. urllib3 logs every new connection at DEBUG, botocore logs every API call, and matplotlib logs a lot too. Turn them down:

python

logging.getLogger("urllib3").setLevel(logging.WARNING)
logging.getLogger("botocore").setLevel(logging.WARNING)
logging.getLogger("matplotlib").setLevel(logging.WARNING)

+ setup added so this can run · re-runs 6 earlier blocks on this page first

# Lightweight mock for objects whose attributes/methods aren't critical
class _AutoMock:
    def __init__(self, name='mock'): self._name = name
    def __getattr__(self, k): return _AutoMock(self._name + '.' + k)
    def __call__(self, *a, **kw):
        print('-> ' + self._name + '() called')
        return _AutoMock(self._name + '()')
    def __repr__(self): return '<mock ' + self._name + '>'
    def __str__(self): return '<mock ' + self._name + '>'
    def __bool__(self): return True
    def __iter__(self): return iter([])
    def __len__(self): return 0
    def __getitem__(self, k): return _AutoMock(self._name + '[...]')
    def __setitem__(self, k, v): pass
    def __enter__(self): return self
    def __exit__(self, *a): return False
    async def __aenter__(self): return self
    async def __aexit__(self, *a): return False
    def __add__(self, o): return self
    def __radd__(self, o): return self
    def __sub__(self, o): return self
    def __mul__(self, o): return self
    def __rmul__(self, o): return self
    def __truediv__(self, o): return self
    def __eq__(self, o): return isinstance(o, _AutoMock)
    def __hash__(self): return hash(self._name)
    def __lt__(self, o): return True
    def __le__(self, o): return True
    def __gt__(self, o): return False
    def __ge__(self, o): return False
    def __mro_entries__(self, bases): return (object,)

logging = _AutoMock('logging')

# Earlier blocks on this page that this one builds on, re-run quietly first.
try:
    import logging
    from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler
    import logging.config
    import os
    from pythonjsonlogger.json import JsonFormatter
except Exception:
    pass
_pm_earlier = [
    'import logging\n\nlogging.basicConfig(\n    level=logging.INFO,\n    format="%(asctime)s %(levelname)s %(name)s: %(message)s",\n)\n\nlogger = logging.getLogger(__name__)\nlogger.info("started")\nlogger.warning("disk at %d%%", 92)',
    '# payments.py\nimport logging\nlogger = logging.getLogger(__name__)        # → "myapp.payments" if module is myapp.payments\n\ndef charge(user, amount):\n    logger.info("charging user %s amount=%s", user.id, amount)\n    ...',
    'import logging\nfrom logging.handlers import RotatingFileHandler, TimedRotatingFileHandler\n\n# Stderr (the default)\nconsole = logging.StreamHandler()\n\n# Plain file: grows forever (don\'t use it in production without rotation)\nplain = logging.FileHandler("app.log", encoding="utf-8")\n\n# Rotate by size: 10 MB per file, keep 5 old files\nrotating = RotatingFileHandler("app.log", maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8")\n\n# Rotate by time: a new file each midnight, keep 14 days\ndaily = TimedRotatingFileHandler("app.log", when="midnight", backupCount=14, encoding="utf-8")',
    'import logging\n\nfmt = logging.Formatter(\n    "%(asctime)s %(levelname)-8s %(name)s %(filename)s:%(lineno)d - %(message)s"\n)\n\nh = logging.StreamHandler()\nh.setFormatter(fmt)\nlogging.getLogger().addHandler(h)',
    'import logging.config\n\nLOGGING = {\n    "version": 1,\n    "disable_existing_loggers": False,\n    "formatters": {\n        "standard": {\n            "format": "%(asctime)s %(levelname)-8s %(name)s: %(message)s",\n        },\n    },\n    "handlers": {\n        "console": {\n            "class": "logging.StreamHandler",\n            "level": "INFO",\n            "formatter": "standard",\n        },\n        "file": {\n            "class": "logging.handlers.RotatingFileHandler",\n            "filename": "logs/app.log",\n            "maxBytes": 10_000_000,\n            "backupCount": 5,\n            "level": "DEBUG",\n            "formatter": "standard",\n            "encoding": "utf-8",\n        },\n    },\n    "loggers": {\n        "": {                                       # root logger\n            "handlers": ["console", "file"],\n            "level": "DEBUG",\n        },\n        "urllib3": {"level": "WARNING"},            # hide the many messages from this dependency\n        "boto3": {"level": "WARNING"},\n    },\n}\n\nimport os\nos.makedirs("logs", exist_ok=True)               # the file handler won\'t create the folder\nlogging.config.dictConfig(LOGGING)',
    '# pip install python-json-logger\nfrom pythonjsonlogger.json import JsonFormatter\n\nhandler = logging.StreamHandler()\nhandler.setFormatter(JsonFormatter("%(asctime)s %(levelname)s %(name)s %(message)s"))\n\nlogger = logging.getLogger("myapp")\nlogger.setLevel(logging.INFO)\nlogger.addHandler(handler)\nlogger.info("user logged in", extra={"user_id": 42, "ip": "10.0.0.1"})',
]
def _pm_run_earlier(_srcs, _g):
    import sys as _s, io as _io, warnings as _w
    for _src in _srcs:
        _o, _e = _s.stdout, _s.stderr
        _s.stdout = _s.stderr = _io.StringIO()
        try:
            with _w.catch_warnings():
                _w.simplefilter('ignore')
                exec(compile(_src, '<earlier block>', 'exec'), _g)
        except (Exception, SystemExit):
            pass
        finally:
            _s.stdout, _s.stderr = _o, _e
    if 'matplotlib.pyplot' in _s.modules:
        _s.modules['matplotlib.pyplot'].close('all')   # their plots belong to their own blocks
_pm_run_earlier(_pm_earlier, globals())
del _pm_earlier, _pm_run_earlier

You can do the opposite too: turn one of your modules up to DEBUG while you debug it, without changing the rest:

python

logging.getLogger("myapp.payments").setLevel(logging.DEBUG)

+ setup added so this can run · re-runs 7 earlier blocks on this page first

# Lightweight mock for objects whose attributes/methods aren't critical
class _AutoMock:
    def __init__(self, name='mock'): self._name = name
    def __getattr__(self, k): return _AutoMock(self._name + '.' + k)
    def __call__(self, *a, **kw):
        print('-> ' + self._name + '() called')
        return _AutoMock(self._name + '()')
    def __repr__(self): return '<mock ' + self._name + '>'
    def __str__(self): return '<mock ' + self._name + '>'
    def __bool__(self): return True
    def __iter__(self): return iter([])
    def __len__(self): return 0
    def __getitem__(self, k): return _AutoMock(self._name + '[...]')
    def __setitem__(self, k, v): pass
    def __enter__(self): return self
    def __exit__(self, *a): return False
    async def __aenter__(self): return self
    async def __aexit__(self, *a): return False
    def __add__(self, o): return self
    def __radd__(self, o): return self
    def __sub__(self, o): return self
    def __mul__(self, o): return self
    def __rmul__(self, o): return self
    def __truediv__(self, o): return self
    def __eq__(self, o): return isinstance(o, _AutoMock)
    def __hash__(self): return hash(self._name)
    def __lt__(self, o): return True
    def __le__(self, o): return True
    def __gt__(self, o): return False
    def __ge__(self, o): return False
    def __mro_entries__(self, bases): return (object,)

logging = _AutoMock('logging')

# Earlier blocks on this page that this one builds on, re-run quietly first.
try:
    import logging
    from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler
    import logging.config
    import os
    from pythonjsonlogger.json import JsonFormatter
except Exception:
    pass
_pm_earlier = [
    'import logging\n\nlogging.basicConfig(\n    level=logging.INFO,\n    format="%(asctime)s %(levelname)s %(name)s: %(message)s",\n)\n\nlogger = logging.getLogger(__name__)\nlogger.info("started")\nlogger.warning("disk at %d%%", 92)',
    '# payments.py\nimport logging\nlogger = logging.getLogger(__name__)        # → "myapp.payments" if module is myapp.payments\n\ndef charge(user, amount):\n    logger.info("charging user %s amount=%s", user.id, amount)\n    ...',
    'import logging\nfrom logging.handlers import RotatingFileHandler, TimedRotatingFileHandler\n\n# Stderr (the default)\nconsole = logging.StreamHandler()\n\n# Plain file: grows forever (don\'t use it in production without rotation)\nplain = logging.FileHandler("app.log", encoding="utf-8")\n\n# Rotate by size: 10 MB per file, keep 5 old files\nrotating = RotatingFileHandler("app.log", maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8")\n\n# Rotate by time: a new file each midnight, keep 14 days\ndaily = TimedRotatingFileHandler("app.log", when="midnight", backupCount=14, encoding="utf-8")',
    'import logging\n\nfmt = logging.Formatter(\n    "%(asctime)s %(levelname)-8s %(name)s %(filename)s:%(lineno)d - %(message)s"\n)\n\nh = logging.StreamHandler()\nh.setFormatter(fmt)\nlogging.getLogger().addHandler(h)',
    'import logging.config\n\nLOGGING = {\n    "version": 1,\n    "disable_existing_loggers": False,\n    "formatters": {\n        "standard": {\n            "format": "%(asctime)s %(levelname)-8s %(name)s: %(message)s",\n        },\n    },\n    "handlers": {\n        "console": {\n            "class": "logging.StreamHandler",\n            "level": "INFO",\n            "formatter": "standard",\n        },\n        "file": {\n            "class": "logging.handlers.RotatingFileHandler",\n            "filename": "logs/app.log",\n            "maxBytes": 10_000_000,\n            "backupCount": 5,\n            "level": "DEBUG",\n            "formatter": "standard",\n            "encoding": "utf-8",\n        },\n    },\n    "loggers": {\n        "": {                                       # root logger\n            "handlers": ["console", "file"],\n            "level": "DEBUG",\n        },\n        "urllib3": {"level": "WARNING"},            # hide the many messages from this dependency\n        "boto3": {"level": "WARNING"},\n    },\n}\n\nimport os\nos.makedirs("logs", exist_ok=True)               # the file handler won\'t create the folder\nlogging.config.dictConfig(LOGGING)',
    '# pip install python-json-logger\nfrom pythonjsonlogger.json import JsonFormatter\n\nhandler = logging.StreamHandler()\nhandler.setFormatter(JsonFormatter("%(asctime)s %(levelname)s %(name)s %(message)s"))\n\nlogger = logging.getLogger("myapp")\nlogger.setLevel(logging.INFO)\nlogger.addHandler(handler)\nlogger.info("user logged in", extra={"user_id": 42, "ip": "10.0.0.1"})',
    'logging.getLogger("urllib3").setLevel(logging.WARNING)\nlogging.getLogger("botocore").setLevel(logging.WARNING)\nlogging.getLogger("matplotlib").setLevel(logging.WARNING)',
]
def _pm_run_earlier(_srcs, _g):
    import sys as _s, io as _io, warnings as _w
    for _src in _srcs:
        _o, _e = _s.stdout, _s.stderr
        _s.stdout = _s.stderr = _io.StringIO()
        try:
            with _w.catch_warnings():
                _w.simplefilter('ignore')
                exec(compile(_src, '<earlier block>', 'exec'), _g)
        except (Exception, SystemExit):
            pass
        finally:
            _s.stdout, _s.stderr = _o, _e
    if 'matplotlib.pyplot' in _s.modules:
        _s.modules['matplotlib.pyplot'].close('all')   # their plots belong to their own blocks
_pm_run_earlier(_pm_earlier, globals())
del _pm_earlier, _pm_run_earlier

Per-logger levels plus loggers named after modules (Section 4) are the key to readable logs.

12. Don't Log Secrets

API keys, passwords, JWTs, credit-card numbers and full request bodies often leak into logs through innocent-looking calls like logger.debug("request: %s", request). Logs end up in S3, in support tickets, in screenshots in Slack. Once a secret is in a log, assume that everyone with log access has seen it, and that is usually a lot of people.

A small redactor function helps a lot:

python

SENSITIVE_KEYS = {"password", "token", "secret", "api_key", "authorization", "card"}

def redact(d):
    """Return a shallow copy with sensitive values masked."""
    return {k: ("***" if k.lower() in SENSITIVE_KEYS else v) for k, v in d.items()}

logger.info("incoming request body=%s", redact(payload))

+ setup added so this can run · defines logger, payload

# Lightweight mock for objects whose attributes/methods aren't critical
class _AutoMock:
    def __init__(self, name='mock'): self._name = name
    def __getattr__(self, k): return _AutoMock(self._name + '.' + k)
    def __call__(self, *a, **kw):
        print('-> ' + self._name + '() called')
        return _AutoMock(self._name + '()')
    def __repr__(self): return '<mock ' + self._name + '>'
    def __str__(self): return '<mock ' + self._name + '>'
    def __bool__(self): return True
    def __iter__(self): return iter([])
    def __len__(self): return 0
    def __getitem__(self, k): return _AutoMock(self._name + '[...]')
    def __setitem__(self, k, v): pass
    def __enter__(self): return self
    def __exit__(self, *a): return False
    async def __aenter__(self): return self
    async def __aexit__(self, *a): return False
    def __add__(self, o): return self
    def __radd__(self, o): return self
    def __sub__(self, o): return self
    def __mul__(self, o): return self
    def __rmul__(self, o): return self
    def __truediv__(self, o): return self
    def __eq__(self, o): return isinstance(o, _AutoMock)
    def __hash__(self): return hash(self._name)
    def __lt__(self, o): return True
    def __le__(self, o): return True
    def __gt__(self, o): return False
    def __ge__(self, o): return False
    def __mro_entries__(self, bases): return (object,)

logger = _AutoMock('logger')
payload = _AutoMock('payload')

For full coverage, a custom logging.Filter can scrub records before they reach the formatter. Either way, nothing removes secrets by default. You have to do it.

13. Correlation IDs: Tracing One Request Across Many Logs

When 200 requests are in flight, the only way to follow one is to tag every log line with a request-scoped ID. The pattern uses a LoggerAdapter or a Filter that pulls the ID from a thread-local or contextvars:

python

import contextvars, logging

request_id_var = contextvars.ContextVar("request_id", default="-")

class RequestIdFilter(logging.Filter):
    def filter(self, record):
        record.request_id = request_id_var.get()
        return True

# Format string then includes %(request_id)s:
# "%(asctime)s %(levelname)s [%(request_id)s] %(name)s: %(message)s"

In your web framework's middleware, set request_id_var.set(uuid4().hex) at the start of each request. Every log line from anywhere in that request now carries the same ID. Most frameworks have a ready-made open-source middleware for this (asgi-correlation-id, django-log-request-id). Write your own only if you have to.

14. Debugging Beyond Logs: `breakpoint()`

Python 3.7 added the built-in breakpoint(), which starts whichever debugger you have configured (PDB by default):

python

def transform(payload):
    cleaned = sanitize(payload)
    breakpoint()                              # drops into PDB right here
    return enrich(cleaned)

+ setup added so this can run · defines sanitize, enrich

# Lightweight mock for objects whose attributes/methods aren't critical
class _AutoMock:
    def __init__(self, name='mock'): self._name = name
    def __getattr__(self, k): return _AutoMock(self._name + '.' + k)
    def __call__(self, *a, **kw):
        print('-> ' + self._name + '() called')
        return _AutoMock(self._name + '()')
    def __repr__(self): return '<mock ' + self._name + '>'
    def __str__(self): return '<mock ' + self._name + '>'
    def __bool__(self): return True
    def __iter__(self): return iter([])
    def __len__(self): return 0
    def __getitem__(self, k): return _AutoMock(self._name + '[...]')
    def __setitem__(self, k, v): pass
    def __enter__(self): return self
    def __exit__(self, *a): return False
    async def __aenter__(self): return self
    async def __aexit__(self, *a): return False
    def __add__(self, o): return self
    def __radd__(self, o): return self
    def __sub__(self, o): return self
    def __mul__(self, o): return self
    def __rmul__(self, o): return self
    def __truediv__(self, o): return self
    def __eq__(self, o): return isinstance(o, _AutoMock)
    def __hash__(self): return hash(self._name)
    def __lt__(self, o): return True
    def __le__(self, o): return True
    def __gt__(self, o): return False
    def __ge__(self, o): return False
    def __mro_entries__(self, bases): return (object,)

def sanitize(*_a, **_kw):
    print('-> sanitize() called')
    return _AutoMock('sanitize()')
def enrich(*_a, **_kw):
    print('-> enrich() called')
    return _AutoMock('enrich()')

The PDB commands you need:

Command	What it does
`n`	Next line (step over)
`s`	Step into a call
`c`	Continue until next breakpoint
`l`	List source around current line
`p expr`	Print `expr`
`pp expr`	Pretty-print
`w`	Where am I: show the stack
`q`	Quit

Better debuggers: ipdb (PDB with IPython features: tab completion and syntax highlighting) and pudb (a full-screen text interface). Set the env var PYTHONBREAKPOINT=ipdb.set_trace and breakpoint() uses it.

For "verbose warnings + checks on" development runs: python -X dev or PYTHONDEVMODE=1. It shows warnings for unclosed files and other resource leaks, coroutines that were never awaited, and other hidden bugs.

15. Common Mistakes

1. print in libraries
A library that prints can't be silenced and can't be routed. Always use a module-level logger, and let the consumer configure output.

2. Configuring logging multiple times
Two addHandler calls (or two different setup functions) mean two handlers, so every line is logged twice. Configure exactly once, in the entry point.

3. Wrong level
ERROR for "user not found" when the code is only checking is noise. INFO for "started up" is right. Match the level to whether a human needs to do anything.

4. Catching exception and logging only str(e)
You lose the traceback, which is the part that tells you where the error happened. Use logger.exception(msg) inside except. See exceptions Section 8.

5. Logging to both stdout and stderr
Pipes interleave the two streams unpredictably. Pick one (stderr is the usual choice for logs) and keep stdout for the program's real output.

6. Eager formatting below threshold
logger.debug(f"big: {expensive()}") calls expensive() even when DEBUG is filtered out. Use lazy %s form or guard with isEnabledFor.

7. No rotation
The 100 GB app.log problem. Always use RotatingFileHandler or TimedRotatingFileHandler for production files.

🎯 Your Turn: `setup_logging`

Write a setup_logging(app_name, level="INFO", log_dir="logs") function that:

1. Creates log_dir if it doesn't exist.
2. Configures a console handler (stderr, human-readable format) at INFO.
3. Configures a daily-rotating file handler (log_dir/{app_name}.log) at DEBUG with JSON formatting.
4. Returns the logger named app_name.
5. Quietens urllib3 and botocore to WARNING.

Then demonstrate it by logging at three levels including an exception inside an except block.

python

import logging

def setup_logging(app_name, level="INFO", log_dir="logs"):
    # TODO 1: ensure log_dir exists
    # TODO 2: build dictConfig with console + rotating-file JSON handlers
    # TODO 3: apply with logging.config.dictConfig
    # TODO 4: return logging.getLogger(app_name)
    ...

Hint 1: Daily rotation

logging.handlers.TimedRotatingFileHandler with when="midnight" starts a new file every day and appends a date suffix to the rotated file. Set backupCount to e.g. 30 to keep a month of history.

Hint 2: JSON format

Use python-json-logger's JsonFormatter. In the dict-config form, set "()": "pythonjsonlogger.json.JsonFormatter" and pass the format string as "format".

Show full solution

python

import logging.config
from pathlib import Path

def setup_logging(app_name, level="INFO", log_dir="logs"):
    """Configure console + daily-rotating-JSON-file logging for an app."""
    log_path = Path(log_dir)
    log_path.mkdir(parents=True, exist_ok=True)

    config = {
        "version": 1,
        "disable_existing_loggers": False,
        "formatters": {
            "console": {
                "format": "%(asctime)s %(levelname)-8s %(name)s: %(message)s",
            },
            "json": {
                "()": "pythonjsonlogger.json.JsonFormatter",
                "format": "%(asctime)s %(levelname)s %(name)s %(message)s %(filename)s %(lineno)d",
            },
        },
        "handlers": {
            "console": {
                "class": "logging.StreamHandler",
                "level": level,
                "formatter": "console",
            },
            "file": {
                "class": "logging.handlers.TimedRotatingFileHandler",
                "filename": str(log_path / f"{app_name}.log"),
                "when": "midnight",
                "backupCount": 30,
                "level": "DEBUG",
                "formatter": "json",
                "encoding": "utf-8",
            },
        },
        "loggers": {
            app_name: {
                "handlers": ["console", "file"],
                "level": "DEBUG",
                "propagate": False,         # don't send each record twice (here and via root)
            },
            "urllib3":  {"level": "WARNING"},
            "botocore": {"level": "WARNING"},
        },
    }

    logging.config.dictConfig(config)
    return logging.getLogger(app_name)


# Demo
logger = setup_logging("myapp")

logger.info("service starting up")
logger.warning("retry attempt %d after transient error", 2)

try:
    1 / 0
except ZeroDivisionError:
    logger.exception("math went off the rails")

Console output (human-readable):

python

2026-05-14 09:30:00,123 INFO     myapp: service starting up
2026-05-14 09:30:00,124 WARNING  myapp: retry attempt 2 after transient error
2026-05-14 09:30:00,125 ERROR    myapp: math went off the rails
Traceback (most recent call last):
  File "...", line ..., in <module>
    1 / 0
ZeroDivisionError: division by zero

File output logs/myapp.log (JSON, one record per line):

json

{"asctime": "2026-05-14 09:30:00,123", "levelname": "INFO", "name": "myapp",
 "message": "service starting up", "filename": "demo.py", "lineno": 55}
{"asctime": "2026-05-14 09:30:00,124", "levelname": "WARNING", "name": "myapp",
 "message": "retry attempt 2 after transient error", "filename": "demo.py", "lineno": 56}
{"asctime": "2026-05-14 09:30:00,125", "levelname": "ERROR", "name": "myapp",
 "message": "math went off the rails", "filename": "demo.py", "lineno": 61,
 "exc_info": "Traceback (most recent call last):\n  File ...\nZeroDivisionError: division by zero"}

What this gives you:

Two destinations, two formats: people read the console, and the aggregator parses the JSON file.
Different levels per destination: the console at INFO keeps the terminal readable, and the file at DEBUG keeps full detail for investigating problems later.
propagate=False: without it, records would also be passed up to the root logger, and if root has its own handlers, you'd get duplicate lines. It is an extra safety measure.
Daily rotation, keeping 30 days: no manual cleanup, and the logs can't fill the disk.
Quieter third-party libraries: messages from urllib3 and botocore don't hide your own.

You'd extend this with: a correlation-ID filter (Section 13), a redactor filter for secrets (Section 12), and a separate error.log handler at ERROR for fast triage. These are all optional, and this setup is a good base for production.

What You Learned

Loggers receive records, handlers send them to a destination, formatters turn them into text, and levels filter them. A record must pass both the logger's and the handler's level check.
Module-level logger = logging.getLogger(__name__) at the top of every module. Configure handlers once, in the entry point.
Choose levels carefully: INFO for normal, WARNING for weird, ERROR for failed, CRITICAL for down.
logger.exception(msg) inside except records the traceback. Always use it there.
logging.config.dictConfig is the production setup. You can load the dict from JSON or YAML.
Always rotate log files with RotatingFileHandler or TimedRotatingFileHandler.
Lazy %s formatting in hot paths. Check isEnabledFor for expensive payloads.
Quieten noisy dependencies: logging.getLogger("urllib3").setLevel(logging.WARNING).
JSON logs for aggregators: python-json-logger or structlog.
breakpoint() drops into PDB, where you use n, s, c, l, p, w and q.
Don't log secrets. Build a redact() helper, and assume logs are public.

Next: Testing with pytest. Logs tell you what broke, and tests check that your code does what it should.

1 · The lesson

1. How It Works: Four Pieces

2. Levels: Use Them Right

3. Basic Setup: `logging.basicConfig`

4. Real Setup: Module-Level Loggers

5. Handlers: Where Records Go

6. Formatters: What Each Line Shows

7. Lazy Formatting: The `%s` Habit

8. `logger.exception`: Always Use It Inside `except`

9. Production Pattern: `dictConfig`

10. Structured Logging: JSON for Aggregators

11. Per-Module Levels and Quietening Dependencies

12. Don't Log Secrets

13. Correlation IDs: Tracing One Request Across Many Logs

14. Debugging Beyond Logs: `breakpoint()`

15. Common Mistakes

🎯 Your Turn: `setup_logging`

What You Learned

Practice this

Logging & Debugging: Beyond print()

1. How It Works: Four Pieces

2. Levels: Use Them Right

3. Basic Setup: logging.basicConfig

4. Real Setup: Module-Level Loggers

5. Handlers: Where Records Go

6. Formatters: What Each Line Shows

7. Lazy Formatting: The %s Habit

8. logger.exception: Always Use It Inside except

9. Production Pattern: dictConfig

10. Structured Logging: JSON for Aggregators

11. Per-Module Levels and Quietening Dependencies

12. Don't Log Secrets

13. Correlation IDs: Tracing One Request Across Many Logs

14. Debugging Beyond Logs: breakpoint()

15. Common Mistakes

🎯 Your Turn: setup_logging

What You Learned

3. Basic Setup: `logging.basicConfig`

7. Lazy Formatting: The `%s` Habit

8. `logger.exception`: Always Use It Inside `except`

9. Production Pattern: `dictConfig`

14. Debugging Beyond Logs: `breakpoint()`

🎯 Your Turn: `setup_logging`