Observability и эксплуатация

Метрики говорят, что что-то не так и насколько, трейсы показывают, где в запросе ушло время или возникла ошибка, а логи объясняют, что именно произошло в одном событии. Метрики: числа, агрегированные по набору лейблов (http_requests_total, гистограммы задержек). Они остаются дешёвыми при любом трафике, поэтому на них строят дашборды и алерты, но один конкретный запрос они не покажут. Трейсы: дерево замеренных спанов одного запроса через все сервисы. Видно, какой хоп из шести съел две секунды, но трейсы обычно сэмплируются, так что нужного запроса может не оказаться. Логи: одна запись на событие с любыми подробностями, включая поля с высокой кардинальностью вроде user_id или order_id. Дороги на больших объёмах и медленно агрегируются. Связывают их общие идентификаторы: trace_id в каждой строке лога и exemplars на гистограммах ведут от алерта к метрике, к трейсу и к логу за пару кликов. Непрерывное профилирование часто называют четвёртым сигналом: оно отвечает, какая строка кода тратит CPU или память.

Структурированное логирование пишет каждое событие как постоянное сообщение плюс типизированные пары ключ/значение, поэтому хранилище логов умеет фильтровать и считать по полям, а не грепать текст; log/slog (Go 1.21+) делает это в стандартной библиотеке. Сообщение называет событие и не меняется; всё переменное идёт рядом: slog.Info("order failed", "order_id", id, "tenant", t). Формат и назначение выбирает Handler: slog.NewJSONHandler(os.Stdout, nil) в проде, slog.NewTextHandler в терминале. Уровни: Debug содержит подробности для разработчиков и в проде выключен; Info описывает обычное бизнес-событие; Warn сообщает о чём-то неожиданном, с чем сервис справился сам (ретрай прошёл, сработал фолбэк); Error означает, что операция не удалась и кому-то, возможно, придётся вмешаться. HandlerOptions.Level принимает *slog.LevelVar, так что один процесс можно переключить в Debug на время инцидента без передеплоя. В проде пишите JSON в stdout с уровнем от Info и выше, а доставку отдайте платформе; тела запросов, токены и пароли не логируйте никогда.

ErrorContext получает err без ключа, поэтому slog пишет его под ключом-заглушкой !BADKEY: строка в логе есть, но поля err, по которому можно искать, фильтровать и алертить, в ней нет. Вариадические args читаются парами ключ/значение. Значение, которое не является ни ключом-string, ни slog.Attr, вызов не роняет: хендлер выводит "!BADKEY":"card declined" и идёт дальше, так что в проде ничего громко не ломается. Исправление состоит в том, чтобы дать каждому значению ключ: "err", err. Типизированные атрибуты, slog.Any("err", err) или slog.String("order_id", orderID), потерять ключ не могут в принципе. go vet сообщает arg "err" should be a string or a slog.Attr (possible missing key or value), и go test эту проверку тоже запускает. Она видит только прямые вызовы slog, а не обёртку, которая пробрасывает args ...any. Команды, которым нужны только типизированные атрибуты, закрепляют это через sloglint (attr-only) в golangci-lint.

Prometheus тянет (pull): раз в интервал скрейпа (обычно 15–30 с) он шлёт GET /metrics каждой цели, а promhttp отвечает текущими значениями всех метрик в текстовом виде. Сервис только держит счётчики в памяти; Grafana потом запрашивает Prometheus на PromQL. В дефолтном реестре уже зарегистрированы Go- и process-коллекторы: go_goroutines, go_threads, go_gc_duration_seconds, go_memstats_*, process_cpu_seconds_total, process_resident_memory_bytes, process_open_fds. Go-коллектор читает runtime/metrics в момент скрейпа, между скрейпами ничего не копится. prometheus.NewRegistry() пуст: collectors.NewGoCollector() и collectors.NewProcessCollector(...) регистрируйте сами и отдавайте реестр через promhttp.HandlerFor(reg, ...), потому что promhttp.Handler() отдаёт только дефолтный. Свой реестр убирает регистрацию из глобального состояния: ни одна библиотека не добавит серии втихаря, и каждый тест стартует с чистого листа. Pull к тому же сразу показывает, что цель лежит (up == 0). Короткоживущие батч-задачи, которые завершаются до скрейпа, вместо этого пушат в Pushgateway.

