consistent repro for deadlock in Gorm prepared statements (repros at gorm v1.26.1)

gormlock.go

package main

import (
	"context"
	"fmt"
	"os"
	"runtime/pprof"
	"sync"
	"time"

	"github.com/jackc/pgx/v5/pgxpool"
	"github.com/jackc/pgx/v5/stdlib"
	gormpg "gorm.io/driver/postgres"
	"gorm.io/gorm"
)

// Set to a valid Postgres connection string. This one works with the default
// config of Postgres.app on macOS.
const connectionString = "postgresql://localhost"

// With poolSize > workerCount, this will make progress.
// With poolSize <= workerCount, it will deadlock.
const (
	poolSize    = 2
	workerCount = 2
)

// Output filename for a goroutine dump in case of suspected deadlock.
const goroutineOutput = "goroutine.out"

func run(ctx context.Context) error {
	db, err := openDB(ctx)
	if err != nil {
		return err
	}
	return useDB(ctx, db)
}

func openDB(ctx context.Context) (*gorm.DB, error) {
	poolConfig, err := pgxpool.ParseConfig(connectionString)
	if err != nil {
		return nil, fmt.Errorf("parsing connection string: %w", err)
	}
	poolConfig.MaxConns = poolSize
	pool, err := pgxpool.NewWithConfig(ctx, poolConfig)
	if err != nil {
		return nil, fmt.Errorf("creating connection pool: %w", err)
	}

	dialector := gormpg.New(gormpg.Config{
		Conn: stdlib.OpenDBFromPool(pool),
	})
	return gorm.Open(dialector, &gorm.Config{
		PrepareStmt: true,
	})
}

func addTwoNumbers(db *gorm.DB, a int32, b int32) (int32, error) {
	var sum int32
	err := db.Raw("SELECT $1::int + $2::int", a, b).First(&sum).Error
	return sum, err
}

func useDB(ctx context.Context, db *gorm.DB) error {
	var workersStarted sync.WaitGroup
	var workersFinished sync.WaitGroup
	workersStarted.Add(workerCount)
	workersFinished.Add(workerCount)

	// do some work inside transactions
	const workerThinkTime = time.Second
	for worker := range workerCount {
		go func() {
			db.WithContext(ctx).Transaction(func(db *gorm.DB) error {
				workersStarted.Done()
				defer workersFinished.Done()

				fmt.Printf("worker %v has a connection and is thinking...\n", worker)
				time.Sleep(workerThinkTime)

				four, err := addTwoNumbers(db, 2, 2)
				if err != nil {
					fmt.Printf("worker %v failed to sum: %s\n", worker, err)
					return err
				}
				fmt.Printf("worker %v thinks that 2 + 2 = %v\n", worker, four)
				return nil
			})
		}()
	}
	workersStarted.Wait()

	// while those workers are ongoing, handle another request
	fmt.Println("non-transactional caller would like to compute a sum...")
	four, err := addTwoNumbers(db.WithContext(ctx), 2, 2)
	if err != nil {
		fmt.Printf("non-transactional caller failed to sum: %s\n", err)
	} else {
		fmt.Printf("non-transactional caller thinks that 2 + 2 = %v\n", four)
	}

	workersFinished.Wait()
	return nil
}

func dumpGoroutines(filename string) error {
	profile := pprof.Lookup("goroutine")
	wr, err := os.Create(goroutineOutput)
	if err != nil {
		return err
	}
	debugLevel := 2
	return profile.WriteTo(wr, debugLevel)
}

func main() {
	ctx, stop := context.WithCancel(context.Background())
	defer stop()

	if err := run(ctx); err != nil {
		fmt.Printf("fatal: %v\n", err)
	}
}

goroutine.out

goroutine 15 [running]:
runtime/pprof.writeGoroutineStacks({0x100fdd7f8, 0x140000b2050})
	/path/to/go/pkg/mod/golang.org/[email protected]/src/runtime/pprof/pprof.go:764 +0x6c
