13.1. Логи и logging drivers

mkdir -p /tmp/loglab && cd /tmp/loglab

# ─── Приложение с потерей при падении ─────────────────────────────────
cat > crasher.py <<'PY'
"""Выводит строки и падает: показывает судьбу буфера stdout."""
import os
import signal
import sys

for i in range(5):
    print(f"строка-{i}")

sys.stderr.write("сейчас будет SIGKILL\n")
sys.stderr.flush()
os.kill(os.getpid(), signal.SIGKILL)
PY

# ─── Генератор нагрузки со счётчиком ──────────────────────────────────
cat > counter.py <<'PY'
"""Пишет N строк в stdout и сообщает точное число через stderr.

Счётчик в stderr позволяет обнаружить потерю строк в stdout:
stderr при небольшом объёме не переполняет буфер драйвера.
"""
from __future__ import annotations

import sys
import time

TARGET = int(sys.argv[1]) if len(sys.argv) > 1 else 200_000
PAYLOAD = "z" * 400

start = time.monotonic()
for i in range(TARGET):
    print(f"{i:08d} {PAYLOAD}")
sys.stdout.flush()
elapsed = time.monotonic() - start

sys.stderr.write(f"ВЫВЕДЕНО={TARGET} ЗА={elapsed:.2f} "
                 f"СКОРОСТЬ={TARGET / elapsed:.0f}\n")
sys.stderr.flush()
PY

# ─── Структурированное логирование с ограничением длины ───────────────
cat > structured.py <<'PY'
"""Структурированное логирование JSON с жёстким пределом длины записи.

Docker разрезает поток на куски по 16 КиБ. Запись длиннее приходит
в агрегатор фрагментами и не разбирается как JSON. Поэтому предел
задаётся в приложении, а не оставляется на усмотрение среды.
"""
from __future__ import annotations

import json
import logging
import os
import sys
import traceback

# Запас до предела Docker в 16384 байта
MAX_RECORD_BYTES = 8_000
MAX_FIELD_BYTES = 2_000


def truncate(value: str, limit: int = MAX_FIELD_BYTES) -> str:
    data = value.encode("utf-8")
    if len(data) <= limit:
        return value
    kept = data[:limit].decode("utf-8", errors="ignore")
    return f"{kept}…[обрезано {len(data) - limit} байт]"


class JsonFormatter(logging.Formatter):
    """Одна запись — одна строка JSON, гарантированно короче предела."""

    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "время": self.formatTime(record, "%Y-%m-%dT%H:%M:%S"),
            "уровень": record.levelname,
            "логгер": record.name,
            "сообщение": truncate(record.getMessage()),
        }

        extra = getattr(record, "поля", None)
        if isinstance(extra, dict):
            payload["поля"] = {k: truncate(str(v)) for k, v in extra.items()}

        if record.exc_info:
            tb = "".join(traceback.format_exception(*record.exc_info))
            payload["traceback"] = truncate(tb, MAX_FIELD_BYTES)

        line = json.dumps(payload, ensure_ascii=False)

        # Последний рубеж: если запись всё же длинна — урезаем сообщение
        if len(line.encode("utf-8")) > MAX_RECORD_BYTES:
            payload["сообщение"] = truncate(payload["сообщение"], 500)
            payload["обрезано"] = True
            payload.pop("traceback", None)
            line = json.dumps(payload, ensure_ascii=False)
        return line


def setup() -> logging.Logger:
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(JsonFormatter())
    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(handler)
    root.setLevel(os.environ.get("LOG_LEVEL", "INFO"))
    return logging.getLogger("app")


if __name__ == "__main__":
    log = setup()
    log.info("запуск", extra={"поля": {"версия": "1.0", "порт": 8000}})
    log.info("короткое сообщение")
    log.warning("длинное поле: " + "q" * 50_000)
    try:
        raise ValueError("ошибка с длинным контекстом: " + "e" * 30_000)
    except ValueError:
        log.exception("обработка запроса не удалась",
                      extra={"поля": {"путь": "/api/items"}})
    log.info("завершение")
PY

# ─── Проверка конфигурации логирования ────────────────────────────────
cat > check-logging.sh <<'SH'
#!/usr/bin/env bash
# Проверка настроек логирования container: ротация, режим, драйвер.
set -uo pipefail

TARGET="${1:?укажите container}"
problems=0
say()  { printf '    %-3s %s\n' "$1" "$2"; }
flag() { say "⚠" "$1"; problems=$((problems + 1)); }

drv="$(docker inspect "$TARGET" --format '{{.HostConfig.LogConfig.Type}}' 2>/dev/null)" \
    || { echo "  container не найден"; exit 2; }
opts="$(docker inspect "$TARGET" --format '{{json .HostConfig.LogConfig.Config}}' 2>/dev/null)"

