Логирование запросов

Восемнадцатый урок закончился точной формулировкой: X-Cache: hit и miss — готовый маркер для лога, а Age и Date — поля, по которым по логам видно, сколько жизни у записи; кэш, который никто не измеряет, превращается в чёрный ящик. Сегодня мы этот мост проходим: решение кэша живёт в заголовке ответа, а заголовок ответа — это то, что логгер умеет печатать без единой строчки своего кода. Тема «fiber логирование» складывается из двух независимых механизмов, которые новички часто сливают в один. Первый — журнал запросов, access log: по одной строке на каждый HTTP-запрос, его пишет middleware/logger из комплекта ядра. Второй — события приложения: «заказ сохранён», «подключение к базе провалилось», «задача взята в работу»; за них отвечает пакет fiberlog из того же ядра. Запрос «логи запросов go» почти всегда ведёт именно к access-логу: что пришло, какой статус, сколько заняло, чем ответило.

У пары есть первая честная асимметрия: access-лог по умолчанию течёт в os.Stdout, а fiberlog — в os.Stderr, причём через стандартный пакет log. Потоки разделили не случайно: журнал запросов собирают целиком и агрегируют, а события приложения фильтруют по уровням — у них разная судьба. Вторая асимметрия — уровни: у fiberlog они есть (от Trace до Panic), у access-лога их нет принципиально — журнал либо пишется, либо нет, а разнообразие внутри обеспечивают формат и Skip. Главная цель урока — чтобы каждая строка журнала отвечала на вопрос «что случилось с этим запросом»: идентификатор, статус, латентность, решение кэша, ошибка.

В шестом уроке вы уже подключали logger.New(), видели DefaultFormat и правило порядка requestid → logger → recover. Сегодня — изнанка того же слоя, и она заслуживает отдельного урока, потому что формат-строка в Fiber — это не printf и не шаблон в привычном смысле, а маленький предметно-ориентированный язык. Каждый тег ${status} или ${latency} — это зарегистрированная функция, компилятор формата превращает строку в цепочку из фиксированных кусков и вызовов ещё на этапе logger.New, а опечатка в имени тега роняет приложение паникой на старте — не в момент первого запроса. Дальше по уроку: полный словарь тегов v3 с параметрическими формами, три крючка управления — Skip, Done и LoggerFunc, механизм цветов с isatty, горутина обновления времени, корреляция по RequestID вплоть до регистрации тегов, адаптер на slog и честное сравнение с Echo. Ничего из этого в шестом уроке не было — там была механика слоя, здесь — экономика строки.

Главное, что стоит знать о производительности формат-строки: она компилируется. Внутри logger.New вызывается logtemplate.Build[fiber.Ctx, Data](cfg.Format, createTagMap(&cfg)) — шаблон разбирается один раз и превращается в пару цепочек: фиксированные куски строки и функции-рендереры. Комментарий в logger.go объясняет замену старого подхода прямо: instead of analyzing the template inside(handler) each time, this is done once before — вместо анализа шаблона на каждый запрос, это делается один раз заранее. На запросе остаётся только прогнать буфер по готовым цепочкам — переиспользуемый буфер из bytebufferpool, как data из sync.Pool.

Ссылка на несуществующий тег — это не пустая подстановка, а паника: фабрика logger.New(config ...Config) собирает конфиг и передаёт формат в Build, тот возвращает ошибку, logger.New переводит её в типизированную UnknownTagError с полями Tag, Param и Hint — подсказкой вроде «возможно, вы имели в виду параметрическую форму» — и паникует. Константа ErrUnknownTag формулирует диагноз без анестезии: logger: unknown template tag. Ошибка конфигурации стреляет при подключении, а не под нагрузкой — тот же принцип, что у KeyAuth в восьмом уроке Echo. Свои теги регистрируются парой RegisterTag / MustRegisterTag: первая возвращает ошибку ErrTagInvalid — logger: tag name and function are required, вторая паникует; реестр глобальный, и новые инстансы логгера видят свежую регистрацию, но существующие инстансы сохраняют скомпилированные цепочки — пере-регистрация тега старые строки не меняет. А на уровне одного инстанса всё можно перекрыть картой CustomTags — комментарий в config.go честен: CustomTags override built-in and globally registered tags with the same name.