runtime/pprof.writeGoroutine({0x100fdd7f8?, 0x140000b2050?}, 0x2a3e03eb?)
	/path/to/go/pkg/mod/golang.org/[email protected]/src/runtime/pprof/pprof.go:753 +0x2c
runtime/pprof.(*Profile).WriteTo(0x100e1111c?, {0x100fdd7f8?, 0x140000b2050?}, 0x140000001b6?)
	/path/to/go/pkg/mod/golang.org/[email protected]/src/runtime/pprof/pprof.go:377 +0x14c
main.dumpGoroutines({0x140002e37a8?, 0x140002e3778?})
	/path/to/example/main.go:117 +0x78
main.useDB.func2()
	/path/to/example/main.go:92 +0x84
created by main.useDB in goroutine 1
	/path/to/example/main.go:86 +0x150

goroutine 1 [select]:
golang.org/x/sync/semaphore.(*Weighted).Acquire(0x1400027a550, {0x100fe4b20, 0x1400027a410}, 0x1)
	/path/to/go/pkg/mod/golang.org/x/[email protected]/semaphore/semaphore.go:74 +0x424
github.com/jackc/puddle/v2.(*Pool[...]).acquire(0x100fefba0, {0x100fe4b20, 0x1400027a410})
	/path/to/go/pkg/mod/github.com/jackc/puddle/[email protected]/pool.go:360 +0x90
github.com/jackc/puddle/v2.(*Pool[...]).Acquire(0x100fefba0, {0x100fe4b20, 0x1400027a410})
	/path/to/go/pkg/mod/github.com/jackc/puddle/[email protected]/pool.go:347 +0xc0
github.com/jackc/pgx/v5/pgxpool.(*Pool).Acquire(0x14000130600, {0x100fe4b20?, 0x1400027a410?})
	/path/to/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:549 +0xe4
github.com/jackc/pgx/v5/stdlib.connector.Connect({{{{0x0, 0x0}, 0x0, {0x0, 0x0}, {0x0, 0x0}, {0x0, 0x0}, 0x0, ...}, ...}, ...}, ...)
	/path/to/go/pkg/mod/github.com/jackc/pgx/[email protected]/stdlib/sql.go:266 +0x16c
database/sql.(*DB).conn(0x14000115040, {0x100fe4b20, 0x1400027a410}, 0x1)
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:1431 +0x9b0
database/sql.(*DB).prepare(0x14000115040, {0x100fe4b20, 0x1400027a410}, {0x140000357e0, 0x18}, 0xd0?)
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:1625 +0x34
database/sql.(*DB).PrepareContext.func1(0x58?)
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:1599 +0x48
database/sql.(*DB).retry(0x140002a79b0?, 0x140001459b8)
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:1576 +0x4c
database/sql.(*DB).PrepareContext(0x140000386f0?, {0x100fe4b20?, 0x1400027a410?}, {0x140000357e0?, 0x140002a79b0?})
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:1598 +0x64
gorm.io/gorm/internal/stmt_store.(*lruStore).New(0x14000076a00, {0x100fe4b20, 0x1400027a410}, {0x140000357e0, 0x18}, 0x0, {0x1016abaa0, 0x14000115040}, {0x100fe1050, 0x140000386f0})
	/path/to/go/pkg/mod/gorm.io/[email protected]/internal/stmt_store/stmt_store.go:173 +0x120
gorm.io/gorm.(*PreparedStmtDB).prepare(0x14000297c20, {0x100fe4b20, 0x1400027a410}, {0x100fe4a40, 0x14000115040}, 0x0, {0x140000357e0, 0x18})
	/path/to/go/pkg/mod/gorm.io/[email protected]/prepare_stmt.go:85 +0x298
