fix: Connection closed на каждом HTTP-вызове + улучшения логгинга (v0.6.1)

[szybnev]

Проблема

В v0.6.0 любой MCP-инструмент, который реально ходит в Ozon API (ozon_call_method, ozon_fetch_all, ozon_get_subscription_status), убивает процесс — MCP-клиент получает MCP error -32000: Connection closed без stacktrace. Статические инструменты (ozon_list_sections, ozon_describe_method, ozon_search_methods) работают нормально.

Корневая причина

structlog в _configure_logging() конфигурировался без logger_factory, из-за чего использовал дефолтный PrintLogger(file=sys.stdout). logging.basicConfig(stream=sys.stderr, ...) настраивал только stdlib-логгер — structlog оставался на stdout.

На каждом реальном API-вызове log.info(\"ozon_request\", ...) в transport/base.py:97 выводил JSON-строку на stdout, который MCP stdio использует для JSON-RPC фреймов. Клиент получал невалидный фрейм и закрывал трубу.

Статические инструменты не логируют — это и маскировало баг. Startup-логи (catalog_loaded, knowledge_loaded и т. п.) тоже уходили в stdout, но ДО того, как FastMCP перехватывал stdio, так что не ломали протокол — а при первом же реальном запросе падало.

Воспроизведение

OZON_CLIENT_ID=... OZON_API_KEY=... uv run python scripts/diagnose_mcp_stdio.py

Скрипт поднимает настоящий MCP-сервер через stdio и шлёт initialize + tools/call ozon_get_subscription_status. На 0.6.0 клиент получает в stdout лог-событие {\"event\": \"loading_catalog\", ...} вместо JSON-RPC ответа.

Исправление

fix: structlog → stderr (корневой)

• PrintLoggerFactory(file=sys.stderr) в structlog.configure(...).
• JSONRenderer(ensure_ascii=False) — Cyrillic в логах читается, а не \uXXXX.
• sys.stderr.reconfigure(encoding=\"utf-8\") на Windows — cp1252 иначе падает на Cyrillic в traceback.

feat: defense-in-depth

• Новый декоратор @safe_tool (tools/_safety.py) оборачивает handlers в try/except BaseException, конвертит всё в envelope {\"error_type\": \"internal\", ...}, пишет стектрейс в лог на ERROR. KeyboardInterrupt/SystemExit по-прежнему пробрасывает. Применён к ozon_call_method, ozon_fetch_all, ozon_get_subscription_status, ozon_list_methods_for_subscription. Добавлен новый error_type=\"internal\" в schema/errors.py.
• BaseClient.request: _auth_headers() и _rate_limits.for_call() перенесены ВНУТРЬ try-блока (раньше любая их ошибка обходила envelope). Добавлен финальный except Exception → OzonError(\"unexpected transport error: ...\") — страховка на httpx-исключения, не являющиеся HTTPError-подклассами, и на чужие middleware.
• asyncio exception handler — unawaited task exceptions теперь уходят в structlog событием asyncio_task_crashed.

feat: логгинг

• DEBUG-события ozon_request_body / ozon_response_body с truncate до 1 KB.
• INFO-событие ozon_response с status_code и duration_ms.
• tool_entry / tool_exit на DEBUG с duration_ms (через @safe_tool).
• Опциональный OZON_LOG_FILE — добавляет RotatingFileHandler (5 MB × 3 бэкапа) параллельно stderr. stderr MCP-клиента часто не видно пользователю — файл-лог выручает.
• ozon-mcp --diagnose — новый CLI-флаг. Делает один вызов /v1/seller/info, печатает OK subscription=... или FAIL + traceback, выходит. Рекомендованный способ проверить связь без MCP-клиента.

scripts/ (отладочные, не часть пакета)

• scripts/diagnose_live_call.py — out-of-band probe транспорта.
• scripts/diagnose_mcp_stdio.py — полный прогон MCP stdio subprocess'ом, как делает Claude Code. Нужен для регрессии на протокольном уровне.

Тесты

Новый файл tests/unit/test_tool_safety.py (8 кейсов):

• safe_tool возвращает envelope на sync/async исключении, пропускает успех, пробрасывает KeyboardInterrupt.
• Транспорт оборачивает ConnectError, generic Exception, исключение из _auth_headers в OzonError.
• Закреплённая регрессия test_configure_logging_does_not_write_to_stdout — structlog НЕ пишет в stdout, иначе протокол ломается.

Также:

• tests/unit/test_version_sync.py — добавлен encoding=\"utf-8\" в read_text (падало на Windows cp1252 при чтении pyproject.toml с Cyrillic — pre-existing, не мой баг, но на той же теме).

Результаты: 244 теста зелёные (tests/unit без test_subscription_generator.py — pre-existing Windows-баг генератора, не связан), mypy --strict чисто, ruff чисто.

Верификация end-to-end

Запущен scripts/diagnose_mcp_stdio.py с реальными credentials — получены корректные JSON-RPC ответы от ozon_get_subscription_status и ozon_call_method(\"ProductAPI_GetProductList\", limit=10). Сервер остался жив между запросами. Логи разделились чисто: JSON-RPC в stdout, structlog-события в stderr, видны duration_ms, tool_entry/tool_exit.

Changelog

Версия поднята до 0.6.1, запись в CHANGELOG.md с подробным описанием. Изменения не ломают обратную совместимость: envelope error_type=\"internal\" — новый вариант, старые клиенты игнорируют.

Test plan

• cd ozon-mcp && uv run pytest tests/unit --ignore=tests/unit/test_subscription_generator.py -v
• uv run mypy src/ && uv run ruff check src/
• OZON_CLIENT_ID=... OZON_API_KEY=... uv run ozon-mcp --diagnose — должен напечатать OK subscription=....
• Подключить к Claude Code / Cursor / любому MCP-клиенту, вызвать ozon_get_subscription_status — получить JSON-ответ, а не Connection closed.