6.6. Logging

   приложение ──► stdout ──► Docker ──► docker logs      ✓
   приложение ──► stderr ──► Docker ──► docker logs      ✓
   приложение ──► /var/log/app.log ──► writable layer    ✗ Docker не видит

2026-07-30 12:14:33 INFO [app.api] запрос обработан за 42 мс

{"ts":"2026-07-30T12:14:33.482Z","level":"INFO","logger":"app.api","message":"запрос обработан","duration_ms":42,"request_id":"a1b2c3"}

logger.info("запрос обработан", extra={"extra_fields": {"duration_ms": 42, "user_id": 17}})

for name in ("uvicorn", "uvicorn.access", "uvicorn.error"):
    logger = logging.getLogger(name)
    logger.handlers.clear()
    logger.propagate = True

   logger.info("сообщение")
          │
          ▼
   создаётся LogRecord
          │
          ▼
   проверка уровня логгера ──► отброшено, если ниже
          │
          ▼
   применяются фильтры
          │
          ▼
   передаётся handlers логгера
          │
          ├─► propagate=True ──► handlers логгера-предка
          │
          ▼
   formatter превращает в строку
          │
          ▼
   handler пишет в назначение (stdout)

root = logging.getLogger()
root.handlers.clear()
root.addHandler(handler)
root.setLevel(level)

mkdir -p /tmp/pylog && cd /tmp/pylog

cat > cause1.py <<'PY'
"""Причина 1: буферизация."""
import time

print("строка в stdout без flush")
time.sleep(6)
PY

cat > cause2.py <<'PY'
"""Причина 2: запись в файл внутри container."""
import logging
import time
from pathlib import Path

Path("/var/log/app").mkdir(parents=True, exist_ok=True)
logging.basicConfig(
    filename="/var/log/app/app.log",
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(message)s",
)

log = logging.getLogger("app")
for i in range(3):
    log.info("запись %s — идёт в файл, не в stdout", i)
    time.sleep(0.2)
time.sleep(6)
PY

for c in cause1 cause2; do
    cat > "Dockerfile.$c" <<EOF
FROM python:3.13-slim
COPY $c.py /app.py
CMD ["python", "/app.py"]
EOF
    docker build -q -f "Dockerfile.$c" -t "log:$c" . > /dev/null
    docker run -d --name "t-$c" "log:$c" > /dev/null
done

sleep 3
for c in cause1 cause2; do
    printf '%-8s строк в docker logs: %s\n' "$c" "$(docker logs "t-$c" 2>&1 | wc -l)"
done

echo
echo "но в causa2 файл есть:"
docker exec t-cause2 sh -c 'wc -l < /var/log/app/app.log; tail -1 /var/log/app/app.log' | sed 's/^/  /'

docker rm -f t-cause1 t-cause2 > /dev/null

cause1   строк в docker logs: 0
cause2   строк в docker logs: 0

но в causa2 файл есть:
  3
  2026-07-30 12:31:07,842 INFO запись 2 — идёт в файл, не в stdout

diagnose_logs() {
    local c="$1"
    echo "── $c ──"
    printf '  docker logs: %s строк\n' "$(docker logs "$c" 2>&1 | wc -l)"
    printf '  файлы .log в container: '
    docker exec "$c" sh -c 'find / -name "*.log" -not -path "/proc/*" -not -path "/sys/*" 2>/dev/null | head -3' \
        | tr '\n' ' ' || echo "нет"
    echo
}

cat > logging_setup.py <<'PY'
"""Настройка logging для контейнеризованного приложения."""
from __future__ import annotations

import logging
import sys


def configure(level: str = "INFO", stream=None) -> None:
    """Настраивает корневой логгер.

    Явная очистка обработчиков надёжнее basicConfig: та не сработает,
    если обработчик уже добавлен библиотекой.
    """
    handler = logging.StreamHandler(stream or sys.stdout)
    handler.setFormatter(
        logging.Formatter(
            fmt="%(asctime)s %(levelname)-8s [%(name)s] %(message)s",
            datefmt="%Y-%m-%dT%H:%M:%S",
        )
    )

    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(handler)
    root.setLevel(level.upper())
PY

cat > app_basic.py <<'PY'
import logging
import os
import time

from logging_setup import configure

configure(os.environ.get("LOG_LEVEL", "INFO"))
log = logging.getLogger("app.worker")

log.debug("отладочное — видно только при LOG_LEVEL=DEBUG")
log.info("приложение запущено")
log.warning("предупреждение")

try:
    1 / 0
