driver: bad connection thrown randomly

[miparnisari]

Issue description

I have a repo with some tests that run against MySQL and Postgres. The tests against Postgres always pass. The tests against MySQL randomly (50% chance i'd say) throw a driver: bad connection error. The error occurs both on one-off queries and transactions.

The interesting thing is that I can only reproduce in GitHub actions, never locally. What this means is that I don't know how to isolate the problem. Is it Github Actions? Docker on Github Actions? MySQL driver? MySQL db? My own code?

Example code

https://github.com/miparnisari/openfga. You can fork it and make commits to main to trigger the tests.

Error log

In a read:

2024-08-29T17:50:06.3432416Z 2024-08-29T17:48:47.981Z	�[31mERROR�[0m	sql	{"error": "driver: bad connection", "stack": "goroutine 44134 [running]:\nruntime/debug.Stack()\n\t/opt/hostedtoolcache/go/1.22.6/x64/src/runtime/debug/stack.go:24 +0x67\ngithub.com/openfga/openfga/pkg/storage/sqlcommon.HandleSQLError({0x21e7900, 0x2d9cc10}, {0x220a5d8, 0xc0011e81b8}, {0x0, 0x0, 0x0?})\n\t/home/runner/work/openfga/openfga/pkg/storage/sqlcommon/sqlcommon.go:412 +0x4d8\ngithub.com/openfga/openfga/pkg/storage/mysql.(*MySQL).read(0xc0010a8280, {0x21fc858, 0xc000c93290}, {0xc001992100, 0x1a}, 0xc000aa70e0, 0x0)\n\t/home/runner/work/openfga/openfga/pkg/storage/mysql/mysql.go:197 +0x10e6\ngithub.com/openfga/openfga/pkg/storage/mysql.(*MySQL).Read(0xc0010a8280, {0x21fc858, 0xc000c93260}, {0xc001992100, 0x1a}, 0xc000aa70e0, {{0x1a7bcb3?}})\n\t/home/runner/work/openfga/openfga/pkg/storage/mysql/mysql.go:140 +0x1dd\ngithub.com/openfga/openfga/pkg/storage/storagewrappers.(*ContextTracerWrapper).Read(0xc000de0510, {0x21fc858, 0xc000c93230}, {0xc001992100, 0x1a}, 0xc000aa70e0, {{0x1a7bf00?}})\n\t/home/runner/work/openfga/openfga/pkg/storage/storagewrappers/context.go:44 +0x117\ngithub.com/openfga/openfga/pkg/storage/storagewrappers.(*boundedConcurrencyTupleReader).Read(0xc000a82918, {0x21fc858, 0xc000c93230}, {0xc001992100, 0x1a}, 0xc000aa70e0, {{0x44a9ed?}})\n\t/home/runner/work/openfga/openfga/pkg/storage/storagewrappers/boundedconcurrency.go:79 +0x1c2\ngithub.com/openfga/openfga/pkg/storage/storagewrappers.(*combinedTupleReader).Read(0xc000ff5410, {0x21fc858, 0xc000c93230}, {0xc001992100, 0x1a}, 0xc000aa70e0, {{0x0?}})\n\t/home/runner/work/openfga/openfga/pkg/storage/storagewrappers/combinedtuplereader.go:55 +0x5c2\ngithub.com/openfga/openfga/pkg/server/commands/listusers.(*listUsersQuery).expandTTU(0xc000b823c0, {0x21fc858, 0xc000c93200}, 0xc000c929c0, 0xc000f47680, 0xc000aa7080)\n\t/home/runner/work/openfga/openfga/pkg/server/commands/listusers/list_users_rpc.go:859 +0x64c\ngithub.com/openfga/openfga/pkg/server/commands/listusers.(*listUsersQuery).expandRewrite(0xc000b823c0, {0x21fc890, 0xc000d7b5e0}, 0xc000c929c0, 0xc000af9e40, 0xc000aa7080)\n\t/home/runner/work/openfga/openfga/pkg/server/commands/listusers/list_users_rpc.go:407 +0x25a\ngithub.com/openfga/openfga/pkg/server/commands/listusers.(*listUsersQuery).expandUnion.func1({0x21fc890, 0xc000d7b5e0})\n\t/home/runner/work/openfga/openfga/pkg/server/commands/listusers/list_users_rpc.go:645 +0xc8\ngithub.com/sourcegraph/conc/pool.(*ContextPool).Go.func1()\n\t/home/runner/go/pkg/mod/github.com/sourcegraph/[email protected]/pool/context_pool.go:38 +0xf3\ngithub.com/sourcegraph/conc/pool.(*ContextPool).Go.(*ErrorPool).Go.func2()\n\t/home/runner/go/pkg/mod/github.com/sourcegraph/[email protected]/pool/error_pool.go:30 +0x34\ngithub.com/sourcegraph/conc/pool.(*Pool).worker(0xc000af6000)\n\t/home/runner/go/pkg/mod/github.com/sourcegraph/[email protected]/pool/pool.go:154 +0xde\ngithub.com/sourcegraph/conc/panics.(*Catcher).Try(0xc000af6010, 0xc0019ede20)\n\t/home/runner/go/pkg/mod/github.com/sourcegraph/[email protected]/panics/panics.go:23 +0x78\ngithub.com/sourcegraph/conc.(*WaitGroup).Go.func1()\n\t/home/runner/go/pkg/mod/github.com/sourcegraph/[email protected]/waitgroup.go:32 +0x90\ncreated by github.com/sourcegraph/conc.(*WaitGroup).Go in goroutine 44132\n\t/home/runner/go/pkg/mod/github.com/sourcegraph/[email protected]/waitgroup.go:30 +0xe5\n"}

In a transaction:

2024-08-29T18:10:13.1788685Z 2024-08-29T18:08:54.771Z	�[31mERROR�[0m	sql	{"error": "driver: bad connection", "stack": "goroutine 29937 [running]:\nruntime/debug.Stack()\n\t/opt/hostedtoolcache/go/1.22.6/x64/src/runtime/debug/stack.go:24 +0x67\ngithub.com/openfga/openfga/pkg/storage/sqlcommon.HandleSQLError({0x21e7920, 0x2d9cc10}, {0x220a5f8, 0xc002742dd8}, {0x0, 0x0, 0x0?})\n\t/home/runner/work/openfga/openfga/pkg/storage/sqlcommon/sqlcommon.go:412 +0x4d8\ngithub.com/openfga/openfga/pkg/storage/mysql.(*MySQL).CreateStore(0xc000210320, {0x21fc878, 0xc000e7c270}, 0xc0017505a0)\n\t/home/runner/work/openfga/openfga/pkg/storage/mysql/mysql.go:479 +0x1a06\ngithub.com/openfga/openfga/pkg/server/commands.(*CreateStoreCommand).Execute(0xc0028f58e0, {0x21fc878, 0xc000e7c270}, 0xc001447200)\n\t/home/runner/work/openfga/openfga/pkg/server/commands/create_store.go:43 +0x275\ngithub.com/openfga/openfga/pkg/server.(*Server).CreateStore(0xc00062e340, {0x21fc878, 0xc000e7c210}, 0xc001447200)\n\t/home/runner/work/openfga/openfga/pkg/server/server.go:1279 +0x856\ngithub.com/openfga/api/proto/openfga/v1._OpenFGAService_CreateStore_Handler.func1({0x21fc878, 0xc000e7c210}, {0x1dac540, 0xc001447200})\n\t/home/runner/go/pkg/mod/github.com/openfga/api/[email protected]/openfga/v1/openfga_service_grpc.pb.go:548 +0xbf\ngithub.com/openfga/openfga/cmd/run.(*ServerContext).Run.UnaryServerInterceptor.func27({0x21fc878, 0xc000e7c1e0}, {0x1dac540, 0xc001447200}, 0xc0028f5860, 0xc000d78a80)\n\t/home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/[email protected]/interceptors/auth/auth.go:48 +0x136\ngoogle.golang.org/grpc.getChainUnaryHandler.func1({0x21fc878, 0xc000e7c1e0}, {0x1dac540, 0xc001447200})\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1196 +0x12d\ngithub.com/openfga/openfga/pkg/middleware/validator.UnaryServerInterceptor.func1.1({0x21fc878, 0xc000e7c150}, {0x1dac540, 0xc001447200})\n\t/home/runner/work/openfga/openfga/pkg/middleware/validator/validator.go:34 +0xff\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/validator.UnaryServerInterceptor.func1({0x21fc878, 0xc000e7c150}, {0x1dac540, 0xc001447200}, 0x38?, 0xc000e72280)\n\t/home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/[email protected]/interceptors/validator/interceptors.go:23 +0xfa\ngithub.com/openfga/openfga/pkg/middleware/validator.UnaryServerInterceptor.func1({0x21fc878, 0xc000e7c150}, {0x1dac540, 0xc001447200}, 0xc0028f5860, 0xc001447400)\n\t/home/runner/work/openfga/openfga/pkg/middleware/validator/validator.go:33 +0xfc\ngoogle.golang.org/grpc.getChainUnaryHandler.func1({0x21fc878, 0xc000e7c150}, {0x1dac540, 0xc001447200})\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1196 +0x12d\ngithub.com/openfga/openfga/cmd/run.(*ServerContext).Run.NewLoggingInterceptor.UnaryServerInterceptor.func85({0x21fc878, 0xc000e7c150}, {0x1dac540, 0xc001447200}, 0xc0028f5860, 0xc0014473c0)\n\t/home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/[email protected]/interceptors/server.go:22 +0x2e2\ngoogle.golang.org/grpc.getChainUnaryHandler.func1({0x21fc878, 0xc000e7c150}, {0x1dac540, 0xc001447200})\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1196 +0x12d\ngithub.com/openfga/openfga/cmd/run.(*ServerContext).Run.NewUnaryInterceptor.UnaryServerInterceptor.func83({0x21fc920, 0xc0003b8310}, {0x1dac540, 0xc001447200}, 0xc0028f5860, 0xc001447380)\n\t/home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/[email protected]/interceptors/server.go:22 +0x2e2\ngoogle.golang.org/grpc.getChainUnaryHandler.func1({0x21fc920, 0xc0003b8310}, {0x1dac540, 0xc001447200})\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1196 +0x12d\ngithub.com/openfga/openfga/cmd/run.(*ServerContext).Run.(*TimeoutInterceptor).NewUnaryTimeoutInterceptor.func18({0x21fc878, 0xc000e7c090}, {0x1dac540, 0xc001447200}, 0xc0028f5860?, 0xc001447340)\n\t/home/runner/work/openfga/openfga/pkg/middleware/timeout.go:35 +0xf7\ngoogle.golang.org/grpc.getChainUnaryHandler.func1({0x21fc878, 0xc000e7c090}, {0x1dac540, 0xc001447200})\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1196 +0x12d\ngithub.com/openfga/openfga/cmd/run.(*ServerContext).Run.NewUnaryInterceptor.UnaryServerInterceptor.func79({0x21fc878, 0xc000e7c090}, {0x1dac540, 0xc001447200}, 0xc0028f5860, 0xc0014472c0)\n\t/home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/[email protected]/interceptors/server.go:22 +0x2e2\ngoogle.golang.org/grpc.getChainUnaryHandler.func1({0x21fc878, 0xc000e7c090}, {0x1dac540, 0xc001447200})\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1196 +0x12d\ngithub.com/grpc-ecosystem/go-grpc-middleware/tags.UnaryServerInterceptor.func1({0x21fc878, 0xc000e7c030}, {0x1dac540, 0xc001447200}, 0xc0028f5860, 0xc001447280)\n\t/home/runner/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/tags/interceptors.go:23 +0x114\ngoogle.golang.org/grpc.getChainUnaryHandler.func1({0x21fc878, 0xc000e7c030}, {0x1dac540, 0xc001447200})\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1196 +0x12d\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/recovery.UnaryServerInterceptor.func1({0x21fc878, 0xc000e7c030}, {0x1dac540, 0xc001447200}, 0xc0028f5860?, 0xc001447240)\n\t/home/runner/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/[email protected]/interceptors/recovery/interceptors.go:34 +0x14b\ngoogle.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1({0x21fc878, 0xc000e7c030}, {0x1dac540, 0xc001447200}, 0xc0028f5860, 0xc000d78a80)\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1187 +0xe8\ngithub.com/openfga/api/proto/openfga/v1._OpenFGAService_CreateStore_Handler({0x1e39cc0, 0xc00062e340}, {0x21fc878, 0xc000e7c030}, 0xc000e38f80, 0xc0010ae880)\n\t/home/runner/go/pkg/mod/github.com/openfga/api/[email protected]/openfga/v1/openfga_service_grpc.pb.go:550 +0x1f4\ngoogle.golang.org/grpc.(*Server).processUnaryRPC(0xc00026a400, {0x21fc878, 0xc000837f20}, {0x2207260, 0xc002804300}, 0xc002b23200, 0xc000ed6b70, 0x2dcc310, 0x0)\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1379 +0x1a2d\ngoogle.golang.org/grpc.(*Server).handleStream(0xc00026a400, {0x2207260, 0xc002804300}, 0xc002b23200)\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1790 +0x1825\ngoogle.golang.org/grpc.(*Server).serveStreams.func2.1()\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1029 +0x159\ncreated by google.golang.org/grpc.(*Server).serveStreams.func2 in goroutine 29990\n\t/home/runner/go/pkg/mod/google.golang.org/[email protected]/server.go:1040 +0x225\n"}

Configuration

Driver version (or git SHA): v1.8.1

Go version: 1.22.6

Server version: MySQL 8

Server OS: The issue happens on Ubuntu 22.04.4 (Github Actions).

[methane]

It is too complex to investigate. Please minimize the reproducer.

Im most cases, "bad connection" errors happens after other error logged (not returned). Long living connection may cause it too.

• Do you use max connection lifetime?
• Any log on stderr?

[miparnisari]

@methane thanks for your reply. I agree, my repo is too complex to investigate, I need to spend some time trimming it. 😢

Do you use max connection lifetime?

My settings for these tests that fail:

• MaxOpenConns: 30
• MaxIdleConns: 10
• ConnMaxIdleLifetime = 0
• ConMaxxLifetime = 0

Any log on stderr?

I have all the logs for a failed test run here: logs_27770610005.zip I don't see any errors there.

[methane]

Are you sure about your test runner doesn't capture and hide logs from the driver?

[methane]

ConMaxLifetime = 0

Use 3 min.

[miparnisari]

@methane is there a way to turn on logs from the driver?

Use 3 min.

Why do you suggest this? Doesn't ConMaxLifetime = 0 mean infinite lifetime? Why would I want to cap it, that would cause connection churn, no?

[methane]

@methane is there a way to turn on logs from the driver?

It is on by default. Unless your test runner capture the log.

Why do you suggest this? Doesn't ConMaxLifetime = 0 mean infinite lifetime? Why would I want to cap it, that would cause connection churn, no?

Because someone close connections and it cause error. Driver should close connection before it is closed by others.

Read https://github.com/go-sql-driver/mysql#important-settings

[miparnisari]

@methane out of curiosity, do you see anything incorrect in this code?
https://github.com/miparnisari/openfga/blob/32b9f3d15102e2854353ef40547d8c44f1106aa8/pkg/storage/mysql/mysql.go#L473-L519