Половина словаря — теги с параметром после двоеточия, и именно они превращают журнал из «как у всех» в ваш собственный. ${query:page}, ${cookie:session_id}, ${form:email} — всё это доступно без единой строчки кода поверх формата. Но рабочий конь структурирования — ${locals:X}. Хендлер или промежуточный слой кладёт значение через c.Locals("user", user), и формат печатает ${locals:user} в каждой строке этого запроса: не надо протаскивать поле через отдельную переменную и не надо переписывать LoggerFunc ради одного поля. Рендерер в tags.go разобран по типам честно: строка и []byte пишутся как есть, nil — ничего, всё остальное печатается через %v — и любой из этих путей проходит санитизацию, чтобы значение из запроса не могло склеить вам лишнюю строку журнала.

Пара правил гигиены. Первое: Locals-ключи — это договор внутри вашего кода, компилятор их не проверяет; опечатались в имени — тег молча напечатает пустоту, ведь nil-ветка рендерит ничего. Второе: не кладите в Locals то, что не хотите видеть в журнале, — пароли из форм, сырые токены: ${locals:} не знает, что для вас секретно. Третье: если поле нужно в каждой строке и вычисляется дёшево, ${locals:} — самый короткий путь; если нужна типизированная структура — это работа для своего LoggerFunc, о нём ниже.

У logger-слоя три ручки управления, и путать их дорого. Next — стандартное для всех middleware Fiber поле: вернул true — слой пропускается целиком, запрос проходит сквозь него как через стекло: ни строки лога, ни ручного вызова ErrorHandler — ошибку обработает кто-то выше или fiber на самом верху. Skip — ручка тоньше: запрос обрабатывается слоем до конца, включая фирменную деталь logger.go — логгер сам вызывает ErrorHandler приложения, если цепочка вернула ошибку, — но строка не пишется. Документ конфига: Skip is a function to determine if logging is skipped or written to Stream. Тонкость, о которой стоит знать заранее: проверка Skip живёт внутри defaultLoggerInstance — если вы подмените LoggerFunc своим кодом, cfg.Skip придётся проверять самому, дефолтный фильтр за вас никто не вызовет.

Done — третий крючок и главный подарок для измеримости. Документ: Done is a function that is called after the log string for a request is written to Output — функция получает logString []byte уже после записи строки в Stream. В этот момент хендлер давно отработал, ответ уехал, клиент ничего не ждёт — идеальное место, чтобы посчитать метрики, отправить строку в агрегатор или распарсить собственный же формат. Заметьте: Skip гасит и Done — ранний выход из defaultLoggerInstance происходит до записи и до хука, у пропущенного запроса строки нет нигде, в том числе в ваших счётчиках.

Цветной вывод в терминале — не украшение, а навигация, и он тоже разобран в исходниках до отображений. statusColor в utils.go: 2xx — зелёный, 3xx — синий, 4xx — жёлтый, всё прочее — красный. methodColor: GET — cyan, POST — зелёный, PUT — жёлтый, DELETE — красный, PATCH — белый, HEAD — пурпурный, OPTIONS — синий. Решение о цветах принимает configDefault: они включены, когда Stream — дефолтный os.Stdout и DisableColors не поднят, либо когда выставлен ForceColors. Уже с новым Stream цвета молча гаснут: вы уводите журнал в файл — и Escape-коды не мусорят его.

Сама проверка терминала живёт в beforeHandlerFunc и собрана честно: Stream заменяется на colorable.NewColorableStdout из пакета mattn/go-colorable, а если ForceColors не поднят и TERM равен dumb, или NO_COLOR равен 1, или стандартный вывод не терминал по isatty.IsTerminal и IsCygwinTerminal — на colorable.NewNonColorable(os.Stdout). Это та самая связка isatty: цвета включаются сами, когда stdout — настоящий терминал, и гаснут сами, когда журнал пайпом уходит в файл или коллектор. Для ручной раскраски своего формата есть девять цветовых тегов ${black}…${reset} — они подставляют ColorScheme из конфигурации приложения, так что и самодельная разметка подчиняется одной палитре.

Тег ${time} дёшев на рендере, потому что дорогая часть вынесена из запроса. TimeFormat по умолчанию — «15:04:05», тот самый Go-layout; TimeZone — «Local» (в исходнике "Local"), и logger.New грузит зону через time.LoadLocation, а при ошибке молча откатывается на time.Local. Дальше начинается инженерия: отформатированная строка времени хранится в atomic.Value и обновляется горутиной раз в TimeInterval — дефолт 500 * time.Millisecond. Никто не форматирует время на каждый запрос: рендерер тега просто читает готовую строку.

