ElasticAPM: три бага одной интеграции

Проблема

Стек в проекте: Gin + GORM v2 + pgx/v5, PostgreSQL и PgBouncer, запущенный в режиме транзакций. Задача: подключить Elastic APM, чтобы в трейсе запроса видеть не только HTTP-транзакцию, но и SQL-спаны – какой запрос, сколько занимал, что тормозит.

Что такое «транзакция»?

В первых же строках термин встретился в трёх значениях – разведём.

APM-транзакция – единица модели данных Elastic APM: верхнеуровневая работа, для веб-сервера одна на входящий HTTP-запрос. apmgin создаёт её в middleware и кладёт в request context; все спаны – её дети. Транзакция БД – обычный BEGIN/COMMIT, к трейсингу отношения не имеет.

Транзакционный режим PgBouncer – режим пула, в котором серверное соединение закрепляется за клиентом только на время транзакции БД, а затем возвращается в пул.

Дерево, которое хочется увидеть в Kibana:

Transaction  POST /api/v1/orders             400ms   ← apmgin
├─ Span  INSERT INTO "orders" ...             12ms   ← apmsql
├─ Span  SELECT * FROM "users" ...             3ms   ← apmsql
└─ Span  GET awesome-monolith/users/123      150ms   ← внешний HTTP-вызов

Спан не существует вне APM-транзакции – поэтому фраза «транзакция не доехала до драйвера» означает: спанам физически некуда привязаться.

Эта статья – полная хронология: две ошибки, которые были сделаны при подключении драйвера базы, и один нюанс, спрятанный во фреймворке, из-за которого спаны не отобразились.

Сделали: подключили apmgin.Middleware в роутер, APM-драйвер в GORM, используем WithContext(ctx) в репозиториях. Деплоим, открываем Kibana. HTTP-транзакции на месте. SQL-спанов нет.

Акт 1: наивное подключение и SQLSTATE 42P05

До APM подключение к базе выглядело так:

// postgres.go – ДО
db, err = gorm.Open(postgres.New(postgres.Config{
	DSN:                  dsn,
	PreferSimpleProtocol: true,
}), &gorm.Config{PrepareStmt: false})

Ранее включили PreferSimpleProtocol: true, потому что в конфигурации этого проекта PgBouncer работал в режиме транзакций без поддержки именованных prepared statements.

Для APM у Elastic есть готовый модуль apmgormv2.

Подключаем:

// postgres.go – ПЕРВАЯ ПОПЫТКА С APM
import apmpostgres "go.elastic.co/apm/module/apmgormv2/v2/driver/postgres"

db, err = gorm.Open(apmpostgres.Open(dsn), &gorm.Config{PrepareStmt: false})

Деплоим: база отвечать не перестала, но репозитории начали сыпать:

ERROR: prepared statement "stmtcache_ffd70399269f8f722..." already exists (SQLSTATE 42P05)

Почему сломалось

PrepareStmt: false в gorm.Config отключает только кэш стейтментов самого GORM. Куда важнее, что apmpostgres.Open(dsn) внутри просто собирает postgres.Dialector с DriverName: apmpgxv5.DriverName – и опция PreferSimpleProtocol теряется, потому что передавать его просто некуда: у обёртки нет аналога postgres.New(Config{...}).

А pgx без явного указания режима работает в default_query_exec_mode=cache_statement: кэширует именованные prepared statements на соединении. PgBouncer в transaction pooling выдаёт соединения из пула – на следующем «своём» соединении стейтмент с тем же именем уже существует. Отсюда 42P05.

Цепочка целиком:

apmpostgres.Open(dsn)
└── postgres.Dialector{DriverName: apmpgxv5.DriverName, DSN: dsn}
    └── аналога postgres.New(Config{...}) нет
        └── PreferSimpleProtocol передать некуда
            └── pgx: default_query_exec_mode = cache_statement
                └── имя стейтмента считается от текста запроса,
                    поэтому у одинаковых запросов оно совпадает