gorm.io/gorm.(*PreparedStmtDB).QueryContext(0x14000297c20, {0x100fe4b20, 0x1400027a410}, {0x140000357e0, 0x18}, {0x140002993a0, 0x2, 0x2})
	/path/to/go/pkg/mod/gorm.io/[email protected]/prepare_stmt.go:121 +0x58
gorm.io/gorm/callbacks.Query(0x140002a78c0)
	/path/to/go/pkg/mod/gorm.io/[email protected]/callbacks/query.go:19 +0xa0
gorm.io/gorm.(*processor).Execute(0x1400027a640, 0x100f842c0?)
	/path/to/go/pkg/mod/gorm.io/[email protected]/callbacks.go:130 +0x348
gorm.io/gorm.(*DB).First(0x14000114c30?, {0x100ef4460, 0x1400028a9dc}, {0x0, 0x0, 0x0})
	/path/to/go/pkg/mod/gorm.io/[email protected]/finisher_api.go:130 +0x168
main.addTwoNumbers(0x140002a7830, 0x2, 0x2)
	/path/to/example/main.go:53 +0xa8
main.useDB({0x100fe4b20, 0x1400027a410}, 0x14000296840)
	/path/to/example/main.go:99 +0x1c0
main.run({0x100fe4b20, 0x1400027a410})
	/path/to/example/main.go:29 +0x4c
main.main()
	/path/to/example/main.go:124 +0x44

goroutine 4 [select]:
github.com/jackc/pgx/v5/pgxpool.(*Pool).backgroundHealthCheck(0x14000130600)
	/path/to/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:433 +0xa0
github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
	/path/to/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:286 +0x44
created by github.com/jackc/pgx/v5/pgxpool.NewWithConfig in goroutine 1
	/path/to/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:283 +0x36c

goroutine 5 [select]:
database/sql.(*DB).connectionOpener(0x14000115040, {0x100fe4b20, 0x1400027a5a0})
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:1261 +0x80
created by database/sql.OpenDB in goroutine 1
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:841 +0x124

goroutine 6 [select]:
gorm.io/gorm/internal/lru.NewLRU[...].func1()
	/path/to/go/pkg/mod/gorm.io/[email protected]/internal/lru/lru.go:83 +0xd0
created by gorm.io/gorm/internal/lru.NewLRU[...] in goroutine 1
	/path/to/go/pkg/mod/gorm.io/[email protected]/internal/lru/lru.go:79 +0x2b4

goroutine 24 [chan receive]:
gorm.io/gorm/internal/stmt_store.(*lruStore).Get(0x14000141978?, {0x140000c6180?, 0x140001419a8?})
	/path/to/go/pkg/mod/gorm.io/[email protected]/internal/stmt_store/stmt_store.go:126 +0x50
gorm.io/gorm.(*PreparedStmtDB).prepare(0x14000297c20, {0x100fe4b20, 0x1400027a410}, {0x100fe4d50, 0x140000c4300}, 0x1, {0x140000c6180, 0x18})
	/path/to/go/pkg/mod/gorm.io/[email protected]/prepare_stmt.go:69 +0xd8
gorm.io/gorm.(*PreparedStmtTX).QueryContext(0x140000b40a8, {0x100fe4b20, 0x1400027a410}, {0x140000c6180, 0x18}, {0x140000aa240, 0x2, 0x2})
	/path/to/go/pkg/mod/gorm.io/[email protected]/prepare_stmt.go:182 +0x7c
gorm.io/gorm/callbacks.Query(0x140000b0b70)
	/path/to/go/pkg/mod/gorm.io/[email protected]/callbacks/query.go:19 +0xa0
gorm.io/gorm.(*processor).Execute(0x1400027a640, 0x100f842c0?)
	/path/to/go/pkg/mod/gorm.io/[email protected]/callbacks.go:130 +0x348
gorm.io/gorm.(*DB).First(0x14000141c88?, {0x100ef4460, 0x140000b84e8}, {0x0, 0x0, 0x0})
	/path/to/go/pkg/mod/gorm.io/[email protected]/finisher_api.go:130 +0x168
