dangling transactions after 'failed to deallocate cached statement' errors

Hey there. First of all, thank you for all your work on this library 👍

Describe the bug

We are using pgx in a fairly typical backend application, that serves requests to clients via grpc. We use pgx as a driver via sqlx. Starting with version 5.5.4, we started to notice some problems:

Our production logs contained lines "failed to deallocate cached statement: conn closed". Roughly it was a couple hundred times a day, for a couple hundred thousand requests a day where each request is a transaction.
This happened predominantly (but not exclusively) in streaming requests. Those are ended when cancelled by the user, so we assume it's some race condition around cancelled context behavior.
The logged error happens from a call to tx.Rollback(), which is called from a defer that is set up with the transaction and run at the end of the cancelled rpc method.
We also started to see dangling transactions left in an idle in transaction state, indefinitely (hours), causing issues particularly when they held on to locks. While this is not definitely related to the log entries, it started happening at the same time and the log entries indicate an error during transaction cleanup.

It seems like something goes wrong around transaction cleanup, but we can't tell what's going on at all.

To Reproduce

Unfortunately, we were unable to reproduce this bug outside our production environment, which also isn't source available. :( Rolling back to 5.5.3 "fixed" the issue for us, so it might be caused by 046f497. We tried some things in our codebase around transaction behavior and made sure we begin/end transactions consistently throughout, to no avail. If you have any ideas, we'd be happy to try.

Version

Go: $ go version -> go version go1.21.5 linux/amd64
PostgreSQL: $ psql --no-psqlrc --tuples-only -c 'select version()' -> PostgreSQL 15.7 on x86_64-pc-linux-musl, compiled by gcc (Alpine 13.2.1_git20240309) 13.2.1 20240309, 64-bit
pgx: $ grep 'github.com/jackc/pgx/v[0-9]' go.mod -> v5.5.4

I do not think that failed to deallocate cached statement: conn closed is directly connected to dangling transactions -- after all the connection is closed -- it can't be holding open a connection. I suppose it could be worth checking that the connection actually is closed on the server though.

I suppose it's possible this has something to do with the context cancellation. But because of the difficulty in reliably interrupting a query and recovering the connection, pgx simply closes the connection when a query is interrupted. So it would seem there's not much that could go wrong there.

👋
I'm seeing some similar errors when using a "child" context to query some rows for locking.

So i'm doing basically this:

tctx, cancel := context.WithTimeout(ctx, 10 * time.Second)
defer cancel()

txx, err := s.sqlClient.BeginTxx(tctx, nil)

defer func() {
   // handle recover
   fn := txx.Commit
   if err != nil {
     fn = txx.Rollback
    }
    funcErr := fn()
    if funErr != nil {
       log.Error("error applying transaction %+v", funcErr)
        // Here i see the error with `failed to deallocate cached statement: conn closed `
       err = fmt.Errorf("failed to apply transaction %w", funErr)
     }
     return err
}

childCtx, cancelChildren := context.WithTimeout(tctx, 1 * time.Secoond)
defer cancelChildren()

var ids []string
err := s.sqlClient.ExecCtx(childCtx, &ids, "select id from users where age > 99 for update"); // this takes more than 1 second
if err != nil {
 return err
}
// use the ids to run an update
// loop through users and run an update
// commit transaction

After the "lock" queries started hitting their context timeout, i started seeing this errors on the application logs. Is it the case that this "child" context being cancelled is closing down the original transaction connection ?

I'm trying to understand where in the code does this happen if there's something I can do to better handle this (I already want to refactor how the transaction is committed/rollbacked to avoid failing)

@xocasdashdash

@xocasdashdash

Is it the case that this "child" context being cancelled is closing down the original transaction connection ?

Yes. Context cancellation closes the connection in most cases because it is very difficult or impossible to reliably recover from an interrupted query.

But beyond that, the fundamental means of interrupting a query in PostgreSQL causes the interrupted query to return an error. If a query returns an error the wrapping transaction is places in an error state. So even at the PostgreSQL level the only way to handle this would be to use savepoints (pseudo nested transactions) around every query you might want to cancel and rollback.

Pin pgx at v5.5.3 due to jackc/pgx#2100

Rolling back to 5.5.3 "fixed" the issue for us,

I've encountered this dangling transactions issue with another project, but downgrading to v5.5.3 hasn't helped. Perhaps setting a low value for idle_in_transaction_session_timeout will "fix" it for me.

