Логирование в Echo: e.Logger, slog и RequestLogger

У любого веб-приложения два лог-потока, и у них разные заказчики. Первый — журнал запросов: одна строка (или запись) на каждый HTTP-запрос, его читают дежурные и метрики, в нём важны метод, путь, статус и латентность. Второй — события самого приложения: «не смогли открыть конфиг», «миграция прошла», «задача создана»; их читают разработчики, и в них важны атрибуты — id сущности, имя пользователя, длительность операции. echo логирование устроено ровно так: за первый поток отвечает middleware, за второй — e.Logger, и смешивать их не стоит.

В седьмом уроке вы уже разобрали штатный middleware.Logger: fasttemplate-формат с тегами ${...}, LoggerConfig, CustomTagFunc, скипер. Свежие версии v4 подвели черту: в v4.14 фабрики Logger и LoggerWithConfig получили комментарий Deprecated с прямой рекомендацией — «please use middleware.RequestLogger or middleware.RequestLoggerWithConfig instead». Сегодняшний урок рассказывает, что пришло на смену, и прихватывает второй вопрос, который всё время зависал рядом: уровень лога — почему одни записи печатаются, а другие молча съедаются.

Поле Logger у структуры Echo объявлено как Logger Logger — интерфейс, который живёт в файле log.go корневого пакета. Контракт широкий: пары Output() io.Writer / SetOutput(w io.Writer), Prefix() / SetPrefix(p string), Level() log.Lvl / SetLevel(v log.Lvl) плюс SetHeader(h string); семейство Print и Printf без уровня; по пять семейств с уровнями — Debug, Info, Warn, Error, Fatal, Panic — в трёх вариантах каждое (обычный, с форматом f и JSON-вариант с суффиксом j). Реализация по умолчанию — не из Echo: конструктор присваивает Logger: log.New("echo"), где log — это github.com/labstack/gommon/log, зависимость из go.mod (v0.4.2). Префикс "echo" вы видите в каждой записи.

Внутри echo.New() происходит ещё два незаметных, но важных действия. Первое: e.Logger.SetLevel(log.ERROR) — сразу после создания уровень лога устанавливается в ERROR, и это объясняет половину жалоб «а почему Info не печатается». Второе: e.StdLogger = stdLog.New(e.Logger.Output(), e.Logger.Prefix()+": ", 0) — Echo создаёт стандартный *log.Logger с префиксом "echo: ", разделяющий тот же вывод, и отдаёт его http.Server-у как ErrorLog в configureServer. Наконец, глобальный DefaultHTTPErrorHandler тоже пишет через e.Logger: если отправить ответ не удалось (ошибка внутри c.JSON), он зовёт e.Logger.Error(err). То есть всё, что Echo сообщает о себе, течёт через один интерфейс — и весь этот поток перенастраивается тремя методами из следующего блока.

Тип уровня — log.Lvl (uint8) с константами DEBUG=1, INFO=2, WARN=3, ERROR=4, OFF=5; внутренние уровни Panic и Fatal стоят выше и не экспортируются. Вся логика решения — одна строка в методе log: запись печатается, если level >= l.Level() или level == 0. Отсюда три практических следствия. Первое: OFF глушит всё уровневое — живут только Print и Printf; при этом Fatal и Panic напечатаются даже при OFF (их уровни выше), потому что они обязаны успеть сообщить причину смерти: Fatal завершает процесс os.Exit(1), Panic паникует. Второе: SetLevel атомарен — внутри atomic.StoreUint32, чтение atomic.LoadUint32, — можно крутить уровень в рантайме без гонок: по сигналу, по env-флагу, по кнопке в админке. Третье: уровень тесно связан с debug-режимом — configureServer при e.Debug == true зовёт e.Logger.SetLevel(log.DEBUG), а заодно заезжает бонусом в другой файл: DefaultHTTPErrorHandler в Debug-режиме добавляет в JSON-ответ поле "error" с текстом ошибки, которого в обычном режиме нет.

