Трейсинг в Go — это просто
В эпоху быстрорастущих сервисов важно иметь возможность контролировать состояние системы в любой момент времени. Одними из инструментов для достижения этого являются логи и метрики, которые помогают нам следить за многими параметрами, такими как количество запросов в секунду (RPS), потребление памяти, процент закешированных вызовов и так далее. Иными словами, логи и метрики добавляют нашей системе такую важную характеристику, как наблюдаемость (Observability)
Наблюдаемость позволяет нам легко устранять баги и решать новые проблемы, отвечая на вопрос »Почему это происходит? ».
Представим, что спустя месяцы работы среднее время ответа сервиса увеличилось в 2 раза, о чем мы узнали по метрикам. Сходу можно предположить, что проблема на стороне базы данных, но в сложных проектах с большим количеством интегрированных технологий причина перестает быть настолько явной. Что, если начали тормозить несколько частей нашего сервиса? В таких ситуациях общее время выполнения запроса не указывает нам ни проблемное место, ни сторону, куда нужно копать. На помощь нам приходит ещё один инструмент под названием трейсинг (tracing).
В этой статье мы рассмотрим основы интеграции трейсинга в приложения, написанные на языке Go c помощью инструментария OpenTelemetry и Jaeger. Большая часть взята из официальных документаций, поэтому вы всегда сможете подробнее изучить эту тему.
OpenTelemetry
OpenTelemetry (OTel) — стандарт сбора данных о работе приложений, который состоит из идей уже существующих реализаций, таких как OpenCensus и OpenTracing. Основная задача — предоставить набор стандартизированных SDK, API и инструментов для подготовки и отправки данных в сервисы (observability back-end) для мониторинга систем.
В OTel входят библиотеки для многих популярных языков (C++, Java, Python, .NET, PHP, Rust полный список), а также готовые инстументы от сообщества для трейсинга популярных библиотек и фреймворков. Прежде чем начать писать код, предлагаю ознакомиться с главными компонентами в OpenTelemetry, которые мы будем использовать в будущем. Первым важным компонентом OpenTelemetry является span.
Span
Span представляет собой единицу работы (выполнения) какой-то операции. Он отслеживает конкретные события (events), которые выполняет запрос, рисуя картину того, что произошло за время, в течение которого эта операция была выполнена. Он содержит имя, данные о времени, структурированные сообщения и другие метаданные (атрибуты) для предоставления информации об отслеживаемой операции.
Пример информации, которую содержит span http запроса:
Метаданные содержат информацию о запросе, процессе + название и версию библиотеки.
Они делятся на два типа: Parent (root) span и Child span. Дочерние спаны создаются при вложенных вызовах функции, которые наследуются от ранее созданного родительского. В реализации для языка Go их передают через context.Context.
Правило простое: если в переданном контексте уже есть спан, то создаем дочерний от него. В противном же случае создаем родительский (root) span.
Каждый span имеет span_id и trace_id. Важно знать, что от начала создания родительского и до конца дочерних спанов trace_id не меняется, в то время как span_id для каждого спана уникален. Такие свойства позволяют объединить вложенности и ветвления нескольких вызовов:
Например, в микросервисной архитектуре мы можем передавать trace_id между сервисами, чтобы в конце получить полное дерево вызовов. Аналогично, отправляя одинаковый идентификатор с клиента, можно получить данные о всех его вызовах для аналитики (и не только).
Пример трассировки запросов клиента с одним trace_id
Статус может иметь один из двух статусов: Error и Ok . Как можно понять из названия, статус Error сигнализирует о том, что во время выполнения операций произошла ошибка, а Ok наоборот — все операции выполнились успешно
Jaeger
Ранее говорилось, что OpenTelemetry только готовит (не хранит!) и отправляет данные в observability back-end. Одним из примеров такого бэкенда является Jaeger.
На момент написания статьи последней версией была 1.41.0. Подробнее об установке можно узнать в документации
Установка
Docker
docker run -d --name jaeger \
-p 16686:16686 \
-p 14268:14268 \
jaegertracing/all-in-one:1.41Docker-compose
version: '3.8'
services:
jaeger:
image: jaegertracing/all-in-one
ports:
- "14268:14268"
- "16686:16686"
docker compose up -dЛокальная установка
Скачать и запустить готовый бинарник https://www.jaegertracing.io/download/
При открытии http://localhost:16686 вы должны увидеть такую картину:
Пишем приложение
Для примера я написал маленький сервис, который сохранят и отдает заметки из Redis.
Структура:
Структура
├── storage
│ └── redis.go
├── server
│ └── http.go
├── models
│ └── note.go
├── main.go
├── go.sum
├── go.mod
├── docker-compose.yaml
└── cmd
└── main.gomodels/note.go
package models
import (
"errors"
"time"
)
import "github.com/google/uuid"
var ErrNotFound = errors.New("note not found")
type Note struct {
NoteID uuid.UUID `json:"note_id"`
Title string `json:"title"`
Content string `json:"content"`
Created time.Time `json:"created"`
}storage/redis.go
package storage
import (
"context"
"encoding/json"
"fmt"
"github.com/go-redis/redis/v9"
"github.com/google/uuid"
"trace-example/models"
)
type NotesStorage struct {
client redis.UniversalClient
}
func NewNotesStorage(client redis.UniversalClient) NotesStorage {
return NotesStorage{client: client}
}
func (s NotesStorage) Store(ctx context.Context, note models.Note) error {
data, err := json.Marshal(note)
if err != nil {
return fmt.Errorf("marshal note: %w", err)
}
if err = s.client.Set(ctx, note.NoteID.String(), data, -1).Err(); err != nil {
return fmt.Errorf("redis set: %w", err)
}
return nil
}
func (s NotesStorage) Get(ctx context.Context, noteID uuid.UUID) (*models.Note, error) {
data, err := s.client.Get(ctx, noteID.String()).Bytes()
if err != nil {
if err == redis.Nil {
return nil, models.ErrNotFound
}
return nil, fmt.Errorf("redis get: %w", err)
}
var note models.Note
if err = json.Unmarshal(data, ¬e); err != nil {
return nil, fmt.Errorf("unmarshal note: %w", err)
}
return ¬e, nil
}
server/http.go
package server
import (
"errors"
"github.com/gofiber/fiber/v2"
"github.com/google/uuid"
"time"
"trace-example/models"
"trace-example/storage"
)
type FiberHandler struct {
notesStorage storage.NotesStorage
}
func NewFiberHandler(notesStorage storage.NotesStorage) FiberHandler {
return FiberHandler{notesStorage: notesStorage}
}
func (h FiberHandler) CreateNote(fiberctx *fiber.Ctx) error {
input := struct {
Title string `json:"title"`
Content string `json:"content"`
}{}
if err := fiberctx.BodyParser(&input); err != nil {
return err
}
noteID := uuid.New()
err := h.notesStorage.Store(fiberctx.UserContext(), models.Note{
NoteID: noteID,
Title: input.Title,
Content: input.Content,
Created: time.Now(),
})
if err != nil {
return fiber.NewError(fiber.StatusInternalServerError, err.Error())
}
return fiberctx.JSON(map[string]any{
"note_id": noteID,
})
}
func (h FiberHandler) GetNote(fiberctx *fiber.Ctx) error {
noteID, err := uuid.Parse(fiberctx.Query("note_id"))
if err != nil {
return fiber.NewError(fiber.StatusBadRequest, err.Error())
}
note, err := h.notesStorage.Get(fiberctx.UserContext(), noteID)
if err != nil {
if errors.Is(err, models.ErrNotFound) {
return fiber.NewError(fiber.StatusNotFound, err.Error())
}
return fiber.NewError(fiber.StatusInternalServerError, err.Error())
}
return fiberctx.JSON(note)
}cmd/main.go
package main
import (
"context"
"github.com/go-redis/redis/v9"
"github.com/gofiber/fiber/v2"
"log"
"trace-example/server"
"trace-example/storage"
)
func main() {
app := fiber.New()
// Подключаемся к Redis
client := redis.NewClient(&redis.Options{
Addr: "localhost:6379",
})
if err := client.Ping(context.TODO()).Err(); err != nil {
log.Fatal("create redis client", err)
}
// Настраиваем роутер
handler := server.NewFiberHandler(storage.NewNotesStorage(client))
app.Post("/create", handler.CreateNote)
app.Get("/get", handler.GetNote)
log.Fatal(app.Listen(":8080"))
}
docker-compose.yaml
version: '3.8'
services:
jaeger:
image: jaegertracing/all-in-one
ports:
- "14268:14268"
- "16686:16686"
redis:
restart: on-failure
image: "redis:latest"
command: redis-server --port 6380
ports:
- "6379:6379"
environment:
REDIS_REPLICATION_MODE: master
volumes:
- redis-data:/var/lib/redis
volumes:
redis-data:Поднимаем контейнеры с Redis и Jaeger
docker compose up -dИ запускаем наш сервис
go run cmd/main.goПосле старта можем добавить заметку:
И получить её обратно:
curl запросы
Добавление заметки
curl --location --request POST 'localhost:8080/create' \
--header 'Content-Type: application/json' \
--data-raw '{
"title":"Something interesting",
"content": "Lorem ipsum..."
}'Получение заметки
curl --location --request GET 'localhost:8080/get?note_id=7411ff79-fd1d-46ab-b9f8-21105cd770ce'Начнем интеграцию OpenTelemetry с создания экспортера (exporter) , который отправляет (экспортирует) данные в observability back-end иимеет простой интефейс
type SpanExporter interface {
ExportSpans(ctx context.Context, spans []ReadOnlySpan) error
Shutdown(ctx context.Context) error
}Здесь мы видим ещё один вид спанов — ReadOnlySpan. Это не отдельный тип, а просто интефейс только для получения информации о спане.
Теперь создадим exporter для Jaeger:
package tracer
import (
"go.opentelemetry.io/otel/exporters/jaeger"
tracesdk "go.opentelemetry.io/otel/sdk/trace"
)
// NewJaegerExporter creates new jaeger exporter
//
// url example - http://localhost:14268/api/traces
func NewJaegerExporter(url string) (tracesdk.SpanExporter, error) {
return jaeger.New(jaeger.WithCollectorEndpoint(jaeger.WithEndpoint(url)))
}
Теперь создадим провайдера (provider), который будет создавать трейсеры (tracers)
package tracer
import (
"go.opentelemetry.io/otel/exporters/jaeger"
"go.opentelemetry.io/otel/sdk/resource"
tracesdk "go.opentelemetry.io/otel/sdk/trace"
semconv "go.opentelemetry.io/otel/semconv/v1.12.0"
)
func NewTraceProvider(exp tracesdk.SpanExporter, ServiceName string) (*tracesdk.TracerProvider, error) {
// Ensure default SDK resources and the required service name are set.
r, err := resource.Merge(
resource.Default(),
resource.NewWithAttributes(
semconv.SchemaURL,
semconv.ServiceNameKey.String(ServiceName),
),
)
if err != nil {
return nil, err
}
return tracesdk.NewTracerProvider(
tracesdk.WithBatcher(exp),
tracesdk.WithResource(r),
), nil
}
Разберем код:
return tracesdk.NewTracerProvider(
tracesdk.WithBatcher(exp),
tracesdk.WithResource(r),
), nilПри создании провайдера мы добавляем опции:
WithBatcher — отправляет данные экспортеру пачками, повышая производительность
WithResourse — добавляет в каждый трейс данные (ресурсы)
resource.Merge(
resource.Default(),
resource.NewWithAttributes(
semconv.SchemaURL,
semconv.ServiceNameKey.String(ServiceName),
),
)resource.Merge объединяет несколько ресурсов. Вместе со стандартными мы добавляем версию библиотеки и название сервиса, чтобы добавить возможность фильтровать трейсы каждого сервиса.
Теперь осталось всего лишь создать трейсер:
package tracer
import (
"fmt"
"go.opentelemetry.io/otel"
"go.opentelemetry.io/otel/exporters/jaeger"
"go.opentelemetry.io/otel/sdk/resource"
tracesdk "go.opentelemetry.io/otel/sdk/trace"
semconv "go.opentelemetry.io/otel/semconv/v1.12.0"
"go.opentelemetry.io/otel/trace"
)
func InitTracer(jaegerURL string, serviceName string) (trace.Tracer, error) {
exporter, err := NewJaegerExporter(jaegerURL)
if err != nil {
return nil, fmt.Errorf("initialize exporter: %w", err)
}
tp, err := NewTraceProvider(exporter, serviceName)
if err != nil {
return nil, fmt.Errorf("initialize provider: %w", err)
}
otel.SetTracerProvider(tp) // !!!!!!!!!!!
return tp.Tracer("main tracer"), nil
}
otel.SetTracerProvider(tp) — очень важная строка. Она задает глобальный провайдер, чтобы другие библиотеки с инструментарием могли начинать свои трейсы
Добавим в main.go вызов InitTracer :
func main() {
tracer, err := trace.InitTracer("http://localhost:14268/api/traces", "Note Service")
if err != nil {
log.Fatal("init tracer", err)
}
........Ищем готовый инстументарий:
Перед тем, как писать свой велосипед, попробуй найти готовый в интернете
Всего можно выделить три способа поиска готового инструментария
Посмотреть в https://github.com/open-telemetry/opentelemetry-go-contrib/tree/main/instrumentation
Найти в репозитории нужной библиотеки пакет
otelXxx(Xxx — название библиотеки)Загуглить :)
golang название_библиотеки OpenTelemetry
Например, давайте найдем инструментарий для github.com/gofiber/fiber:
Видим, что сторонний репозиторий заархивирован, но его код был добавлен в официальный
Многие библиотеки не имеют readme.md файла, поэтому всегда лучше смотреть в папку example. Находим строку app.Use(otelfiber.Middleware("my-server")) . Добавим её в наш код!
import "github.com/gofiber/contrib/otelfiber"
func main() {
_, err := trace.InitTracer("http://localhost:14268/api/traces", "Note Service")
.......
app := fiber.New()
app.Use(otelfiber.Middleware("my-server")) // <-------
.......После перезапуска выполним несколько запросов и вернемся в Jaeger:
Наш сервис виден в списке! 
Нажимаем Find Traces!
После нажатия на Find Traces увидим список наших трейсов:
Для перехода в нужный нам трейс достаточно нажать на его название.
Как это работает?
Ранее мы создали мидлварь для фреймворка fiber, который перехватывает входящий запрос, создает родительский спан и передает его в контексе. Заметьте, что без строки otel.SetTracerProvider этот трейс нигде не будет записываться.
В метаданные спана он включил данные запроса и ответа, которые могут оказаться важными при исправлении проблем.
Теперь добавим трассировку для редиса: с помощью второго метода поиска узнаем, что нужный пакет уже лежит в репозитории go-redis — https://github.com/go-redis/redis/tree/master/extra/redisotel. Добавим его в код:
import "github.com/go-redis/redis/extra/redisotel/v9"
func main() {
.........
// Подключаемся к Redis
client := redis.NewClient(&redis.Options{
Addr: "localhost:6379",
})
if err := client.Ping(context.TODO()).Err(); err != nil {
log.Fatal("create redis client", err)
}
if err := redisotel.InstrumentTracing(client); err != nil { // <------
log.Fatal("enable instrument tracing", err)
}
.........Выполним ещё раз запросы и посмотрим на трейсы. Не забудьте нажать кнопку Find Traces ещё раз (или перезагрузить страницу)
Теперь мы видим не только данные фибера, но и запросы в бд!
Как это работает?
redisotel добавляет хук для нашего клиента, чтобы при вызове любой операции создавать ещё один спан с нужными данными.
В нашем примере мы рассмотрели только две библиотеки, но вы можете найти несколько сотен для популярных библиотек. Примеры:
otelgrpc — унарный interceptor для запросов gRPC
otelmongo — трейсер для клиента mongodb
otelhttp — middleware для net/http
otelsarama — трейсер для sarama, популярного клиента kafka
otelfiber, otelgin, otelbeego, otelecho — мидлвари для веб-фреймворков
otelmemcached — трейсер для клиента memcached
otelkit — трейсер для микросервисного фреймворка kit
otelgocql — трейсер для клиента Cassandra
otelpgx — трейсер для клиента PostresSQL pgx (и pgxpool)
И много других!
Ручной трейсинг
Казалось бы, что с таким инструментарием мы уже на порядок повышаем observability нашего сервиса. Но часто возникают ситуации, когда нужно создать свои спаны с более подробной информацией. Взглянем на интерфейс трейсера:
type Tracer interface {
Start(ctx context.Context, spanName string, opts ...SpanStartOption) (context.Context, Span)
}Добавим его в структуру FiberHandlers
type FiberHandler struct {
notesStorage storage.NotesStorage
tracer trace.Tracer // <-------
}
func NewFiberHandler(notesStorage storage.NotesStorage, tracer trace.Tracer) FiberHandler {
return FiberHandler{notesStorage: notesStorage, tracer: tracer}
}Теперь создадим свой спан:
ctx, span := h.tracer.Start(fiberctx.UserContext(), "GetNote")
defer span.End()
....
note, err := h.notesStorage.Get(ctx, noteID)
....Важные моменты:
Во всех последующих функциях нужно передавать контекст, полученный из
tracer.Startdefer span.End()завершает спан. Время выполнения спана = время вызоваspan.End()— время вызоваtracer.Start()
Для добавление своей информации в спан нужно воспользоваться функцией trace.WithAttributes()
ctx, span := h.tracer.Start(fiberctx.UserContext(), "GetNote", trace.WithAttributes(
attribute.String("MyKey", "MyValue")),
)Теперь посмотрим на новый трейс:
События (events):
Зачастую наши функции делают несколько вызовов других. Для измерения времени каждой есть возможность разделить спан на события с помощью span.AddEvent(). В параметрах можно также задать атрибуты:
func (h FiberHandler) GetNote(fiberctx *fiber.Ctx) error {
ctx, span := h.tracer.Start(fiberctx.UserContext(), "GetNote")
defer span.End()
span.AddEvent("parse note_id") // <------
noteID, err := uuid.Parse(fiberctx.Query("note_id"))
if err != nil {
return fiber.NewError(fiber.StatusBadRequest, err.Error())
}
span.AddEvent("call redis storage", trace.WithAttributes( // <----
attribute.String("MyEventKey", "MyEventValue")),
)
note, err := h.notesStorage.Get(ctx, noteID)
if err != nil {
if errors.Is(err, models.ErrNotFound) {
return fiber.NewError(fiber.StatusNotFound, err.Error())
}
return fiber.NewError(fiber.StatusInternalServerError, err.Error())
}
span.AddEvent("write note in json") // <------
return fiberctx.JSON(note)
}Если откроем подробности нового спана, то увидим следующее
Цифры здесь — это не время выполнения, а количество времени, пройденное с начала спана (иными словами offset). Например, реальное время выполнения запроса в редис = время спана — предыдущий сдвиг = 914 — 43 = 871 микросекунд.
Состояния спанов и ошибки
Остановим Redis и попробуем выполнить запрос:
$ docker ps --format '{{.ID}} {{.Names}}'
3d69134be67f trace-example-redis-1
830c81a3b071 trace-example-jaeger-1
$ docker stop 3d69134be67f
3d69134be67f
У трейса появились ошибки
По трейсу можно понять, что клиент редиса попытался 4 раза восстановить соединение, но в конце вернул ошибку. Подробности можем увидеть в родительском спане:
Но почему мы видим тип *fiber.Error? Ранее подключенный middleware от otelfiber проверяет ошибку нашего обработчика (handler’а). Если err!= nil, то он записывает ошибку в спан с помощью метода span.RecordError(err) . Добавим эту строку в наш код:
import "go.opentelemetry.io/otel/codes"
....
err := h.notesStorage.Store(ctx, ......)
if err != nil {
span.RecordError(err)
span.SetStatus(codes.Error, err.Error())
return fiber.NewError(fiber.StatusInternalServerError, err.Error())
}
....Обратите внимание на дополнительный вызов span.SetStatus . Из описания RecordError:
An additional call to SetStatus is required if the Status of the Span should be set to Error, as this method does not change the Span status
Ранее говорилось, что спан имеет один из двух статусов: Ok и Error . В коде выше мы дополнительно задаем этот статус (хотя Jeager считает трейс с ошибкой даже без него).
В запись ошибки также можно добавить артибуты, как в спан и его ивенты:
span.RecordError(err, trace.WithAttributes(
attribute.String("SomeErrorInfo", "FATAL!!!!")),
)
Теперь ошибка будет записываться не только через инструментарий, но и в нашем коде. Если вы поднимаете все ошибки наверх, то вызывать span.RecordError можно только на уровне транспорта или сервисов. В противном случае (если ошибки логируются на месте), может быть полезно добавление записи на каждом этапе.
Заключение
Код: https://github.com/illiafox/tracing-example
В этой статье я хотел показать, что страшное слово трейсинг — всего лишь полчаса чтения документации. Добавив буквально несколько строчек в клиенты используемых продуктов мы можем легко отследить любое выполнение с малейшими подробностями, а с ручными спанами вообще узнать всю нужную информацию не залезая в код.
Много информации было взято из официальных документаций:
В следующей статье мы рассмотрим трейсинг между микросервисами, который (спойлер) тоже реализуется одной строкой.