клиент 1 --> PgBouncer --> backend A    PREPARE stmtcache_ffd7...   ok
клиент 2 --> PgBouncer --> backend A    PREPARE stmtcache_ffd7...   42P05
                           ^
                           то же соединение выдано из пула,
                           имя на нём уже занято для prepared statement

Как диагностировали

42P05 – ошибка случилась на стороне БД, соответственно запрос до базы дошёл и упал на сервере. Стектрейс в логах указывал на репозиторий, но репозиторий не менялся – менялся режим, в котором драйвер сделал стейтменты.

Акт 2: чиним драйвер, не ломая PgBouncer

Хочется написать так:

// НЕ РАБОТАЕТ: PreferSimpleProtocol игнорируется
db, err = gorm.Open(postgres.New(postgres.Config{
	DSN:                  dsn,
	PreferSimpleProtocol: true,
	DriverName:           apmpgxv5.DriverName,
}), &gorm.Config{PrepareStmt: false})

Не работает. Открываем исходник gorm.io/driver/postgres:

func (dialector Dialector) Initialize(db *gorm.DB) (err error) {
	...
	if dialector.Conn != nil {
		db.ConnPool = dialector.Conn
	} else if dialector.DriverName != "" {
		// наш случай: сразу sql.Open по DSN-строке
		db.ConnPool, err = sql.Open(dialector.DriverName, dialector.Config.DSN)
	} else {
		// ветка с PreferSimpleProtocol недостижима при заданном DriverName
		config, err = pgx.ParseConfig(dialector.Config.DSN)
		if dialector.Config.PreferSimpleProtocol {
			config.DefaultQueryExecMode = pgx.QueryExecModeSimpleProtocol
		}
		db.ConnPool = stdlib.OpenDB(*config)
	}
}

Ветвление жёсткое: задан DriverName – GORM делает sql.Open и вообще не парсит DSN через pgx. PreferSimpleProtocol игнорируется и в логах этого нет. Опять тихо, опять режим по умолчанию, опять PgBouncer.

Решение – собрать pgx-конфиг самим, до GORM, и передать его в sql.Open как «зарегистрированный» DSN:

// postgres.go – РАБОЧИЙ ВАРИАНТ
import (
	"github.com/jackc/pgx/v5"
	"github.com/jackc/pgx/v5/stdlib"
	apmpgxv5 "go.elastic.co/apm/module/apmsql/v2/pgxv5"
	"gorm.io/driver/postgres"
	"gorm.io/gorm"
)

func Connect(dsn string) *gorm.DB {
	syncOnce.Do(func() {
		// 1. Парсим DSN в pgx-конфиг и принудительно ставим simple protocol –
		//    единственное место, где этот режим задаётся надёжно.
		pgxConfig, err := pgx.ParseConfig(dsn)
		if err != nil {
			log.Fatalf("failed to parse postgres config: %v", err)
		}
		pgxConfig.DefaultQueryExecMode = pgx.QueryExecModeSimpleProtocol

		// 2. Регистрируем конфиг в stdlib – получаем DSN-строку,
		//    которая на самом деле ключ к нашему конфигу.
		registeredDSN := stdlib.RegisterConnConfig(pgxConfig)

		// 3. Отдаём GORM APM-драйвер с этой строкой. DriverName задан,
		//    sql.Open откроет соединение через apmpgxv5, а конфиг
		//    (с simple protocol) уже вшит в registeredDSN.
		db, err = gorm.Open(
			postgres.New(postgres.Config{
				DSN:        registeredDSN,
				DriverName: apmpgxv5.DriverName,
			}),
			&gorm.Config{PrepareStmt: false},
		)
		...
	})
	return db
}

sql.Open(apmpgxv5.DriverName, registeredDSN) сначала резолвит DSN через pgx-stdlib, используя конфиг опцию QueryExecModeSimpleProtocol, потом оборачивает соединение APM-трассировкой.

Деплоим: 42P05 исчез, HTTP-транзакции в Kibana видны, SQL-спанов по-прежнему не видно. Команда не понимает почему так, в чем нюанс, непонятно что делать дальше.

Акт 3: спаны есть, но их нет