Строка «user alice created todo 42» удобна человеку и неудобна машине: чтобы посчитать задачи по пользователям, её надо парсить. Структурированные логи переворачивают формат: событие — это сообщение плюс набор атрибутов ключ-значение, а сериализация (текст или JSON) — забота хендлера. Со времён Go 1.21 она решается стандартной библиотекой: пакет log/slog. Примитивы короткие: slog.New(h) оборачивает хендлер в *slog.Logger; slog.NewJSONHandler и slog.NewTextHandler — две штатные сериализации; опции — slog.HandlerOptions{Level, ReplaceAttr}: порог уровня и перерисовка атрибутов на выходе; атрибуты — slog.String, slog.Int, slog.Duration, slog.Int64, slog.Group; logger.With("service", "api") возвращает НОВОГО логгера с приклеенными атрибутами.

Отдельный метод — slog.SetDefault(l): он делает l логгером пакетных функций slog.Info/slog.Errorf и заодно перепривязывает пакет log: внутри вызываются log.SetOutput и log.SetFlags(0), после чего всё, что печатает пакетный log, течёт через ваш хендлер на уровне Info. Тонкость, на которой ловятся: перепривязывается только ДЕФОЛТНЫЙ пакетный log.Logger — чужие экземпляры *log.Logger, созданные через log.New, живут своей жизнью. К ним относится и e.StdLogger из Echo. Именно поэтому связка «slog echo» в рецептах собирается не одной строкой SetDefault, а тремя путями, которые разберём ниже.

Путь первый — грубая сила: e.Logger.SetOutput(адаптер), где адаптер превращает строки gommon в вызовы slog. Работает, но честно скажем, что это костыль: адаптер видит ГОТОВУЮ строку, атрибуты уже сериализованы, и вы либо парсите их обратно, либо пишете текстом. Спасает только JSON-режим заголовка из блока выше — тогда каждая строка gommon сама валидный JSON. Этот путь живёт для старых проектов, где весь код уже пишет через e.Logger.

Путь второй — установить slog.SetDefault и подключить middleware.RequestLogger() без конфига: его дефолтная LogValuesFunc пишет именно пакетными slog.LogAttrs, значит, попадает в ваш JSONHandler автоматически. Минимум кода, но формат записи фиксирован — REQUEST со стандартным набором полей, и приклеить атрибут из c.Get не выйдет.

Путь третий — явный и рекомендуемый: middleware.RequestLoggerWithConfig с собственной LogValuesFunc, в замыкании которой живёт ваш *slog.Logger. Полный контроль над уровнем, сообщением и атрибутами. Любопытно, что доккомментарий request_logger.go содержит готовые примеры для slog, fmt.Printf, zerolog, zap и logrus — Echo прямо документирует, что middleware не навязывает библиотеку: LogValuesFunc получает структуру значений и пишет хоть в бумажную газету.

RequestLoggerConfig — это Skipper (первое поле по канону каталога), два крючка и полтора десятка флагов. Крючки: BeforeNextFunc func(c echo.Context) — вызывается перед next(c), удобно поставить метку начала; LogValuesFunc func(c echo.Context, v RequestLoggerValues) error — обязательная, документ помечает её словом Mandatory. Флаги-булевы, каждый вытаскивает своё значение в v: LogLatency (длительность цепочки), LogProtocol, LogRemoteIP (через c.RealIP()), LogHost, LogMethod, LogURI (полный URI с query), LogURIPath (только путь), LogRoutePath (шаблон маршрута c.Path() — тот же, что тег ${route}), LogRequestID, LogReferer, LogUserAgent, LogStatus, LogError, LogContentLength, LogResponseSize. Списковые поля: LogHeaders []string, LogQueryParams []string, LogFormValues []string — называют имена, и в v.Headers/v.QueryParams/v.FormValues падают срезы значений.

RequestLoggerValues — зеркало с типами: StartTime, Latency time.Duration, Protocol, RemoteIP, Host, Method, URI, URIPath, RoutePath, RequestID, Referer, UserAgent string, Status int, Error error, ContentLength string, ResponseSize int64. Если LogValuesFunc не задана, ToMiddleware возвращает ошибку "missing LogValuesFunc callback function for request logger middleware", а фабрика RequestLoggerWithConfig на ней паникует — то же правило «ошибка конфигурации стреляет при подключении», которое вы видели у KeyAuth в восьмом уроке. Дефолтный RequestLogger() включает latency, remoteIP, host, method, uri, requestID, userAgent, status, error, contentLength, responseSize плюс HandleError: true и печатает REQUEST или REQUEST_ERROR.

