go-redis icon indicating copy to clipboard operation
go-redis copied to clipboard

Closing pubsub gracefully with cancellation context will log discarding connection

Open titpetric opened this issue 2 years ago • 2 comments

When using context cancellation, the underlying connection isn't closed nicely, triggering a logger error in pubsub.go:159.

redis: 2022/06/10 11:26:24 pubsub.go:159: redis: discarding bad PubSub connection: read tcp 127.0.0.1:49920->127.0.0.1:6379: use of closed network connection

The closeTheCn function is invoked from reconnect(ctx, err), Close() - the context cancellation happens before Close() is invoked; pubsub has an initHealthCheck which uses a context.TODO() value, rather than a cancellation context supplied to Subscribe, Receive, ReceiveMessage.

closeTheCn is checking !c.closed to log the error. And then changes c.cn to nil after invoking closeConn;

  1. isBadConn would return true, if it received a context.Cancelled/DeadlineExceeded;
  2. releaseConn invokes c.reconnect as isBadConn would return true

It's really hard to say what the appropriate fix here would be. Ideally, if a context cancellation occurs, the connections should be silently cleaned up, and the underlying ctx.Err() returned.

titpetric avatar Jun 10 '22 10:06 titpetric

goroutine 21 [running]:
runtime/debug.Stack()
	/go/src/runtime/debug/stack.go:24 +0x65
runtime/debug.PrintStack()
	/go/src/runtime/debug/stack.go:16 +0x19
github.com/go-redis/redis/v8.(*PubSub).closeTheCn(0xc00054e000, {0x2141680?, 0xc0002c0460})
	/root/tyk/redis/pubsub.go:161 +0xf3
github.com/go-redis/redis/v8.(*PubSub).reconnect(0x2141680?, {0x214c8d8, 0xc00003c540}, {0x2141680?, 0xc0002c0460?})
	/root/tyk/redis/pubsub.go:151 +0x38
github.com/go-redis/redis/v8.(*PubSub).releaseConn(0xc00054e000, {0x214c8d8, 0xc00003c540}, 0xc00010f4a0?, {0x2141680, 0xc0002c0460}, 0x18?)
	/root/tyk/redis/pubsub.go:146 +0x89
github.com/go-redis/redis/v8.(*PubSub).releaseConnWithLock(0xc00054e000, {0x214c8d8?, 0xc00003c540?}, 0x0?, {0x2141680?, 0xc0002c0460?}, 0x0?)
	/root/tyk/redis/pubsub.go:137 +0xb7
github.com/go-redis/redis/v8.(*PubSub).ReceiveTimeout(0xc00054e000, {0x214c8d8?, 0xc00003c540}, 0x0)
	/root/tyk/redis/pubsub.go:380 +0x139
github.com/go-redis/redis/v8.(*PubSub).Receive(0x0?, {0x214c8d8?, 0xc00003c540?})
	/root/tyk/redis/pubsub.go:393 +0x25
github.com/TykTechnologies/tyk/storage.(*RedisCluster).handleReceive(0x0?, {0x214c8d8?, 0xc00003c540?}, 0xc000516000?, 0x1?)
	/root/tyk/tyk/storage/redis_cluster.go:677 +0x37
github.com/TykTechnologies/tyk/storage.(*RedisCluster).StartPubSubHandler(0xc00052c0c0, {0x214c8d8, 0xc00003c540}, {0x1d63f96, 0x19}, 0x0?)
	/root/tyk/tyk/storage/redis_cluster.go:668 +0x29f
github.com/TykTechnologies/tyk/gateway.TestGroupResetHandler.func1()
	/root/tyk/tyk/gateway/api_test.go:1500 +0x114
created by github.com/TykTechnologies/tyk/gateway.TestGroupResetHandler
	/root/tyk/tyk/gateway/api_test.go:1492 +0x285

titpetric avatar Jun 10 '22 10:06 titpetric

Context deadline is conditional on timeout - Receive() doesn't set a timeout, so a context deadline is not created, nor is the context used for cancellation in Conn.WithReader;

titpetric avatar Jun 10 '22 10:06 titpetric

This issue is marked stale. It will be closed in 30 days if it is not updated.

github-actions[bot] avatar Sep 22 '23 00:09 github-actions[bot]