Интереснее то, сколько горутин у вас заведётся. Пакетная функция sharedTimestamp держит кэш обновляльщиков, и ключ — тройка формат/зона/интервал: два logger-инстанса с одинаковыми настройками времени делят одну горутину на двоих. Комментарий в logger.go формулирует это в лоб: Process-lifetime shared updater, deduplicated by format/zone/interval — общий на процесс, дедуплицирован по формату, зоне и интервалу. Плата за общий лайфтайм — горутина, живущая до конца процесса, и для тестов она неудобна; для этого в конфиге есть TimeDone: канал, чьё закрытие останавливает выделенный обновляльщик, — комментарий зовёт сценарий useful for tests and short-lived apps. В обычном сервере поле не нужно, в утилите командной строки с Fiber внутри — обязательная гигиена.

Механику requestid.New — переиспользование входящего заголовка X-Request-ID, генерацию SecureToken с тремя попытками — вы разбирали в шестом уроке; здесь нас интересует только путь идентификатора в строку журнала, и он в v3 поучительный. requestid хранит готовый ID в контексте запроса через fiber.StoreInContext, а не в Locals, и при первом создании слоя выполняет sync.Once-регистрацию двух тегов сразу: ${requestid} и ${request-id}. Регистрация идёт через logger.RegisterContextTag, и её документ точен: so that the same name can be used in a logger.Config.Format and in fiberlog.SetContextTemplate — двойной реестр, один вызов.

Практические следствия три. Первое: порядок — requestid.New() строго раньше logger.New(), иначе заглушка из прошлого интерактива. Второе: альтернативы без контекста. ${respHeader:X-Request-ID} надёжен всегда — requestid ставит заголовок ответа до раскрутки, и к рендеру строки он уже стоит; ${reqHeader:X-Request-ID} печатает только то, что прислал клиент, и годится разве что для отладки входящих трасс. Третье: ценность корреляции за пределами одного процесса — клиент или балансировщик присылает свой ID, requestid его валидирует и переиспользует, и строки двух сервисов склеиваются по одному значению. Требование валидности — видимые ASCII — не бюрократия: идентификатор уезжает в заголовок ответа и в журнал, а управляющие байты там не гости.

Второй поток fiber логирования — события приложения — живёт в пакете github.com/gofiber/fiber/v3/log (привычное имя fiberlog). По умолчанию это обёртка над стандартным пакетом log: writer — os.Stderr, флаги LstdFlags с Lshortfile и Lmicroseconds, к каждой записи приклеивается префикс уровня вроде «[Info] ». Уровней семь и объявлены они честным iota: LevelTrace, LevelDebug, LevelInfo, LevelWarn, LevelError, LevelFatal, LevelPanic. Фильтр формулирует документ уровня: When a logger is configured with a level, any log message with a lower log level (smaller by integer comparison) will not be output — всё, что ниже порога числом, не печатается; дефолтный логгер порог не поднимает, печатается всё. Одна деталь с характером: Fatal завершает процесс даже тогда, когда его строка ниже порога и не была написана.

Интерфейсная семья: Logger — плоские методы Trace…Panic, FormatLogger — семейство Tracef…Panicf, WithLogger — Tracew…Panicw с парами ключ-значение; комбинация плюс управление — AllLogger. Пакетные функции fiberlog.Info, fiberlog.Errorf и компания пишут через глобальный экземпляр, а fiberlog.SetLogger подменяет его целиком, SetOutput и SetLevel — ручки поточнее. Отдельный слой — контекст: fiberlog.WithContext(c) возвращает логгера, приклеенного к запросу, а SetContextTemplate задаёт, какие контекстные теги печатать в каждой строке — константа RequestIDFormat из пакета собирает формат [${requestid}], а ${value:KEY} — зарезервированный параметрический тег для любых значений из контекста. Журнал запросов уровней не имеет и не должен: он либо пишется, либо нет — уровни живут в событийном потоке.

Ставить Fiber и Echo рядом честно именно на этом уроке: их девятый урок Echo уже разобрал логирование Echo, и архитектурно пары похожи — у обоих два потока. У Echo события приложения идут через e.Logger с уровнями gommon, а журнал запросов — через middleware.RequestLoggerWithConfig с полтора десятком флагов LogStatus, LogURI, LogRequestID и обязательной LogValuesFunc. У Fiber события — fiberlog, журнал — middleware/logger. Разница в языке конфигурации: Echo описывает колонку флагом-булевым, Fiber — тегом в строке формата. Флаг надёжнее против опечаток, строка гибче: добавить в лог решение кэша — это ${respHeader:X-Cache} в Format, а не новый флаг и не правка LogValuesFunc.