except ZeroDivisionError:
    log.exception("поймано исключение")

time.sleep(0.3)
log.info("завершение")
PY

cat > Dockerfile.basic <<'EOF'
FROM python:3.13-slim
ENV PYTHONUNBUFFERED=1
WORKDIR /app
COPY logging_setup.py app_basic.py ./
CMD ["python", "app_basic.py"]
EOF

docker build -q -f Dockerfile.basic -t log:basic . > /dev/null
docker run --rm log:basic

2026-07-30T12:35:12 INFO     [app.worker] приложение запущено
2026-07-30T12:35:12 WARNING  [app.worker] предупреждение
2026-07-30T12:35:12 ERROR    [app.worker] поймано исключение
Traceback (most recent call last):
  File "/app/app_basic.py", line 14, in <module>
    1 / 0
    ~~^~~
ZeroDivisionError: division by zero
2026-07-30T12:35:12 INFO     [app.worker] завершение

docker run --rm -e LOG_LEVEL=DEBUG log:basic 2>&1 | head -2

2026-07-30T12:35:40 DEBUG    [app.worker] отладочное — видно только при LOG_LEVEL=DEBUG
2026-07-30T12:35:40 INFO     [app.worker] приложение запущено

cat > json_logging.py <<'PY'
"""Structured logging в JSON без внешних зависимостей."""
from __future__ import annotations

import json
import logging
import sys
from datetime import datetime, timezone

# Служебные поля LogRecord — их не переносим в вывод как есть
_RESERVED = frozenset(vars(logging.LogRecord("", 0, "", 0, "", (), None)))


class JsonFormatter(logging.Formatter):
    """Одна строка JSON на запись."""

    def format(self, record: logging.LogRecord) -> str:
        payload: dict[str, object] = {
            "ts": datetime.fromtimestamp(record.created, tz=timezone.utc)
            .isoformat(timespec="milliseconds")
            .replace("+00:00", "Z"),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
        }

        if record.exc_info:
            payload["exception"] = self.formatException(record.exc_info)

        # Дополнительные поля из extra={"extra_fields": {...}}
        for key, value in getattr(record, "extra_fields", {}).items():
            if key not in payload:
                payload[key] = value

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


def configure(level: str = "INFO") -> None:
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(JsonFormatter())

    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(handler)
    root.setLevel(level.upper())
PY

cat > app_json.py <<'PY'
import logging
import os
import random
import time

from json_logging import configure

configure(os.environ.get("LOG_LEVEL", "INFO"))
log = logging.getLogger("app.api")

log.info("сервис запущен", extra={"extra_fields": {"version": "1.4.2", "pid": os.getpid()}})

for i in range(3):
    duration = random.randint(10, 800)
    log.info(
        "запрос обработан",
        extra={"extra_fields": {
            "request_id": f"req-{i:03d}",
            "method": "GET",
            "path": "/api/items",
            "status": 200,
            "duration_ms": duration,
        }},
    )
    time.sleep(0.1)

try:
    raise ValueError("некорректный параметр")
except ValueError:
    log.exception("ошибка обработки", extra={"extra_fields": {"request_id": "req-003"}})
PY

cat > Dockerfile.jsonlog <<'EOF'
FROM python:3.13-slim
ENV PYTHONUNBUFFERED=1
WORKDIR /app
COPY json_logging.py app_json.py ./
CMD ["python", "app_json.py"]
EOF

docker build -q -f Dockerfile.jsonlog -t log:json . > /dev/null
docker run --rm log:json | head -3

{"ts":"2026-07-30T12:40:11.203Z","level":"INFO","logger":"app.api","message":"сервис запущен","version":"1.4.2","pid":1}
{"ts":"2026-07-30T12:40:11.204Z","level":"INFO","logger":"app.api","message":"запрос обработан","request_id":"req-000","method":"GET","path":"/api/items","status":200,"duration_ms":412}
{"ts":"2026-07-30T12:40:11.305Z","level":"INFO","logger":"app.api","message":"запрос обработан","request_id":"req-001","method":"GET","path":"/api/items","status":200,"duration_ms":97}

echo "=== все строки валидны как JSON? ==="
docker run --rm log:json | python3 -c "
import json, sys
n = 0
for line in sys.stdin:
    json.loads(line)
    n += 1
print(f'  {n} строк, все валидны')
"

