Чтение MCP-логов: что искать и где

После работы с контекстом и токенами настало время разобраться, что происходит внутри MCP-сессии на уровне протокольного трафика. Для этого нужны логи — и умение их читать.

Структура MCP-лога и уровни детализации

Каждое сообщение MCP-протокола оставляет след в логе. Запись содержит несколько ключевых полей, и понимание их смысла — отправная точка любой диагностики. Что входит в одну запись лога

Минимально информативная запись включает:

• timestamp — момент события с точностью до миллисекунды
• direction — откуда и куда идёт сообщение (client→server или server→client)
• type — тип сообщения: request, response или notification
• method — имя метода (например, tools/call, initialize)
• id — идентификатор запроса (присутствует только у request и response)
• payload — тело сообщения в виде JSON-объекта

Формат хранения чаще всего — JSON-lines: каждая строка файла это самостоятельный JSON-объект. Это позволяет потоково читать лог, фильтровать grep-ом или jq без парсинга всего файла целиком. Пример одной строки лога:

{"timestamp": "2024-11-15T10:23:41.082Z", "direction": "client→server", "type": "request", "method": "tools/call", "id": 42, "payload": {"name": "run_query", "arguments": {"sql": "SELECT * FROM orders LIMIT 10"}}}

И ответ на неё:

{"timestamp": "2024-11-15T10:23:41.910Z", "direction": "server→client", "type": "response", "id": 42, "payload": {"result": {"content": [{"type": "text", "text": "10 rows returned"}], "isError": false}}}

Оба события связаны через id: 42 — это и есть механизм сопоставления, но о нём подробнее в следующем разделе. Уровни логирования и зачем они нужны

Глубина записи определяется уровнем логирования. Для MCP-диагностики различают четыре рабочих уровня:

• DEBUG — пишет полный payload каждого сообщения. Только на этом уровне видно содержимое аргументов вызова инструмента и тело ответа. Незаменим при отладке.
• INFO — фиксирует метаданные: метод, id, направление, временну́ю метку. Тело сообщения не пишется. Достаточно для мониторинга нормальной работы.
• WARN — сигнализирует о нештатных, но не критичных состояниях: неожиданный порядок сообщений, медленный ответ, deprecated-метод.
• ERROR — фиксирует сбои обработки и нарушения протокола: упавший инструмент, невалидный JSON, отсутствие обязательного поля. Выбор уровня — это компромисс между полнотой и безопасностью. На DEBUG в лог попадает всё, включая аргументы запросов, которые могут содержать токены, пароли или персональные данные. Поэтому DEBUG включают только на период активной диагностики — не в штатном режиме. Для первичной диагностики сбоя INFO чаще всего недостаточен: видно, что запрос был отправлен и что пришёл ERROR, но не видно ни аргументов, ни деталей ошибки. Переключение на DEBUG и воспроизведение проблемы — стандартный первый шаг при разборе инцидента.

Lifecycle MCP-сессии в логах

Прежде чем читать конкретные записи, полезно понимать, какую форму имеет вся сессия целиком. MCP-сессия — не поток произвольных сообщений: у неё есть чёткий порядок, и лог этот порядок отражает. Нормальная последовательность инициализации

Каждая сессия начинается с трёхшагового рукопожатия:

1. Клиент отправляет initialize request — сообщает свою версию протокола и список поддерживаемых возможностей.
2. Сервер отвечает initialize response — подтверждает совместимость и возвращает свои capabilities.
3. Клиент отправляет initialized notification — сигнализирует, что готов к работе. Только после initialized notification сессия считается открытой. Любые рабочие запросы (tools/list, tools/call и прочие) до этой точки — нарушение протокола. В логе это выглядит примерно так:

{"timestamp": "2024-11-15T10:23:40.010Z", "direction": "client→server", "type": "request", "method": "initialize", "id": 1, "payload": {"protocolVersion": "2024-11-05", "capabilities": {}}}
{"timestamp": "2024-11-15T10:23:40.031Z", "direction": "server→client", "type": "response", "id": 1, "payload": {"result": {"protocolVersion": "2024-11-05", "capabilities": {"tools": {}}}}}
{"timestamp": "2024-11-15T10:23:40.035Z", "direction": "client→server", "type": "notification", "method": "initialized", "payload": {}}