Drive-by comment as I've just been debugging a similar issue. For those experiencing this issue, is it possible that you're using the *pgx.Conn concurrently? Such concurrent use could potentially trigger this error message.

I have a demo here to reproduce the scenario.

Run the provided Go code as a gRPC service. The SQL queries in the service take between 0.5s and 1.5s to execute.
Run an HTTP server that calls this gRPC service. The key point is that the gRPC client timeout is set to 1s.
Finally, perform a load test on the HTTP layer by sending a large volume of requests.

# go log 
Commit: 140122_d8dee5c2-08d2-49f5-861e-008c1c81a23b failed to deallocate cached statement(s): conn closed

# sql info  
INFO ThreadId(12) Client 192.168.xx.xx:58445 issued a cancel query request    
INFO ThreadId(12) Client 192.168.xx.xx:58446 issued a cancel query request    
WARN ThreadId(12) Server returned while still in transaction, rolling back transaction    
WARN ThreadId(09) Server returned while still in transaction, rolling back transaction

gRPC Server

package main

import (
	"context"
	"database/sql"
	"fmt"
	"log"
	"net"

	pb "example.com/go_grpc_server/v2/proto"
	"github.com/jackc/pgx/v5/pgxpool"
	"google.golang.org/grpc"
)

type server struct {
	pb.DemoServiceServer
	pool *pgxpool.Pool
}

func (s *server) SayHello(ctx context.Context, in *pb.SayHelloRequest) (*pb.SayHelloResponse, error) {
	in_name := in.GetName()
	pool, err := s.pool.Acquire(ctx)
	if err != nil {
		fmt.Println("get db:", in_name, err)
	}

	tx, err := pool.Begin(ctx)
	if err != nil {
		fmt.Println("Begin:", err)
	}
	defer tx.Rollback(ctx)
	rows, err := tx.Query(ctx, "SELECT 'data' ,pg_sleep(0.5 + RANDOM()) where $1 = $1", in_name)
	if err != nil {
		fmt.Println("Query:", err)
	}
	var name string
	var n sql.NullString
	for rows.Next() {
		err := rows.Scan(&name, &n)
		if err != nil {
			fmt.Println("Scan: ", err)
		}

	}
	
	defer rows.Close()
	err = tx.Commit(ctx)
	if err != nil {
		fmt.Println("Commit:", in_name, err)

	}
	defer pool.Release()
	return &pb.SayHelloResponse{Message: "Hello " + name}, nil
}

func main() {
	ctx := context.Background()
	pgxConfig, err := pgxpool.ParseConfig("postgresql://localhost:5432/postgres")
	pgxConfig.MaxConns = 100
	pgxConfig.MinConns = 1
	if err != nil {
		fmt.Println("Could not parse PostgreSQL connection URI, check config:", err)
	}
	db_conn, err := pgxpool.NewWithConfig(ctx, pgxConfig)

	port := ":50051"
	lis, err := net.Listen("tcp", port)
	if err != nil {
		log.Fatalf("failed to listen: %v", err)
	}

	s := grpc.NewServer()
	pb.RegisterDemoServiceServer(s, &server{pool: db_conn})
	log.Printf("server listening at %v", lis.Addr())

	if err := s.Serve(lis); err != nil {
		log.Fatalf("failed to serve: %v", err)
	}
}

syntax = "proto3";

package demo;

option go_package = "./proto";

// The demo service definition.
service DemoService {
  // Sends a greeting
  rpc SayHello(SayHelloRequest) returns (SayHelloResponse) {}
}

// The request message containing the user's name.
message SayHelloRequest {
  string name = 1;
}

// The response message containing the greeting.
message SayHelloResponse {
  string message = 1;
}

module example.com/go_grpc_server/v2

go 1.25.5

require (
	github.com/jackc/pgx/v5 v5.8.0
	google.golang.org/grpc v1.78.0
	google.golang.org/protobuf v1.36.10
)

require (
	github.com/jackc/pgpassfile v1.0.0 // indirect
	github.com/jackc/pgservicefile v0.0.0-20240606120523-5a60cdf6a761 // indirect
	github.com/jackc/puddle/v2 v2.2.2 // indirect
	golang.org/x/net v0.47.0 // indirect
	golang.org/x/sync v0.18.0 // indirect
	golang.org/x/sys v0.38.0 // indirect
	golang.org/x/text v0.31.0 // indirect
	google.golang.org/genproto/googleapis/rpc v0.0.0-20251029180050-ab9386a59fda // indirect
)

