GORM и zap: логи базы данных

Пакет gorm.io/gorm/logger описывает контракт: LogMode(level) Interface переключает минимальный уровень и возвращает логгера, Info, Warn и Error получают строку формата с аргументами для редких событий GORM — миграций и внутренних предупреждений, а Trace — сердце моста. Его вызывают после каждого SQL-вызова с тремя аргументами: контекст запроса, время начала и функция fc(), которая возвращает готовую SQL-строку и число затронутых строк, плюс err. Константы уровня свои: Silent=1, Error=2, Warn=3, Info=4 — выше, тем больше SQL попадает в лог. Уровни не совпадают с zap, и мост честно переводит: Error GORM — Error zap, Warn — Warn, трейс — Info или Debug по вашему выбору. Логирование gorm-слоя начинается с решения, куда направить обычные запросы: у нас они пойдут в Debug — иначе под Info утонет весь трафик приложения.

Вся логика моста живёт в Trace, и исходов три. Первый — err не nil: запрос упал, уходим в Error с полем error, длительностью, числом строк и SQL — но с одной оговоркой, которой посвящён отдельный раздел ниже. Второй — ошибок нет, но время превысило SlowThreshold: медленный запрос уходит в Warn с полем elapsed рядом с порогом, и именно эти записи кормят дашборд производительности. Третий — обычный запрос: Info или Debug с длительностью и числом строк. Важная мелочь: fc() стоит времени — он собирает финальную строку SQL с подставленными значениями, поэтому его вызывают только когда уровень позволяет писать, а не безусловно. Экономия мелкая на запрос, но запросов тысячи, и в мостах, где fc() зовётся всегда, она видна в бенчмарках.

SlowThreshold — главный рабочий параметр моста, и дефолт у GORM осознанный: двести миллисекунд. Это примерно граница, за которой интерактивный ответ уже чувствуется пользователем: быстрее — норма, дольше — повод посмотреть план запроса и индексы. Каждое превышение становится Warn-записью с elapsed и SQL — прямым материалом для алерта «медленный SQL растёт». Менять порог стоит не глобально, а по месту: отчётные запросы по своей природе медленные, и рубить их порогом в двести миллисекунд — заспамить Warn самим собой. У GORM для этого db.Session(&gorm.Session{Logger: мостСПорогом}) — отдельная сессия со своим мостом и, например, секундным порогом. Такую настройку честнее делать не ради одной функции, а через репозиторий отчётов: у медленного кода свой порог, у интерактивного — свой.

db.First(&u, id) на несуществующем ключе возвращает gorm.ErrRecordNotFound — и это нормальный поток приложения: проверка наличия записи, а не сбой. Дефолтный конфиг моста поднимает флаг IgnoreRecordNotFoundError, и NotFound не превращается в Error-запись: без него каждый 404-подобный сценарий заводил бы алерт, и через неделю алерты отключили бы целиком. Запись при этом не исчезает совсем — на уровне Info она остаётся как обычный трейс. Игнорировать NotFound стоит не всегда: если для вашей логики отсутствие записи — исключение, которое ломает инварианты, а не ожидаемая ветка, оставьте его ошибкой и поднимите флаг только в интерактивных сервисах. Как всегда с уровнями: правило задаёт бизнес-смысл, а не привычка.

Trace принимает контекст, и мост может достать из него request_id посредника — но только если контекст вообще доехал до GORM. Вызов db.WithContext(r.Context()) прокидывает контекст запроса в слой базы, и в Trace он приходит тем же самым: мост вытаскивает идентификатор и добавляет полем к каждой SQL-записи. Без WithContext контекст пустой — background, и связка рвётся на первом же шаге: access-лог говорит, что запрос был, а SQL-записей с этим request_id нет. Практика, которая работает: репозитории принимают ctx первым аргументом и не зовут GORM без WithContext — правило закрепляется код-ревью, а не призывами. Проверка на два grep: один запрос, поиск request_id в access-записи и в SQL-записи — оба должны найтись.

У моста GORM есть опция SourceLocation: с ней в запись добавляется файл и строка вызова — не моста, а места, где код позвал .Find или .Save. Разница с zap.AddCaller принципиальная: caller zap показал бы внутренности GORM, где лог реально писался, и был бы бесполезен. GORM решает это через utils.FileWithLineNum — обход стека до первого кадра вне orm. Опция отвечает на вопрос, который без неё разбирается глазами: один и тот же SELECT выполняется из пяти мест, и какое из них медленное? Цена — обход стека на каждый SQL-вызов, на фоне самого запроса она теряется, но включайте осознанно: в горячих циклах с тысячами мелких запросов разница видна. Рабочая схема: SourceLocation включена всегда, а выключают её по замеру, а не по вере.

Вот место, где мост становится оружием. fc() возвращает SQL уже с интерполированными значениями — так устроен дефолтный вывод GORM: вместо плейсхолдеров $1 в записи стоит готовый запрос. Значит, в лог с каждым трейсом уходят значения аргументов: почта пользователя, номер карты, токен из WHERE, поле с персональными данными из INSERT. Логи читают шире, чем базу: дежурные, системы сбора, бэкапы логов — и регуляторные требования к ним жёстче. Мой рабочий компромисс, за который меня ругали: в интерактивных сервисах SQL пишем на Debug и маскируем значения, в системных интеграциях — пишем как есть, но канал с ограниченным доступом и коротким сроком хранения. Универсального ответа нет, но осознанное решение должно быть: «просто логировать SQL» — это решение писать персональные данные всем, у кого есть доступ к логам.

Мост встраивается в конвейер из уроков про HTTP-middleware и request id: SQL-записи с request_id соединяются с access-логом в одну хронологию. Цену логирования каждого запроса в цифрах считают в материале про производительность zap, а полю error из ветки ошибки место в уроке про zap.Error и стек-трейсы. Подключение самой GORM и DSN разбирались в уроке про подключение к базе курса GORM; карта остальных тем — на странице курса.