Обратите внимание: initialized — это notification, поэтому у него нет поля id. Это не ошибка записи, это нормально по спецификации. Как выглядит завершение сессии

Завершение фиксируется двумя способами в зависимости от реализации. В некоторых серверах — явный shutdown request с ответом, после которого клиент закрывает транспортное соединение. В других — просто разрыв транспорта (закрытие stdio, WebSocket). В логе это либо запись о shutdown, либо запись о разрыве соединения на транспортном уровне. Если лог обрывается без явного завершения — сессия скорее всего упала, а не закрылась штатно. Что считается нарушением порядка

Есть два типичных нарушения lifecycle, которые хорошо видны в логах:

• Рабочий запрос до initialized notification. Например, tools/call появляется в логе раньше, чем initialized. Это означает, что клиент не дождался завершения рукопожатия — либо баг в реализации клиента, либо гонка условий при асинхронной инициализации.
• Отсутствие initialize response при наличии initialize request. Сервер не ответил на рукопожатие — транспортный сбой, падение сервера или несовместимость версий протокола. Когда видишь ERROR-запись в логе, первый вопрос — в какой фазе сессии она произошла. Если ошибка случилась до initialized, её природа совершенно другая, чем у ошибки внутри рабочей фазы. Lifecycle-контекст сужает пространство возможных причин ещё до того, как ты начинаешь разбирать конкретный payload.

Трассировка запроса по id и особенности уведомлений

Когда в логе появляется ERROR-запись, первый вопрос — к какому запросу она относится. Ответ почти всегда в поле id. Как работает сопоставление request/response

Каждый JSON-RPC request в MCP несёт числовой или строковый id, который клиент генерирует сам. Сервер обязан вернуть ответ с тем же id — либо успешный (result), либо ошибочный (error). Это соглашение и есть основа трассировки. Практически это выглядит так: берёшь id из любой интересующей записи и фильтруешь весь лог по нему:

grep '"id": 42' session.log

или через jq:

jq 'select(.id == 42)' session.log

В результате получаешь ровно две записи — request и response. Этого достаточно, чтобы восстановить полный цикл одного вызова: что клиент попросил и что сервер вернул. Пример пары для tools/call:

{"timestamp": "2024-11-15T10:23:41.082Z", "direction": "client→server", "type": "request", "method": "tools/call", "id": 42, "payload": {"name": "run_query", "arguments": {"sql": "SELECT * FROM orders WHERE id = 9999"}}}
{"timestamp": "2024-11-15T10:23:44.210Z", "direction": "server→client", "type": "response", "id": 42, "payload": {"error": {"code": -32603, "message": "execution timeout after 3000ms"}}}

Разница временны́х меток — 3,1 секунды. Это уже диагностический факт: сервер принял запрос, но не уложился в таймаут. Без сопоставления по id этот разрыв был бы невидим. Почему notifications не трассируются так же

Нотификации — отдельный случай. По спецификации JSON-RPC, notification — это сообщение, которое не требует ответа и не несёт id. Видел уже в секции про lifecycle: initialized notification приходит без id, и это норма. Если попытаться применить ту же фильтрацию по id к notification, получишь пустой результат — не потому что запись потерялась, а потому что её там просто нет. Notification идентифицируется только по методу и временно́й метке. Практический подход к уведомлениям — фильтровать по method:

jq 'select(.type == "notification" and .method == "tools/list_changed")' session.log

Затем смотришь на временну́ю метку: было ли уведомление получено раньше или позже проблемного запроса. Это помогает понять, не спровоцировало ли уведомление (например, tools/list_changed) неожиданное поведение клиента. Когда в логе нет response на request

Ещё один сценарий: request с id есть, а response — нет. Это само по себе аномалия. Возможные причины:

• Сервер упал до того, как успел ответить — лог обрывается или дальше идут только транспортные записи о разрыве соединения.
• Ответ потерян на транспортном уровне — редко при stdio, чаще при сетевом транспорте.
• Лог собирается не на том конце — клиентский лог не видит серверных ответов, если логирование настроено только на клиенте. Отсутствие response — это не всегда ошибка в payload. Иногда это признак того, что смотришь в неполный лог.

Классификация ошибок в MCP-логах

