{ "cells": [ { "cell_type": "markdown", "id": "0", "metadata": {}, "source": [ "---\n", "title: \"Part 21: Logging for ML Projects\"\n", "---" ] }, { "cell_type": "markdown", "id": "1", "metadata": {}, "source": [ "[![Open In Colab](https://colab.research.google.com/assets/colab-badge.svg)](https://colab.research.google.com/github/sambaiga/ds-mlops-path/blob/main/tutorials/02-dev-tools/09-logging.ipynb) [![Download Notebook](https://img.shields.io/badge/Download-Notebook-blue.svg?logo=jupyter&logoColor=white)](https://raw.githubusercontent.com/sambaiga/ds-mlops-path/main/tutorials/02-dev-tools/09-logging.ipynb)" ] }, { "cell_type": "markdown", "id": "2", "metadata": {}, "source": [ "**DS-MLOps Dev Tools**\n", "\n", "**Python 3.12+ | Author: Anthony Faustine**\n", "\n", "## Before you begin\n", "\n", "This notebook assumes you have completed [Part 19: Data Validation with Pydantic](07-pydantic-validation.ipynb). Logging is the complement to validation: Pydantic stops bad data at the boundary; logging tells you what happened after it was let in.\n", "\n", "The `grade-predictor` project appears throughout as a concrete reference. You will see how a library, an experiment script, a production API, and a notebook each use a different tool from the same logging ecosystem.\n", "\n", "> Callout markers used throughout this notebook are explained on the [book cover page](../../index.qmd#callout-guide).\n", "\n", "::: {.callout-note collapse=\"true\" icon=false}\n", "## Topics covered\n", "\n", "| Topic | Why it matters |\n", "| --- | --- |\n", "| **Python logging hierarchy** | Understand loggers, handlers, formatters as one system |\n", "| **NullHandler pattern** | Write library code that never hijacks the caller |\n", "| **Handlers and formatters** | Route logs to console and file with different detail levels |\n", "| **LogContext and log_section** | Attach context to a block of calls without string formatting |\n", "| **Loguru** | Experiment scripts with half the boilerplate |\n", "| **structlog** | Structured JSON logs for production services |\n", "| **Rich handler** | Beautiful notebook and CLI output |\n", ":::" ] }, { "cell_type": "markdown", "id": "3", "metadata": {}, "source": [ "::: {.callout-note collapse=\"true\" icon=false}\n", "## Learning Objectives\n", "\n", "By the end of Part 21 you will be able to:\n", "\n", "| # | Skill | Covered in |\n", "| --- | --- | --- |\n", "| 1 | Explain why `print()` is not a substitute for logging in production code | Sec. 0 |\n", "| 2 | Use `get_logger(__name__)` and `NullHandler` to write library-safe logging | Sec. 2 |\n", "| 3 | Build a `configure()` function with colour console and file handlers | Sec. 3 |\n", "| 4 | Attach per-call context with `LogContext` and mark pipeline stages with `log_section` | Sec. 4 |\n", "| 5 | Replace stdlib ceremony with loguru in experiment scripts | Sec. 5 |\n", "| 6 | Emit structured JSON logs with structlog for production services | Sec. 6 |\n", "| 7 | Drop in `RichHandler` for pretty notebook output | Sec. 7 |\n", "| 8 | Choose the right tool for each layer of an ML project | Sec. 8 |\n", ":::" ] }, { "cell_type": "markdown", "id": "4", "metadata": {}, "source": [ "## 0. The Print That Vanished\n", "\n", "It is 11 PM. A 12-hour cross-validation run finishes. You open the terminal to check results. There is nothing there, because the window scrolled past the output hours ago. You did not redirect stdout to a file. Fold 3 crashed with a shape mismatch, silently recovered to a default, and corrupted the metric average. You have no record of when it happened, which model it was, or what the stack trace said.\n", "\n", "This is the `print()` problem. It is not that `print()` is slow or ugly. It is that `print()` has no:\n", "\n", "- **Severity**: you cannot ask \"show me only errors\" after the fact\n", "- **Routing**: you cannot send errors to a file while keeping the console quiet\n", "- **Timestamps**: you cannot tell which fold took 40 minutes\n", "- **Persistence**: if the terminal closes, the output is gone\n", "- **Silencing**: you cannot turn off a dependency's output without patching its source\n", "\n", "Python's logging module solves all five. You do not need to replace every `print()` with a log call. You need to understand when you are debugging versus when you are operating, and log accordingly.\n", "\n", "### Install\n", "\n", "Python's `logging` module is stdlib. The other tools used in this notebook:\n", "\n", "```bash\n", "uv add loguru structlog rich\n", "```" ] }, { "cell_type": "markdown", "id": "5", "metadata": {}, "source": [ "## 1. Python's Logging Hierarchy" ] }, { "cell_type": "raw", "id": "6", "metadata": { "raw_mimetype": "text/markdown" }, "source": [ "```{mermaid}\n", "flowchart LR\n", " A[\"your code\\nlog.info('Computing grades')\"] --> B[\"Logger\\n'grade_predictor.core'\"]\n", " B -->|\"propagate=True\"| C[\"Logger\\n'grade_predictor'\"]\n", " C -->|\"propagate=True\"| D[\"Logger\\n'' (root)\"]\n", " D --> E[\"Handler\\nStreamHandler / FileHandler\"]\n", " E --> F[\"Formatter\\n'%(asctime)s %(levelname)s %(message)s'\"]\n", " F --> G[\"output\\nconsole / file\"]\n", "\n", " style A fill:#EAF3FA,stroke:#0369A1,color:#0C4A6E\n", " style B fill:#F5F3FF,stroke:#7C3AED,color:#3B0764\n", " style G fill:#EBF5F0,stroke:#059669,color:#065F46\n", "```" ] }, { "cell_type": "markdown", "id": "7", "metadata": {}, "source": [ "Python's logging system has four objects that work together as one pipeline:\n", "\n", "- **Logger**: the object your code calls (`log.info(...)`, `log.warning(...)`). Every logger has a name, typically `__name__`, which creates a dotted hierarchy: `grade_predictor.core` is a child of `grade_predictor`, which is a child of the root logger.\n", "- **Handler**: decides where a log record goes: console, file, HTTP endpoint. A logger can have multiple handlers.\n", "- **Formatter**: decides how a record looks: plain text, JSON, coloured terminal output.\n", "- **Level**: a numeric threshold (`DEBUG=10`, `INFO=20`, `WARNING=30`, `ERROR=40`, `CRITICAL=50`). Records below the threshold are discarded.\n", "\n", "The key insight is **propagation**: when `grade_predictor.core` logs a record, it walks up the hierarchy towards the root logger, passing the record to every handler it encounters. This means:\n", "\n", "- The same `log.info(\"Computing grades\")` inside `grade_predictor.core` can reach a console handler on the root logger AND a file handler on `grade_predictor`, with different formatters on each\n", "- A caller can silence `grade_predictor.core` by setting its level to `CRITICAL`, without touching any code inside the library\n", "- A library can opt out of all output by default, leaving every routing decision to the caller\n", "\n", "Here is the minimal configuration most tutorials show first:" ] }, { "cell_type": "code", "execution_count": null, "id": "8", "metadata": {}, "outputs": [], "source": [ "import logging\n", "\n", "# basicConfig attaches a StreamHandler to the root logger\n", "logging.basicConfig(level=logging.INFO, format=\"%(asctime)s %(levelname)s %(message)s\")\n", "\n", "log = logging.getLogger(__name__)\n", "log.info(\"Training started\")\n", "log.warning(\"Fold 3 has only 12 samples\")\n", "log.debug(\"This is below INFO threshold -- not shown\")" ] }, { "cell_type": "markdown", "id": "9", "metadata": {}, "source": [ "This works for a script you run yourself. The problem is `basicConfig()`. It configures the **root logger** at import time, which means every library in your Python process that uses `logging` will suddenly emit output through your format. Section 2 explains why library code must never call it." ] }, { "cell_type": "markdown", "id": "10", "metadata": {}, "source": [ "## 2. The Library/Application Boundary" ] }, { "cell_type": "raw", "id": "11", "metadata": { "raw_mimetype": "text/markdown" }, "source": [ "```{mermaid}\n", "flowchart LR\n", " subgraph lib [\"Library side (grade_predictor, any pip package)\"]\n", " L1[\"logging.getLogger(__name__)\"]\n", " L2[\"NullHandler\\n(silent by default)\"]\n", " L1 --> L2\n", " end\n", " subgraph app [\"Application side (script, notebook, service)\"]\n", " A1[\"configure()\\ncalled once at startup\"]\n", " A2[\"StreamHandler\\n+ ColourFormatter\"]\n", " A3[\"FileHandler\\n+ PlainFormatter\"]\n", " A1 --> A2\n", " A1 --> A3\n", " end\n", " lib -->|\"log records propagate\"| app\n", "\n", " style lib fill:#FEF2F2,stroke:#DC2626,color:#991B1B\n", " style app fill:#EBF5F0,stroke:#059669,color:#065F46\n", "```" ] }, { "cell_type": "markdown", "id": "12", "metadata": {}, "source": [ "The single most important rule in Python logging is the **library/application boundary**.\n", "\n", "A **library** is any code you publish as a package: `grade_predictor`, or any pip-installable project. Its job is to be imported and used. It should never decide where its log output goes, because its caller's environment is unknown. The correct pattern at the library level:\n", "\n", "1. In `__init__.py`, add a `NullHandler` to the top-level logger. This silences the \"No handler found\" warning without emitting any actual output.\n", "2. In every module, use `logging.getLogger(__name__)` to get a logger named after the module's dotted path.\n", "3. Never call `logging.basicConfig()` anywhere in library code.\n", "\n", "An **application** is code you run: a training script, a notebook, a FastAPI service. It owns the process and decides where logs go. It calls `configure()` once at startup to attach real handlers.\n", "\n", "Here is how `grade_predictor` would be structured:" ] }, { "cell_type": "code", "execution_count": null, "id": "13", "metadata": {}, "outputs": [], "source": [ "import logging\n", "\n", "# grade_predictor/__init__.py -- the only NullHandler call in the entire library\n", "logging.getLogger(\"grade_predictor\").addHandler(logging.NullHandler())\n", "\n", "\n", "# grade_predictor/core.py -- every module gets its own logger\n", "log = logging.getLogger(\"grade_predictor.core\")\n", "\n", "\n", "def fit(X, y):\n", " log.info(\"Fitting model on %d samples\", len(X))\n", " # ... training logic ...\n", " log.debug(\"Gradient norm: %.4f\", 0.0023) # detail only visible at DEBUG level\n", " log.info(\"Fit complete\")\n", "\n", "\n", "# Without configure(), this produces no output -- the NullHandler swallows everything\n", "fit([1, 2, 3], [0, 1, 0])" ] }, { "cell_type": "markdown", "id": "14", "metadata": {}, "source": [ "
\n", " Common Mistake: Calling basicConfig() inside a library module

\n", "Calling logging.basicConfig() inside a library module silently configures the root logger the moment the library is imported. Every other library and application in the same process suddenly emits output through your format, at your level, with no way for the caller to undo it without reaching into your code. This is one of the most common complaints about Python logging in third-party packages. The fix is one line: logging.getLogger(\"yourlib\").addHandler(logging.NullHandler()) in __init__.py, and nothing else.\n", "
" ] }, { "cell_type": "markdown", "id": "15", "metadata": {}, "source": [ "## 3. Handlers and Formatters\n", "\n", "Now we are on the application side. The application calls `configure()` once. `configure()` attaches real handlers to the root logger (or to a named logger like `grade_predictor`) so that all log records from the library flow through.\n", "\n", "A useful pattern is two handlers: a `StreamHandler` for the console with colour and brevity, and a `FileHandler` for the log file with full detail including timestamps and module names.\n", "\n", "The `_ColourFormatter` below uses ANSI escape codes. It checks whether stdout is a real TTY before applying colour, so that redirected output to a file or CI log stays clean:" ] }, { "cell_type": "code", "execution_count": null, "id": "16", "metadata": {}, "outputs": [], "source": [ "import logging\n", "import sys\n", "\n", "LEVEL_COLOURS = {\n", " \"DEBUG\": \"\\033[36m\", # cyan\n", " \"INFO\": \"\\033[32m\", # green\n", " \"WARNING\": \"\\033[33m\", # yellow\n", " \"ERROR\": \"\\033[31m\", # red\n", " \"CRITICAL\": \"\\033[35m\", # magenta\n", "}\n", "RESET = \"\\033[0m\"\n", "\n", "\n", "class _ColourFormatter(logging.Formatter):\n", " \"\"\"Console formatter: colour level name when stdout is a TTY.\"\"\"\n", "\n", " _is_tty: bool = sys.stdout.isatty()\n", "\n", " def format(self, record: logging.LogRecord) -> str:\n", " if self._is_tty:\n", " colour = LEVEL_COLOURS.get(record.levelname, \"\")\n", " record.levelname = f\"{colour}{record.levelname:<8}{RESET}\"\n", " else:\n", " record.levelname = f\"{record.levelname:<8}\"\n", " return super().format(record)\n", "\n", "\n", "class _PlainFormatter(logging.Formatter):\n", " \"\"\"File formatter: full detail, no colour codes.\"\"\"\n", "\n", " pass\n", "\n", "\n", "def configure(\n", " level: int = logging.INFO,\n", " log_file: str | None = None,\n", " file_level: int = logging.DEBUG,\n", ") -> None:\n", " \"\"\"Attach handlers to the root logger. Call once at application startup.\"\"\"\n", " root = logging.getLogger()\n", " root.setLevel(logging.DEBUG) # let handlers decide their own threshold\n", "\n", " # Console handler\n", " console = logging.StreamHandler(sys.stdout)\n", " console.setLevel(level)\n", " console.setFormatter(_ColourFormatter(fmt=\"%(levelname)s %(name)s: %(message)s\"))\n", " root.addHandler(console)\n", "\n", " # Optional file handler\n", " if log_file:\n", " fh = logging.FileHandler(log_file)\n", " fh.setLevel(file_level)\n", " fh.setFormatter(\n", " _PlainFormatter(\n", " fmt=\"%(asctime)s %(levelname)-8s %(name)s %(funcName)s: %(message)s\",\n", " datefmt=\"%Y-%m-%dT%H:%M:%S\",\n", " )\n", " )\n", " root.addHandler(fh)" ] }, { "cell_type": "code", "execution_count": null, "id": "17", "metadata": {}, "outputs": [], "source": [ "# Reset any existing handlers from the basicConfig call in Sec 1\n", "logging.getLogger().handlers.clear()\n", "\n", "configure(level=logging.INFO, log_file=\"training.log\")\n", "\n", "log = logging.getLogger(\"grade_predictor.core\")\n", "log.info(\"Training started\")\n", "log.warning(\"Fold 3 has only 12 samples\")\n", "log.debug(\"Hidden from console (INFO threshold), captured in file\")\n", "log.error(\"Fold 3 failed: shape mismatch (32, 10) vs (32, 8)\")" ] }, { "cell_type": "markdown", "id": "18", "metadata": {}, "source": [ "
\n", " Pro Tip: Set root to DEBUG and let handlers filter

\n", "Setting root.setLevel(logging.DEBUG) and applying level thresholds on the individual handlers means you only need one configure() call to achieve: console shows INFO and above, file captures everything from DEBUG upwards. If you set the root level to INFO instead, DEBUG records are discarded before they reach any handler, even the file handler that wanted them. Always set the root to the lowest level any handler needs.\n", "
" ] }, { "cell_type": "markdown", "id": "19", "metadata": {}, "source": [ "## 4. Attaching Context Without Touching Every Log Call\n", "\n", "Imagine a cross-validation loop. Each fold runs the same `fit()` function. When something goes wrong, you want every log line inside fold 2 to say `fold=2`. The naive approach: add `fold=2` to every `log.info()` call inside the loop. This is repetitive and error-prone.\n", "\n", "A better approach is a context manager that patches the logger's filter for the duration of a block. Python's `logging.LogRecord` supports an `extra` dict for exactly this purpose.\n", "\n", "`LogContext` below uses `logging.Filter` to inject key-value pairs into every record emitted during the `with` block, without changing a single call site:" ] }, { "cell_type": "code", "execution_count": null, "id": "20", "metadata": {}, "outputs": [], "source": [ "from collections.abc import Generator\n", "from contextlib import contextmanager\n", "import logging\n", "from typing import Any\n", "\n", "\n", "class _ContextFilter(logging.Filter):\n", " \"\"\"Injects extra key-value pairs into every record that passes through.\"\"\"\n", "\n", " def __init__(self, **kwargs: Any) -> None:\n", " super().__init__()\n", " self._context = kwargs\n", "\n", " def filter(self, record: logging.LogRecord) -> bool:\n", " for key, value in self._context.items():\n", " setattr(record, key, value)\n", " return True\n", "\n", "\n", "@contextmanager\n", "def log_context(logger: logging.Logger, **kwargs: Any) -> Generator[None, None, None]:\n", " \"\"\"Context manager: inject key-value pairs into every log record in the block.\"\"\"\n", " f = _ContextFilter(**kwargs)\n", " logger.addFilter(f)\n", " try:\n", " yield\n", " finally:\n", " logger.removeFilter(f)\n", "\n", "\n", "@contextmanager\n", "def log_section(logger: logging.Logger, name: str) -> Generator[None, None, None]:\n", " \"\"\"Mark the start and end of a named pipeline stage.\"\"\"\n", " logger.info(\"[START] %s\", name)\n", " try:\n", " yield\n", " except Exception:\n", " logger.exception(\"[FAIL] %s\", name)\n", " raise\n", " else:\n", " logger.info(\"[END] %s\", name)" ] }, { "cell_type": "code", "execution_count": null, "id": "21", "metadata": {}, "outputs": [], "source": [ "# Demonstrate LogContext: every log line inside the with-block carries fold and model\n", "logging.getLogger().handlers.clear()\n", "\n", "# Use a formatter that shows the extra fields\n", "root = logging.getLogger()\n", "root.setLevel(logging.DEBUG)\n", "handler = logging.StreamHandler()\n", "handler.setFormatter(logging.Formatter(\"%(levelname)-8s %(name)s [fold=%(fold)s model=%(model)s]: %(message)s\"))\n", "root.addHandler(handler)\n", "\n", "log = logging.getLogger(\"grade_predictor.core\")\n", "\n", "for fold in range(1, 4):\n", " with log_context(log, fold=fold, model=\"MLP\"), log_section(log, f\"fold-{fold}\"):\n", " log.info(\"Loading data\")\n", " log.info(\"Fitting model\")\n", " log.info(\"Evaluating metrics\")" ] }, { "cell_type": "markdown", "id": "22", "metadata": {}, "source": [ "
\n", " Activity 1 - LogContext in a Training Loop

\n", "Goal: Write a function train_fold(fold: int, epochs: int, model_name: str) -> None that simulates training by logging one line per epoch. Wrap the function body in a LogContext so that every log line automatically carries fold, model, and epochs. Call it for folds 1 and 2 with model \"LSTM\" and confirm the context fields appear in every line.\n", "
log = logging.getLogger(\"grade_predictor.core\")\n",
    "\n",
    "def train_fold(fold: int, epochs: int, model_name: str) -> None:\n",
    "    with LogContext(log, fold=fold, model=model_name, epochs=epochs):\n",
    "        for epoch in range(1, epochs + 1):\n",
    "            log.info(\"epoch %d complete\", epoch)
\n", "
" ] }, { "cell_type": "code", "execution_count": null, "id": "23", "metadata": {}, "outputs": [], "source": [ "# TODO: implement train_fold and call it for fold=1 and fold=2\n" ] }, { "cell_type": "markdown", "id": "24", "metadata": {}, "source": [ "## 5. Loguru: Less Ceremony for Your Own Code" ] }, { "cell_type": "raw", "id": "25", "metadata": { "raw_mimetype": "text/markdown" }, "source": [ "```{mermaid}\n", "flowchart LR\n", " subgraph stdlib [\"stdlib approach\"]\n", " S1[\"getLogger(__name__)\"]\n", " S2[\"addHandler(NullHandler)\"]\n", " S3[\"configure()\\n(20 lines)\"]\n", " S4[\"LogContext(log, fold=2)\"]\n", " S1 --> S2 --> S3 --> S4\n", " end\n", " subgraph loguru [\"loguru approach\"]\n", " L1[\"from loguru import logger\"]\n", " L2[\"logger.add('run.log',\\nenqueue=True)\"]\n", " L3[\"logger.bind(fold=2, model='MLP')\"]\n", " L1 --> L2 --> L3\n", " end\n", "\n", " style stdlib fill:#FEF2F2,stroke:#DC2626,color:#991B1B\n", " style loguru fill:#EBF5F0,stroke:#059669,color:#065F46\n", "```" ] }, { "cell_type": "markdown", "id": "26", "metadata": {}, "source": [ "The stdlib approach works, but it is verbose. For experiment scripts that you run yourself, `loguru` ([loguru.readthedocs.io](https://loguru.readthedocs.io/)) replaces all of it with a single import and a one-liner sink configuration.\n", "\n", "Loguru's `logger` is a pre-configured singleton. You call `logger.add()` to attach sinks (files, functions, external services). You call `logger.bind()` to attach context. You use `@logger.catch` to automatically log and suppress exceptions from a function.\n", "\n", "Here is the same experiment loop from Section 4, rewritten with loguru:" ] }, { "cell_type": "code", "execution_count": null, "id": "27", "metadata": {}, "outputs": [], "source": [ "from loguru import logger\n", "\n", "# Remove loguru's default stderr sink, add a file sink and a stdout sink\n", "logger.remove()\n", "logger.add(\"experiment.log\", level=\"DEBUG\", rotation=\"10 MB\")\n", "logger.add(\n", " lambda msg: print(msg, end=\"\"), # custom sink: print to stdout\n", " level=\"INFO\",\n", " format=\"{time:HH:mm:ss} {level:<8} fold={extra[fold]} model={extra[model]}: {message}\",\n", ")\n", "\n", "\n", "@logger.catch(reraise=False)\n", "def train_fold_loguru(fold: int, model: str = \"MLP\") -> float:\n", " \"\"\"Simulate one fold. @logger.catch logs any exception automatically.\"\"\"\n", " bound = logger.bind(fold=fold, model=model)\n", " bound.info(\"Starting fold\")\n", " for epoch in range(1, 4):\n", " bound.debug(\"Epoch {} complete\", epoch)\n", " if fold == 2:\n", " raise ValueError(\"Shape mismatch in fold 2\")\n", " bound.info(\"Fold complete\")\n", " return 0.92\n", "\n", "\n", "for fold_id in range(1, 4):\n", " train_fold_loguru(fold=fold_id)" ] }, { "cell_type": "markdown", "id": "28", "metadata": {}, "source": [ "
\n", " Common Mistake: Using loguru in a library you publish

\n", "Loguru's logger is a global singleton shared across your entire process. If you use it inside a library (grade_predictor, ark, any package you pip-install), your library will emit log output the moment it is imported, in your format, at your level, with no way for the caller to silence it. This is the same problem as calling basicConfig() in a library, but worse because loguru does not integrate with the stdlib propagation chain. Use loguru only in code you run yourself: scripts, notebooks, and applications you own end to end.\n", "
" ] }, { "cell_type": "markdown", "id": "29", "metadata": {}, "source": [ "## 6. Structured Logging for Production\n", "\n", "A loguru experiment log is a text file. It is readable by humans and `grep`. For a FastAPI serving endpoint, that is not enough. An ops team needs to query logs by `model_version`, correlate a request across services using `request_id`, and alert on `latency_ms > 500`. None of these are possible with string logs.\n", "\n", "**structlog** ([structlog.readthedocs.io](https://www.structlog.org/en/stable/)) solves this by treating log records as dicts first and strings second. Every `log.info(\"prediction\", model_version=\"v2\", latency_ms=42)` produces a JSON line that Datadog, CloudWatch, and Loki can index natively.\n", "\n", "The design of structlog separates three concerns:\n", "\n", "- **Processors**: a pipeline of functions that transform the event dict (add timestamps, add log level, call stack info)\n", "- **Renderer**: the final processor that turns the dict into a string (JSON for production, pretty-printed for development)\n", "- **Bound loggers**: carry context across calls without re-stating it" ] }, { "cell_type": "code", "execution_count": null, "id": "30", "metadata": {}, "outputs": [], "source": [ "import logging\n", "import time\n", "\n", "import structlog\n", "\n", "# stdlib backend: PrintLoggerFactory has no .name attribute, so add_logger_name\n", "# requires LoggerFactory (wraps logging.Logger which does have .name)\n", "logging.getLogger().handlers.clear()\n", "logging.basicConfig(level=logging.DEBUG, format=\"%(message)s\", force=True)\n", "\n", "structlog.configure(\n", " processors=[\n", " structlog.stdlib.add_log_level,\n", " structlog.stdlib.add_logger_name,\n", " structlog.processors.TimeStamper(fmt=\"iso\"),\n", " structlog.processors.StackInfoRenderer(),\n", " structlog.processors.JSONRenderer(),\n", " ],\n", " wrapper_class=structlog.stdlib.BoundLogger,\n", " context_class=dict,\n", " logger_factory=structlog.stdlib.LoggerFactory(),\n", ")\n", "\n", "slog = structlog.get_logger(\"prediction_service\")\n", "\n", "\n", "def compute_grade_api(request_id: str, model_version: str, student_id: str) -> dict:\n", " \"\"\"Simulate a grading API endpoint. Every log line carries request context.\"\"\"\n", " bound = slog.bind(request_id=request_id, model_version=model_version, student_id=student_id)\n", " bound.info(\"grade_start\")\n", "\n", " t0 = time.perf_counter()\n", " score = 78.5 # placeholder: real logic reads from DB\n", " latency_ms = round((time.perf_counter() - t0) * 1000, 2)\n", "\n", " bound.info(\"grade_complete\", score=round(score, 4), latency_ms=latency_ms)\n", " return {\"student_id\": student_id, \"score\": score, \"model_version\": model_version}\n", "\n", "\n", "compute_grade_api(\"req-abc123\", \"grade-predictor-v1\", \"S0042\")" ] }, { "cell_type": "markdown", "id": "31", "metadata": {}, "source": [ "
\n", " Key Concept: structlog separates processors from renderers

\n", "The processors list is a pipeline: each processor receives the event dict, transforms it, and passes it on. The last processor is the renderer. To switch from JSON (production) to pretty-printed console output (development), swap only the last processor: structlog.dev.ConsoleRenderer() instead of structlog.processors.JSONRenderer(). Nothing else in your code changes, because the calling convention (log.info(\"event\", key=value)) is identical regardless of output format.\n", "
" ] }, { "cell_type": "markdown", "id": "32", "metadata": {}, "source": [ "## 7. Rich Handler: The Notebook Layer\n", "\n", "Everything above assumes a terminal or a file. In Jupyter, `logging.StreamHandler` writes plain text to the notebook's output cell. There are no colours, no traceback formatting, no syntax highlighting.\n", "\n", "`RichHandler` from the `rich` library drops into stdlib logging in one line. It renders log records with colour, aligns level names, pretty-prints tracebacks with source context, and respects the notebook's display environment.\n", "\n", "Here is a before/after comparison:" ] }, { "cell_type": "code", "execution_count": null, "id": "33", "metadata": {}, "outputs": [], "source": [ "import logging\n", "\n", "# Before: plain StreamHandler output in a notebook\n", "logging.getLogger().handlers.clear()\n", "plain_handler = logging.StreamHandler()\n", "plain_handler.setFormatter(logging.Formatter(\"%(levelname)s %(name)s: %(message)s\"))\n", "logging.getLogger().addHandler(plain_handler)\n", "logging.getLogger().setLevel(logging.DEBUG)\n", "\n", "log = logging.getLogger(\"grade_predictor.core\")\n", "log.info(\"plain handler: training started\")\n", "log.warning(\"plain handler: fold 3 has 12 samples\")\n", "\n", "\n", "def _bad_op():\n", " raise ValueError(\"Shape mismatch (32, 10) vs (32, 8)\")\n", "\n", "\n", "try:\n", " _bad_op()\n", "except ValueError:\n", " log.exception(\"plain handler: fold 3 failed\")" ] }, { "cell_type": "code", "execution_count": null, "id": "34", "metadata": {}, "outputs": [], "source": [ "import logging\n", "\n", "from rich.logging import RichHandler\n", "\n", "# After: RichHandler -- drop-in replacement, one line change\n", "logging.getLogger().handlers.clear()\n", "logging.basicConfig(\n", " level=logging.DEBUG,\n", " format=\"%(message)s\",\n", " datefmt=\"[%X]\",\n", " handlers=[RichHandler(rich_tracebacks=True, markup=True)],\n", ")\n", "\n", "log = logging.getLogger(\"grade_predictor.core\")\n", "log.info(\"rich handler: training started\")\n", "log.warning(\"rich handler: fold 3 has 12 samples\")\n", "\n", "\n", "def _bad_op():\n", " raise ValueError(\"Shape mismatch (32, 10) vs (32, 8)\")\n", "\n", "\n", "try:\n", " _bad_op()\n", "except ValueError:\n", " log.exception(\"rich handler: fold 3 failed\")" ] }, { "cell_type": "markdown", "id": "35", "metadata": {}, "source": [ "
\n", " Pro Tip: Use RichHandler only in notebooks and scripts, not in library code

\n", "RichHandler is a stdlib logging.Handler subclass, so it obeys the library/application boundary perfectly: add it in your configure() call (application side) and never in library code. For notebooks, the simplest setup is logging.basicConfig(handlers=[RichHandler(rich_tracebacks=True)]) at the top of your notebook. This replaces the default handler and gives you pretty output for the rest of the session.\n", "
" ] }, { "cell_type": "markdown", "id": "36", "metadata": {}, "source": [ "## 8. One Project, Four Layers" ] }, { "cell_type": "raw", "id": "37", "metadata": { "raw_mimetype": "text/markdown" }, "source": [ "```{mermaid}\n", "flowchart TD\n", " subgraph lib [\"Library code (grade_predictor)\"]\n", " L1[\"stdlib logging\\n+ NullHandler\\nSilent by default\"]\n", " end\n", " subgraph exp [\"Experiment scripts\"]\n", " E1[\"loguru\\nLow ceremony\\nRich context binding\"]\n", " end\n", " subgraph prod [\"Production API / MLOps pipeline\"]\n", " P1[\"structlog\\nStructured JSON\\nTraceable request IDs\"]\n", " end\n", " subgraph nb [\"Notebooks\"]\n", " N1[\"Rich handler\\nPretty output\\nZero config\"]\n", " end\n", "\n", " lib -->|\"log records propagate to caller\"| exp\n", " lib -->|\"log records propagate to caller\"| prod\n", " lib -->|\"log records propagate to caller\"| nb\n", "\n", " style lib fill:#FEF2F2,stroke:#DC2626,color:#991B1B\n", " style exp fill:#EBF5F0,stroke:#059669,color:#065F46\n", " style prod fill:#EAF3FA,stroke:#0369A1,color:#0C4A6E\n", " style nb fill:#F5F3FF,stroke:#7C3AED,color:#3B0764\n", "```" ] }, { "cell_type": "markdown", "id": "38", "metadata": {}, "source": [ "The four tools you have learned are not alternatives. They are layers. A real ML project uses all four, each in its right place:\n", "\n", "| Layer | Tool | Rule |\n", "| --- | --- | --- |\n", "| Library (`grade_predictor`, any pip package) | stdlib + NullHandler | Must not emit output by default |\n", "| Experiment scripts | loguru | Low ceremony, rich context binding |\n", "| Production API / MLOps pipeline | structlog | Structured JSON, traceable |\n", "| Notebooks | Rich handler | Pretty output, zero config |\n", "\n", "The one-sentence rule: **if you are shipping it, use stdlib; if you are running it, use loguru; if someone else is querying your logs, use structlog.**\n", "\n", "The library/application boundary from Section 2 is what makes the layers composable. Library code that uses `NullHandler` and `getLogger(__name__)` can be imported by any of the three application layers, each of which attaches its own handlers, without any conflict.\n", "\n", "
\n", " Activity 2 - Four Layers in One Notebook

\n", "Goal: In a fresh notebook cell, set up all four layers for a single import of a mock grade_predictor library. The mock library should use NullHandler and getLogger(__name__). The notebook cell should use RichHandler. Write a separate script string (as a Python string literal) showing how an experiment script would use loguru to import and call the library. Write a second script string showing how a FastAPI endpoint would use structlog. You do not need to run the scripts, just define them clearly as code strings.\n", "
" ] }, { "cell_type": "code", "execution_count": null, "id": "39", "metadata": {}, "outputs": [], "source": [ "# TODO: implement the four-layer demonstration\n" ] }, { "cell_type": "markdown", "id": "40", "metadata": {}, "source": [ "## Further Reading\n", "\n", "| Resource | Why it matters |\n", "| --- | --- |\n", "| [Python logging HOWTO](https://docs.python.org/3/howto/logging.html) | The canonical guide to stdlib logging, including the propagation model and handler configuration |\n", "| [Python logging cookbook](https://docs.python.org/3/howto/logging-cookbook.html) | Practical patterns: rotating files, multiprocessing, filters, and more |\n", "| [loguru documentation](https://loguru.readthedocs.io/) | Full reference for sinks, `bind()`, `@catch`, and integration with stdlib |\n", "| [structlog documentation](https://www.structlog.org/en/stable/) | Processor pipeline design, stdlib integration, async support, and testing |\n", "| [rich logging](https://rich.readthedocs.io/en/stable/logging.html) | `RichHandler` options: tracebacks, markup, log levels, width |\n", "| [Twelve-Factor App: Logs](https://12factor.net/logs) | The production principle behind structured logging: treat logs as event streams, not files |" ] }, { "cell_type": "markdown", "id": "41", "metadata": {}, "source": [ "## Summary\n", "\n", "| Concept | Key rule |\n", "| --- | --- |\n", "| `logging.getLogger(__name__)` | Get a logger named after the module's dotted path; enables the propagation hierarchy |\n", "| `NullHandler` | Add once in library `__init__.py`; silences warnings without emitting output |\n", "| `basicConfig()` | Never call inside library code; call once at application startup if using stdlib alone |\n", "| `configure()` | Application-side function that attaches real handlers; call once at startup |\n", "| Root logger level | Set to `DEBUG`; let individual handlers filter; ensures file handler captures DEBUG even if console shows INFO |\n", "| `LogContext` | Context manager that injects key-value pairs into every record in a block, without touching call sites |\n", "| `log_section` | Marks start and end of a named pipeline stage; logs exceptions automatically |\n", "| loguru | Experiment scripts: one import, `logger.add()` for sinks, `logger.bind()` for context, `@logger.catch` for exceptions |\n", "| loguru in libraries | Never: it is a global singleton that leaks into every caller |\n", "| structlog | Production services: processors pipeline transforms event dicts; swap JSON renderer for console renderer without changing call sites |\n", "| `RichHandler` | Notebooks and CLIs: drop-in stdlib handler with colour, alignment, and rich tracebacks |\n", "| The one-sentence rule | Shipping it: stdlib. Running it: loguru. Someone else queries it: structlog. |\n", "\n", "**Next:** This completes Part 3: Dev Tools. Part 4 builds on everything here to train, evaluate, and deploy machine learning modeltterns for ML pipelines, and how to run tests in CI alongside the Quarto render." ] } ], "metadata": { "kernelspec": { "display_name": "Python 3 (ipykernel)", "language": "python", "name": "python3" }, "language_info": { "codemirror_mode": { "name": "ipython", "version": 3 }, "file_extension": ".py", "mimetype": "text/x-python", "name": "python", "nbconvert_exporter": "python", "pygments_lexer": "ipython3", "version": "3.12.12" } }, "nbformat": 4, "nbformat_minor": 5 }