gRPC: перехватчики для логов

Связку zap и grpc для unary-вызовов описывает тип grpc.UnaryServerInterceptor: grpc interceptor logging — это функция, принимающая контекст, запрос, info с описанием вызова и handler — сам вызов обработчика. Между «до» и «после» handler у перехватчика полная свобода: засечь время, достать metadata, построить дочерний логгер. info.FullMethod даёт стабильное имя вида /user.UserService/GetUser — оно же ключ для дашбордов и алертов, в отличие от путей HTTP-роутера, меняющихся от версии API. Возвращённые ответ и ошибка проходят наружу как есть: перехватчик — наблюдатель, а не фильтр. Регистрация — через grpc.NewServer(grpc.ChainUnaryInterceptor(...)): цепочка выполняется по порядку, и логирующий перехватчик обычно ставят первым, чтобы он видел полное время остальных — recovery, валидацию, аутентификацию.

Каждое поле отвечает на конкретный вопрос. method с FullMethod — какие вызовы приходят и куда смотреть в коде; для access-аналитики этого мало, но для поиска по логам его хватает. code — строка из codes.Code через String(): в JSON уходит DEADLINE_EXCEEDED, а не магическое число 4 — грепается и строится в дашборды. latency считается вокруг handler: вместе с перехватчиками выше по цепочке цифра вырастет, поэтому меряющий перехватчик ставят первым — иначе в латентность затесаются чужие задержки. peer — адрес клиента: для расследований «кто долбит сервис» это первое поле, куда смотрят. А вот сам req в лог перехватчик не пишет: там почты, суммы и идентификаторы, и сериализация тела запроса — отдельное осознанное решение с маскированием, как с SQL в уроке про GORM.

Ошибки в gRPC — не произвольные объекты: их конструируют через status.Error(codes.NotFound, "user not found"), и код путешествует по сети внутри status. На сервере err из handler — это *status.Status, спрятанная за интерфейсом error, и status.Code(err) достаёт код обратно. Два граничных случая стоит запомнить. err == nil даёт codes.OK. А ошибка, созданная без status — errors.New, fmt.Errorf — даёт codes.Unknown: gRPC честно не знает, что с ней делать. Unknown — самый дорогой код в логах: за ним прячется всё, что вы забыли обернуть в статус, и именно его стоит сначала перевести в осмысленные коды, а потом уже настраивать уровни логирования. Иначе Error-лог покажет «что-то упало», но не скажет, что именно.

Код статуса — машинное поле, уровень — ваше решение, и сводить их в правило «все ошибки — Error» значит утопить алерты. Моя рабочая политика простая. Internal, DataLoss и Unknown — Error: за ними баг в коде или потеря данных. DeadlineExceeded, Unavailable и ResourceExhausted — Warn: таймауты и недоступность живут в ретраях, и алерт на каждого клиента с плохой сетью отключают через неделю. Спорное место — codes.Canceled: я пишу его на Info и не согласен с командами, поднимающими его в Warn. Клиент сам закрыл соединение — аварии нет, а Warning на каждый закрытый контекст создаёт шум, маскирующий настоящие проблемы. Если ваша система реагирует на canceled иначе — политика у вас своя, но она должна быть записана кодом, а не в голове дежурного.

grpc-go не ставит recover вокруг вызовов обработчиков: паника внутри handler раскручивает стек через все перехватчики и убивает процесс — пост-код логирующего перехватчика не выполнится, записи не будет, клиент увидит обрыв соединения вместо кода. Лечение — перехватчик recovery: defer с recover переводит панику в status.Error(codes.Internal), пишет zap.Error со стеком debug.Stack() и возвращает клиенту честную ошибку. Порядок в ChainUnaryInterceptor зеркальный Gin: логирующий первым, recovery вторым — паника гасится глубже, и логирующий после возврата handler видит обычную ошибку Internal с латентностью и пишет access-запись. Recovery последним в цепочке панику тоже поймает, но записи лога она не оставит — тот же симптом, что и в уроке про HTTP-посредников.

HTTP-конвейер из урока про request id живёт в заголовках, gRPC — в metadata: та же идея, другой транспорт. На сервере metadata.FromIncomingContext(ctx) достаёт map из входящего контекста, и ключи в нём всегда в нижнем регистре: X-Request-Id с клиента превратится в x-request-id. Достали значение — собрали дочерний логгер base.With(zap.String("request_id", id)), и весь лог перехватчика, и всё, что обработчик нафлогирует через переданный дальше логгер, окажется с одним идентификатором. Две оговорки. Клиент может прислать какой угодно request_id: длину и алфавит стоит ограничить, иначе поле станет вектором для раздувания записей. И md.Get возвращает слайс: повторяющийся ключ легален в metadata, берите первый элемент, остальные игнорируйте.

Стримы ломают картину «один запрос — один ответ». Перехватчик типа grpc.StreamServerInterceptor получает не запрос, а grpc.ServerStream — канал, через который сообщения бегут в обе стороны, и handler возвращает одну ошибку на весь стрим. Асимметрия важная: сообщений много, записей лога лучше одна, иначе десятистрочный чат заспамит access-лог. А вот ошибок в стриме несколько: SendMsg и RecvMsg возвращают их по ходу, и финальная ошибка handler — агрегат. Особый случай — io.EOF из RecvMsg: это штатный сигнал «клиент перестал слать», а не авария; без фильтра он превратит каждый обычный стрим в Error-запись. StreamServerInfo дополнительно к FullMethod даёт IsClientStream и IsServerStream — по ним различают виды стримов в логе, если трафик смешанный.

Перехватчики устроены так же, как middleware Gin: идея обёртки одна, тип другой. Без логирования их разбирает урок про перехватчики курса gRPC, семантику кодов статусов — урок про статусы. Request id из HTTP-конвейера — в уроке про request id; связь логов с метриками и трейсами — в материале про наблюдаемость. Связка zap grpc собирается в один файл: перехватчик, политика уровней, извлечение request id.