main.addTwoNumbers(0x14000304150, 0x2, 0x2)
	/path/to/example/main.go:53 +0xa8
main.useDB.func1.1(0x14000304150)
	/path/to/example/main.go:74 +0xd4
gorm.io/gorm.(*DB).Transaction(0x14000304030, 0x14000141f98, {0x0?, 0x0?, 0x0?})
	/path/to/go/pkg/mod/gorm.io/[email protected]/finisher_api.go:653 +0x1ec
main.useDB.func1()
	/path/to/example/main.go:67 +0x98
created by main.useDB in goroutine 1
	/path/to/example/main.go:66 +0x8c

goroutine 25 [chan receive]:
gorm.io/gorm/internal/stmt_store.(*lruStore).Get(0x14000147978?, {0x14000035800?, 0x140001479a8?})
	/path/to/go/pkg/mod/gorm.io/[email protected]/internal/stmt_store/stmt_store.go:126 +0x50
gorm.io/gorm.(*PreparedStmtDB).prepare(0x14000297c20, {0x100fe4b20, 0x1400027a410}, {0x100fe4d50, 0x140000c4180}, 0x1, {0x14000035800, 0x18})
	/path/to/go/pkg/mod/gorm.io/[email protected]/prepare_stmt.go:69 +0xd8
gorm.io/gorm.(*PreparedStmtTX).QueryContext(0x140000b4060, {0x100fe4b20, 0x1400027a410}, {0x14000035800, 0x18}, {0x14000299420, 0x2, 0x2})
	/path/to/go/pkg/mod/gorm.io/[email protected]/prepare_stmt.go:182 +0x7c
gorm.io/gorm/callbacks.Query(0x140002a7a10)
	/path/to/go/pkg/mod/gorm.io/[email protected]/callbacks/query.go:19 +0xa0
gorm.io/gorm.(*processor).Execute(0x1400027a640, 0x100f842c0?)
	/path/to/go/pkg/mod/gorm.io/[email protected]/callbacks.go:130 +0x348
gorm.io/gorm.(*DB).First(0x14000147c88?, {0x100ef4460, 0x1400028aa00}, {0x0, 0x0, 0x0})
	/path/to/go/pkg/mod/gorm.io/[email protected]/finisher_api.go:130 +0x168
main.addTwoNumbers(0x140000b0660, 0x2, 0x2)
	/path/to/example/main.go:53 +0xa8
main.useDB.func1.1(0x140000b0660)
	/path/to/example/main.go:74 +0xd4
gorm.io/gorm.(*DB).Transaction(0x140000b0540, 0x14000147f98, {0x0?, 0x0?, 0x0?})
	/path/to/go/pkg/mod/gorm.io/[email protected]/finisher_api.go:653 +0x1ec
main.useDB.func1()
	/path/to/example/main.go:67 +0x98
created by main.useDB in goroutine 1
	/path/to/example/main.go:66 +0x8c

goroutine 27 [chan receive]:
database/sql.(*Tx).awaitDone(0x140000c4180)
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:2212 +0x34
created by database/sql.(*DB).beginDC in goroutine 25
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:1925 +0x19c

goroutine 32 [chan receive]:
database/sql.(*Tx).awaitDone(0x140000c4300)
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:2212 +0x34
created by database/sql.(*DB).beginDC in goroutine 24
	/path/to/go/pkg/mod/golang.org/[email protected]/src/database/sql/sql.go:1925 +0x19c

~go.mod

module example.com/m/gormlock

go 1.24.2

require (
	github.com/jackc/pgx/v5 v5.7.5
	gorm.io/driver/postgres v1.5.11
	gorm.io/gorm v1.26.1
)

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
	github.com/jinzhu/inflection v1.0.0 // indirect
	github.com/jinzhu/now v1.1.5 // indirect
	golang.org/x/crypto v0.37.0 // indirect
	golang.org/x/sync v0.13.0 // indirect
	golang.org/x/text v0.24.0 // indirect
)