Честные отличия по трём пунктам. Уровни: у gommon и у fiberlog они есть, у access-логов у обоих нет — тут фреймворки совпадают. RequestID: Echo читает идентификатор из заголовков запроса и ответа флагом LogRequestID; Fiber v3 хранит его в контексте и печатает контекстным тегом ${requestid}, с оговоркой о порядке регистрации. slog: Echo документирует три готовых пути присадки, а в ядре Fiber адаптера нет — LoggerFunc, LoggerToWriter или fiberlog.SetLogger, клей за вами. Ни тот ни другой не конвертирует автоматически свой встроенный логгер в slog — SetDefault из Echo и SetLogger из Fiber меняют только свой поток, чужие writer'ы живут своей жизнью.

Журнал запросов — парсер читает его автоматически, — и строка, склеенная из пользовательского ввода, опасна вдвойне: путь ?q=foo%0A200 OK — это попытка подсунуть парсеру вторую строку. logger v3 защищается системно: все теги, печатающие значения из запроса, проходят writeSanitized — ASCII-управляющие байты заменяются пробелами, горизонтальный таб сохраняется. Быстрый путь DefaultFormat чистит те же значения руками: IP, путь и сообщение ошибки, — и комментарий в default_logger.go называет причину по номеру issues: raw CR/LF lets a client forge additional access-log lines. See #4341. Метод при этом не чистится — fasthttp отвергает запрос, чей метод-токен содержит управляющие байты, так что в ${method} мусора не бывает по построению.

Для тех, кто пишет свои теги, пакет экспортирует SanitizeValue — ту же функцию с тем же контрактом; комментарий прямо перечисляет дыры, через которые сырой ввод обычно попадает в лог: RegisterTag, CustomTags, LoggerFunc. Отдельная честность про ${resBody}: рендерер берёт c.Res().Body(), но для стриминговых ответов тело равно nil — комментарий в tags.go: Res.Body answers nil for a streamed response rather than draining it — логгер не осушает SSE-поток и не буферизует SendFile, которые обязан был только наблюдать. И практическое правило поверх всего: ${body}, ${resBody} и ${reqHeaders} — инструменты отладки, не продакшена; пароли в формах и токены в заголовках попадут в журнал точно так же, как и всё остальное.

Соберите канон: инстанс на :8080, requestid, логгер с форматом из канона, кэш и /api/tasks. Клиент — curl, и сценарии короткие. Первый: два GET /api/tasks подряд с curl -i — в первом ответе X-Cache: miss, во втором X-Cache: hit, а в журнале две строки с одинаковым форматом, разными RequestID и разными значениями cache=: так прошлогодний маркер становится полем журнала без правки кэша. Второй: curl -i /healthz при Skip — ответ есть, строки в журнале нет. Третий: curl -i /api/missing — строка с 404 и прочерк в ${error}, ведь fiber сам отработал ошибку маршрута; а хендлер, вернувший fiber.NewError, даст в хвосте строки своё сообщение. Четвёртый: заголовок X-Request-ID в ответе — то же значение, что в строке журнала: корреляция проверяется глазами за секунду.

Честное слово про инструментарий: песочница сайта сетевые сценарии не исполняет — runner-ов в уроках Fiber нет с первого урока, интерактивы здесь quiz, predict, fill, order и флешкарты; журнал проверяется локально, где ваш curl видит и заголовки, и строки целиком. Материал держится на исходниках ветки main ядра fiber v3.5.0: logger.go, config.go, tags.go, format.go, default_logger.go, context_tag.go, timestamp.go плюс пакет log. Полный план курса — на странице курса Fiber.

Следующий, двадцатый урок — конфигурация и настройка сервера: Settings, Prefork, graceful shutdown, сигналы. Связь с сегодняшней темой прямая и практическая. Во-первых, тег ${pid} из таблицы выше перестанет быть диковинкой: с Prefork родительский процесс плодит воркеров, и в общем журнале строки легко разнести по процессам именно по PID. Во-вторых, graceful shutdown — это в том числе судьба последних строк журнала: слушатель закрыт, но запросы в полёте должны дописать свои записи, а буферы — дойти до Stream; сигнал SIGTERM и аккуратное завершение — то, чем заканчивается каждый честный сервер. В-третьих, поток ошибок fiberlog на stderr и журнал на stdout обретают при настройке сервиса systemd буквальные пути: Stderr и Stdout — два файла, две судьбы. До встречи в двадцатом уроке.