Counter только растёт и читается через rate(); gauge ходит вверх и вниз и читается как есть; histogram раскладывает наблюдения по бакетам, чтобы перцентили можно было посчитать по всем подам; summary считает перцентили внутри одного процесса. Задержку кладут в гистограмму. Counter: запросы, ошибки, отправленные байты; имя заканчивается на _total. При рестарте он обнуляется, и rate() это учитывает, поэтому counter никогда не Set-ят. Gauge: текущее значение: запросы в работе, глубина очереди, размер пула. Inc ставьте в паре с отложенным Dec, иначе ранний return оставит его навсегда ползти вверх. rate() от gauge смысла не имеет. Histogram: экспортирует _bucket{le="..."}, _sum и _count. Бакеты со всех подов можно сложить, а histogram_quantile после этого даёт p99 по всему флоту. Summary: квантили, заранее посчитанные в клиенте; объединить их между инстансами нельзя. Сегодня это редко правильный выбор. Среднее (_sum / _count) прячет хвост: если один запрос из ста идёт 5 с, среднее почти не сдвинется, а почти каждая пятая загрузка страницы с 20 вызовами на него наткнётся.

Трейс описывает весь путь одного запроса: дерево спанов, где каждый спан соответствует одной замеренной операции (хендлер, запрос в базу, исходящий вызов) с атрибутами и статусом. Все спаны запроса несут один и тот же 128-битный trace id, а также свой span id и id родителя. Внутри процесса текущий спан живёт в context.Context: tracer.Start(ctx, name) создаёт ребёнка того спана, что лежит в ctx, и возвращает новый ctx для кода ниже. Между процессами он едет в заголовке. Формат W3C выглядит как traceparent: 00-<trace-id>-<parent-span-id>-<flags>: клиент его вставляет, сервер извлекает и продолжает тот же трейс. otelhttp и otelgrpc вставляют и извлекают заголовок сами; для очереди его нужно положить в метаданные сообщения вручную. SDK собирает завершённые спаны в батчи и отправляет по OTLP в коллектор, а тот передаёт их в Jaeger, Tempo или бэкенд вендора.

SLI измеряет долю хороших событий, например запросов, отвеченных без 5xx быстрее 300 мс. SLO задаёт цель для неё на окне, скажем 99.9% за 30 дней. SLA представляет собой договор с клиентами со штрафами, и его ставят мягче, чем SLO. Измеряйте SLI там, где его чувствует пользователь: на балансировщике или по счётчикам запросов сервера, а не по CPU или памяти. Бюджет ошибок: это 1 − SLO: при 99.9% за 30 дней можно провалить 0.1% запросов, что эквивалентно 43 минутам полного простоя. Бюджет служит инструментом для решений: пока он есть, выкатывайте фичи; когда он кончился, рискованные релизы ждут, а работа над надёжностью идёт первой. 100% как цель неверна: каждая следующая девятка стоит намного дороже предыдущей, а собственные сети пользователей всё равно падают чаще. SLO строже, чем SLA, даёт время среагировать до того, как начнутся штрафы.

На HTTP-сервисе начинают с RED (Rate, Errors, Duration) по каждому роуту; на воркере очереди начинают с saturation в духе USE (глубина очереди и возраст самого старого сообщения) и добавляют RED для обрабатываемых задач. RED сводится к двум метрикам: счётчик http_requests_total{route,method,status} и гистограмма http_request_duration_seconds{route}. И частота, и доля ошибок считаются запросами по счётчику. Для сервиса оформления заказов это первая строка дашборда: запросы в секунду, доля 5xx и p99 по каждому роуту, а рядом те же три цифры для каждой зависимости, которую он вызывает. У воркера saturation означает глубину очереди плюс возраст самого старого ждущего сообщения. Одна глубина врёт: та же цифра нормальна при 1000 msg/s и катастрофична при 10. USE означает Utilisation, Saturation, Errors для каждого ресурса. Utilisation считают как долю занятых воркеров от размера пула. prometheus.NewGaugeFunc читает такие значения в момент скрейпа, так что сам цикл воркера трогать не нужно.

Привяжите атрибуты запроса один раз через **logger.With(...)** и передавайте этот дочерний логгер вниз. Context нужен, чтобы пройти через чужой код, а не вместо параметра, который вы могли бы передать. With возвращает новый *slog.Logger, у которого handler уже отформатировал эти атрибуты, так что цена платится раз на запрос, а не на каждую запись. Логгер в Context создаёт скрытую зависимость: используйте его для кода, который вы не можете изменить, а хелпер обязан откатываться к slog.Default(), чтобы забытый middleware не вызвал панику. Самым выгодным атрибутом оказывается trace_id: оберните Handler, чтобы он добавлял его из trace.SpanContextFromContext(ctx); это работает только для вызовов с методами *Context (InfoContext, ErrorContext).