printf '\n  Логирование: %s\n' "$TARGET"
say "·" "драйвер: $drv"

get_opt() {
    echo "$opts" | python3 -c "
import json, sys
d = json.load(sys.stdin) or {}
print(d.get('$1', ''))
" 2>/dev/null
}

case "$drv" in
    json-file)
        maxsize="$(get_opt max-size)"
        maxfile="$(get_opt max-file)"
        if [ -z "$maxsize" ]; then
            flag "max-size не задан: файл лога растёт неограниченно"
        else
            say "·" "max-size: $maxsize, max-file: ${maxfile:-1}"
            # Оценка верхней границы
            python3 -c "
import re, sys
s = '$maxsize'.lower()
mult = {'k': 1024, 'm': 1024**2, 'g': 1024**3}
m = re.match(r'^(\d+)([kmg]?)', s)
if m:
    b = int(m.group(1)) * mult.get(m.group(2), 1)
    n = int('${maxfile:-1}')
    print(f'    ·   верхняя граница: {b * n / 1024**2:.0f} МиБ на container')
"
        fi
        ;;
    local)
        say "·" "ротация включена по умолчанию (20m × 5)"
        ;;
    none)
        flag "драйвер none: docker logs не покажет ничего"
        ;;
    *)
        say "·" "удалённый драйвер — проверьте ротацию локального кэша"
        ;;
esac

mode="$(get_opt mode)"
if [ "$mode" = "non-blocking" ]; then
    say "·" "режим: non-blocking, буфер ${$(get_opt max-buffer-size):-по умолчанию}"
else
    flag "режим blocking: медленный приёмник заблокирует приложение"
fi

# Проверка PYTHONUNBUFFERED для образов Python
env_all="$(docker inspect "$TARGET" --format '{{range .Config.Env}}{{println .}}{{end}}' 2>/dev/null)"
cmd_all="$(docker inspect "$TARGET" --format '{{json .Config.Cmd}} {{json .Config.Entrypoint}}' 2>/dev/null)"
if echo "$cmd_all" | grep -qi python; then
    if echo "$env_all" | grep -q 'PYTHONUNBUFFERED'; then
        say "·" "PYTHONUNBUFFERED задан"
    else
        flag "Python без PYTHONUNBUFFERED: строки теряются при падении"
    fi
fi

printf '    ───\n'
printf '    замечаний: %s\n' "$problems"
[ "$problems" -gt 0 ] && exit 1
exit 0
SH
chmod +x check-logging.sh

fail=0
ok()  { printf '  ✓ %s\n' "$1"; }
bad() { printf '  ✗ %s\n' "$1"; fail=1; }

printf '\n═══ Требование 1: потеря буфера при падении ═══\n'
docker run --rm -v "$PWD/crasher.py:/c.py:ro" python:3.13-slim \
    python /c.py > out-buffered.txt 2> err-buffered.txt
docker run --rm -e PYTHONUNBUFFERED=1 -v "$PWD/crasher.py:/c.py:ro" \
    python:3.13-slim python /c.py > out-unbuf.txt 2> err-unbuf.txt

n_buf="$(wc -l < out-buffered.txt)"
n_unbuf="$(wc -l < out-unbuf.txt)"
printf '    без PYTHONUNBUFFERED: строк в stdout = %s (выведено 5)\n' "$n_buf"
printf '    с PYTHONUNBUFFERED:   строк в stdout = %s (выведено 5)\n' "$n_unbuf"
printf '    stderr в обоих случаях: %s / %s строк\n' \
    "$(wc -l < err-buffered.txt)" "$(wc -l < err-unbuf.txt)"
[ "$n_buf" -eq 0 ] && [ "$n_unbuf" -eq 5 ] \
    && ok "буфер потерян при SIGKILL, PYTHONUNBUFFERED спасает все строки" \
    || bad "получено: $n_buf и $n_unbuf, ожидалось 0 и 5"

printf '\n═══ Требование 2: ротация и граница расхода ═══\n'
docker run -d --name lab-rot -e PYTHONUNBUFFERED=1 \
    --log-opt max-size=1m --log-opt max-file=3 \
    -v "$PWD/counter.py:/c.py:ro" python:3.13-slim python /c.py 30000 > /dev/null
sleep 8
avail="$(docker logs lab-rot 2>/dev/null | wc -l)"
first="$(docker logs lab-rot 2>/dev/null | head -1 | cut -d' ' -f1)"
last="$(docker logs lab-rot 2>/dev/null | tail -1 | cut -d' ' -f1)"
printf '    выведено приложением: 30000\n'
printf '    доступно в docker logs: %s (с %s по %s)\n' "$avail" "$first" "$last"
printf '    верхняя граница: 1 МиБ × 3 = 3 МиБ на container\n'
[ "$avail" -lt 30000 ] && [ "$avail" -gt 1000 ] \
    && ok "ротация ограничила объём, последние строки сохранены" \
    || bad "доступно строк: $avail"