Механику middleware.RequestID вы разобрали в седьмом уроке: заголовок клиента переиспользуется, иначе генерируется randomString(32), заголовок X-Request-Id ставится в ответ до next(c). Здесь — только то, как идентификатор попадает в структурированную запись. Способ первый, встроенный: LogRequestID: true — RequestLogger сам читает константу echo.HeaderXRequestID из заголовков запроса, а если клиент её не прислал, берёт из заголовка ответа (там RequestID к моменту снятия значений уже стоит). Порядок относительно RequestID в цепочке не критичен: значения снимаются на раскрутке, после next(c), — но RequestID первым остаётся доброй привычкой.

Способ второй — RequestIDHandler func(c echo.Context, string) в RequestIDConfig: положите id в контекст своей константой c.Set(ctxRequestIDKey, id) и читайте в LogValuesFunc через c.Get вместе с пользователем — так id попадает и в собственные события приложения, не только в access-запись. Способ третий — протянуть заголовок дальше: если ваш сервис ходит в бэкенды, копируйте X-Request-Id в исходящие запросы, и строки логов разных программ склеятся по одному значению. И прибережём сантиметр честности: не создавайте slog.With(logger, ...) на каждый запрос — With аллоцирует нового логгера; в access-логе передавайте id атрибутом в LogAttrs, как в коде выше.

В восьмом уроке metricsTimer печатала fmt.Printf("%s: total=%d err=%d avg=%s last=%s") — работало, но строку нельзя было ни отфильтровать по уровню, ни распарсить без regexp. Переезд делается в три действия. Первое: в MetricsConfig добавляется поле Log *slog.Logger, nil-резолв в теле фабрики ставит slog.Default() — тот же паттерн «дефолты на первой ступени», что и для Prefix. Второе: fmt.Printf заменяется на logger.Info с атрибутами: slog.Int64("total", total), slog.Int64("errored", errored), slog.Duration("avg", elapsed/time.Duration(total)), slog.Duration("last", latency). Третье — уровни по смыслу: обычная строка Info, а если вы делали SlowThreshold из домашнего задания, медленные запросы заслуживают Warn — дежурный увидит их в алертах, не переписывая фильтры.

Помните и про отличие потоков: метрика — агрегат за жизнь процесса, лог — событие. Строка лога с total на каждый запрос — это деградация до Printf с лишними расходами; настоящие счётчики стоит отдавать в Prometheus-экспортёр, а в логе оставлять событие «случилось что-то, достойное внимания». И правило статуса никуда не делось: c.Error(err) до печати нужно и здесь — при HandleError: true у RequestLogger тот же контракт выполняет middleware сам.

Мы разложили echo логирование по двум потокам и свели их на общем языке JSON: e.Logger управляется тремя ручками с уровнями DEBUG-OFF и атомарной сменой порога, slog даёт структурированные записи с With и SetDefault, а middleware.RequestLogger заменяет deprecated Logger из каталога и снимает честный статус через HandleError или errors.As. Идентификатор запроса из RequestID доезжает до записи тремя способами, строки metricsTimer переезжают в slog.Info/Warn с атрибутами, а ReplaceAttr прикрывает токены в query. order-задание — репетиция вашего main: логгер, SetDefault, RequestID, access-лог, маршруты, запуск.

Белым пятном осталась ошибка как объект: мы упоминали echo.HTTPError по имени, но не разбирали — поле Internal для исходной причины, Message, принимающий не только строки, собственный ErrorHandler с единым форматом всего API и его дружбу с HandleError: true из этого урока. Полный разбор — дело десятого урока. Пока проверьте себя карточками, соберите fill и order ещё раз и перенесите конфиг RequestLogger в учебный сервер восьмого урока: bearerAuth уже кладёт пользователя в контекст — одна запись с request_id, user, uri и статусом закрывает половину вопросов дежурного. Навигация по курсу — на странице курса Echo, фабрики звеньев и c.Set/c.Get — в уроке про кастомные middleware, каталог штатных слоёв и судьба старого Logger — в уроке про встроенные middleware.