echo
echo "=== запросы дольше 300 мс ==="
docker run --rm log:json | python3 -c "
import json, sys
for line in sys.stdin:
    r = json.loads(line)
    if r.get('duration_ms', 0) > 300:
        print(f\"  {r['request_id']}: {r['duration_ms']} мс\")
"

echo
echo "=== только ошибки ==="
docker run --rm log:json | python3 -c "
import json, sys
for line in sys.stdin:
    r = json.loads(line)
    if r['level'] == 'ERROR':
        print(f\"  {r['message']} (request_id={r.get('request_id')})\")
"

=== все строки валидны как JSON? ===
  5 строк, все валидны

=== запросы дольше 300 мс ===
  req-000: 412 мс
  req-002: 638 мс

=== только ошибки ===
  ошибка обработки (request_id=req-003)

cat > split_streams.py <<'PY'
"""Разделение: INFO и ниже в stdout, WARNING и выше в stderr."""
from __future__ import annotations

import logging
import sys


class MaxLevelFilter(logging.Filter):
    """Пропускает записи не выше заданного уровня."""

    def __init__(self, max_level: int):
        super().__init__()
        self.max_level = max_level

    def filter(self, record: logging.LogRecord) -> bool:
        return record.levelno <= self.max_level


def configure(level: str = "INFO") -> None:
    fmt = logging.Formatter("%(levelname)-8s %(message)s")

    out = logging.StreamHandler(sys.stdout)
    out.setFormatter(fmt)
    out.addFilter(MaxLevelFilter(logging.INFO))   # только DEBUG и INFO

    err = logging.StreamHandler(sys.stderr)
    err.setFormatter(fmt)
    err.setLevel(logging.WARNING)                  # WARNING и выше

    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(out)
    root.addHandler(err)
    root.setLevel(level.upper())


if __name__ == "__main__":
    configure()
    log = logging.getLogger("app")
    log.info("информационное сообщение")
    log.warning("предупреждение")
    log.error("ошибка")
PY

cat > Dockerfile.split <<'EOF'
FROM python:3.13-slim
ENV PYTHONUNBUFFERED=1
COPY split_streams.py /app.py
CMD ["python", "/app.py"]
EOF

docker build -q -f Dockerfile.split -t log:split . > /dev/null
docker run -d --name split-t log:split > /dev/null
sleep 1

echo "=== только stdout ==="
docker logs split-t 2>/dev/null | sed 's/^/  /'
echo "=== только stderr ==="
docker logs split-t 2>&1 1>/dev/null | sed 's/^/  /'
docker rm split-t > /dev/null

=== только stdout ===
  INFO     информационное сообщение
=== только stderr ===
  WARNING  предупреждение
  ERROR    ошибка

cat > correlation.py <<'PY'
"""Correlation ID через contextvars: доступен во всех функциях запроса."""
from __future__ import annotations

import contextvars
import json
import logging
import sys
import uuid
from datetime import datetime, timezone

request_id_var: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="-")


class CorrelationFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": datetime.fromtimestamp(record.created, tz=timezone.utc)
            .isoformat(timespec="milliseconds").replace("+00:00", "Z"),
            "level": record.levelname,
            "logger": record.name,
            "request_id": request_id_var.get(),
            "message": record.getMessage(),
        }
        for k, v in getattr(record, "extra_fields", {}).items():
            payload.setdefault(k, v)
        return json.dumps(payload, ensure_ascii=False, default=str)


def configure(level: str = "INFO") -> None:
    h = logging.StreamHandler(sys.stdout)
    h.setFormatter(CorrelationFormatter())
    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(h)
    root.setLevel(level.upper())


log = logging.getLogger("app")


def validate(payload: dict) -> None:
    """Вложенная функция: request_id доступен без передачи параметром."""
    log.info("валидация", extra={"extra_fields": {"fields": len(payload)}})


def persist(payload: dict) -> None:
    log.info("сохранение в базу")


def handle_request(payload: dict) -> None:
    token = request_id_var.set(f"req-{uuid.uuid4().hex[:8]}")
    try:
        log.info("запрос принят")
        validate(payload)
        persist(payload)
        log.info("запрос обработан")
    finally:
        request_id_var.reset(token)


if __name__ == "__main__":
    configure()
    for i in range(2):
        handle_request({"a": 1, "b": 2})
PY

cat > Dockerfile.corr <<'EOF'
FROM python:3.13-slim
ENV PYTHONUNBUFFERED=1
COPY correlation.py /app.py
CMD ["python", "/app.py"]
EOF

