Проблема
Стек в проекте: 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:
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-транзакции и спаны, связывает их через context.Context и отправляет собранные данные в APM Server.
apmgin и apmsql — модули, которые используют этот агент. apmgin создаёт APM-транзакцию для входящего HTTP-запроса, а apmsql создаёт SQL-спаны. Сам агент предоставляет общую инфраструктуру, через которую они работают с одними и теми же Transaction и Span.
Далее проверяем по цепочке. 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 — это спан, который агент создаёт как заглушку, когда не находит APM-транзакцию в контексте. SQL-запрос при этом выполняется как обычно, но сам спан не записывается и не отправляется в APM Server. Ошибки тоже не возникает так как для агента отсутствие транзакции является штатной ситуацией. Например, код может выполняться в фоновой джобе вне HTTP-запроса. Агент не может отличить такой случай от ситуации, когда транзакция была создана, но потерялась по дороге. Поэтому приложение продолжает работать, 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, а в документации он описан
одной строкой:
ContextWithFallbackenable 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 об отмене не узнаёт и продолжает выполнять запросы к БД. Так работало с самого старта проекта, а нашлось случайно при том же фиксе, что и спаны. В логах это никак не проявлялось: запрос просто продолжал выполняться после того, как клиент уже ушёл. В результате база могла выполнять ненужную работу и дольше удерживать занятые ресурсы. После правки отмена context.Context передаётся в pgx. Драйвер прерывает операцию с базой, поэтому PostgreSQL больше не продолжает выполнять запрос после ухода клиента.
Как это отлаживать
Инструментация, которая «тихо не работает», – худший класс багов. Ошибок нет, логов нет, просто наблюдаемость исчезла. Протокол, который сработал здесь:
- Проверять контекст на границах между слоями. Добавьте
apm.TransactionFromContext(ctx) != nilв хендлер, юзкейс и репозиторий. Где значение впервые сталоfalse, там и потерялась APM-транзакция. - Тест без посредников. Один прямой запрос
sqlDB.QueryRowContext(ctx, "SELECT 1 FROM pg_sleep(0.2)")из хендлера: если спан есть, а через GORM нет – виноват слой GORM -> sql; если нет и здесь – контекст умирает раньше. - Проверить семплирование. Прежде чем искать проблему в коде, выставьте
ELASTIC_APM_TRANSACTION_SAMPLE_RATE=1, чтобы сохранялись все транзакции. Для проверки SQL-спанов используйте заведомо долгий запрос, напримерpg_sleep(0.2): слишком короткие спаны могут быть отброшены агентом. - Читать исходники обёрток. Все три проблемы возникли из-за неочевидного поведения библиотек(лично для нас):
apmgormv2не позволял передатьPreferSimpleProtocol, GORM игнорировал эту настройку при заданномDriverName, а Gin не передавал значения из request context без отдельного флага. При этом ни одна из этих ситуаций явно не отражалась в логах.
Подводные камни
Конфликт строковых ключей. После включения флага c.Value("key") сначала ищет значение в хранилище Gin (c.Set), а затем — в request context. Если строковый ключ с одинаковым именем есть в обоих местах, значение из Gin имеет приоритет. Поэтому строковые ключи лучше оставить для хранилища Gin, а для context.Context использовать ключи собственного типа, как рекомендует стандартная библиотека Go.
Флаг не превращает gin.Context в замену context.Context Он по-прежнему
мутабельный (его Value может менять поведение между вызовами), и хранить
его «на потом» – всё ещё нельзя.
Альтернатива — передавать c.Request.Context() явно. С точки зрения разделения слоёв это более прозрачный вариант: нижние слои получают обычный context.Context и не зависят от Gin. В нашем случае для этого пришлось бы менять 50+ хендлеров. Поэтому мы выбрали ContextWithFallback как практический компромисс: одна настройка исправляет передачу контекста во всём приложении, а комментарий рядом с флагом объясняет, зачем он нужен.
Тесты этого не ловят. В юнит-тестах хендлеры вызываются через
gin.CreateTestContext – без engine.ContextWithFallback, с нужными
значениями в gin-хранилище. Всё зелёное, но observability сломана.
Elastic APM Go Agent находится в maintenance mode. Elastic рекомендует постепенно переходить на OpenTelemetry. Но сама проблема с контекстом от этого не исчезает. OpenTelemetry тоже хранит текущий span в context.Context. Если передавать в нижние слои gin.Context без ContextWithFallback, значения из c.Request.Context() по-прежнему будут недоступны. Поэтому при миграции на OpenTelemetry важно отдельно проверить передачу контекста между слоями.
Выводы
-
«Подключил инструментацию по документации» ещё не значит, что она действительно работает. В нашем случае проблемы скрывались сразу в нескольких слоях:
apmgormv2не позволял передать нужную настройку pgx, GORM игнорировалPreferSimpleProtocolпри заданномDriverName, а Gin без отдельного флага не использовал request context. -
gin.Contextреализует интерфейсcontext.Context, но безContextWithFallbackне передаёт дальше значения, отмену и таймауты изc.Request.Context(). Поэтому APM-транзакция существовала, но нижние слои её не видели. -
Включение
ContextWithFallbackрешило сразу несколько проблем: появились SQL-спаны, начала работать отмена запросов и стали передаваться таймауты. Но более явный вариант — передаватьc.Request.Context()в нижние слои напрямую. -
Если пропали спаны или другие данные из контекста, проверяйте контекст по всей цепочке: хендлер юзкейс -> репозиторий. Где нужное значение исчезло, там и стоит искать проблему.