Трассировка по id показывает, что пошло не так. Классификация отвечает на вопрос — почему и что с этим делать. Это разные вопросы, и путать их дорого: способ устранения ошибки полностью зависит от её класса. В MCP-логах встречается три принципиально разных типа ошибок, и у каждого своя сигнатура в записях. Протокольные ошибки

Это нарушение самого протокола: невалидный JSON в теле сообщения, обращение к несуществующему методу, попытка вызвать инструмент до завершения фазы инициализации. Протокольная ошибка фиксируется в поле error ответа с кодом из диапазона JSON-RPC: -32700 (Parse error), -32601 (Method not found), -32600 (Invalid Request). В логе это выглядит так:

{"timestamp": "2024-11-15T10:23:41.100Z", "direction": "client→server", "type": "request", "method": "tools/invoke", "id": 17, "payload": {"name": "run_query"}}
{"timestamp": "2024-11-15T10:23:41.105Z", "direction": "server→client", "type": "response", "id": 17, "payload": {"error": {"code": -32601, "message": "Method not found: tools/invoke"}}}

Метод tools/invoke не существует в MCP — правильный метод tools/call. Сервер отвечает немедленно, без задержки: он даже не пытается выполнить запрос. Код -32601 и мгновенный ответ — визуальные маркеры протокольной ошибки. Ремедиация: исправлять клиентский код или версию протокола, а не логику инструмента на сервере. Ошибки выполнения инструмента (tool execution failure)

Протокол отработал корректно, сервер принял запрос и передал его инструменту — но инструмент упал. Это принципиально другой класс. Сервер возвращает технически успешный ответ (нет поля error верхнего уровня), но внутри result стоит флаг isError: true, а в content — описание сбоя.

{"timestamp": "2024-11-15T10:23:43.082Z", "direction": "client→server", "type": "request", "method": "tools/call", "id": 55, "payload": {"name": "run_query", "arguments": {"sql": "DROP TABLE orders"}}}
{"timestamp": "2024-11-15T10:23:43.190Z", "direction": "server→client", "type": "response", "id": 55, "payload": {"result": {"content": [{"type": "text", "text": "Error: permission denied for table orders"}], "isError": true}}}

Обратите внимание: HTTP-статус (если используется HTTP-транспорт) здесь был бы 200. Внешние мониторинги, смотрящие только на транспортный уровень, такую ошибку не поймают. Её видно только в payload на уровне DEBUG. Маркеры: isError: true внутри result, текстовое описание в content. Задержка ответа — нормальная или увеличенная в зависимости от того, на каком шаге упал инструмент. Ремедиация: разбирать логику самого инструмента, права доступа, входные аргументы — не трогать конфигурацию протокола. Доменные ошибки

Инструмент выполнился, isError: false, но результат содержит логический сбой: пустой датасет там, где ожидались строки, неожиданный статус внешнего API, бизнес-правило, которое не выполнилось. Это не ошибка протокола и не падение инструмента — это корректный ответ с семантически неожиданным содержимым. В логе такой ответ выглядит как успешный:

{"timestamp": "2024-11-15T10:24:01.350Z", "direction": "server→client", "type": "response", "id": 61, "payload": {"result": {"content": [{"type": "text", "text": "{\"status\": \"ok\", \"rows\": 0, \"warning\": \"No records match filter\"}" }], "isError": false}}}

MCP-протокол здесь ни при чём. Инструмент тоже работает правильно. Проблема в домене: либо входные аргументы построены неверно, либо данные в источнике не соответствуют ожиданиям. Такие ошибки в логах не светятся как ERROR — их нужно искать в теле content, читая фактический результат. Маркеры: отсутствие error и isError: true, но аномальное содержимое content — пустые списки, нулевые счётчики, предупреждения внутри результата. Ремедиация: анализировать входные аргументы запроса и состояние внешней системы, не трогать ни протокол, ни реализацию инструмента. Почему различение классов важно

Когда видишь в логе аномалию и не определяешь класс, риск — потратить время не там. Протокольная ошибка не лечится перезапуском инструмента. Tool execution failure не лечится исправлением метода запроса. Доменная ошибка вообще не диагностируется без чтения payload на уровне DEBUG. Первый вопрос при разборе любой аномалии: где находится маркер ошибки — в поле error верхнего уровня, в isError внутри result, или вообще только в семантике content? Ответ сразу сужает область поиска.

