Логирование HTTP-запросов: middleware

Любой посредник Gin — это функция, возвращающая gin.HandlerFunc: внешняя принимает зависимости, внутренняя обрабатывает каждый запрос. Скелет всегда один и тот же: зафиксировать время до c.Next(), дать обработчикам отработать, а всё после c.Next() выполнить уже с готовым ответом. Именно поэтому статус берут из c.Writer.Status() после Next — до Next там ноль, ответа ещё нет. Трассировка запросов через zap начинается с каркаса: логгер, метод, путь, query-строка, статус, латентность и клиент собираются в один With-потомок — по образцу per-request логгера из урока про request id. Дальше один вызов Info или Error пишет всё разом: поля в JSON лягут рядом с request_id, если тот уже стоит в base.

Механическая привязка уровня к классу ответа экономит десятки решений: пятисотые — Error, потому что это авария сервера и под них заводят алерты; четырёхсотые — Warn, потому что это поведение клиента, но шумное или подозрительное; остальное — Info, потому что по ним считают трафик. Спорные места всё равно появятся, и их лучше решить заранее командным правилом. 401 и 403: Warn наполняет дашборд брутфорса, но на публичном API с чужими сканерами — это половина потока. 404: Warn полезен после релиза, когда ищут битые ссылки, и превращается в мусор от сканеров путей. Моё рабочее правило: всё, что вы собираетесь алертить, — Error; всё, что вы собираетесь смотреть раз в день, — Warn; остальное — Info, и алерты на 4xx держать, только если умеете их глушить.

Access-запись без request_id — половина пользы потеряна: вы видите, что GET /orders был медленным, но не можете найти внутренние записи этого запроса. Поэтому base для access-лога собирают тем же приёмом, что и в уроке про request id: посредник идентификатора стоит первым, кладёт потомка в контекст, и логирующий посредник либо берёт готового из контекста, либо строит своего от base с тем же ID. В Gin прокинуть можно и через c.Set("logger", log) с достаёт c.Get — способ грубее контекста, но живёт в одной структуре запроса. Порядок посредников: RequestLogger, затем GinLogger — тогда access-запись и внутренние записи уносят один request_id, и grep по нему соединяет обе истории в одну хронологию.

Встроенный gin.Recovery() делает ровно два дела: ловит панику и отдаёт клиенту 500 — молча. В access-логе появится пятисотый статус без причины, а текст паники уйдёт в stderr штатным логом net/http — текстовым, без полей и без привязки к вашему потоку. Свой recovery пишет структуру: значение паники как поле, стек через debug.Stack() из runtime/debug, путь запроса — чтобы связать с access-записью. Стек в JSON выглядит громоздко, но это единственный артефакт, по которому ночной дежурный находит строку кода без пересборки и отладчика: его место в Error-записи, а не в отдельном файле.

Recovery ловит панику только в горутине запроса: defer с recover работает в той функции, где зарегистрирован, и в чужую горутину не тянет. Обработчик, запустивший фоновую горутину — отправка письма, прогрев кеша, — ответственности за её падение посреднику не передаёт: паника в новой горутине проходит мимо всех defer'ов запроса и убивает процесс, печатая стек текстом в stderr мимо zap. Лечение одно: каждая спавненная горутина оборачивается тем же паттерном руками — defer, recover, logger.Error с zap.Any("panic", err) и debug.Stack(). В крупных проектах для этого заводят helper вида WithRecovery(logger, fn) и правило код-ревью: «горутина — значит с обёрткой».

Здесь спотыкаются чаще всего. Паника раскручивает стек вверх, и посредник, у которого c.Next() ещё не вернулся, свой пост-код не выполняет. Если Recovery стоит снаружи, а Logger внутри, то access-запись умирает вместе с паникой: Recovery напишет стек, а строки с латентностью и статусом не будет вовсе. Правильный порядок обратный: Logger первым, Recovery вторым — Recovery гасит панику глубже, отдаёт 500, и Logger после Next видит обычный ответ со статусом 500 и честной латентностью. Регистрация в сборке — отдельный маленький код, и его стоит один раз прочитать вслух: Use перечисляет посредников снаружи внутрь в порядке вызова. Тонкость стоит минуты внимания, а экономит час поисков «почему паникующие запросы не в access-логе».

Каркас переносится один в один, меняется только сигнатура. В Echo посредник — e.Use(func(next echo.HandlerFunc) echo.HandlerFunc), статус берут из c.Response().Status после next(c), клиент — из c.RealIP(). В Fiber — app.Use(func(c *fiber.Ctx) error) с вызовом c.Next() посередине, статус — c.Response().StatusCode(), время — time.Since(start) вокруг того же Next. Уровень по статусу, стек паники и порядок «лог снаружи, recovery внутри» повторяются без изменений: различия не в идее, а в именах методов. Единственное, что стоит проверить при переносе, — как конкретный фреймворк считает время начала запроса: у Fiber латентность доступна и встроенной метрикой, но поле в своей записи всё равно надёжнее.

Следующий источник логов стоит в том же конвейере ниже: урок про GORM и zap покажет, как SQL-события попадают в общий поток с тем же request_id. Внутренние записи запроса — поле request_id из урока про сквозную трассировку, а тот же каркас на другом транспорте разобран в материале про перехватчики gRPC. Встроенные посредники Gin и их семантика — в уроке про middleware Gin; карта курса — на странице курса.