# Logging

> **Conformance:** L0 / L1 / L2 (see `README.md`)
> **Audience:** Human engineers AND AI coding agents.

> **📦 Post-extraction note:** `setup_logging`, `JsonFormatter`, `TextFormatter`, `Redactor`, `setup_otel`, `operation_span`, `install_excepthook`, `install_threading_excepthook`, `report_now`, and the crash-reporter sinks now live in **`mgf.common.observability`**. The OpenTelemetry SDK + Sentry + httpx-instrumentation deps are pulled in by the **`mgf-common[observability]`** extra. Citations to `src/vmanager/observability/` in the body describe how the consumer (VManager) imports them — the canonical implementation is at `src/mgf/common/observability/`. The "VManager gap-closure plan" sections are now an obsolete record of how the gaps were closed; treat them as a worked example for bringing a new project to L2.

---

## Rules box (read this first)

| ID | Rule | Applies to |
|---|---|---|
| **LG-01** | Every module MUST acquire its logger via `logging.getLogger(__name__)` (or the equivalent canonical hierarchical name). No bare `logging.info(...)`. | all |
| **LG-02** | The application MUST configure logging in **exactly one place per entry point** (CLI `main`, GUI `app.run`, scheduler service entry, etc.) and MUST emit JSON when stdout is not a TTY (so log aggregators can parse it). Human-readable text is the TTY default. | all |
| **LG-03** | Every log record MUST carry the OpenTelemetry **trace_id** and **span_id** when a span is active. The standard formatter adds these automatically. | all |
| **LG-04** | Sensitive fields (passwords, tokens, private keys, session cookies, IP addresses on request) MUST be redacted by the formatter before any sink sees them. The redaction set MUST be configurable. | all |
| **LG-05** | ERROR-level logs MUST include the exception via `LOG.exception(...)` or `exc_info=True`. Never just the stringified exception in the message. | all |
| **LG-06** | Logs MUST reach an aggregator the operator can search. The aggregator MAY be: a **rotating local file** (desktop / single-server, no platform aggregator), the process's **stdout/stderr** (cloud-native / container; the runtime captures + forwards to the platform aggregator per 12-factor §XI), or a **remote sink** (OTLP / syslog / HTTP webhook; opt-in). A "console only, no aggregation" configuration is non-compliant in production. **Revised in v0.18.0** (closes FEEDBACK LOG-01 — the original rotating-file mandate didn't fit cloud-native consumers). | all |
| **LG-07** | GUI apps MUST ship a **log-viewer dialog** that reads the rotating file sink so users can view logs without a terminal. | gui-app |
| **LG-08** | Log messages MUST use lazy %-style formatting (`LOG.info("processing %s", x)`), NOT f-strings. Lazy formatting is skipped when the level is filtered. | all |
| **LG-09** | Structured fields MUST be passed via `extra={...}`, NOT concatenated into the message. The JSON formatter promotes them to top-level keys. | all |
| **LG-10** | Headless services (systemd timers, daemons, mobile background tasks) MUST configure logging at their entry point too, with `JournalHandler` (Linux) / equivalent OS sink in addition to the file sink. | service |
| **LG-11** | Operation start/end SHOULD be logged with a stable `operation` name field at INFO so traces of complex flows are reconstructable from logs alone. | all |
| **LG-12** | Log emission MUST be cheap (≤100 µs per record). Heavy formatting / IO MUST happen in the handler, not the call site. | all |
| **LG-13** | High-frequency log sites (inner loops, per-event callbacks, per-progress-tick) MUST use rate-limiting or sampling so a runaway condition does not flood every sink. The canonical shapes are in §17. | all |
| **LG-14** | Custom correlation context (request ID, user ID, lab name) MUST propagate through `contextvars.ContextVar`, not thread-local storage or function arguments. The standard formatter promotes registered contextvars to log fields. See §18. | all |

### Per-kind compliance matrix