Инструментация подключена по документации:

apmgin.Middleware(router) – первым в цепочке;
APM-драйвер в GORM;
в каждом репозитории db.WithContext(ctx).Where(...).

Агент – библиотека go.elastic.co/apm/v2: ядро, которое живёт в процессе приложения, создаёт транзакции и спаны, держит их в контексте и отправляет в APM Server. apmgin и apmsql – модули-инструментации поверх агента: первый открывает транзакцию на HTTP-запрос, второй – спан на SQL-запрос. Делят одну модель данных (те же типы Transaction/Span), но каждый отвечает за свой слой: apmgin работает на входе, apmsql – у самой базы, агент – то, что между ними и вокруг.

Проверяем по цепочке. apmgin кладёт транзакцию в запрос через middleware:

// apmgin/v2 middleware.go
tx, body, req := apmhttp.StartTransactionWithBody(m.tracer, requestName, c.Request)
c.Request = req // транзакция – внутри c.Request.Context()

Хендлер далее передает контекст в h.useCase.Create

func (h *OrderHandler) Create(c *gin.Context) {
	user, ok := requireUser(h.base, c)
	...
	// внимание на первый аргумент
	order, err := h.useCase.Create(c, user.ID, input)
	...
}

Дальше контекст без изменений проходит юзкейс и репозиторий db.WithContext(ctx), доезжает до драйвера apmsql. apmsql просит агента открыть спан – агент ищет транзакцию через ctx.Value(...), получает nil, и реагирует молчанием (исходник агента, go.elastic.co/apm/v2):

// apm/v2 span.go
func (tx *Transaction) StartSpanOptions(name, spanType string, opts SpanOptions) *Span {
	if tx == nil {
		return newDroppedSpan() // штатная ветка, а не ошибка
	}
	...
}

DroppedSpan – обычный спан без трейсера: SQL-запрос выполняется, но в очередь на отправку спан не попадает. Ошибки нет ни в одной сигнатуре. Для агента «нет транзакции» – штатный случай: фоновая джоба живёт без HTTP-запроса, и агент не может отличить её от запроса, у которого транзакция потерялась по дороге. Инструментация всё равно может вызвать End у такого спана, поэтому SQL-запрос завершается как обычно, а в Kibana ничего не попадает.

Выясняем где же теряется транзакция apm:

apm.TransactionFromContext(c.Request.Context()) // хендлер: транзакция найдена
apm.TransactionFromContext(ctx)                 // репозиторий: nil

Возникает вопрос, почему с c.Request.Context() работает, но есть проблемы с *gin.Context.

`gin.Context` – это не `context.Context`

Хендлер передаёт в юзкейс *gin.Context, он реализует интерфейс context.Context. На схеме изображено как gin.Context «содержит» настоящий контекст:

*gin.Context                          ← то, что пришло в usecase как ctx
├── Keys   map[string]any             ← пространство имён gin: c.Set("UserID") / c.Get(...)
├── Request *http.Request             ← поле-указатель
│    └── ctx context.Context          ← пространство имён запроса: Request.Context()
│         └── valueCtx(hub Sentry)    ←   положило sentry-middleware
│              └── valueCtx(tx APM)   ←   положило apmgin
└── Value()/Deadline()/Done()/Err()
    ├── Value сначала ищет в Keys
    └── request context доступен только с включённым fallback

Транзакция живёт во втором пространстве имён, а реализации gin ищут только в первом: gin.Context содержит настоящий контекст, но не проксирует его. Исходник gin (ветка v1.12):

// gin/context.go
func (c *Context) Value(key any) any {
	...
	if val, exists := c.Get(key); exists {
		return val // пространство имён gin (Keys)
	}
	if !c.hasRequestContext() {
		return nil // ← наш случай
	}
	return c.Request.Context().Value(key) // пространство имён запроса – только с флагом
}

func (c *Context) hasRequestContext() bool {
	hasFallback := c.engine != nil && c.engine.ContextWithFallback // ← false
	...
}