Дайте типу метод **LogValue() slog.Value**: slog.LogValuer разрешается хендлером в момент вывода, поэтому вычищенный вид выдаёт любое место, где это значение логируют. Возвращайте slog.StringValue("REDACTED") или slog.GroupValue(...) с одними только безопасными полями. Следите за ресивером. LogValue на *User не сработает, если логируют значение User: структура печатается целиком, и вычистка молча не происходит. fmt про LogValuer ничего не знает, поэтому fmt.Sprintf("%+v", u) проходит мимо и печатает токен. Сделайте секрет отдельным типом, type Token string: вычистка на поле остаётся правилом, которое забудут, а вычистка на типе становится поведением по умолчанию.

Обработайте ошибку один раз: либо залогируйте, либо верните, но не то и другое. Каждый слой добавляет контекст обёрткой fmt.Errorf("load order %s: %w", id, err), а единственную запись пишет самая внешняя граница. Границей служит HTTP-хендлер, gRPC-интерсептор, цикл воркера или main: место, где известен код ответа и понятно, сказали ли что-то пользователю. Пять строк на один сбой делают любой счёт по логам неверным в пять раз, и та же переоценка бьёт по метрике, если счётчик инкрементит каждый слой. Уровень выбирает тоже граница, через errors.Is: context.Canceled от отвалившегося клиента логируют как Info, а не Error. Горутина, которой некому возвращать ошибку, сама служит себе границей, и именно поэтому логировать обязана она.

Второй вызов prometheus.MustRegister паникует с duplicate metrics collector registration attempted, потому что счётчик с таким именем уже есть в дефолтном реестре. net/http перехватывает панику и рвёт соединение, так что начиная со второго запроса ни один заказ не создаётся. Метрики создают и регистрируют один раз, на старте, package-level переменными через promauto или в конструкторе с внедрённым prometheus.Registerer. На горячем пути только Inc, Add или Observe. Must* нужен, чтобы дубликат упал на старте, где это громко. Внутри хендлера он падает на каждом запросе, и единственным следом остаётся строка http: panic serving ... в stderr. Перейти на Register и игнорировать ошибку не поможет: каждый запрос будет инкрементить собственный свежий счётчик, которого /metrics никогда не покажет. Внедрённый Registerer к тому же позволяет тесту передать prometheus.NewRegistry() и прочитать значение через testutil.ToFloat64.

Ставьте границы бакетов вокруг SLO и за таймаут: квантиль интерполируется внутри бакета, поэтому с верхней границей по умолчанию в 10 с плохой p99 выглядит как «около десяти секунд». Граница ровно на SLO (le="0.3") делает «запросы быстрее 300 мс» точным делением двух счётчиков, а не интерполированной догадкой. Чем больше бакетов, тем больше рядов: каждый бакет даёт ряд на каждую комбинацию лейблов, так что десяток бакетов на много роутов быстро складывается. Нативные гистограммы (NativeHistogramBucketFactor) снимают ручной выбор: клиент экспортирует бакеты экспоненциального размера, а сервер хранит их компактно.

Аргументы отложенного вызова вычисляются в момент defer, поэтому time.Since(start) берётся сразу после установки start: каждый запрос записывается как примерно ноль секунд, p99 выглядит идеально, а алерт по задержке не сработает никогда. defer откладывает только вызов Observe. Аргумент time.Since(start).Seconds() выполняется сразу, через наносекунды после time.Now(), ещё до того, как checkout вообще начался. Больше ничего подозрительного не видно: _count растёт вместе с трафиком, панели с rate правильные, врёт только задержка. Обычно это всплывает на инциденте, когда клиенты отваливаются по таймауту, а p99 остаётся ровным. prometheus.NewTimer(h) запоминает время старта и читает часы внутри ObserveDuration, который выполняется при выходе из функции. Замыкание defer func() { h.Observe(time.Since(start).Seconds()) }() работает так же. go vet сообщает call to time.Since is not deferred, но go test эту проверку не запускает, поэтому в CI нужен go vet ./... или golangci-lint. Ловит баг и тест, в котором фейковый checkout спит 50 мс, а проверяется сумма наблюдений гистограммы.