~go.sum

github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
github.com/jackc/pgpassfile v1.0.0 h1:/6Hmqy13Ss2zCq62VdNG8tM1wchn8zjSGOBJ6icpsIM=
github.com/jackc/pgpassfile v1.0.0/go.mod h1:CEx0iS5ambNFdcRtxPj5JhEz+xB6uRky5eyVu/W2HEg=
github.com/jackc/pgservicefile v0.0.0-20240606120523-5a60cdf6a761 h1:iCEnooe7UlwOQYpKFhBabPMi4aNAfoODPEFNiAnClxo=
github.com/jackc/pgservicefile v0.0.0-20240606120523-5a60cdf6a761/go.mod h1:5TJZWKEWniPve33vlWYSoGYefn3gLQRzjfDlhSJ9ZKM=
github.com/jackc/pgx/v5 v5.7.5 h1:JHGfMnQY+IEtGM63d+NGMjoRpysB2JBwDr5fsngwmJs=
github.com/jackc/pgx/v5 v5.7.5/go.mod h1:aruU7o91Tc2q2cFp5h4uP3f6ztExVpyVv88Xl/8Vl8M=
github.com/jackc/puddle/v2 v2.2.2 h1:PR8nw+E/1w0GLuRFSmiioY6UooMp6KJv0/61nB7icHo=
github.com/jackc/puddle/v2 v2.2.2/go.mod h1:vriiEXHvEE654aYKXXjOvZM39qJ0q+azkZFrfEOc3H4=
github.com/jinzhu/inflection v1.0.0 h1:K317FqzuhWc8YvSVlFMCCUb36O/S9MCKRDI7QkRKD/E=
github.com/jinzhu/inflection v1.0.0/go.mod h1:h+uFLlag+Qp1Va5pdKtLDYj+kHp5pxUVkryuEj+Srlc=
github.com/jinzhu/now v1.1.5 h1:/o9tlHleP7gOFmsnYNz3RGnqzefHA47wQpKrrdTIwXQ=
github.com/jinzhu/now v1.1.5/go.mod h1:d3SSVoowX0Lcu0IBviAWJpolVfI5UJVZZ7cO71lE/z8=
github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
golang.org/x/crypto v0.37.0 h1:kJNSjF/Xp7kU0iB2Z+9viTPMW4EqqsrywMXLJOOsXSE=
golang.org/x/crypto v0.37.0/go.mod h1:vg+k43peMZ0pUMhYmVAWysMK35e6ioLh3wB8ZCAfbVc=
golang.org/x/sync v0.13.0 h1:AauUjRAJ9OSnvULf/ARrrVywoJDy0YS2AwQ98I37610=
golang.org/x/sync v0.13.0/go.mod h1:1dzgHSNfp02xaA81J2MS99Qcpr2w7fw1gpm99rleRqA=
golang.org/x/text v0.24.0 h1:dd5Bzh4yt5KYA8f9CJHCP4FB4D51c2c6JvN37xJJkJ0=
golang.org/x/text v0.24.0/go.mod h1:L8rBsPeo2pSS+xqN0d5u2ikmjtmoJbDBT1b7nHvFCdU=
gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=
gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
gorm.io/driver/postgres v1.5.11 h1:ubBVAfbKEUld/twyKZ0IYn9rSQh448EdelLYk9Mv314=
gorm.io/driver/postgres v1.5.11/go.mod h1:DX3GReXH+3FPWGrrgffdvCk3DQ1dwDPdmbenSkweRGI=
gorm.io/gorm v1.26.1 h1:ghB2gUI9FkS46luZtn6DLZ0f6ooBJ5IbVej2ENFDjRw=
gorm.io/gorm v1.26.1/go.mod h1:8Z33v652h4//uMA76KjeDH8mJXPm1QNCYrMeatR0DOE=