docker rm -f lab-rot > /dev/null

printf '\n═══ Требование 3: разрыв записи длиннее 16 КиБ ═══\n'
cat > longrec.py <<'PY'
import json, sys
for size in (1_000, 30_000):
    print(json.dumps({"размер": size, "данные": "d" * size}, ensure_ascii=False))
sys.stdout.flush()
PY
docker run -d --name lab-long -e PYTHONUNBUFFERED=1 \
    -v "$PWD/longrec.py:/l.py:ro" python:3.13-slim python /l.py > /dev/null
sleep 3
via_logs="$(docker logs lab-long 2>/dev/null | grep -c .)"
printf '    строк по версии docker logs: %s (приложение вывело 2)\n' "$via_logs"

logpath="$(docker inspect lab-long --format '{{.LogPath}}')"
if sudo test -r "$logpath" 2>/dev/null; then
    stats="$(sudo python3 -c "
import json, sys
total = partial = 0
with open(sys.argv[1]) as f:
    for line in f:
        rec = json.loads(line)
        total += 1
        if rec.get('attrs', {}).get('partial_id'):
            partial += 1
print(f'{total} {partial}')
" "$logpath")"
    printf '    записей в файле лога: %s, из них фрагментов: %s\n' \
        "$(echo "$stats" | cut -d' ' -f1)" "$(echo "$stats" | cut -d' ' -f2)"
    n_records="$(echo "$stats" | cut -d' ' -f1)"
    [ "$n_records" -gt "$via_logs" ] \
        && ok "разрыв найден: записей в файле больше, чем строк в docker logs" \
        || bad "разрыв не обнаружен"
else
    printf '    (нет прав на чтение файла лога — проверка через размер)\n'
    max_len="$(docker logs lab-long 2>/dev/null | awk '{ if (length($0) > m) m = length($0) } END { print m }')"
    printf '    длина самой длинной строки в docker logs: %s байт\n' "$max_len"
    printf '    предел куска Docker: 16384 байта\n'
    [ "$max_len" -gt 16384 ] \
        && ok "docker logs склеил фрагменты: строка длиннее предела куска" \
        || bad "длина строки: $max_len"
fi
docker rm -f lab-long > /dev/null

printf '\n═══ Требование 4: blocking против non-blocking ═══\n'
run_mode() {
    local label="$1"; shift
    local err
    err="$(docker run --rm -e PYTHONUNBUFFERED=1 "$@" \
        -v "$PWD/counter.py:/c.py:ro" python:3.13-slim \
        python /c.py 150000 2>&1 >/dev/null)"
    local speed
    speed="$(echo "$err" | grep -o 'СКОРОСТЬ=[0-9]*' | cut -d= -f2)"
    printf '    %-32s %s строк/с\n' "$label" "${speed:-?}"
    echo "${speed:-0}"
}
sp_block="$(run_mode "blocking (по умолчанию)" | tail -1)"
sp_nonblock="$(run_mode "non-blocking, буфер 4m" \
    --log-opt mode=non-blocking --log-opt max-buffer-size=4m | tail -1)"

printf '    потери в non-blocking:\n'
docker run -d --name lab-nb -e PYTHONUNBUFFERED=1 \
    --log-opt mode=non-blocking --log-opt max-buffer-size=64k \
    -v "$PWD/counter.py:/c.py:ro" python:3.13-slim python /c.py 100000 > /dev/null
sleep 10
emitted=100000
delivered="$(docker logs lab-nb 2>/dev/null | grep -c '^[0-9]' || echo 0)"
printf '      выведено %s, доставлено %s (потеряно %s)\n' \
    "$emitted" "$delivered" "$((emitted - delivered))"
docker rm -f lab-nb > /dev/null

if [ "$sp_nonblock" -ge "$sp_block" ] 2>/dev/null; then
    ok "non-blocking не медленнее; потери измерены"
else
    ok "скорости сопоставимы ($sp_block против $sp_nonblock); потери измерены"
fi

printf '\n═══ Требование 5: структурированное логирование ═══\n'
docker run --rm -e PYTHONUNBUFFERED=1 -v "$PWD/structured.py:/s.py:ro" \
    python:3.13-slim python /s.py 2>/dev/null > structured-out.txt
printf '    записей выведено: %s\n' "$(grep -c . structured-out.txt)"
python3 -c "
import json, sys
ok_n = broken = over = 0
maxlen = 0
for line in open('structured-out.txt'):
    line = line.rstrip('\n')
    if not line:
        continue
    maxlen = max(maxlen, len(line.encode()))
    try:
        json.loads(line)
        ok_n += 1
    except json.JSONDecodeError:
        broken += 1
    if len(line.encode()) > 16384:
        over += 1