**span.RecordError(err) добавляет только событие-исключение; статус спана остаётся Unset, пока вы не вызовете span.SetStatus(codes.Error, err.Error())**, а красит, фильтрует и алертит бэкенд именно по статусу. Атрибуты, переданные в Start через trace.WithAttributes(...), видны сэмплеру; добавленные позже уже не видны. RecordError добавляет событие с именем exception, типом и текстом ошибки; статус оно не меняет. Error ставьте только для настоящих сбоев: not-found или 4xx на серверном спане не считаются ошибкой спана.

Два бага: ctx, который вернул tracer.Start, выброшен, поэтому спан репозитория цепляется к родителю GetOrder; а span.End() вызывается только при успехе, так что каждый неудачный поиск оставляет спан, который никогда не закрывается и не экспортируется. tracer.Start не может изменить переданный ctx: контексты неизменяемы. Пишите ctx, span := tracer.Start(ctx, ...) и передавайте дальше именно этот ctx. defer span.End() сразу после Start покрывает каждый return и каждую панику. Ошибку ещё нужно пометить через span.RecordError(err) и span.SetStatus(codes.Error, ...), иначе спан будет зелёным. Линтер spancheck в golangci-lint ловит пропущенный End или SetStatus раньше, чем ревью.

Пропагатор в Go SDK по умолчанию пустой: пока вы не вызовете otel.SetTextMapPropagator(...) (причём в обоих процессах), заголовок W3C traceparent никто не пишет и не читает. traceparent несёт trace id, id спана вызывающего и флаг сэмплирования; сервер его извлекает, и его спан становится ребёнком, а не новым корнем. Ставится один раз на старте: propagation.NewCompositeTextMapPropagator(propagation.TraceContext{}, propagation.Baggage{}). Второе типичное место разрыва: клиент. otelhttp.NewHandler инструментирует ваш сервер, а исходящему вызову нужен otelhttp.NewTransport, иначе следующий хоп не увидит заголовка вообще. Любой context.Background() посередине обрывает трейс прямо там, а вместе с ним и отмену.

Liveness решает, перезапустить ли контейнер, readiness определяет, пускать ли на под трафик, а startup-проба придерживает обе, пока не закончится медленная инициализация. Все три должны проверять только собственное состояние процесса. Liveness: 200, если процесс не завис: цикл воркера перестал тикать, компонент попал в deadlock. Рестарт должен уметь исправить то, что проба обнаружила, а значит, ничего через сеть. Readiness: 200, когда инициализация закончена (конфиг загружен, кэши прогреты), и 503 с момента прихода SIGTERM, чтобы балансировщики с проверкой здоровья переставали слать трафик, пока под дренируется. Startup: для медленного прогрева: liveness не запускается, пока она не пройдёт. Это лучше, чем угадывать initialDelaySeconds, который либо мал для холодного старта, либо слишком велик, чтобы поймать зависание. Отдавайте /livez и /readyz с основного листенера: если сервер перестанет принимать соединения, пробы упадут вместе с ним. Никогда не пингуйте из пробы общую базу (см. вопрос про простой из-за readiness).

**SIGTERM и удаление пода из эндпоинтов Service происходят одновременно, а не по очереди**, и удаление за секунды доходит до kube-proxy и балансировщиков, а они всё это время шлют трафик в сервер, который Shutdown уже закрыл. preStop-сон на 5–10 с (встроенное действие sleep в Kubernetes 1.30+, шелл не нужен) даёт удалению из эндпоинтов дойти до kube-proxy до начала Shutdown. Потом зовите srv.Shutdown(ctx): он закрывает листенеры, роняет простаивающие keep-alive соединения и ждёт хендлеры, которые ещё работают (последовательность Shutdown описана в теме про HTTP). Только после этого закрывайте то, чем пользуются хендлеры (пул к базе), и вызывайте TracerProvider.Shutdown, чтобы отправить последние спаны. terminationGracePeriodSeconds (по умолчанию 30) покрывает preStop плюс ваш дренаж; когда он истекает, kubelet шлёт SIGKILL. Сон плюс таймаут дренажа должны в него укладываться.

