-
Notifications
You must be signed in to change notification settings - Fork 2.3k
driver: bad connection
thrown randomly
#1629
-
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月29日T17:50:06.3432416Z 2024年08月29日T17: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/conc@v0.3.0/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/conc@v0.3.0/pool/error_pool.go:30 +0x34\ngithub.com/sourcegraph/conc/pool.(*Pool).worker(0xc000af6000)\n\t/home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/pool/pool.go:154 +0xde\ngithub.com/sourcegraph/conc/panics.(*Catcher).Try(0xc000af6010, 0xc0019ede20)\n\t/home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/panics/panics.go:23 +0x78\ngithub.com/sourcegraph/conc.(*WaitGroup).Go.func1()\n\t/home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/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/conc@v0.3.0/waitgroup.go:30 +0xe5\n"}
In a transaction:
2024年08月29日T18:10:13.1788685Z 2024年08月29日T18: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/proto@v0.0.0-20240807201305-c96ec773cae9/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/v2@v2.1.0/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/grpc@v1.65.0/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/v2@v2.1.0/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/grpc@v1.65.0/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/v2@v2.1.0/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/grpc@v1.65.0/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/v2@v2.1.0/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/grpc@v1.65.0/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/grpc@v1.65.0/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/v2@v2.1.0/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/grpc@v1.65.0/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/go-grpc-middleware@v1.4.0/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/grpc@v1.65.0/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/v2@v2.1.0/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/grpc@v1.65.0/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/proto@v0.0.0-20240807201305-c96ec773cae9/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/grpc@v1.65.0/server.go:1379 +0x1a2d\ngoogle.golang.org/grpc.(*Server).handleStream(0xc00026a400, {0x2207260, 0xc002804300}, 0xc002b23200)\n\t/home/runner/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1790 +0x1825\ngoogle.golang.org/grpc.(*Server).serveStreams.func2.1()\n\t/home/runner/go/pkg/mod/google.golang.org/grpc@v1.65.0/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/grpc@v1.65.0/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).
Beta Was this translation helpful? Give feedback.
All reactions
Replies: 2 comments 5 replies
-
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?
Beta Was this translation helpful? Give feedback.
All reactions
-
@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.
Beta Was this translation helpful? Give feedback.
All reactions
-
Are you sure about your test runner doesn't capture and hide logs from the driver?
Beta Was this translation helpful? Give feedback.
All reactions
-
ConMaxLifetime = 0
Use 3 min.
Beta Was this translation helpful? Give feedback.
All reactions
-
@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?
Beta Was this translation helpful? Give feedback.
All reactions
-
@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
Beta Was this translation helpful? Give feedback.
All reactions
-
@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
Beta Was this translation helpful? Give feedback.