jackc
Occasional prepared statement already exist errors when using statement timeout
Describe the bug
We have a web service where we set a statement_timeout on our connections to ensure that queries do not run for an extended period of time. As part of this web service, we have a large, generated query. We occasionally see errors such as the following:
ERROR: prepared statement "stmtcache_2b7087dc2ab6296b87fa5baa7f329541c23d17376faa03b7" already exists (SQLSTATE 42P05)
My hypothesis is that there is a statement timeout in the PREPARE but after Postgres has actually created the prepared statement. This causes pgx to end up in a state where the prepared statement isn't added to the statement cache but does exist for the connection in Postgres. I was able to reproduce this with the code below.
To Reproduce
The following sample code reliably produces the error with a local Postgres server for me. This probably could be simplified a bit further.
package main
import (
"context"
"database/sql"
"errors"
"fmt"
"log"
"math/rand"
"os"
"github.com/jackc/pgx/v5/pgconn"
_ "github.com/jackc/pgx/v5/stdlib"
)
func main() {
db, err := sql.Open("pgx", os.Getenv("DATABASE_URL"))
if err != nil {
log.Fatal(err)
}
ctx := context.Background()
conn, err := db.Conn(ctx)
if err != nil {
log.Fatal(err)
}
_, err = conn.ExecContext(ctx, "SET statement_timeout TO 1")
if err != nil {
log.Fatal(err)
}
p := "s"
for {
var v uint
q := fmt.Sprintf("SELECT 1 AS %s", p)
err := conn.QueryRowContext(
ctx,
q,
).Scan(&v)
if err != nil && !errors.Is(err, context.Canceled) {
var pgErr *pgconn.PgError
if errors.As(err, &pgErr) && pgErr.Code == "57014" {
continue
}
log.Fatal(err)
}
p = randString(100000)
}
}
var letterRunes = []rune("abAB")
func randString(n int) string {
b := make([]rune, n)
for i := range b {
b[i] = letterRunes[rand.Intn(len(letterRunes))]
}
return string(b)
}
Expected behavior
No prepared statement already exists error.
Actual behavior
ERROR: prepared statement "stmtcache_087f9f36620ff21723cd288c17d7806ba6fdd9b160f73186" already exists (SQLSTATE 42P05)
Version
- Go:
go version go1.23.4 linux/amd64 - PostgreSQL:
PostgreSQL 16.6 (Ubuntu 16.6-1.pgdg24.10+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 14.2.0-4ubuntu2) 14.2.0, 64-bit - pgx:
v5.7.2
My hypothesis is that there is a statement timeout in the PREPARE but after Postgres has actually created the prepared statement. This causes the pgx to end up in a state where the prepared statement isn't added to the statement cache but does exist for the connection in Postgres. I was able to reproduce this with the code below.
You are correct. Based on your example code I was able to build a reproduction case directly at the PostgreSQL protocol layer.
I send a Parse, sleep, and then send a Describe. The Parse succeeds and the Describe fails. Preparing and releasing statements are not transactional, so even though the extended protocol pseudo-transaction fails the prepare is not undone.
pgx and pgconn always send Parse and Describe together . pgx keeps a record of the statement description for each prepared statement.
In theory, I know how to solve this, but in practice it's tricky / messy enough I'm not sure. pgconn.PgConn.Prepare() could return a special error that denoted that Parse succeeded and Describe failed. Callers would detect that error and deallocate the statement on the server. Similar logic would need to be implemented for batches and pipeline mode. However, there are many contexts in which the prepare path can be called, so I'm not confident in this solution's robustness.
package main
import (
"context"
"fmt"
"log"
"os"
"time"
"github.com/jackc/pgx/v5"
"github.com/jackc/pgx/v5/pgproto3"
)
func main() {
ctx := context.Background()
conn, err := pgx.Connect(ctx, os.Getenv("DATABASE_URL"))
if err != nil {
log.Fatal(err)
}
defer conn.Close(ctx)
_, err = conn.Exec(ctx, "SET statement_timeout TO 1")
if err != nil {
log.Fatal(err)
}
conn.PgConn().Frontend().SendParse(&pgproto3.Parse{Name: "ps1", Query: "select 1", ParameterOIDs: nil})
err = conn.PgConn().Frontend().Flush()
if err != nil {
log.Fatal(err)
}
time.Sleep(1 * time.Millisecond)
conn.PgConn().Frontend().SendDescribe(&pgproto3.Describe{ObjectType: 'S', Name: "ps1"})
time.Sleep(1 * time.Millisecond)
conn.PgConn().Frontend().SendSync(&pgproto3.Sync{})
err = conn.PgConn().Frontend().Flush()
if err != nil {
log.Fatal(err)
}
for range 3 {
msg, err := conn.PgConn().Frontend().Receive()
if err != nil {
log.Fatal(err)
}
fmt.Printf("%#v\n", msg)
}
conn.PgConn().Frontend().SendParse(&pgproto3.Parse{Name: "ps1", Query: "select 1", ParameterOIDs: nil})
err = conn.PgConn().Frontend().Flush()
if err != nil {
log.Fatal(err)
}
time.Sleep(1 * time.Millisecond)
conn.PgConn().Frontend().SendDescribe(&pgproto3.Describe{ObjectType: 'S', Name: "ps1"})
time.Sleep(1 * time.Millisecond)
conn.PgConn().Frontend().SendSync(&pgproto3.Sync{})
err = conn.PgConn().Frontend().Flush()
if err != nil {
log.Fatal(err)
}
for range 2 {
msg, err := conn.PgConn().Frontend().Receive()
if err != nil {
log.Fatal(err)
}
fmt.Printf("%#v\n", msg)
}
}
jack@glados ~/dev/pgx_issues/pgx-2223 ±master⚡ » gor .
&pgproto3.ParseComplete{}
&pgproto3.ErrorResponse{Severity:"ERROR", SeverityUnlocalized:"ERROR", Code:"57014", Message:"canceling statement due to statement timeout", Detail:"", Hint:"", Position:0, InternalPosition:0, InternalQuery:"", Where:"", SchemaName:"", TableName:"", ColumnName:"", DataTypeName:"", ConstraintName:"", File:"postgres.c", Line:3356, Routine:"ProcessInterrupts", UnknownFields:map[uint8]string(nil)}
&pgproto3.ReadyForQuery{TxStatus:0x49}
&pgproto3.ErrorResponse{Severity:"ERROR", SeverityUnlocalized:"ERROR", Code:"42P05", Message:"prepared statement \"ps1\" already exists", Detail:"", Hint:"", Position:0, InternalPosition:0, InternalQuery:"", Where:"", SchemaName:"", TableName:"", ColumnName:"", DataTypeName:"", ConstraintName:"", File:"prepare.c", Line:415, Routine:"StorePreparedStatement", UnknownFields:map[uint8]string(nil)}
&pgproto3.ReadyForQuery{TxStatus:0x49}