Каждая уникальная комбинация значений лейблов образует отдельный временной ряд: свои записи в индексе, свои чанки на диске. Поэтому лейбл user_id умножает всю метрику на число пользователей. Кардинальность перемножается, а не складывается: 50 роутов × 5 классов статуса × 100k пользователей дают 25 миллионов рядов из одной метрики. Лейбл должен быть множеством, которое можно выписать ещё на деплое: шаблон роута, метод, класс статуса. Идентичность (пользователь, заказ, запрос) живёт в логах и трейсах, они для этого и сделаны. В Go 1.23+ берите r.Pattern: шаблон, который сматчил ServeMux; с r.URL.Path каждый /orders/8f2c… становится новым рядом. Всё несматченное сводите к фиксированному значению вроде "unmatched", а не к сырому вводу. Виновника ищите на странице статуса TSDB в Prometheus (там метрики и лейблы с наибольшим числом рядов) или запросом topk(10, count by (__name__) ({__name__=~".+"})). Ограничьте это и на стороне сервера: sample_limit валит скрейп, у которого число рядов внезапно взорвалось, а metric_relabel_configs с labeldrop убирает лейбл до записи. Читайте r.Pattern после возврата из next.ServeHTTP: mux заполняет его при маршрутизации, поэтому до вызова он пуст.

Все реплики разом завалили пробу, и у Service не осталось эндпоинтов: они вернулись только после успешных проб, когда поды переподключили пулы и прогрелись, а шквал переподключений замедлил только что поднявшуюся базу. Мощности не было даже под запросы, которым база не нужна, и отказ живёт дольше сбоя: под возвращается в эндпоинты Service только после успешных проб (период на successThreshold), потом все поды разом переподключают пулы с холодными кэшами и заваливают только что поднявшуюся базу переподключениями. Readiness отвечает на вопрос «могу ли я прямо сейчас взять запрос»: локально, без сети, и 503 сразу, как началась остановка. Вывести под из-под трафика на деплое и есть её настоящая работа. Если в базу ходит ещё и liveness, поды перезапускаются, и поверх отказа вы платите холодный старт. Проверку зависимости оставьте как /health/deep для синтетического монитора и алерта: она сообщает людям и не имеет права снимать мощность.

Head-сэмплер решает на корневом спане, до того как случилось что-то интересное, поэтому редкий медленный запрос выживает только по удаче: 1% отвечает про форму трафика, но никогда не скажет про «вот этот запрос». sdktrace.ParentBased(sdktrace.TraceIDRatioBased(0.01)): монетку бросает корень, а все ниже уважают флаг из traceparent, иначе трейсы выходят с дырами. На что 1% отвечает хорошо: форма распределения задержек, какой даунстрим съедает основное время типичного запроса, где оно уходит на обычном пути. Tail-сэмплинг переносит решение в коллектор: он копит все спаны трейса до конца, а потом оставляет ошибочные и медленные. Именно он сохранил бы ваш девятисекундный чекаут. Цена: все спаны трейса должны попасть в один экземпляр коллектора, то есть нужен балансировщик по trace id и память под буфер; экономия только на хранении.

Утроившийся p99 при ровном CPU означает ожидание, а не вычисления: сужайте по уже готовым лейблам, откройте один трейс из медленного бакета и берите профиль block, mutex или goroutine, а не CPU. Разложите гистограмму задержек по роуту и инстансу: один инстанс указывает на хост, один роут на эту ветку кода, а все сразу на общую зависимость. Откройте трейс, на который указывает exemplar из медленного бакета: спан, чья длительность выросла, и называет виновника (вызов вниз, блокировка, ретрай). Если код не считает, а ждёт, берите профили block, mutex и goroutine (см. тему про runtime). Непрерывное профилирование (Pyroscope, Parca или агент вендора) хранит профили и до инцидента, так что есть с чем сравнить здоровый час. net/http/pprof регистрируется в http.DefaultServeMux; отдавайте его с собственного mux на 127.0.0.1 и ходите туда через kubectl port-forward.

Будят по симптому, который чувствует пользователь, измеренному как скорость сжигания бюджета ошибок относительно SLO, и никогда по причине. Алерт обязан отвечать, не тратится ли бюджет быстрее допустимого: это скорость за окно, а не значение в моменте. SLI считают как долю хороших событий среди валидных, по уже экспортируемым счётчикам: ответы не-5xx или запросы быстрее 300 мс. 99.9% за 30 дней дают 43 минуты бюджета на месяц. Скорость сжигания (burn rate) заменяет порог. 14.4× за час тратит 2% месячного бюджета и опустошит его примерно за двое суток, поэтому будим. При 6× за шесть часов будим. При 1× за три дня достаточно тикета. В одном правиле держите длинное окно и короткое, час и пять минут: длинное даёт сигнал, короткое гасит алерт, как только проблема кончилась. CPU, память и глубина очереди относятся к причинам, им место на дашбордах и в тикетах. Они срабатывают постоянно, когда никто не пострадал.