{"action":"created","issue":{"url":"https://api.github.com/repos/mp911de/lettuce/issues/342","repository_url":"https://api.github.com/repos/mp911de/lettuce","labels_url":"https://api.github.com/repos/mp911de/lettuce/issues/342/labels{/name}","comments_url":"https://api.github.com/repos/mp911de/lettuce/issues/342/comments","events_url":"https://api.github.com/repos/mp911de/lettuce/issues/342/events","html_url":"https://github.com/mp911de/lettuce/issues/342","id":173117036,"number":342,"title":"Connection leak when there is a master/slave node fail over","user":{"login":"long-xuan-nguyen","id":5634670,"avatar_url":"https://avatars.githubusercontent.com/u/5634670?v=3","gravatar_id":"","url":"https://api.github.com/users/long-xuan-nguyen","html_url":"https://github.com/long-xuan-nguyen","followers_url":"https://api.github.com/users/long-xuan-nguyen/followers","following_url":"https://api.github.com/users/long-xuan-nguyen/following{/other_user}","gists_url":"https://api.github.com/users/long-xuan-nguyen/gists{/gist_id}","starred_url":"https://api.github.com/users/long-xuan-nguyen/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/long-xuan-nguyen/subscriptions","organizations_url":"https://api.github.com/users/long-xuan-nguyen/orgs","repos_url":"https://api.github.com/users/long-xuan-nguyen/repos","events_url":"https://api.github.com/users/long-xuan-nguyen/events{/privacy}","received_events_url":"https://api.github.com/users/long-xuan-nguyen/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/mp911de/lettuce/labels/question","name":"question","color":"cc317c"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":2,"created_at":"2016-08-25T05:28:02Z","updated_at":"2016-08-25T19:41:54Z","closed_at":null,"body":"I encountered an issue when there is a change in topology\r\n\r\nSetup: 20 master nodes, each with 2 slaves. Running 4.1.1.Final. ReadFrom is read from slaves\r\n\r\nSequence of events:\r\n\r\n- M1 went down; redis process got killed completely\r\n- S1 got promoted to be new master\r\n- S2 now starts syncing from S1, the new master\r\n\r\nDuring the time window when S2 is syncing from S1, there are many connections opened from a host to S2, eventually causing Redis to hit its client count limit and reject other connections. I see a bunch of IOException Connection reset by peer in the log.\r\n\r\nLooking into the code (https://github.com/mp911de/lettuce/blob/4.2.x/src/main/java/com/lambdaworks/redis/cluster/PooledClusterConnectionProvider.java#L520), here is what i think is happening:\r\n\r\n- Cluster topology refresh happens\r\n- Requests for reading against S2 come in; new connection is initialized\r\n- Before this new connection is passed back to the LoadingCache, readonly() is invoked on the sync interface.\r\n- This command fails with error \"Loading redis is loading dataset in memory\"\r\n- The exception got propagated back to the caller, resulting in a failure. The connection created in second step is now orphaned and not accessible thru the cache\r\n- The loading process takes a few minutes and with enough TPS, S2 is completely saturated with connections.\r\n\r\nIs the fix here to close the connection when readonly() fails?\r\n\r\nWould be nice if Redis \"cluster nodes\" command provides a flag for this state when Redis is loading in RAM so we can exclude from topology. An alternative is to somehow trigger an event when this happens (first time seeing Redis loading error on a connection) and have the topology refresher exclude the node from the topology. These are just wish-list  items though. Would really appreciate if you can provide feedback on the bug and the proposed fix.\r\n\r\nNote that when S2 is saturated, we're also seeing very weird behavior in another set of servers where they purely perform writes which should never establish any connection to slaves except for topology refresh. These hosts would have ConnectionWatchdog throwing exceptions like NullPointerException, cannot initialize channel ... Unfortunately, we don't have debug/trace log enabled so cant really debug more that that. I am assuming this issue is related to https://github.com/mp911de/lettuce/issues/278 ? After a while, both the writer hosts and reader hosts got into a state where this exception is seen everywhere\r\n\r\n```\r\n21 Aug 2016 08:59:17,579 [WARN]  (lettuce-nioEventLoop-3-152) com.lambdaworks.redis.protocol.CommandHandler: [/10.91.86.192:49672 -> /10.162.234.169:6379] Unexpected exception during request: io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 16777216 byte(s) of direct memory (used: 5133828096, max: 5145362432)\r\nio.netty.util.internal.OutOfDirectMemoryError: failed to allocate 16777216 byte(s) of direct memory (used: 5133828096, max: 5145362432)\r\n\tat io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:613)\r\n\tat io.netty.util.internal.PlatformDependent.allocateDirectNoCleaner(PlatformDependent.java:567)\r\n\tat io.netty.buffer.PoolArena$DirectArena.allocateDirect(PoolArena.java:699)\r\n\tat io.netty.buffer.PoolArena$DirectArena.newChunk(PoolArena.java:688)\r\n\tat io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:237)\r\n\tat io.netty.buffer.PoolArena.allocate(PoolArena.java:213)\r\n\tat io.netty.buffer.PoolArena.allocate(PoolArena.java:141)\r\n\tat io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:262)\r\n\tat io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:179)\r\n\tat io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:170)\r\n\tat io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:131)\r\n\tat io.netty.channel.DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle.allocate(DefaultMaxMessagesRecvByteBufAllocator.java:73)\r\n\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:111)\r\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:571)\r\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:512)\r\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:426)\r\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:398)\r\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:805)\r\n\tat io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:145)\r\n\tat java.lang.Thread.run(Thread.java:745)\r\n```\r\nThanks,\r\n\r\n\r\n<!--\r\nThank you for creating an issue. This template will guide you through the essential steps necessary to create an amazing issue.\r\n\r\n## Logs\r\nPlease use Gist (https://gist.github.com/) or a similar code paster for longer\r\nlogs.\r\n-->\r\nMake sure that:\r\n\r\n- [ ] You have read the [contribution guidelines](https://github.com/mp911de/lettuce/blob/master/.github/CONTRIBUTING.md).\r\n- [ ] You specify the lettuce version and environment so it's obvious which version is affected\r\n- [ ] You provide a reproducible test case (either descriptive of as JUnit test) if it's a bug or the expected behavior differs from the actual behavior.\r\n\r\n <!--\r\nGreat! Live long and prosper.\r\n-->"},"comment":{"url":"https://api.github.com/repos/mp911de/lettuce/issues/comments/242512259","html_url":"https://github.com/mp911de/lettuce/issues/342#issuecomment-242512259","issue_url":"https://api.github.com/repos/mp911de/lettuce/issues/342","id":242512259,"user":{"login":"long-xuan-nguyen","id":5634670,"avatar_url":"https://avatars.githubusercontent.com/u/5634670?v=3","gravatar_id":"","url":"https://api.github.com/users/long-xuan-nguyen","html_url":"https://github.com/long-xuan-nguyen","followers_url":"https://api.github.com/users/long-xuan-nguyen/followers","following_url":"https://api.github.com/users/long-xuan-nguyen/following{/other_user}","gists_url":"https://api.github.com/users/long-xuan-nguyen/gists{/gist_id}","starred_url":"https://api.github.com/users/long-xuan-nguyen/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/long-xuan-nguyen/subscriptions","organizations_url":"https://api.github.com/users/long-xuan-nguyen/orgs","repos_url":"https://api.github.com/users/long-xuan-nguyen/repos","events_url":"https://api.github.com/users/long-xuan-nguyen/events{/privacy}","received_events_url":"https://api.github.com/users/long-xuan-nguyen/received_events","type":"User","site_admin":false},"created_at":"2016-08-25T19:41:54Z","updated_at":"2016-08-25T19:41:54Z","body":"1. We already have our own ReadFrom implementation which basically prefer slave over master\r\n2. Thanks for the fix. Is there any other place where this could potentially be an issue?\r\n3. in \"info\" command output, you can have tell whether the node is doing a full sync by looking at the flag \"master_sync_in_progress\". If only this flag got exposed as part of \"cluster nodes\", we will be able to exclude this node. Alternatively, we can call \"info\" on each node but that seems excessive. Would be nice to have Lettuce detect this error \"LOADING\" the first time and have topology reacts to this event and automatically exclude this node from further requests until this is done. This can be achieved with a background process to detect when the node is done syncing by checking this flag from \"info\" command once every 10 seconds or something\r\n4. I thought so too. Upgraded our library to 4.2.2 and will report back if there is any issue\r\n\r\nThanks for your quick turnaround on this\r\n"}}
{"actor":{"display_login":"long-xuan-nguyen"}}