Логи и трейсинг: trace_id в каждом сообщении

Запрос в реальном сервисе проходит несколько программ: балансировщик, HTTP-слой, хранилище, платёжный шлюз. У каждой свои логи, и склейка по времени превращается в угадывание: записи трёх сервисов идут вперемешку, а поля method и route одинаковы у всех. trace_id решает это честно: трейсер выдаёт идентификатор на входе, он сопровождает весь путь через контекст и попадает в каждую запись — теперь поиск по одному значению собирает цепочку из всех программ. Механика slog в этот замысел встаёт без переделок: With возвращает логгер с предзаданными полями, и его достаточно вызывать один раз на запрос. В этом уроке соберём middleware с полями трейсера, проведём логгер в глубину сервиса, разберём парные действия с span-ом и посмотрим, где корреляция ломается.

Трейсинг go: откуда берётся trace_id#

Начало пути — трейсер: SDK создаёт span на входе запроса, span получает trace_id — общий для всей цепочки — и span_id — идентификатор текущего участка. Честная оговорка: трейсинга в стандартной библиотеке нет; де-факто стандарт — OpenTelemetry SDK, сторонний пакет с go get. Но контракт, вокруг которого всё строится, — context.Context: трейсер кладёт span-контекст в request, middleware достаёт его оттуда, и никакие глобальные переменные не нужны. slog сам ничего не знает про трейсы — и это правильно: логгеру безразлично, что за значение в поле trace_id, строка есть строка. Мост между системами строит приложение: middleware извлекает span-контекст из контекста и подмешивает поля в логгер через With. Дальше все записи запроса получают trace_id без единого вызова With в бизнес-коде — тот же приём, на котором держится request_id из урока про сквозные поля, только источник значения теперь трейсер, а не генератор ID.

Middleware с полями трейсера

func Logging(base *slog.Logger) func(http.Handler) http.Handler {
        return func(next http.Handler) http.Handler {
                return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
                        ctx := r.Context()
                        logger := base
                        if sc := trace.SpanContextFromContext(ctx); sc.IsValid() {
                                logger = base.With(
                                        "trace_id", sc.TraceID().String(),
                                        "span_id", sc.SpanID().String(),
                                )
                        }
                        next.ServeHTTP(w, r.WithContext(withLogger(ctx, logger)))
                })
        }
}

SpanContextFromContext достаёт span-контекст, который трейсер положил в request. IsValid отсеивает запросы без трейса: запись без полей честнее нулей. With возвращает новый логгер — base не меняется. Готовый логгер кладётся в контекст, чтобы глубинные функции писали уже с trace_id.

Trace id в логах: подмешивание один раз#

Ключевое правило: поля запроса подмешиваются один раз в middleware, а не в каждом вызове. With возвращает копию логгера с предзаданными полями — механика описана в уроке про With, — и копия эта живёт один запрос: входящий лог, записи бизнес-логики и итоговая запись получают trace_id и span_id бесплатно. base при этом не трогается: фоновые задачи и стартеры пишут без полей запроса, потому что у них этих полей нет. Второй вопрос — что делать запросам без трейса: часть маршрутов может не участвовать в трейсинге, а SDK может быть ещё не подключён. Правильный ответ — писать без trace_id, оставляя честное отсутствие: выдуманный ноль или uuid на месте испорчен поиск, потому что в хранилище трейсов такого значения не найдётся. Третий вопрос — сосуществование с request_id: оба поля живут вместе, request_id склеивает записи одного запроса внутри сервиса, trace_id — цепочку между сервисами; если трейса нет, request_id остаётся единственным ключом.

Поля span: span_id, service и парные действия#

trace_id редко ходит один. span_id указывает на текущий участок работы: по нему в хранилище трейсов находится конкретный span, а не вся цепочка — это разница между «сервис замедлился» и «замедлился именно вызов хранилища». Имя сервиса обычно ставит SDK в ресурсные атрибуты, но в записи его часто дублируют полем service: в хранилище логов разрез по сервисам строится по этому полю, а не по атрибутам трейсера. Отдельная дисциплина — парные действия с ошибкой: сбой помечается и в логе, и в span-е — logger.Error рядом с RecordError у трейсера. Тогда и запись с полями ошибки, и трейс с пометкой на span-е находятся по одному trace_id. Честно: RecordError — API трейсера, не slog, и вызывать его надо рядом с записью, а не вместо неё: span хранит пометку и короткое описание, запись хранит поля — order, kind, err — и оба взгляда нужны.

Запись из глубины сервиса

func saveOrder(ctx context.Context, o Order) error {
        logger := loggerFrom(ctx)
        if err := db.Insert(ctx, o); err != nil {
                logger.Error("заказ не сохранён", "order", o.ID, "err", err)
                return fmt.Errorf("insert order: %w", err)
        }

        logger.Info("заказ сохранён", "order", o.ID)
        return nil
}

