Трейсинг в 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 между сервисами, чтобы в конце получить полное дерево вызовов. Аналогично, отправляя одинаковый идентификатор с клиента, можно получить данные о всех его вызовах для аналитики (и не только).

Статус может иметь один из двух статусов: Error и Ok . Как можно понять из названия, статус Error сигнализирует о том, что во время выполнения операций произошла ошибка, а Ok наоборот - все операции выполнились успешно

Jaeger

Ранее говорилось, что OpenTelemetry только готовит (не хранит!) и отправляет данные в observability back-end. Одним из примеров такого бэкенда является Jaeger.

На момент написания статьи последней версией была 1.41.0. Подробнее об установке можно узнать в документации

Установка

docker run -d --name jaeger 
  -p 16686:16686 
  -p 14268:14268 
  jaegertracing/all-in-one:1.41

version: '3.8'

services:
  jaeger:
    image: jaegertracing/all-in-one
    ports:
      - "14268:14268"
      - "16686:16686"

docker compose up -d

При открытии http://localhost:16686 вы должны увидеть такую картину:

Пишем приложение

Для примера я написал маленький сервис, который сохранят и отдает заметки из Redis.

Структура:

├── storage
│   └── redis.go
├── server
│   └── http.go
├── models
│   └── note.go
├── main.go
├── go.sum
├── go.mod
├── docker-compose.yaml
└── cmd
    └── main.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"`
}

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, &note); err != nil {
		return nil, fmt.Errorf("unmarshal note: %w", err)
	}

	return &note, nil
}

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)
}

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"))
}

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 --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)
}
........

Ищем готовый инстументарий:

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

Всего можно выделить три способа поиска готового инструментария

1. Посмотреть в https://github.com/open-telemetry/opentelemetry-go-contrib/tree/main/instrumentation

2. Найти в репозитории нужной библиотеки пакет otelXxx (Xxx - название библиотеки)

3. Загуглить :) 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 увидим список наших трейсов:

Для перехода в нужный нам трейс достаточно нажать на его название.

Как это работает?

Ранее мы создали мидлварь для фреймворка 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.Start

• defer 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 можно только на уровне транспорта или сервисов. В противном случае (если ошибки логируются на месте), может быть полезно добавление записи на каждом этапе.

Sampling rate

При высоких нагрузках выполнять трейс на каждый запрос крайне избыточно. OpenTelemetry имеет параметр Sampling probability. Существует несколько способов его настройки:

1. Через tracesdk.TraceIDRatioBased

provider := tracesdk.NewTracerProvider(
    ......
	tracesdk.WithSampler(
		tracesdk.TraceIDRatioBased(0.1),
	),
)

2. Через переменные окружения

OTEL_TRACES_SAMPLER=traceidratio 
OTEL_TRACES_SAMPLER_ARG=0.1 
go run cmd/main.go

Например, при значении 0.1 из 10000 трейсов будут записаны только 1000*0.1=100 . При 1.0 будут записаны все трейсы, а с 0.0 - никакие.

Значение, которое должен иметь коефициент, зависит от нагрузки вашего приложения. Зачастую его можно узнать обычным подбором и сравнением с временем ответа сервиса без трейсинга. Значение по-умолчанию равно 1.0

Заключение

Код: https://github.com/illiafox/tracing-example

В этой статье я хотел показать, что страшное слово трейсинг - всего лишь полчаса чтения документации. Добавив буквально несколько строчек в клиенты используемых продуктов мы можем легко отследить любое выполнение с малейшими подробностями, а с ручными спанами вообще узнать всю нужную информацию не залезая в код.

Много информации было взято из официальных документаций:

• https://opentelemetry.io/docs/instrumentation/go/

• https://www.jaegertracing.io/docs/1.41/getting-started/

В следующей статье мы рассмотрим трейсинг между микросервисами, который (спойлер) тоже реализуется одной строкой.