HTTP Server

pub mod proto_demo {
    tonic::include_proto!("demo");
}

use actix_web::{
    App, HttpResponse, HttpServer, get,
    http::header::ContentType,
    middleware::{self, Logger},
    web::{self, ThinData},
};
use proto_demo::{SayHelloRequest, demo_service_client::DemoServiceClient};
use serde::Deserialize;
use std::time::Duration;
use tonic::{Request, transport::Channel};

#[derive(Deserialize)]
struct QueryDatas {
    data: Option<String>,
}

#[get("/")]
async fn index(
    q: web::Query<QueryDatas>,
    ThinData(name): web::ThinData<String>,
    ThinData(channel): web::ThinData<Channel>,
) -> HttpResponse {
    let demo = tonic::Request::new(SayHelloRequest {
        name: format!(
            "{name}_{}",
            q.data.clone().unwrap_or(uuid::Uuid::new_v4().to_string())
        ),
    });
    let mut demo_client =
        DemoServiceClient::with_interceptor(channel.clone(), move |req: Request<()>| Ok(req));
    let response = demo_client.say_hello(demo).await.unwrap();

    HttpResponse::Ok()
        .content_type(ContentType::json())
        .body(format!("{:?}!", response))
}

#[tokio::main]
async fn main() -> Result<(), Box<dyn std::error::Error>> {
    env_logger::init();

    let channel = Channel::from_static("http://127.0.0.1:50051")
        .timeout(Duration::from_secs(1))
        .connect()
        .await?;

    let name = chrono::Local::now().format("%H%m%S").to_string();
    let server_addr = "0.0.0.0:8080";
    let _ = HttpServer::new(move || {
        App::new()
            .wrap(Logger::default())
            .wrap(middleware::Compress::default())
            .app_data(ThinData(channel.clone()))
            .app_data(ThinData(name.clone()))
            .service(index)
    })
    .bind(server_addr)?
    .workers(8)
    .run()
    .await;

    Ok(())
}

http benchmark

rewrk -h http://127.0.0.1:8080 -t 2 -c 10 -d 60s

Adding to the above, this issue caused a partial outage of a CT Log server:

https://groups.google.com/a/chromium.org/d/msgid/ct-policy/5bd292eb-9485-4e85-9c3a-379f604f2a6fn%40chromium.org?utm_medium=email&utm_source=footer

@mingjunyang

@mingjunyang I don't have a Rust build environment handy, so I can't test your example. But I reviewed the code and I did spot some anomalies that may be factors.

The defers in SayHello are out of order. Below is that function with everything removed except the lines that need a defer to ensure cleanup and the actual cleanup calls.

pool, err := s.pool.Acquire(ctx)
tx, err := pool.Begin(ctx)
defer tx.Rollback(ctx)
rows, err := tx.Query(ctx, "SELECT 'data' ,pg_sleep(0.5 + RANDOM()) where $1 = $1", in_name)
defer rows.Close()
err = tx.Commit(ctx)
defer pool.Release()

Defers happen in reverse order so it would be possible to release the pool before the tx is committed or rolled back. Not sure if that is actually what's happening here, but it's suspicious.

Also, I would recommend renaming the pool variable to conn. Connections are checked out of the pool by Acquire. The pool itself isn't checked out.

Mitigate PostgreSQL connection pool contamination

fix(postgres): handle conn closed err (#16066)

fix(postgres): handle conn closed err (kumahq#16066)

@Valodim

@Valodim Hi,
look for potential deadlocks e.g. opening a transaction and inside the transaction you try to acquire another connection from the pool. Verify your connection pool has enough capacity to serve the requests, when you run into a timeout. When a timeout happens the transaction is dropped but it's not yet commited that's why the statement cache does not find anything.
I'll also suggest to use pgxs beginFunc as it handles most of the transaction error cases. We had the same problem. :)

Navigation Menu

Repository navigation

dangling transactions after 'failed to deallocate cached statement' errors #2100

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

dangling transactions after 'failed to deallocate cached statement' errors #2100

Description

Activity

jackc commented on Aug 3, 2024

xocasdashdash commented on Oct 3, 2024

jackc commented on Oct 5, 2024

robstradling commented on Mar 24, 2025

twpayne commented on May 3, 2025

mingjunyang commented on Jan 7, 2026

riking commented on Jan 13, 2026

jackc commented on Jan 24, 2026

tilomangin commented on May 26, 2026

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions