{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Avoid common logging mistakes\n",
    "\n",
    "**The question.** Log messages are missing, duplicated, or expensive to produce — and you can't work out why. Something in the configuration is fighting you. You want the short list of traps and the fix for each.\n",
    "\n",
    "The answer: use `%s` formatting (not f-strings), configure once at the entry point (never in libraries), log exceptions with `logger.exception`, and watch out for the logger-vs-handler level gotcha. The full catalogue follows.\n"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "# The canonical logger setup plus the four most common traps in one cell.\n",
    "import logging\n",
    "\n",
    "# (1) Module-level named logger — always __name__ in real code. One per module.\n",
    "log = logging.getLogger('demo-module')\n",
    "log.setLevel(logging.DEBUG)\n",
    "\n",
    "# We add a handler just so this cell shows output; in real code the app does this once.\n",
    "if not log.handlers:\n",
    "    h = logging.StreamHandler()\n",
    "    h.setFormatter(logging.Formatter('%(name)s - %(levelname)s: %(message)s'))\n",
    "    log.addHandler(h)\n",
    "    log.propagate = False         # don't duplicate via root\n",
    "\n",
    "expensive_value = sum(range(1000))\n",
    "\n",
    "# (2) %s formatting, not f-strings — the args aren't formatted unless the record\n",
    "#     will actually be emitted. f-strings format eagerly and cost you even when\n",
    "#     the level is filtered out.\n",
    "log.debug('computed value: %s', expensive_value)   # lazy\n",
    "# log.debug(f'computed value: {expensive_value}')  # eager — avoid\n",
    "\n",
    "# (3) Log exceptions with .exception() — it captures the traceback. Plain .error()\n",
    "#     gives you the message without the stack, which is almost always the wrong call\n",
    "#     when there's a live exception.\n",
    "try:\n",
    "    1 / 0\n",
    "except ZeroDivisionError:\n",
    "    log.exception('division failed')    # == log.error(msg, exc_info=True)\n",
    "\n",
    "# (4) Guard handler setup so repeated configuration doesn't create duplicates.\n",
    "#     `if not log.handlers:` above does this for the cell; dictConfig with\n",
    "#     `disable_existing_loggers: False` does it at the app level.\n",
    "log.info('message appears exactly once')\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Why each trap bites\n",
    "\n",
    "**f-strings vs %-args.** `log.debug(f'{expensive()}')` runs `expensive()` every time, even when the logger's level is WARNING and the message will never be emitted. `log.debug('%s', expensive())` *also* runs `expensive()` — but `log.debug('user %s logged in', user_id)` does not format the string unless the record is actually kept. The difference matters mostly for format calls with real expense (a `repr()` of a big structure, a DB roundtrip for a label). Default to `%s`.\n",
    "\n",
    "**Libraries don't configure.** A library that calls `logging.basicConfig()` fights with the application for control. The convention is: library creates a logger with `getLogger(__name__)` and optionally attaches a `NullHandler` to suppress the 'no handlers' warning. The app decides what to do with those records.\n",
    "\n",
    "**`logger.exception` vs `logger.error`.** `exception` is `error` + `exc_info=True`. Inside an `except` block you almost always want the traceback — that's the diagnostic you'll come back to at 3 a.m.\n",
    "\n",
    "**Logger level AND handler level.** Both gates must open for a record to emerge. A handler at DEBUG on a logger whose level is still WARNING (the default, inherited from root) won't show DEBUG messages. Set the logger's level explicitly.\n",
    "\n",
    "**Don't use the root logger directly.** `logging.info(...)` writes via the root logger and doesn't tell you which module produced it. Named loggers (via `__name__`) make the source obvious in every line.\n",
    "\n",
    "**Duplicate handlers.** Calling a `setup_logging()` helper twice adds two handlers; every message now appears twice. Guard with `if not logger.handlers:`, or configure once via `dictConfig` at startup.\n",
    "\n",
    "**Don't log secrets.** Log files end up in backups, monitoring systems, bug reports, emails. Passwords, API keys, full request bodies — assume they'll be seen by someone who shouldn't have them.\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Checklist\n",
    "\n",
    "| Do | Do not |\n",
    "| --- | --- |\n",
    "| `log.info('user %s done', user_id)` | `log.info(f'user {user_id} done')` |\n",
    "| Configure once at the app entry point | Configure inside a library |\n",
    "| `log.exception('blew up')` inside `except` | `log.error('blew up')` — no traceback |\n",
    "| `logging.getLogger(__name__)` | `logging.info(...)` directly |\n",
    "| Set both the logger level and the handler level | Set only one and wonder why DEBUGs vanish |\n",
    "| Guard handler setup with `if not log.handlers:` | Add handlers unconditionally |\n",
    "| Redact or omit sensitive fields | Log passwords, tokens, PII |\n",
    "\n",
    "Each of these is a pattern. For the rare case where the default doesn't fit — an app that really does log every call via the root logger on purpose, say — it's fine. The traps bite when the shortcut is applied reflexively.\n"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Related reading\n",
    "\n",
    "- [Configure logging for a project](https://agilearn.co.uk/guides/logging-and-debugging/recipes/configure-logging-for-a-project) — the `dictConfig` shape that solves the 'configure once' and 'no duplicates' traps together.\n",
    "- [Create custom log handlers](https://agilearn.co.uk/guides/logging-and-debugging/recipes/create-custom-log-handlers) — when you need a destination the built-ins don't cover.\n",
    "- [Understanding log levels](https://agilearn.co.uk/guides/logging-and-debugging/concepts/understanding-log-levels) — what DEBUG/INFO/WARNING/ERROR should actually mean.\n",
    "- [Why logging, not print](https://agilearn.co.uk/guides/logging-and-debugging/concepts/why-logging-not-print) — when to reach for the log and when not to.\n"
   ]
  }
 ],
 "metadata": {
  "kernelspec": {
   "display_name": "Python 3 (ipykernel)",
   "language": "python",
   "name": "python3"
  },
  "language_info": {
   "name": "python",
   "version": "3.12.0"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 5
}