docker build -q -f Dockerfile.corr -t log:corr . > /dev/null
docker run --rm log:corr | python3 -c "
import json, sys
for line in sys.stdin:
    r = json.loads(line)
    print(f\"  {r['request_id']}  {r['message']}\")
"

  req-3f2a1b4c  запрос принят
  req-3f2a1b4c  валидация
  req-3f2a1b4c  сохранение в базу
  req-3f2a1b4c  запрос обработан
  req-8e7d6c5b  запрос принят
  req-8e7d6c5b  валидация
  req-8e7d6c5b  сохранение в базу
  req-8e7d6c5b  запрос обработан

cat > uvicorn_app.py <<'PY'
"""Логи Uvicorn в том же формате, что и логи приложения."""
from __future__ import annotations

import json
import logging
import os
import sys
from datetime import datetime, timezone

from fastapi import FastAPI


class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": datetime.fromtimestamp(record.created, tz=timezone.utc)
            .isoformat(timespec="milliseconds").replace("+00:00", "Z"),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
        }
        if record.exc_info:
            payload["exception"] = self.formatException(record.exc_info)
        for k, v in getattr(record, "extra_fields", {}).items():
            payload.setdefault(k, v)
        return json.dumps(payload, ensure_ascii=False, default=str)


def configure(level: str = "INFO") -> None:
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(JsonFormatter())

    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(handler)
    root.setLevel(level.upper())

    # Логгеры Uvicorn: убираем их обработчики, включаем передачу корневому
    for name in ("uvicorn", "uvicorn.access", "uvicorn.error"):
        lg = logging.getLogger(name)
        lg.handlers.clear()
        lg.propagate = True


configure(os.environ.get("LOG_LEVEL", "INFO"))
log = logging.getLogger("app")

app = FastAPI()


@app.get("/")
async def root():
    log.info("обработка запроса", extra={"extra_fields": {"path": "/"}})
    return {"ok": True}
PY

cat > Dockerfile.uvicorn <<'EOF'
FROM python:3.13-slim
ENV PYTHONUNBUFFERED=1
RUN pip install --no-cache-dir "fastapi[standard]==0.141.1"
WORKDIR /app
COPY uvicorn_app.py .
CMD ["fastapi", "run", "uvicorn_app.py", "--port", "8000"]
EOF

docker build -q -f Dockerfile.uvicorn -t log:uvicorn . > /dev/null
docker run -d --name uv-t -p 8200:8000 log:uvicorn > /dev/null
sleep 6
curl -s localhost:8200/ > /dev/null

echo "все записи, включая uvicorn, в одном формате:"
docker logs uv-t 2>&1 | grep '^{' | python3 -c "
import json, sys
for line in sys.stdin:
    try:
        r = json.loads(line)
    except json.JSONDecodeError:
        continue
    print(f\"  [{r['logger']:<16}] {r['message'][:60]}\")
" | head -6
docker rm -f uv-t > /dev/null

все записи, включая uvicorn, в одном формате:
  [uvicorn.error   ] Started server process [1]
  [uvicorn.error   ] Waiting for application startup.
  [uvicorn.error   ] Application startup complete.
  [app             ] обработка запроса
  [uvicorn.access  ] 172.17.0.1:52134 - "GET / HTTP/1.1" 200

docker run -d --name rotate-t \
    --log-driver local \
    --log-opt max-size=1m \
    --log-opt max-file=3 \
    log:json > /dev/null 2>&1 || \
docker run -d --name rotate-t \
    --log-opt max-size=1m \
    --log-opt max-file=3 \
    log:json > /dev/null

sleep 2
docker inspect rotate-t --format 'драйвер: {{.HostConfig.LogConfig.Type}}, опции: {{.HostConfig.LogConfig.Config}}'
docker rm -f rotate-t > /dev/null

драйвер: local, опции: map[max-file:3 max-size:1m]

cd /tmp
docker rmi -f $(docker images -q --filter 'reference=log:*') 2>/dev/null || true
rm -rf /tmp/pylog

mkdir -p /tmp/vlog && cd /tmp/vlog
cat > a.py <<'PY'
import logging, sys
h = logging.StreamHandler(sys.stdout)
h.setFormatter(logging.Formatter("%(levelname)s %(message)s"))
r = logging.getLogger(); r.handlers.clear(); r.addHandler(h); r.setLevel("INFO")
logging.getLogger("app").info("видно сразу")
PY
printf 'FROM python:3.13-slim\nENV PYTHONUNBUFFERED=1\nCOPY a.py /a.py\nCMD ["python","/a.py"]\n' > Dockerfile
docker build -q -t vlog:1 . > /dev/null
docker run --rm vlog:1
docker rmi vlog:1 > /dev/null; cd /tmp && rm -rf /tmp/vlog