Процедура разбора реального сбоя на примере timeout

Теперь соберём всё вместе и пройдём по реальному фрагменту лога шаг за шагом. Сценарий: клиент вызвал инструмент run_query, но ответа не дождался в срок. Нужно идентифицировать проблемное сообщение и понять класс сбоя. Фрагмент лога

{"timestamp": "2024-11-15T10:23:40.010Z", "direction": "client→server", "type": "request", "method": "initialize", "id": 1, "payload": {"protocolVersion": "2024-11-05", "capabilities": {}}}
{"timestamp": "2024-11-15T10:23:40.031Z", "direction": "server→client", "type": "response", "id": 1, "payload": {"result": {"protocolVersion": "2024-11-05", "capabilities": {"tools": {}}}}}
{"timestamp": "2024-11-15T10:23:40.035Z", "direction": "client→server", "type": "notification", "method": "initialized", "payload": {}}
{"timestamp": "2024-11-15T10:23:41.082Z", "direction": "client→server", "type": "request", "method": "tools/call", "id": 42, "payload": {"name": "run_query", "arguments": {"sql": "SELECT * FROM orders WHERE status = 'pending'"}}}
{"timestamp": "2024-11-15T10:23:44.210Z", "direction": "server→client", "type": "response", "id": 42, "payload": {"error": {"code": -32603, "message": "execution timeout after 3000ms"}}}

Шаг 1: найти ERROR/WARN-записи

Фильтруем по уровню или ищем поле error в payload:

jq 'select(.payload.error != null)' session.log

Находим одну запись — response с id: 42. Шаг 2: извлечь id проблемного запроса

Из найденной записи берём id: 42. Шаг 3: собрать все записи с этим id

jq 'select(.id == 42)' session.log

Возвращает две записи: request в 10:23:41.082 и response в 10:23:44.210. Разница — 3,128 секунды. Это точно укладывается в описание ошибки execution timeout after 3000ms. Шаг 4: установить метод и направление

Request: client→server, метод tools/call, инструмент run_query. Сервер принял запрос, инструмент запустился — и не успел вернуть результат за 3 секунды. Шаг 5: сравнить request payload и response payload

Request передаёт SQL-запрос SELECT * FROM orders WHERE status = 'pending'. Response содержит не result, а error верхнего уровня с кодом -32603. Тело результата отсутствует — инструмент не завершил выполнение. Шаг 6: классифицировать ошибку

Код -32603 — Internal Error по JSON-RPC. Но природа сбоя — таймаут инструмента, не нарушение протокола. Это граничный случай: формально ошибка оформлена как протокольная (поле error верхнего уровня), но причина — tool execution failure. Сервер сам решил оборвать выполнение и вернул протокольную обёртку. Ремедиация направлена на инструмент: увеличить таймаут, оптимизировать запрос, добавить индекс на колонку status. Шаг 7: проверить lifecycle-последовательность вокруг сбоя

Smoke-проверка: initialize → initialize response → initialized notification — всё на месте, сессия была открыта корректно. tools/call появляется после initialized. Lifecycle чистый, сбой произошёл внутри рабочей фазы, а не при инициализации. Предостережение: не держи DEBUG в продакшене постоянно

Чтобы пройти шаги выше, нужен был полный payload каждой записи — а значит, уровень DEBUG. Это правильный выбор для диагностической сессии. Проблема возникает, когда DEBUG остаётся включённым постоянно. В payload tools/call могут оказаться SQL-запросы с чувствительными параметрами, токены авторизации, персональные данные из аргументов инструментов. При высокой нагрузке объём лог-файлов на DEBUG вырастает в десятки раз по сравнению с INFO. В продакшене стандартная конфигурация — INFO с маскированием чувствительных полей перед записью:

def sanitize_payload(payload: dict) -> dict:
    sensitive_keys = {"token", "password", "api_key", "secret"}
    return {
        k: "***" if k in sensitive_keys else v
        for k, v in payload.items()
    }

DEBUG включается точечно: на конкретном сервере, на период воспроизведения инцидента, затем возвращается на INFO. Такой режим даёт всю нужную глубину при разборе сбоя и не оставляет открытых данных в логах на постоянной основе.