Value – единственный способ достать данные из контекста, и какой код выполнится, определяет конкретный тип за интерфейсом. Пока по цепочке шёл стандартный контекст, поиск шёл по обёрткам WithValue и находил транзакцию; когда пришёл *gin.Context – подменилась реализация. Данные не потерялись, транзакция по-прежнему в c.Request.Context(). Но данные недоступны.

То же с Deadline, Done, Err: без флага ctx.Done() у gin.Context всегда nil – отмена клиента не существует.

Цепочка падения спана, целиком:

apmgin.Middleware
└── c.Request.Context()   <-- транзакция APM лежит здесь

handler   useCase.Create(c, ...)        передали gin.Context вместо ctx
usecase   repo.Create(ctx, ...)         тот же gin.Context
repo      db.WithContext(ctx)           gin.Context уезжает в database/sql
apmsql    apm.StartSpanOptions(ctx)     ищет транзакцию через ctx.Value(...)

          gin.Context.Value(key)
          ├── служебные ключи gin        нет
          ├── строковые ключи из c.Set   нет
          └── c.Request.Context()        закрыто, так как флаг не установлен:
                  hasRequestContext() == false
                  ContextWithFallback = false

          результат nil, спан дропнут молча

HTTP-транзакция при этом видна – её apmgin создаёт и завершает сам, в обход всей этой цепочки. Отсюда и обманчивая картина «APM работает, но частично».

Почему это не баг gin

Fallback в request context появился в Gin v1.8.0. В v1.8.1 добавили флаг ContextWithFallback; оба изменения записаны в changelog Gin. Делегирование выключено по умолчанию ради обратной совместимости. После его включения c.Value(key) может вернуть значение из request context там, где старый код получал nil. Поэтому флаг opt-in, а в документации он описан одной строкой:

ContextWithFallback enable fallback Context.Deadline(), Context.Done(), Context.Err() and Context.Value() when Context.Request.Context() is not nil.

Одна строка документации вместо работающих спанов, отмены запросов и таймаутов – так рождаются многочасовые детективы.

Рабочее решение

Одна строка в роутере:

func (app *app) registryRoutes() {
	app.router = gin.New()
	// Без флага gin.Context.Value/Deadline/Done/Err не делегируют в
	// c.Request.Context(), где apmgin кладёт транзакцию.
	// Хендлеры передают gin.Context в юзкейсы как context.Context –
	// и всё содержимое request context для них невидимо.
	app.router.ContextWithFallback = true
	app.router.Use(gin.Recovery())
	app.router.Use(apmgin.Middleware(app.router))
	...
}

Что меняет эта строка:

Система	Что искала в ctx	До флага	После
APM: SQL-спаны	транзакцию (apmgin)	дропнуты молча	спаны на месте
Отмена запроса	`Done()/Err()`	отмена клиента не видна	GORM-запросы прерываются
Таймауты	`Deadline()`	не пробрасывались	пробрасываются
Любой ctx-based инструмент	свои значения	не видны слоям ниже	доезжают

Колонка «отмена» – самая незаметная и самая дорогая. Эту проблему никто не искал: ошибок она не даёт, запросы просто выполняются до конца. Клиент закрыл вкладку, net/http отменил request context – но gin.Context.Done() без флага всегда nil, GORM об отмене не узнаёт и доигрывает транзакцию за ушедшего клиента. Так работало с самого старта проекта, а нашлось случайно – при том же фиксе, что и спаны. В логах это не видно, видно в нагрузке: база доделывает ненужную работу и держит транзакции дольше необходимого.

После флага отмена контекста доезжает до конца цепочки: pgx отправляет PostgreSQL cancel request, и сервер прерывает запрос сам.

Как это отлаживать

Инструментация, которая «тихо не работает», – худший класс багов. Ошибок нет, логов нет, просто наблюдаемость исчезла. Протокол, который сработал здесь:

Зонды на границах. apm.TransactionFromContext(ctx) != nil в хендлере, в юзкейсе, в репозитории – по одной строке лога. Точка, где true превращается в false, – место утечки контекста.
Тест без посредников. Один прямой запрос sqlDB.QueryRowContext(ctx, "SELECT 1 FROM pg_sleep(0.1)") из хендлера: если спан есть, а через GORM нет – виноват слой GORM→sql; если нет и здесь – контекст умирает раньше.
Проверка семплирования, прежде чем обвинять код: ELASTIC_APM_TRANSACTION_SAMPLE_RATE=1, unsampled-транзакции спанов не хранят; exit-спаны короче миллисекунды отбрасываются – потому и pg_sleep(0.1).
Читать исходники обёрток до конца. Все три бага этой истории – «тихие умолчания»: apmgormv2 не принял PreferSimpleProtocol, GORM-диалектор проигнорировал его при заданном DriverName, gin спрятал request context за флагом. Ни одно из них не оставило записи в логе.

Подводные камни

Ключи gin теперь «проваливаются». С флагом c.Value("key") сначала ищет в gin-хранилище (c.Set), потом – в request context. Если в проекте есть привычка класть строковые значения в оба хранилища с одинаковыми именами, gin-значение победит – а у вас появится невидимая связность через имя. Правило простое: строковые ключи – только для gin-хранилища, для request context – типизированные ключи.

Флаг не делает gin.Context полноценным контекстом. Он по-прежнему мутабельный (его Value может менять поведение между вызовами), и хранить его «на потом» – всё ещё нельзя. Если контекст нужно унести за пределы запроса (фоновая задача) – только context.WithoutCancel(c.Request.Context()) или явное копирование нужных значений.

Альтернатива – c.Request.Context() в каждом хендлере. В нашем случае это 50+ хендлеров, и одномоментная правка несла риск ревью-усталости больше, чем пользы. Включение флага осознанный компромисс: одна строка, мгновенный эффект, комментарий в коде объясняет, зачем.

Тесты этого не ловят. В юнит-тестах хендлеры вызываются через gin.CreateTestContext – без engine.ContextWithFallback, с нужными значениями в gin-хранилище. Всё зелёное, observability сломана. Проверить можно только интеграционно: зонд apm.TransactionFromContext в e2e-тесте.

Elastic APM Go Agent – в maintenance mode. Официальное уведомление – в README репозитория elastic/apm-agent-go: баги будут чинить, новые фичи – нет, в качестве замены Elastic рекомендует миграцию на OpenTelemetry. Но это не поможет, так как OTel-трейсеры кладут span context точно так же в context.Context, и gin.Context без флага точно так же его не отдаст.

Выводы

«Подключил инструментацию по документации» ≠ «инструментация работает». Все три слоя – apmgormv2, GORM-диалектор, gin – приняли наши параметры молча и молча же их проигнорировали. Тихие умолчания не логируются.
gin.Context формально реализует context.Context, но без engine.ContextWithFallback = true это односторонняя реализация: наружу торчат только gin-ключи. Всё, что middleware кладёт в request context – APM-транзакция, deadline, отмена – для нижних слоёв не существует.
Цена флага – одна строка. Выигрыш – сразу несколько систем: SQL-спаны, отмена запросов, таймауты, enrichment любых ctx-based инструментов (пример – Sentry в статье 10). Если в вашем стеке gin + любой ctx-based инструмент – проверьте этот флаг первым делом.
Диагностика «пропавшей наблюдаемости» – это бинарный поиск зондами по слоям. Точка, где TransactionFromContext меняется с true на false, интереснее любых логов.

Вывод: цепочка этой истории: apmgin middleware кладёт APM-транзакцию в request context → хендлеры передают вниз gin.Context → драйвер базы (apmsql) ищет транзакцию через контекст, который получил. Посередине цепочки стоит gin.Context: он реализует интерфейс context.Context, но пока флаг не включён, через него нельзя достать то, что лежит в c.Request.Context(). Если фреймворк передаёт вниз собственный объект вместо стандартного контекста – надо проверить, что его методы Value/Done/Err передают вызов дальше – в обернутый request context (c.Request.Context() в случае gin), а не обслуживают только внутреннее хранилище фреймворка (c.Set/c.Get).