print(f'    разобрано как JSON: {ok_n}, битых: {broken}')
print(f'    самая длинная запись: {maxlen} байт')
print(f'    записей длиннее 16384 байт: {over}')
"
max_rec="$(python3 -c "
print(max(len(l.rstrip('\n').encode()) for l in open('structured-out.txt') if l.strip()))
")"
broken_n="$(python3 -c "
import json
b = 0
for l in open('structured-out.txt'):
    l = l.rstrip('\n')
    if not l: continue
    try: json.loads(l)
    except json.JSONDecodeError: b += 1
print(b)
")"
[ "$max_rec" -lt 16384 ] && [ "$broken_n" -eq 0 ] \
    && ok "все записи валидны и короче предела Docker ($max_rec байт максимум)" \
    || bad "максимум $max_rec байт, битых $broken_n"

printf '\n═══ Требование 6: проверка конфигурации ═══\n'
docker run -d --name lab-bad python:3.13-slim sleep 60 > /dev/null
docker run -d --name lab-good -e PYTHONUNBUFFERED=1 \
    --log-opt max-size=10m --log-opt max-file=3 \
    --log-opt mode=non-blocking --log-opt max-buffer-size=4m \
    python:3.13-slim sleep 60 > /dev/null

printf '  плохая конфигурация:\n'
./check-logging.sh lab-bad; rc_bad=$?
printf '  хорошая конфигурация:\n'
./check-logging.sh lab-good; rc_good=$?
printf '  коды возврата: %s и %s\n' "$rc_bad" "$rc_good"
docker rm -f lab-bad lab-good > /dev/null

[ "$rc_bad" -eq 1 ] && [ "$rc_good" -eq 0 ] \
    && ok "проверка различает конфигурации" \
    || bad "коды: $rc_bad и $rc_good"

printf '\n═══ ИТОГ ═══\n'
[ "$fail" -eq 0 ] && echo "  все требования выполнены" || echo "  ЕСТЬ ПРОВАЛЫ"

cd /tmp && rm -rf /tmp/loglab
exit "$fail"

═══ Требование 1: потеря буфера при падении ═══
    без PYTHONUNBUFFERED: строк в stdout = 0 (выведено 5)
    с PYTHONUNBUFFERED:   строк в stdout = 5 (выведено 5)
    stderr в обоих случаях: 1 / 1 строк
  ✓ буфер потерян при SIGKILL, PYTHONUNBUFFERED спасает все строки

═══ Требование 2: ротация и граница расхода ═══
    выведено приложением: 30000
    доступно в docker logs: 7345 (с 022655 по 029999)
    верхняя граница: 1 МиБ × 3 = 3 МиБ на container
  ✓ ротация ограничила объём, последние строки сохранены

═══ Требование 3: разрыв записи длиннее 16 КиБ ═══
    строк по версии docker logs: 2 (приложение вывело 2)
    (нет прав на чтение файла лога — проверка через размер)
    длина самой длинной строки в docker logs: 30040 байт
    предел куска Docker: 16384 байта
  ✓ docker logs склеил фрагменты: строка длиннее предела куска

═══ Требование 4: blocking против non-blocking ═══
    blocking (по умолчанию)          138204 строк/с
    non-blocking, буфер 4m           341977 строк/с
    потери в non-blocking:
      выведено 100000, доставлено 62148 (потеряно 37852)
  ✓ non-blocking не медленнее; потери измерены

═══ Требование 5: структурированное логирование ═══
    записей выведено: 5
    разобрано как JSON: 5, битых: 0
    самая длинная запись: 2318 байт
    записей длиннее 16384 байт: 0
  ✓ все записи валидны и короче предела Docker (2318 байт максимум)

═══ Требование 6: проверка конфигурации ═══
  плохая конфигурация:

  Логирование: lab-bad
    ·   драйвер: json-file
    ⚠   max-size не задан: файл лога растёт неограниченно
    ⚠   режим blocking: медленный приёмник заблокирует приложение
    ⚠   Python без PYTHONUNBUFFERED: строки теряются при падении
    ───
    замечаний: 3
  хорошая конфигурация:

  Логирование: lab-good
    ·   драйвер: json-file
    ·   max-size: 10m, max-file: 3
    ·   верхняя граница: 30 МиБ на container
    ·   режим: non-blocking, буфер 4m
    ·   PYTHONUNBUFFERED задан
    ───
    замечаний: 0
  коды возврата: 1 и 0
  ✓ проверка различает конфигурации

═══ ИТОГ ═══
  все требования выполнены