loggerFrom достаёт из контекста логгер, который middleware подмешал вместе с trace_id: функция не знает ни про трейсинг, ни про middleware, но каждая её запись попадает в цепочку запроса. Ошибка оборачивается через %w — об цепочках ошибок говорил одиннадцатый урок. Запись с trace_id находится в хранилище логов, и по тому же значению открывается трейс.

trace_id, который не находится

Кейс: в платёжном сервисе middleware с полями трейсера добавили не на все маршруты — внутренние ручки пошли в обход. Инцидент с зачислением платежа: поиск по trace_id собирает половину цепочки, а вторая половина лежит в записях без поля, и стык приходится восстанавливать по времени. Второй вариант той же болезни: trace_id генерировали сами через uuid, потому что SDK не подключили — значение в записях есть, а в хранилище трейсов его нет, корреляция выглядит рабочей и не работает. Фикс из трёх частей: один middleware на все маршруты, включая внутренние; отсутствие трейса — честное отсутствие поля, а не подставное значение; источник trace_id — один трейсер, а не локальные генераторы. Соглашение проверяется тестом: middleware-тест из урока про тестирование логов показывает, что поле есть или что его нет — но не что оно пустое.

Поиск по цепочке: от записи к трейсу#

Механика на практике выглядит так. В хранилище логов — запрос по полю: service, окно инцидента, trace_id — и записи собираются в хронологию одного запроса. В хранилище трейсов — Tempo или Jaeger — поиск по тому же trace_id отдаёт каскад span-ов: какой сервис начал, сколько длился каждый вызов, где родилась ошибка. Именно поэтому trace_id в записи — не поле на всякий случай, а внешний ключ: без него переход от лога к трейсу возможен только по времени, а на потоке в тысячи запросов в секунду время не выделяет никого. Временные окна хранения различаются: трейсы живут днями — их объём велик, а логи — неделями и месяцами. Отсюда честное ограничение: из записи уйти в трейс получается, пока трейс не истёк; обратно — из трейса в логи — работает дольше, и это устраивает обе стороны расследования. Для разбора инцидента приоритет такой: сперва записи с полями, потом трейс по ключу — механика дедупликации из предыдущего урока остаётся на месте.

Спорное: трейс вместо логов#

Мнение, которое стоит оспорить на ретро: с трейсингом логи почти не нужны — путь запроса и так виден в каскаде span-ов. За: трейс показывает структуру запроса честнее любой записи — кто кого вызвал и сколько это заняло. Против: span описывает жизнь запроса, а сервис пишет и вне запросов — фоновые воркеры, ночные кроны, старт и остановка; у span-а нет поля err с деталями и полем order, а хранится он днями, когда записи живут месяцами. Компромисс, который прижился: запросы живут в трейсах, а логи на запросах сокращаются до границ — вход, выход, ошибки; фоновая работа пишется в логи с полями задачи, где trace_id не бывает по определению. Граница по природе события: событие, у которого есть span, получает пару запись-пометка; событие без запроса живёт только в логах.

Поля корреляции#

Поле	Откуда	Зачем
trace_id	трейсер, через контекст	цепочка между сервисами
span_id	трейсер, текущий span	переход к конкретному участку
request_id	middleware сервиса	склейка записей одного запроса
user_id	после аутентификации	фильтр по пользователю
service	ресурсные атрибуты SDK	разрез по сервисам в хранилище

Контракт — контекст, мост — приложение

В стандартной библиотеке трейсинга нет, и slog про span-ы не знает. Контракт один — context.Context: через него трейсер передаёт span-контекст, через него же логгер попадает в глубину сервиса. OpenTelemetry SDK — сторонний пакет, и его подключение не меняет ни одной записи бизнес-логики: middleware подмешал поля — и записи поехали с trace_id. Это тот же контур, что с request_id в пятнадцатом уроке, только источник значений другой. Для хранилищ и конвейеров схема полей из семнадцатого урока продолжается: trace_id и span_id — обычные строковые поля в JSON-записи.

Чек-лист trace_id в логах#

Один middleware на все маршруты: подмешивание trace_id и span_id через With.
Запрос без трейса — запись без полей: выдуманные значения портят поиск.
Логгер кладётся в контекст: глубинные функции пишут уже с полями запроса.
Ошибка — парное действие: запись Error рядом с RecordError у span-а.
Имя поля — одно во всех сервисах: поиск по цепочке ломается на разнобое.
trace_id — внешний ключ к хранилищу трейсов, span_id — к конкретному участку.

Песочница: псевдо-трейс на map и fmt