The `Applies to` column is machine-readable. `catch-up` and
future audit tooling filter by the project's detected kind so
non-applicable rules don't surface as violations. Closes FEEDBACK
LOG-02 (LG-07's GUI-only scope) + provides the contract pattern
ASPIRE-02 prescribes for kind-aware standards.

| Kind | Applicable LG-* rules |
|---|---|
| **all** | LG-01, LG-02, LG-03, LG-04, LG-05, LG-06, LG-08, LG-09, LG-11, LG-12, LG-13, LG-14 |
| **gui-app** | All-applicable + **LG-07** (log-viewer dialog) |
| **service** | All-applicable + **LG-10** (headless / journald sink) |
| **fastapi**, **django** | All-applicable. LG-06's *stdout-aggregator* branch typically applies (cloud-native deploy); see [`docs/public/recipes/cloud-native-logging.md`](../public/recipes/cloud-native-logging.md). |
| **cli**, **library** | All-applicable. LG-06's *rotating-file* branch typically applies. |

---

## 1. Mental model

Logging exists to answer four questions, in order of how often they get asked:

1. **What is happening right now?** — operator watching a tail.
2. **Why did this fail?** — debugger reading after the fact.
3. **What was the user's full session?** — correlation across services.
4. **Are we within budget?** — metrics derived from logs.

A logging stack that cannot answer all four is incomplete. The standard prescribes:

- **Per-module loggers** so output can be filtered by source.
- **Structured records** so machines can parse them.
- **Correlation IDs** (OpenTelemetry trace_id / span_id) so a single user action can be reconstructed end-to-end.
- **Multiple sinks** — console for the human, rotating file for the operator, OTLP/syslog for the aggregator.
- **Redaction** so secrets don't leak.
- **A GUI viewer** so non-CLI users can see what's happening.

The standard library `logging` module is **sufficient** for all of this. We do not adopt `structlog` or `loguru` — the cost (extra dep, learning curve) is not worth the benefit when stdlib handles it well.

---

## 2. Logger acquisition

### 2.1 Naming

Every logger MUST be acquired with the **canonical module path** as its name. The conventional shape is `<app>.<subpackage>.<module>`. For Python, this is `__name__`:

```python
# RIGHT
import logging
LOG = logging.getLogger(__name__)
```

If the canonical `__name__` is awkward (very deep path, or test code), an explicit hierarchical string is acceptable:

```python
# RIGHT (still hierarchical)
LOG = logging.getLogger("<app>.gui.dashboard")
```

**MUST NOTs:**
- `logging.info("...")` (uses the root logger; can't be filtered).
- `logging.getLogger("dashboard")` (flat name; can't be category-filtered).
- A function-level `logging.getLogger(...)` call (allocation per call; create once at module scope).

### 2.2 The `LOG` convention

The conventional binding is `LOG = logging.getLogger(__name__)` at module scope. Use uppercase `LOG` (some shops use lowercase `log` or `logger` — pick one per project and stick to it; VManager uses `LOG`).

**AS-IS in VManager:** all 21 loggers in the codebase use `logging.getLogger("vmanager.<path>")` with explicit string literals (not `__name__`). Both shapes are acceptable per this standard, but **`__name__` is preferred for new code** because it never drifts when modules are renamed. Existing string literals MAY remain unchanged.

---

## 3. Levels and what they mean

| Level | Meaning | Example |
|---|---|---|
| **DEBUG** | Internal state useful when chasing a bug. Off in production by default. | `LOG.debug("snapshot tree built: %d nodes", len(nodes))` |
| **INFO** | Normal lifecycle events that an operator wants to see. | `LOG.info("started VM %s", vm.name)` |
| **WARNING** | Something unexpected that the application recovered from. | `LOG.warning("notify-send missing; falling back to log notifier")` |
| **ERROR** | An operation failed. The user (or operator) should know. MUST include `exc_info`. | `LOG.exception("failed to attach disk %s to %s", disk, vm.name)` |
| **CRITICAL** | A condition that may take the process down or makes further work impossible. | `LOG.critical("metrics DB is corrupt; shutting down poller")` |

**MUSTs:**
- INFO is the default level a user sees. The default verbosity SHOULD print INFO + WARN + ERROR.
- DEBUG MUST NOT contain user-facing instructions; it's for engineers.
- ERROR MUST include `exc_info` — see rule **LG-05**. The wrong shape (`LOG.error(f"failed: {e}")`) loses the traceback.
- CRITICAL MUST trigger the crash-reporter pipeline if reached during a top-level handler — see [`ERROR_HANDLING.md`](ERROR_HANDLING.md) §6.

---

## 4. Message style and structured fields

### 4.1 Lazy %-formatting

```python
# RIGHT — lazy: format only happens if level passes
LOG.info("processing %s for %s", item, user)

# WRONG — eager: format runs even if INFO is filtered
LOG.info(f"processing {item} for {user}")
```

The cost difference is small per record but adds up to milliseconds in tight loops. More importantly, the lazy form keeps the message template stable across records, which makes log aggregators happy (they group by template).

### 4.2 Structured `extra={}` fields

```python
# RIGHT — fields promoted to JSON top-level keys
LOG.info(
    "vm started",
    extra={"vm_name": vm.name, "vm_uuid": vm.uuid, "duration_ms": elapsed_ms},
)

# WRONG — fields buried in the message
LOG.info("vm %s (uuid=%s) started in %d ms", vm.name, vm.uuid, elapsed_ms)
```

The wrong shape is fine for human eyes; the right shape lets the aggregator filter on `vm_name="prod-1"` without regex.

### 4.3 The `operation` field convention

Every long-running operation SHOULD log a start and end record with a stable `operation` name:

```python
LOG.info("operation start", extra={"operation": "vm.create", "vm_name": spec.name})
try:
    handle = build_and_run(spec, provider)
except AppError:
    LOG.exception("operation failed", extra={"operation": "vm.create", "vm_name": spec.name})
    raise
else:
    LOG.info(
        "operation end",
        extra={"operation": "vm.create", "vm_name": spec.name, "duration_ms": ...},
    )
```

This lets a single log query (`operation:vm.create`) list every create attempt across users / time.

### 4.4 Forbidden in messages

- **No newlines.** A record with `\n` confuses aggregators that delimit on newline. Use `extra={...}` for multi-field info.
- **No trailing periods.** Log messages are statements, not sentences.
- **No emoji** — they break terminal renderers and confuse some aggregators.

---

## 5. Configuration (rule LG-02)

### 5.1 Single setup point

Each entry point calls one setup function:

```python
# src/<app>/cli/__main__.py
from <app>.observability.logging_setup import setup_logging

@click.group(...)
def main(ctx, log_level, log_format):
    setup_logging(level=log_level, fmt=log_format)
    ...
```

### 5.2 Drop-in template — `<app>/observability/logging_setup.py`

```python
"""Single-point logging configuration.

Call ``setup_logging(...)`` once from each entry point (CLI main,
GUI app.run, scheduler service entry, mobile background task entry).
Calling it twice is harmless (idempotent — `force=True`).

Sinks installed by default:
  - Console (stderr) — text on TTY, JSON when not a TTY (LG-02).
  - Rotating file under <state>/logs/<app>.log.

Optional sinks (opt-in via env / config):
  - Journald (Linux) when running under systemd.
  - OTLP exporter when OTLP_ENDPOINT is set.
  - Syslog when SYSLOG_ADDR is set.
  - HTTP webhook when LOG_HTTP_SINK is set.

Every record carries OpenTelemetry trace_id + span_id when a span is
active (LG-03). Sensitive fields are redacted (LG-04).
"""

from __future__ import annotations

import json
import logging
import os
import sys
from logging.handlers import RotatingFileHandler
from pathlib import Path
from typing import Any, Literal

from <app>.observability.json_formatter import JsonFormatter
from <app>.observability.text_formatter import TextFormatter
from <app>.observability.redaction import Redactor

LogFormat = Literal["text", "json", "auto"]

def _state_dir() -> Path:
    """Lazy resolve so tests can monkeypatch HOME (rule CF-04 generalised)."""
    xdg = os.environ.get("XDG_STATE_HOME")
    base = Path(xdg) if xdg else Path.home() / ".local" / "state"
    return base / "<app>"

def setup_logging(
    *,
    level: str = "INFO",
    fmt: LogFormat = "auto",
    log_file: Path | None = None,
    redactor: Redactor | None = None,
    enable_otlp: bool | None = None,
) -> None:
    """Configure the root logger and standard handlers.

    Parameters
    ----------
    level : str
        Root level (DEBUG/INFO/WARNING/ERROR/CRITICAL).
    fmt : LogFormat
        "text" for human-readable, "json" for structured, "auto" to
        pick based on ``stdout.isatty()``.
    log_file : Path or None
        Override the rotating-file destination. Default:
        ``<state>/logs/<app>.log``.
    redactor : Redactor or None
        Custom redactor. Default: ``Redactor.default()``.
    enable_otlp : bool or None
        Enable the OTLP log exporter. Default: ``None`` (env-driven).
    """
    redactor = redactor or Redactor.default()
    chosen_fmt = _resolve_format(fmt)

    handlers: list[logging.Handler] = []

    # 1) Console handler — always present.
    console = logging.StreamHandler(stream=sys.stderr)
    console.setFormatter(_make_formatter(chosen_fmt, redactor))
    handlers.append(console)

    # 2) Rotating file handler — always present.
    file_path = log_file or (_state_dir() / "logs" / "<app>.log")
    file_path.parent.mkdir(parents=True, exist_ok=True)
    file_handler = RotatingFileHandler(
        filename=str(file_path),
        maxBytes=10 * 1024 * 1024,        # 10 MiB
        backupCount=5,                    # keep 5 rotations
        encoding="utf-8",
    )
    # File handler ALWAYS uses JSON — no colours, no TTY heuristics.
    file_handler.setFormatter(JsonFormatter(redactor=redactor))
    handlers.append(file_handler)

    # 3) Optional sinks (opt-in via env).
    _maybe_add_journald(handlers, redactor)
    _maybe_add_syslog(handlers, redactor)
    _maybe_add_otlp(handlers, redactor, enable_otlp=enable_otlp)
    _maybe_add_http(handlers, redactor)

    logging.basicConfig(
        level=getattr(logging, level.upper()),
        handlers=handlers,
        force=True,  # override any handlers from earlier setup_logging calls
    )

    # Lower the noise from chatty third-party libraries by default.
    for noisy in ("urllib3", "asyncio", "PIL", "matplotlib"):
        logging.getLogger(noisy).setLevel(logging.WARNING)

def _resolve_format(fmt: LogFormat) -> Literal["text", "json"]:
    if fmt == "auto":
        return "text" if sys.stderr.isatty() else "json"
    return fmt

def _make_formatter(fmt: Literal["text", "json"], redactor: Redactor) -> logging.Formatter:
    if fmt == "json":
        return JsonFormatter(redactor=redactor)
    return TextFormatter(redactor=redactor)

def _maybe_add_journald(handlers: list[logging.Handler], redactor: Redactor) -> None:
    """Add JournalHandler when running under systemd."""
    if "JOURNAL_STREAM" not in os.environ and "INVOCATION_ID" not in os.environ:
        return  # not under systemd
    try:
        from systemd.journal import JournalHandler
    except ImportError:
        return
    h = JournalHandler(SYSLOG_IDENTIFIER="<app>")
    h.setFormatter(JsonFormatter(redactor=redactor))
    handlers.append(h)

def _maybe_add_syslog(handlers: list[logging.Handler], redactor: Redactor) -> None:
    addr = os.environ.get("<APP>_SYSLOG_ADDR")
    if not addr:
        return
    from logging.handlers import SysLogHandler
    host, _, port = addr.partition(":")
    h = SysLogHandler(address=(host, int(port) if port else 514))
    h.setFormatter(JsonFormatter(redactor=redactor))
    handlers.append(h)

def _maybe_add_otlp(
    handlers: list[logging.Handler],
    redactor: Redactor,
    *,
    enable_otlp: bool | None,
) -> None:
    """Add the OTLP log exporter when OTLP is enabled.

    Lazy import — opentelemetry deps are optional.
    """
    if enable_otlp is None:
        enable_otlp = bool(os.environ.get("OTEL_EXPORTER_OTLP_ENDPOINT"))
    if not enable_otlp:
        return
    try:
        from <app>.observability.otel_setup import build_otlp_log_handler
    except ImportError:
        return
    h = build_otlp_log_handler()
    h.setFormatter(JsonFormatter(redactor=redactor))
    handlers.append(h)

def _maybe_add_http(handlers: list[logging.Handler], redactor: Redactor) -> None:
    url = os.environ.get("<APP>_LOG_HTTP_SINK")
    if not url:
        return
    from logging.handlers import HTTPHandler
    from urllib.parse import urlparse
    parsed = urlparse(url)
    h = HTTPHandler(host=parsed.netloc, url=parsed.path or "/", method="POST", secure=parsed.scheme == "https")
    h.setFormatter(JsonFormatter(redactor=redactor))
    handlers.append(h)
```

### 5.3 Drop-in template — `<app>/observability/json_formatter.py`

```python
"""JSON formatter that adds OpenTelemetry trace context and runs
the redactor before emit. The output is one JSON object per line —
the format every mainstream aggregator (Loki, ELK, Splunk, Datadog,
Cloudwatch) understands out of the box.
"""

from __future__ import annotations

import json
import logging
import time
from typing import Any

from <app>.observability.redaction import Redactor

# Standard LogRecord attributes — anything else is treated as a custom
# field (came from `extra={...}`) and promoted to a top-level JSON key.
_RESERVED = frozenset({
    "name", "msg", "args", "levelname", "levelno", "pathname",
    "filename", "module", "exc_info", "exc_text", "stack_info",
    "lineno", "funcName", "created", "msecs", "relativeCreated",
    "thread", "threadName", "processName", "process",
    "message", "asctime", "taskName",
})

class JsonFormatter(logging.Formatter):
    """One JSON object per record. Always single-line, always UTC."""

    def __init__(self, *, redactor: Redactor) -> None:
        super().__init__()
        self._redactor = redactor

    def format(self, record: logging.LogRecord) -> str:
        # Compose the base record.
        payload: dict[str, Any] = {
            "ts": _iso_utc(record.created),
            "level": record.levelname,
            "logger": record.name,
            "msg": record.getMessage(),
            "module": record.module,
            "func": record.funcName,
            "line": record.lineno,
            "thread": record.threadName,
            "process": record.process,
        }

        # Custom extras.
        for key, value in record.__dict__.items():
            if key in _RESERVED or key.startswith("_"):
                continue
            payload[key] = value

        # OpenTelemetry trace context (LG-03).
        _add_otel_context(payload)

        # Exception info.
        if record.exc_info:
            payload["exception"] = self.formatException(record.exc_info)
        if record.stack_info:
            payload["stack"] = self.formatStack(record.stack_info)

        # Redact (LG-04). The redactor walks the dict in place.
        self._redactor.redact(payload)

        return json.dumps(payload, default=_json_default, ensure_ascii=False)

def _iso_utc(epoch: float) -> str:
    return time.strftime("%Y-%m-%dT%H:%M:%S", time.gmtime(epoch)) + f".{int((epoch % 1) * 1000):03d}Z"

def _json_default(obj: Any) -> Any:
    """Best-effort JSON encoder for non-JSON-native types."""
    if isinstance(obj, bytes):
        return obj.decode("utf-8", errors="replace")
    return repr(obj)

def _add_otel_context(payload: dict[str, Any]) -> None:
    """Attach trace_id / span_id when an OTel span is active."""
    try:
        from opentelemetry import trace
    except ImportError:
        return
    span = trace.get_current_span()
    ctx = span.get_span_context() if span else None
    if ctx and ctx.is_valid:
        payload["trace_id"] = format(ctx.trace_id, "032x")
        payload["span_id"] = format(ctx.span_id, "016x")
```

### 5.4 Drop-in template — `<app>/observability/text_formatter.py`

```python
"""Human-readable text formatter for TTY console output.

ANSI-coloured by level. Falls back to plain text when stderr is not
a TTY (the JSON formatter takes over via the auto-format heuristic).
"""

from __future__ import annotations

import logging
import sys
import time

from <app>.observability.redaction import Redactor

_LEVEL_COLORS = {
    "DEBUG":    "\033[90m",  # bright black
    "INFO":     "\033[37m",  # light grey
    "WARNING":  "\033[33m",  # yellow
    "ERROR":    "\033[31m",  # red
    "CRITICAL": "\033[1;31m",  # bold red
}
_RESET = "\033[0m"

class TextFormatter(logging.Formatter):
    def __init__(self, *, redactor: Redactor) -> None:
        super().__init__()
        self._redactor = redactor
        self._supports_color = sys.stderr.isatty()

    def format(self, record: logging.LogRecord) -> str:
        ts = time.strftime("%H:%M:%S", time.localtime(record.created))
        msg = record.getMessage()

        # Promote extras to a `key=value` tail so humans see them too.
        extras: dict = {}
        for key, value in record.__dict__.items():
            if key.startswith("_") or key in (
                "name", "msg", "args", "levelname", "levelno",
                "pathname", "filename", "module", "exc_info",
                "exc_text", "stack_info", "lineno", "funcName",
                "created", "msecs", "relativeCreated", "thread",
                "threadName", "processName", "process", "message",
                "asctime", "taskName",
            ):
                continue
            extras[key] = value

        self._redactor.redact_text_extras(extras)

        tail = " " + " ".join(f"{k}={v!r}" for k, v in extras.items()) if extras else ""

        head = f"{ts} {record.levelname:<8} {record.name}: {msg}{tail}"

        if record.exc_info:
            head = head + "\n" + self.formatException(record.exc_info)

        if self._supports_color:
            color = _LEVEL_COLORS.get(record.levelname, "")
            return f"{color}{head}{_RESET}"
        return head
```

---

## 6. Sensitive-field redaction (rule LG-04)

### 6.1 What gets redacted

Default redaction applies to:

- **Exact key names** (case-insensitive): `password`, `passwd`, `secret`, `token`, `api_key`, `apikey`, `private_key`, `cookie`, `set-cookie`, `authorization`, `auth`, `session`, `client_secret`, `access_token`, `refresh_token`.
- **Pattern matches** in string values: `Bearer <...>`, `Basic <...>`, JWT-shaped strings (3 base64 segments separated by `.`), PEM blocks (`-----BEGIN ... PRIVATE KEY-----`).
- **Optionally** (per-project): IP addresses, email addresses, full file paths under `$HOME` (replaced with `~/...`).

### 6.2 Drop-in template — `<app>/observability/redaction.py`

```python
"""Redact sensitive fields from log records before any sink sees them.

The redactor walks the record's structured payload (the dict produced
by JsonFormatter, or the extras dict produced by TextFormatter) in
place. The match set is configurable via constructor; defaults are
the well-known secret-bearing keys.
"""

from __future__ import annotations

import re
from dataclasses import dataclass, field
from typing import Any

_DEFAULT_KEY_PATTERNS = frozenset({
    "password", "passwd", "secret", "token", "api_key", "apikey",
    "private_key", "privatekey", "cookie", "set-cookie",
    "authorization", "auth", "session", "client_secret",
    "access_token", "refresh_token", "x-api-key",
})

_BEARER_RE = re.compile(r"\b(Bearer|Basic)\s+[A-Za-z0-9._\-+/=]{8,}\b")
_JWT_RE = re.compile(r"\beyJ[A-Za-z0-9_\-]{8,}\.[A-Za-z0-9_\-]{8,}\.[A-Za-z0-9_\-]{8,}\b")
_PEM_RE = re.compile(r"-----BEGIN [A-Z ]*PRIVATE KEY-----.*?-----END [A-Z ]*PRIVATE KEY-----", re.S)

_REDACTED = "[REDACTED]"

@dataclass
class Redactor:
    """Walks log payloads and redacts sensitive values.

    Configurable: pass extra key names or value-pattern regexes via
    the constructor. The default configuration covers the common
    secret-bearing keys and Bearer/JWT/PEM value shapes.
    """

    extra_keys: frozenset[str] = field(default_factory=frozenset)
    extra_value_patterns: tuple[re.Pattern[str], ...] = ()

    @classmethod
    def default(cls) -> Redactor:
        return cls()

    def redact(self, payload: dict[str, Any]) -> None:
        """Walk the dict in place, replacing sensitive values."""
        keys_to_redact = _DEFAULT_KEY_PATTERNS | self.extra_keys
        self._walk(payload, keys_to_redact)

    def redact_text_extras(self, extras: dict[str, Any]) -> None:
        """Convenience for the TextFormatter — same as redact()."""
        self.redact(extras)

    def _walk(self, node: Any, keys: frozenset[str]) -> Any:
        if isinstance(node, dict):
            for k in list(node.keys()):
                if k.lower() in keys:
                    node[k] = _REDACTED
                else:
                    node[k] = self._walk(node[k], keys)
            return node
        if isinstance(node, list):
            return [self._walk(v, keys) for v in node]
        if isinstance(node, str):
            return self._scrub_string(node)
        return node

    def _scrub_string(self, s: str) -> str:
        s = _BEARER_RE.sub(_REDACTED, s)
        s = _JWT_RE.sub(_REDACTED, s)
        s = _PEM_RE.sub(_REDACTED, s)
        for pat in self.extra_value_patterns:
            s = pat.sub(_REDACTED, s)
        return s
```

**MUSTs:**
- The redactor MUST run before the formatter writes to any sink.
- The default key set MUST include the canonical secret-bearing names (above).
- A unit test MUST assert that a record with `extra={"password": "x"}` produces `"password": "[REDACTED]"` in the JSON output.
- Per-project additions go in the `extra_keys` constructor arg, not by editing the default set.

---

## 7. Correlation — OpenTelemetry (rule LG-03)

VManager (and every L2 project) uses OpenTelemetry as the **strong, reliable tracing path**.

### 7.1 What you get

- **Trace ID** + **span ID** automatically attached to every log record (rule LG-03, via `JsonFormatter._add_otel_context`).
- **Spans** for every operation, with start/end times, attributes, and parent/child relationships.
- **OTLP export** to any OTel-compatible backend (Tempo, Jaeger, Datadog, Honeycomb, AWS X-Ray, etc.).
- **Auto-instrumentation** for `httpx`, `paramiko`, `subprocess` (via wrapper), DB drivers.

### 7.2 Drop-in template — `<app>/observability/otel_setup.py`

```python
"""OpenTelemetry initialization — Tier C observability.

Lazy imports — opentelemetry deps are optional. Calling
``setup_otel(enabled=False)`` short-circuits and is safe even when
the OTel SDK is not installed.

Endpoints + service identity come from standard OTel env vars:
  - OTEL_EXPORTER_OTLP_ENDPOINT
  - OTEL_EXPORTER_OTLP_HEADERS
  - OTEL_SERVICE_NAME      (default: "<app>")
  - OTEL_RESOURCE_ATTRIBUTES
"""

from __future__ import annotations

import contextlib
import logging
import os
from typing import Iterator

def setup_otel(*, enabled: bool | None = None, service_name: str = "<app>") -> None:
    """Initialize the OpenTelemetry SDK + OTLP exporter.

    Idempotent — call once per entry point. When disabled (default if
    OTEL_EXPORTER_OTLP_ENDPOINT is unset and `enabled` is None), the
    no-op tracer remains active and `trace.get_current_span()` keeps
    returning the no-op span; `trace_id` is NOT added to log records.
    """
    if enabled is None:
        enabled = bool(os.environ.get("OTEL_EXPORTER_OTLP_ENDPOINT"))
    if not enabled:
        return

    try:
        from opentelemetry import trace
        from opentelemetry.sdk.resources import Resource
        from opentelemetry.sdk.trace import TracerProvider
        from opentelemetry.sdk.trace.export import BatchSpanProcessor
        from opentelemetry.exporter.otlp.proto.http.trace_exporter import OTLPSpanExporter
    except ImportError:
        logging.getLogger(__name__).warning(
            "OTEL_EXPORTER_OTLP_ENDPOINT is set but opentelemetry SDK is not installed; "
            "install with `pip install <app>[observability]`"
        )
        return

    resource = Resource.create({"service.name": os.environ.get("OTEL_SERVICE_NAME", service_name)})
    provider = TracerProvider(resource=resource)
    provider.add_span_processor(BatchSpanProcessor(OTLPSpanExporter()))
    trace.set_tracer_provider(provider)

    # Auto-instrument common libraries.
    _maybe_instrument_httpx()
    _maybe_instrument_subprocess()

def _maybe_instrument_httpx() -> None:
    try:
        from opentelemetry.instrumentation.httpx import HTTPXClientInstrumentor
        HTTPXClientInstrumentor().instrument()
    except ImportError:
        pass

def _maybe_instrument_subprocess() -> None:
    """Wrap our own shell wrapper instead of monkey-patching subprocess.

    See <app>/common/shell.py — when otel is active, run_command opens
    a span around each invocation and tags argv[0], returncode, and
    duration.
    """

@contextlib.contextmanager
def operation_span(name: str, **attributes) -> Iterator[None]:
    """Open a span around an operation. Attributes auto-attach.

    Usage:
        with operation_span("vm.create", vm_name=spec.name):
            handle = build_and_run(spec, provider)

    When OTel is not initialised, this is a no-op (returns the
    no-op span; ``with`` block runs normally).
    """
    try:
        from opentelemetry import trace
        tracer = trace.get_tracer("<app>")
    except ImportError:
        yield
        return
    with tracer.start_as_current_span(name) as span:
        for k, v in attributes.items():
            span.set_attribute(k, v)
        yield

def build_otlp_log_handler() -> logging.Handler:
    """Build an OTLP log exporter handler (used by setup_logging)."""
    from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler
    from opentelemetry.sdk._logs.export import BatchLogRecordProcessor
    from opentelemetry.exporter.otlp.proto.http._log_exporter import OTLPLogExporter

    provider = LoggerProvider()
    provider.add_log_record_processor(BatchLogRecordProcessor(OTLPLogExporter()))
    return LoggingHandler(level=logging.NOTSET, logger_provider=provider)
```

### 7.3 Wrapping operations

```python
# src/<app>/operations/clone.py
from <app>.observability.otel_setup import operation_span

def full_clone(provider, source_handle, *, name) -> EntityHandle:
    with operation_span("clone.full", source=source_handle.name, target=name):
        ...
```

**MUSTs:**
- Every L2 use case (the function the CLI / GUI invokes) MUST be wrapped in an `operation_span`.
- Span names MUST follow `<subject>.<verb>` (e.g., `vm.create`, `clone.full`, `backup.export`).
- Attributes attached to the span MUST use snake_case keys.

### 7.4 What kinds of failures actually appear in traces

A subtle and important consequence of the wrapping shape: **traces only show *execution* failures, not *validation* failures.**

Reason: parameter validation, name normalisation, and entity-handle resolution all happen at the entry-point boundary (CLI / GUI) — *upstream* of the L2 use case. By the time `operation_span` opens, the inputs are already valid and the entity exists. So a span fires only if the validated, well-formed operation reaches some real-world failure later (libvirt rejected the start, the disk file is missing, `qemu-img convert` exited non-zero, the snapshot name already exists, etc.).

Concretely, you will **not** see:
- "VM name has illegal characters" — rejected at the CLI parser.
- "no VM named X" — caught by `_resolve_handle` in the CLI before the operation runs.
- "spec file is missing required field" — caught by the spec loader.

You **will** see:
- "libvirt rejected `start_domain`" — provider call inside the span.
- "qemu-img convert exited 2" — subprocess child span with non-zero `returncode`.
- "host port already forwarded" — caught inside `port_forward.add` after the validation pass.

This is the right scope. Validation errors are the user's problem; their feedback channel is the immediate CLI output / GUI dialog. Execution errors are operational; their feedback channel is the trace. Mixing them would inflate trace volume with low-signal "user typed it wrong" entries while diluting the high-signal "the platform broke" entries.

**Practical implication when demoing:** a "let's see the failure span!" demo via the CLI is surprisingly hard to construct because most CLI commands cleanly reject bad input *before* opening any span. The reliable demo path is a Python one-liner that explicitly raises inside `operation_span`:

```python
from vmanager.observability import setup_otel, operation_span
from opentelemetry import trace
setup_otel()
try:
    with operation_span("demo.failing", purpose="failure-demo"):
        raise RuntimeError("synthetic failure for demo")
except RuntimeError:
    pass
trace.get_tracer_provider().shutdown()
```

---

## 8. Sinks summary

| Sink | When active | Format | Notes |
|---|---|---|---|
| Console (stderr) | Always | text on TTY, JSON otherwise | Default level INFO in CLI; configurable via `--log-level` |
| Rotating file | Always | JSON | 10 MiB × 5 rotations under `<state>/logs/<app>.log` |
| Journald | Only when running under systemd | JSON | Auto-detected via `JOURNAL_STREAM` / `INVOCATION_ID` env |
| Syslog | When `<APP>_SYSLOG_ADDR=host:port` set | JSON | TCP/UDP per OS |
| OTLP logs | When `OTEL_EXPORTER_OTLP_ENDPOINT` set | OTel proto | Requires `opentelemetry` extra installed |
| HTTP webhook | When `<APP>_LOG_HTTP_SINK=http://...` set | JSON POST | One record per request (no batching by default) |

---

## 9. The GUI log-viewer dialog (rule LG-07)

Every desktop app MUST ship a log-viewer dialog accessible from the Help menu. It reads the rotating file sink and renders records with level-based colouring, filter controls (by level, by logger), and a Copy button.

### 9.1 Drop-in template — `<app>/gui/dialogs/log_viewer_dialog.py`

```python
"""Log-viewer dialog — reads the rotating file sink and renders it
with level filtering and search.

Designer file: gui/ui/log_viewer.ui (a QDialog with a QPlainTextEdit
for the body, a QComboBox for level filter, a QLineEdit for search,
and Copy/Clear/Open-folder buttons).

Tail mode: reads new lines as the file grows (5-second poll) so the
user can watch a long operation without re-opening the dialog. Off
by default; toggled by a checkbox.
"""

from __future__ import annotations

import json
from pathlib import Path

from PySide6.QtCore import QTimer, Qt
from PySide6.QtWidgets import QDialog, QPlainTextEdit

from <app>.gui.ui_loader import load_ui, require_child

class LogViewerDialog:
    def __init__(self, log_file: Path, parent=None) -> None:
        self.dialog = load_ui("log_viewer.ui")
        self._body: QPlainTextEdit = require_child(self.dialog, "logBody", QPlainTextEdit)
        self._log_file = log_file
        self._tail_timer = QTimer(self.dialog)
        self._tail_timer.setInterval(5000)
        self._tail_timer.timeout.connect(self._refresh)
        self._refresh()

    def _refresh(self) -> None:
        if not self._log_file.exists():
            self._body.setPlainText(f"(no log file at {self._log_file})")
            return
        text_lines: list[str] = []
        with self._log_file.open(encoding="utf-8", errors="replace") as fh:
            for line in fh.readlines()[-2000:]:  # cap at last 2000 lines
                text_lines.append(self._render_line(line))
        self._body.setPlainText("\n".join(text_lines))

    def _render_line(self, raw: str) -> str:
        try:
            rec = json.loads(raw)
        except json.JSONDecodeError:
            return raw.rstrip()
        ts = rec.get("ts", "?")
        lvl = rec.get("level", "?")
        logger = rec.get("logger", "?")
        msg = rec.get("msg", "")
        extras = " ".join(
            f"{k}={v!r}" for k, v in rec.items()
            if k not in {"ts", "level", "logger", "msg", "module", "func", "line", "thread", "process"}
        )
        return f"{ts} {lvl:<8} {logger}: {msg} {extras}".rstrip()
```

**MUSTs:**
- The dialog MUST tail the file — refresh on a timer so a watching user sees new records.
- A "Open log folder" button MUST open the log directory in the OS file manager (`QDesktopServices.openUrl(QUrl.fromLocalFile(str(folder)))`).
- The dialog MUST gracefully handle a missing log file (first run, never written) and a corrupt JSON line (display raw).

**AS-IS in VManager:** there is a `LogPanel` widget (`src/vmanager/gui/widgets/log_panel.py`) but it shows in-app worker progress messages, NOT the rotating file logs. The standard's log viewer is **missing** — gap-closure plan addresses it.

---

## 10. Headless services (rule LG-10)

systemd timer / service entry points MUST configure logging too — they cannot inherit the CLI's setup because they run as separate processes.

### 10.1 Pattern

```python
# scheduler/cli_entry.py — invoked by systemd
def main() -> int:
    from <app>.observability.logging_setup import setup_logging
    from <app>.observability.otel_setup import setup_otel

    setup_logging(level="INFO", fmt="json")  # always JSON for headless
    setup_otel()
    ...
```

systemd auto-detects journald (`JOURNAL_STREAM` is set), so the journald handler attaches automatically. systemd captures stdout/stderr too, but JSON-on-stdout to journald is awkward; the journald handler is the right path.

**MUSTs:**
- Headless entry points MUST call `setup_logging(fmt="json")` (not `"auto"`) — there is no TTY to detect.
- `journalctl --user -u <unit>` MUST show structured records.
- Failure inside the headless tick MUST NOT prevent subsequent ticks (rule **EH-10** never-raises).

---

## 11. Testing pitfalls (discovered in VManager round 2)

When you adopt the standard logging stack and your `pyproject.toml`
has `filterwarnings = ["error"]` (recommended for any project that
takes warnings seriously), `RotatingFileHandler` will trip the test
suite with `PytestUnraisableExceptionWarning` on every test that
calls `setup_logging` — the file object is closed by Python's GC
during pytest teardown, and on Python 3.12+ that GC fires a
`ResourceWarning` which the filter escalates to an error.

**Fix:** in the test fixture that resets logging between tests,
explicitly close every handler before removing it from the root
logger:

```python
@pytest.fixture(autouse=True)
def _isolate_logging():
    yield
    for handler in logging.root.handlers[:]:
        with contextlib.suppress(Exception):
            handler.close()
        logging.root.removeHandler(handler)
```

Also: **mypy override for the optional observability deps.** When
`pyproject.toml` declares `[observability]` as an extra (which the
default install does NOT pull in), `mypy --strict` fails on the
lazy `import opentelemetry` / `import sentry_sdk` / `import systemd`
unless they are listed as `ignore_missing_imports = true`:

```toml
[[tool.mypy.overrides]]
module = [
    "sentry_sdk",
    "opentelemetry",
    "opentelemetry.*",
    "systemd",
    "systemd.*",
]
ignore_missing_imports = true
```

Also: **the `JOURNAL_STREAM` env var is set when running under
systemd**, including some IDE / CI / dev sessions. Tests that assert
"no journald handler attached" MUST `monkeypatch.delenv("JOURNAL_STREAM", raising=False)` and `monkeypatch.delenv("INVOCATION_ID", raising=False)` first.

Also: **OpenTelemetry tests MUST share a session-scoped
TracerProvider via `conftest.py`.** `set_tracer_provider` is a
one-shot per-process operation in OTel — calling it again
silently does nothing and leaves the no-op proxy in place. So if
two test modules each install their own module-scoped
`TracerProvider`, only the first one wins; every span assertion
in the second module fails because `trace.get_tracer().start_span()`
returns the no-op span. The fix is to put the provider + the
in-memory exporter in `tests/<dir>/conftest.py` at session scope,
and let each test pull a per-test fixture that just clears the
exporter:

```python
# tests/unit/observability/conftest.py
@pytest.fixture(scope="session")
def _session_tracer_provider() -> Iterator[InMemorySpanExporter]:
    exporter = InMemorySpanExporter()
    provider = TracerProvider(resource=Resource.create({"service.name": "test"}))
    provider.add_span_processor(SimpleSpanProcessor(exporter))
    trace.set_tracer_provider(provider)
    yield exporter

@pytest.fixture
def in_memory_spans(_session_tracer_provider) -> Iterator[InMemorySpanExporter]:
    _session_tracer_provider.clear()
    yield _session_tracer_provider
```

Test modules then just declare `in_memory_spans` as a parameter and
get a clean exporter per test. **Do NOT install a per-module
provider in test files** — only one wins and the others silently
break.

### 11.1 Pytest stderr-capture distorts full-stack logging benchmarks (VManager round 2)

When you write a benchmark for rule LG-12 (≤ 100 µs per log record)
that uses the default `setup_logging()` output, the number you
measure will be dominated by **pytest's stderr-capture machinery**
rather than by the logging stack itself. The default setup attaches
a console `StreamHandler` on `sys.stderr`; under pytest, every
record that handler emits goes through capture, which adds real
overhead per line. VManager's first cut at the LG-12 benchmark
timed out at 128.6 µs/record — 28 % over the budget — even though
production emission is well under 60 µs/record.

**What LG-12 actually constrains.** The rule says "heavy formatting
/ IO MUST happen in the handler, not the call site". The handler
the rule is worried about is the **rotating file sink** (synchronous
I/O, per-record `write()`). That's what a benchmark should measure.
Pytest's stderr-capture is not part of any production path.

**Fix.** After `setup_logging(...)` completes, drop the console
`StreamHandler` so only the rotating file handler participates in
the timed loop:

```python
from logging.handlers import RotatingFileHandler

setup_logging(level="DEBUG", fmt="json", log_file=tmp_path / "perf.log")

# Drop the console StreamHandler so we measure the rotating-file
# sink path (the surface LG-12 really constrains) without also
# paying for pytest's stderr-capture machinery per record.
for handler in logging.root.handlers[:]:
    if not isinstance(handler, RotatingFileHandler):
        logging.root.removeHandler(handler)

# ... warm-up + timed loop here
```

This is a reasonable proxy for production: in production stderr
either lands in journald (a pipe — effectively free) or on a
terminal (similar cost to pytest capture, but not a latency
concern at interactive typing rates). The file sink is the
one-per-record synchronous surface that matters.

### 11.2 Consumer-side guards when the implementation lives upstream

Once a consumer project depends on `mgf.common.observability`, it
does not own the formatter, the redactor, the handler wiring, or
the OTel setup. Upstream (here, `mgf-common`) owns the fine-grained
benchmarks and contract tests. A consumer might then be tempted to
drop its own logging tests entirely — the upstream covers it.

**Don't.** Keep a thin *consumer-side guard* for every rule the
upstream enforces. Three reasons:

1. **Shim regressions.** A consumer's `src/<app>/observability/`
   package is typically a re-export shim over `mgf.common.observability`.
   A future PR that reaches for a sibling-module import reintroduces
   coupling the shim was supposed to prevent. An import-linter
   contract catches that statically; a consumer-side test catches
   it dynamically.
2. **Consumer-specific extensions.** When a project grows its own
   formatter, redactor, or handler (e.g., scrub a domain-specific
   secret name pattern), the upstream benchmarks no longer cover
   the full path. A consumer-side test is the only place that sees
   the composed shape.
3. **Pin regressions.** A future `mgf-common` release that
   accidentally violates its own rule (imagine LG-12 silently
   regressing in a refactor) lights up on the consumer's CI
   before it reaches a production caller.

VManager's `tests/unit/test_logging_perf.py` is the canonical
example — one test, one assertion, runs in ~0.6 s, catches all
three regression classes above.

---

## 12. Anti-patterns (forbidden)

| Anti-pattern | What's wrong | Right shape |
|---|---|---|
| `LOG.error(f"failed: {e}")` | Loses traceback | `LOG.exception("failed")` or `LOG.error("failed", exc_info=True)` |
| `print("starting...")` | Bypasses sinks, levels, redaction | `LOG.info("starting...")` |
| `LOG.info(f"x={x}")` | Eager format; no structured field | `LOG.info("x", extra={"x": x})` |
| `logging.getLogger("x")` at module top with hardcoded short name | Flat name, can't be category-filtered | `logging.getLogger(__name__)` |
| Multiple `setup_logging` calls in one process from different modules | Handler duplication | One call per entry point only |
| Log a password / token in any field | Leaks secrets to file/aggregator | Redactor handles common cases; per-call MUST use `extra={"redacted_field": "..."}` if explicit |
| Synchronous network call in a custom handler | Blocks the calling thread | Use a `QueueHandler` + `QueueListener` for any remote sink that may block |
| INFO-level "successfully did X" after every method | Log noise | INFO for user-visible lifecycle events only; DEBUG for detail |
| `LOG.info("...", extra={"name": x, "msg": y, "args": z, "level": q})` | `KeyError("Attempt to overwrite 'name' in LogRecord")` at runtime — these are reserved `LogRecord` attributes (see §12.2 below) | Use distinct field names: `subject` / `kind` / `payload_args` / `severity` |

---

### 12.1 Reserved `LogRecord` attribute names

Python's stdlib `logging.LogRecord` reserves a fixed set of
attribute names. Passing any of them via `extra={...}` raises
`KeyError("Attempt to overwrite '<name>' in LogRecord")` at the
`LOG.info(...)` call site — runtime, not lint-time, so the bug
ships unnoticed until the offending log line fires.

The reserved set (Python 3.12):

```
name msg args levelname levelno pathname
filename module exc_info exc_text stack_info
lineno funcName created msecs relativeCreated
thread threadName processName process
message asctime taskName
```

**MUSTs:**

- `extra={...}` keys MUST NOT collide with the reserved set.
- A common collision: passing the user / resource / domain entity
  by `name` (`extra={"name": vm_name}`) — this is the trap that
  bites first. Use `subject`, `subject_name`, `entity_name`,
  `vm_name`, `widget_name`, etc.
- A custom JsonFormatter that writes structured fields MUST treat
  the reserved set as a deny-list when promoting `__dict__` entries
  to JSON keys (the standard formatter at
  `mgf.common.observability.json_formatter` already does this via
  the `_RESERVED` frozenset).

The standard `JsonFormatter` ALSO promotes `extra={...}` keys to
top-level JSON keys, so a renamed key like `subject` lands as
`"subject": "..."` in the output — operators filter on it the
same way they would have filtered on `name`.

---

## 13. Performance

**MUSTs:**
- Per-record cost MUST stay ≤100 µs at INFO. Profile with `pytest --benchmark` if a logger sits in a hot loop.
- Remote sinks (HTTP, OTLP) MUST be batched — use `QueueHandler` + `QueueListener` to push emission off the calling thread:

```python
import logging
import queue
from logging.handlers import QueueHandler, QueueListener

# In setup_logging:
q: queue.Queue = queue.Queue(-1)
queue_handler = QueueHandler(q)
listener = QueueListener(q, http_handler, otlp_handler, respect_handler_level=True)
listener.start()
# atexit.register(listener.stop)
```

This way the call site only enqueues; emission happens on a background thread.

---

## 14. AS-IS in VManager (full snapshot)

- **Loggers** — 21 declarations, all `logging.getLogger("vmanager.<path>")` with explicit string literals. Hierarchical naming is consistent.
- **Setup** — single `logging.basicConfig` inside the click `main` callback at `src/vmanager/cli/__main__.py`. Format string: `"%(asctime)s %(levelname)s %(name)s: %(message)s"`. No JSON. No file. No correlation.
- **Levels** — only 2 `LOG.exception()` calls in the entire codebase (in `monitor/events.py`). All other error logs use `LOG.warning("failed: %s", e)` — losing tracebacks.
- **Structured fields** — never used (`extra={...}` does not appear).
- **Correlation** — none. No `contextvars`, no OTel, no operation IDs.
- **Sinks** — stderr only via the default `StreamHandler`.
- **Redaction** — none.
- **GUI viewer** — only the in-app `LogPanel` widget (worker progress); no file-log viewer.
- **Headless services** — scheduler/hooks/alerts inherit basicConfig at import time; journald not configured.

---

## 15. Gap-closure plan for VManager

### Priority P0 — bring logging to L1

1. **Create `src/vmanager/observability/logging_setup.py`** — paste from §5.2; rename `<app>` → `vmanager`, `<APP>` → `VMANAGER`.
2. **Create `src/vmanager/observability/json_formatter.py`, `text_formatter.py`, `redaction.py`** — paste from §5.3, §5.4, §6.2.
3. **Replace the `basicConfig` call** in `cli/__main__.py` (inside the click `main` callback) with `setup_logging(level=log_level, fmt="auto")`.
4. **Add `setup_logging(fmt="json")` to `gui/app.py::run`** — GUI is rarely a TTY; default to JSON for the file sink and console.
5. **Add `setup_logging(fmt="json")` to `cli/groups/schedule.py::schedule_tick`** so journald records are structured when run under systemd.
6. **Convert every `LOG.warning("...: %s", e)` after a caught exception to `LOG.exception("...")`** — sweep `monitor/`, `hooks/`, `scheduler/`, `gui/workers/`, `interchange/`. 40+ call sites.
7. **Add `extra={...}` for the obvious identifiers** at the same time: `vm_name`, `lab_name`, `hook_name`, `schedule_name`, `rule_name`. Every record that already mentions these in the message text MUST instead pass them as fields.

### Priority P1 — Tier C observability

8. **Add `opentelemetry` and `opentelemetry-exporter-otlp-proto-http` to optional `[observability]` extra** in `pyproject.toml`.
9. **Create `src/vmanager/observability/otel_setup.py`** — paste from §7.2.
10. **Wrap every L2 use case in `operation_span(...)`**: `creator/builder.py::build_and_run`, every `operations/*.py` top-level function, `lab/orchestrator.py::up/down/snap`, `scheduler/runner.py::ScheduleRunner.fire_one`, `hooks/executor.py::fire_all`. Span name = `<subject>.<verb>`.
11. **Call `setup_otel()`** from CLI `cli_main()` and GUI `app.py::run()`.
12. **Verify trace_id appears in JSON log records** when `OTEL_EXPORTER_OTLP_ENDPOINT` is set — manual smoke test against a local Jaeger / Tempo.

### Priority P2 — GUI log viewer

13. **Create `src/vmanager/gui/ui/log_viewer.ui`** (Qt Designer): QDialog with QPlainTextEdit (`logBody`), QComboBox level filter, QLineEdit search, buttons (Copy / Clear / Open folder / Tail toggle).
14. **Create `src/vmanager/gui/dialogs/log_viewer_dialog.py`** — paste from §9.1; rename `<app>` → `vmanager`.
15. **Add Help → View Logs menu item** in `gui/windows/main_window.py`.
16. **Add tests** under `tests/unit/gui/test_log_viewer_dialog.py`: write a synthetic JSON log file, open the dialog, assert lines render, assert tail-mode picks up appends.

### Priority P3 — testing + lint enforcement

17. **Add a pytest test that asserts `password=secret` in `extra={}` produces `[REDACTED]` in the JSON output**.
18. **Add a ruff/mypy lint that catches `logging.info(`, `logging.warning(`, etc. at module top** — only `LOG.info(` etc. is allowed (must use a per-module logger).
19. **Add a lint that catches f-string log calls** — `LOG.info(f"...")` is a defect; pre-commit hook can grep for it.

---

## 16. Cross-references

- Crash reporter integration (ERROR / unhandled records): [`ERROR_HANDLING.md`](ERROR_HANDLING.md) §6.
- Performance budgets per record: [`DESIGN_PRINCIPLES.md`](DESIGN_PRINCIPLES.md) §6.
- The `extra={...}` field pattern is the same one pydantic-settings uses for env-var aliases — naming consistency matters: [`CONFIGURATION.md`](CONFIGURATION.md) §3.
- Sensitive-field redaction policy + per-project additions: [`SECURITY_STANDARD.md`](SECURITY_STANDARD.md) §9.
- Audit log records (rule SC-17): [`SECURITY_STANDARD.md`](SECURITY_STANDARD.md) §9.3.
- Test patterns for log-record content + perf benchmarks: [`TESTING.md`](TESTING.md) §8 + §10.3.

---

## 17. Log volume control (rule LG-13)

A logger that fires ten thousand records per second silently turns a
log aggregator into a denial-of-service victim, and the signal you
needed disappears in noise. High-frequency sites MUST limit their
output.

### 17.1 The four shapes

| Shape | When to use | Cost |
|---|---|---|
| **Rate-limit per logger** | A loop that may fire often but where each record is individually meaningful | Bounded ops/s |
| **Sample 1-in-N** | Per-record telemetry where the aggregate matters but individuals don't | 1/N records |
| **Dedup window** | Repeated identical messages from the same site | Each unique message ≤1× per window |
| **Aggregate** | Counters / gauges that should be a metric, not a log | One record per flush interval |

### 17.2 Rate-limit per logger

The drop-in pattern:

```python
# src/<app>/observability/rate_limit.py
import logging
import time
from collections import defaultdict
from threading import Lock

class RateLimitFilter(logging.Filter):
    """Allow at most `max_per_second` records per (logger, level) pair.

    Excess records are dropped. A WARNING fires once per window
    indicating how many records were dropped.

    Use this for high-frequency sites where each record is meaningful
    but the aggregate volume may overwhelm sinks.
    """

    def __init__(self, max_per_second: float = 100.0) -> None:
        super().__init__()
        self._max = max_per_second
        self._counts: dict[tuple[str, int], int] = defaultdict(int)
        self._dropped: dict[tuple[str, int], int] = defaultdict(int)
        self._window_start = time.monotonic()
        self._lock = Lock()

    def filter(self, record: logging.LogRecord) -> bool:
        key = (record.name, record.levelno)
        with self._lock:
            now = time.monotonic()
            if now - self._window_start >= 1.0:
                self._flush(now)
            if self._counts[key] >= self._max:
                self._dropped[key] += 1
                return False
            self._counts[key] += 1
            return True

    def _flush(self, now: float) -> None:
        for key, dropped in self._dropped.items():
            if dropped:
                logger_name, _ = key
                logging.getLogger(logger_name).warning(
                    "rate-limited: dropped %d records in the last second",
                    dropped,
                )
        self._counts.clear()
        self._dropped.clear()
        self._window_start = now
```

Wire from `setup_logging`:

```python
rate_limit = RateLimitFilter(max_per_second=200.0)
for handler in handlers:
    handler.addFilter(rate_limit)
```

### 17.3 Sample 1-in-N

For per-event telemetry where individuals don't matter but the
distribution does:

```python
import random

class SampleFilter(logging.Filter):
    """Keep 1 in N records per logger; the rest dropped silently."""

    def __init__(self, *, sample_rate: int = 100) -> None:
        super().__init__()
        self._sample_rate = sample_rate

    def filter(self, record: logging.LogRecord) -> bool:
        return random.randint(1, self._sample_rate) == 1
```

`random.randint` is OK here — the choice is not security-relevant.

### 17.4 Dedup window

Repeated identical messages collapse to one record + a count:

```python
class DedupFilter(logging.Filter):
    """Within a window, suppress identical (logger, level, msg) tuples."""

    def __init__(self, window_s: float = 5.0) -> None:
        super().__init__()
        self._window_s = window_s
        self._last: dict[tuple[str, int, str], float] = {}
        self._lock = Lock()

    def filter(self, record: logging.LogRecord) -> bool:
        key = (record.name, record.levelno, record.getMessage())
        now = time.monotonic()
        with self._lock:
            last_seen = self._last.get(key)
            if last_seen is not None and (now - last_seen) < self._window_s:
                return False
            self._last[key] = now
            return True
```

### 17.5 Aggregate (logs as metrics anti-pattern)

Counters, gauges, and histograms are NOT log records. A loop that
emits one INFO record per processed item to "count throughput" is a
metrics emitter wearing a logging costume. The right shape is to
emit a metric (OpenTelemetry meter, Prometheus counter) and log
only at the operation boundary:

```python
# WRONG — one log per item, ten thousand records per second
for item in stream:
    process(item)
    LOG.info("processed item")

# RIGHT — metric per item, log at the boundary
for item in stream:
    process(item)
    items_processed.add(1)

LOG.info(
    "stream processed",
    extra={"operation": "stream.process", "count": items_processed.get()},
)
```

### 17.6 Choosing a shape

| Symptom | Use |
|---|---|
| "Some records here are critical; we just can't have all of them" | Rate-limit |
| "We need to know the typical record but not every one" | Sample |
| "The same message keeps repeating" | Dedup |
| "We're tracking a number, not an event" | Metric (not a log) |

A site that fires >100 records/s in steady state at INFO is almost
certainly using the wrong shape. Re-classify before adding more
handlers.

---

## 18. Async-context propagation (rule LG-14)

A long-running operation typically spans many `await` points across
many tasks. Correlation context (request ID, user ID, lab name,
trace ID) MUST follow the operation across those points or a single
user action's logs scatter across unrelated entries.

### 18.1 Why contextvars

Python's `contextvars.ContextVar` was introduced in 3.7 specifically
to solve this for asyncio. asyncio creates a **copy** of the context
for each task, so a `ContextVar` set inside a task does not leak to
its parent — but it DOES propagate to the task's awaited callees.

Threads have their own context; thread-local storage works for
synchronous code but not for async (a single thread runs many
tasks). `contextvars` works for both.

### 18.2 Drop-in template

```python
# src/<app>/observability/correlation.py
"""Correlation context that propagates across thread + async boundaries.

Register a ContextVar here, set it at the entry point that owns the
correlation, and the JSON formatter will promote it to a top-level
field on every log record fired inside the context.
"""

from __future__ import annotations

import contextvars
from typing import Any

# Each ContextVar registered here gets promoted to a log field with
# the same name. Keep the set small — every record pays the lookup
# cost.
_REGISTERED: dict[str, contextvars.ContextVar[Any]] = {}

def register(name: str, default: Any = None) -> contextvars.ContextVar[Any]:
    """Register a correlation field. Returns the ContextVar to set / read."""
    if name in _REGISTERED:
        return _REGISTERED[name]
    cv: contextvars.ContextVar[Any] = contextvars.ContextVar(name, default=default)
    _REGISTERED[name] = cv
    return cv

def snapshot() -> dict[str, Any]:
    """Read all registered correlation values for the current context."""
    out: dict[str, Any] = {}
    for name, cv in _REGISTERED.items():
        try:
            value = cv.get()
        except LookupError:
            continue
        if value is not None:
            out[name] = value
    return out
```

### 18.3 Wiring into the formatter

```python
# In <app>/observability/json_formatter.py — extend _add_otel_context:

def _add_correlation(payload: dict[str, Any]) -> None:
    """Promote registered correlation contextvars to log fields."""
    from <app>.observability.correlation import snapshot
    payload.update(snapshot())
```

### 18.4 Setting and clearing

At the boundary that owns the correlation (CLI command, HTTP
handler, scheduler tick, GUI worker), set + reset via a token:

```python
from <app>.observability.correlation import register

request_id = register("request_id")
user_id = register("user_id")

async def handle_request(req_id: str, user: str) -> None:
    tokens = [request_id.set(req_id), user_id.set(user)]
    try:
        await do_work()  # every log record inside carries request_id + user_id
    finally:
        for token in reversed(tokens):
            request_id.reset(token) if token.var is request_id else user_id.reset(token)
```

The `try / finally` pattern is critical — without `reset`, the
context value persists into whatever ran after the boundary.
`contextvars.copy_context().run(...)` is an alternative for code
that prefers a snapshot/restore shape.

### 18.5 Cross-thread propagation

When dispatching to a thread (`run_in_executor`,
`asyncio.to_thread`, plain `Thread`), the asyncio runtime
**already** propagates the context to the thread for its lifetime
of the dispatch — `to_thread` and `run_in_executor` both copy
context. For raw `threading.Thread`, copy explicitly:

```python
import contextvars
import threading

def _run_in_context(ctx: contextvars.Context, fn, *args, **kwargs):
    return ctx.run(fn, *args, **kwargs)

ctx = contextvars.copy_context()
thread = threading.Thread(target=_run_in_context, args=(ctx, do_work))
thread.start()
```

Without the copy, the new thread starts with an empty context and
the correlation fields disappear from every log record it emits.

### 18.6 Cost

The lookup is `O(registered fields)` per log record. Keep the
registered set small — five fields is fine; fifty is not. Use
`extra={...}` for one-off fields that don't need cross-await
propagation.

---

*End of `LOGGING.md`.*