OpenTelemetry SDK и HTTP-сервер в песочнице не живут — там работают fmt, strings, strconv, math, sort, errors и time. Механику подмешивания она разминает честно: псевдо-trace_id собирается из времени через fmt.Sprintf с %x, поля запроса копятся в map, и функция пишет записи, доставая logger из контейнера-словаря — модель loggerFrom. Склейка записей цепочки разминается на strings.Builder: одна карта полей, три записи, общий идентификатор в каждой. Форматирование идентификаторов — strconv.FormatInt и hex через fmt. Полный middleware с SDK поднимается локально после go get otel.

Проверка: где живёт trace_id

Где trace_id хранится между middleware и глубинной функцией сервиса?

Проверка: запрос без трейса

Часть внутренних маршрутов не участвует в трейсинге. Что писать в их записи?

Сколько записей получат поля?

Прочитайте код и выберите, что он выведет:

base := slog.New(slog.NewJSONHandler(os.Stdout, nil))

req := base.With("trace_id", "a1b2c3")
req.Info("запрос принят", "route", "/checkout")
base.Info("фоновая задача")

Соберите запись с трейсом

Допишите: ключ поля трейса, уровень записи и оборачивание ошибки.

logger := base.With("", sc.TraceID().String()) logger.Info("запрос принят", "method", "POST") if err := db.Insert(ctx, o); err != nil { logger.("заказ не сохранён", "order", o.ID, "err", err) return fmt.("insert order: %w", err) }

Запрос с трейсом по строкам

Расставьте по порядку: достать span-контекст, подмешать поля, обернуть контекст, входящий лог, вызов, итоговая запись.

Строки

Ваша программа

Нажимайте на строки слева, чтобы собрать программу

Карточки: логи и трейсинг

Термин

trace_id

нажмите, чтобы перевернуть

Определение

Идентификатор цепочки от трейсера: общий для всех сервисов запроса, кладётся в контекст и в поля записей.

1 / 6

Цепочка собрана: middleware подмешивает trace_id и span_id один раз, логгер едет в контексте до глубинных функций, ошибки помечаются парно, а по записи открывается трейс. Механика With — в уроке про With, request_id как второй ключ корреляции — в уроке про сквозные поля. Контекст целиком — в уроке про context курса по продвинутому Go и в контексте chi; поля записей — в четвёртом уроке. Связка с числами — в предыдущем уроке про метрики, всё вместе собирает итоговый проект. Карта курса — на странице курса.

Песочница урока

Редактируйте код и запускайте его прямо здесь — интерпретатор работает в браузере, ничего устанавливать не нужно. За каждый запуск — +2 XP.

Вывод

Запустите код, чтобы увидеть вывод.

Коротко: что запомнить

trace_id приходит из трейсера через контекст: middleware достаёт span-контекст и подмешивает поля через With.
Поля запроса подмешиваются один раз: копия логгера живёт один запрос, base остаётся фоновым.
Запрос без трейса пишется без полей: выдуманные нули и uuid портят поиск в хранилище трейсов.
span_id ведёт к конкретному участку, service — к разрезу по сервисам; ошибка помечается парно с RecordError.
trace_id в записи — внешний ключ: по нему Tempo и Jaeger открывают каскад span-ов всей цепочки.
Трейсы хранятся днями, логи — месяцами: из записи в трейс уходим свежим, обратно — работает дольше.

Домашнее задание

Соберите middleware с полями трейсера: SpanContextFromContext, IsValid, With с trace_id и span_id, логгер в контексте. Затем добавьте в сервис второй сервис-заглушку с тем же SDK и прогоните один запрос: найдите его записи в обоих хранилищах по одному trace_id и откройте трейс. После этого отключите middleware на одном маршруте и посмотрите, как обрывается цепочка поиска — запишите, какие записи потеряли поле.

Вопросы и ответы по уроку

Обязателен ли OpenTelemetry SDK?

Для распределённого трейсинга — де-факто да: SDK создаёт span-ы, раздаёт trace_id и шлёт их в хранилище трейсов. Но сам контракт проще: middleware может подмешивать любые значения, и даже request_id без трейсера склеивает записи одного запроса. SDK нужен тогда, когда начинается несколько сервисов и поиск по цепочке между ними.

Что логировать на span-е, а что в записи?

Span хранит структуру запроса: участки, длительности, статус. Запись хранит поля события: order, kind, err с деталями. Практика: границы запроса — по записи, ошибка — парой запись плюс RecordError, всё остальное — по мере смысла. Дублировать каждый вызов функции записью не нужно: каскад span-ов это покажет.

Почему бы не генерировать trace_id самим?

Свой uuid выглядит как trace_id в записях, но в хранилище трейсов его нет: корреляция с трейсом ломается, хотя поле заполнено. Если трейсинга ещё нет — честнее жить на request_id и подключить трейсер целиком, когда он понадобится: middleware заменит источник значения, записи менять не придётся.

Термины урока

Ключевые понятия из этого урока — короткие определения в глоссарии. Наведите на термин, чтобы вспомнить, откройте карточку для подробностей и ссылки на практику.