[infinispan-issues] [JBoss JIRA] (ISPN-10236) Hotrod client error releasing channel after server cache stop

[ https://issues.jboss.org/browse/ISPN-10236?page=com.atlassian.jira.plugin... ] Dan Berindei commented on ISPN-10236: ------------------------------------- I'm seeing related test failures almost every time I run the client tests with {{taskset -c 1-2}} and trace logging enabled. {{CompleteShutdownDistRetryTest}}/{{CompleteShutdownDistRetryTest}} hang after the same {{AssertionError}}: {noformat} 11:23:24,208 TRACE (Test-Client-Async-141-1:[]) [ChannelRecord] Closing channel [id: 0x6f6f3467, L:/127.0.0.1:48102 ! R:127.0.0.1/127.0.0.1:37957] 11:23:24,208 TRACE (Test-Client-Async-141-3:[]) [ChannelFactory] Releasing channel [id: 0x6f6f3467, L:/127.0.0.1:48102 ! R:127.0.0.1/127.0.0.1:37957] 11:23:24,208 TRACE (Test-Client-Async-141-3:[]) [ChannelPool] Requesting [id: 0x6f6f3467, L:/127.0.0.1:48102 ! R:127.0.0.1/127.0.0.1:37957] close due to exception java.lang.AssertionError: Error releasing [id: 0x6f6f3467, L:/127.0.0.1:48102 ! R:127.0.0.1/127.0.0.1:37957] java.lang.AssertionError: Error releasing [id: 0x6f6f3467, L:/127.0.0.1:48102 ! R:127.0.0.1/127.0.0.1:37957] at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.release(ChannelPool.java:170) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.releaseChannel(ChannelFactory.java:309) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.HotRodOperation.releaseChannel(HotRodOperation.java:105) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.invoke(RetryOnFailureOperation.java:80) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.activateChannel(ChannelPool.java:217) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.acquire(ChannelPool.java:86) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:259) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:254) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.AbstractKeyOperation.fetchChannelAndInvoke(AbstractKeyOperation.java:43) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.retryIfNotDone(RetryOnFailureOperation.java:100) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.logAndRetryOrFail(RetryOnFailureOperation.java:200) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.handleException(RetryOnFailureOperation.java:179) ~[classes/:?] at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.cancel(RetryOnFailureOperation.java:86) ~[classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.lambda$createAndInvoke$0(ChannelPool.java:147) ~[classes/:?] at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) [?:?] at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) [?:?] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) [?:?] at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) [?:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelInitializer$ActivationFuture.operationComplete(ChannelInitializer.java:202) [classes/:?] at org.infinispan.client.hotrod.impl.transport.netty.ChannelInitializer$ActivationFuture.operationComplete(ChannelInitializer.java:195) [classes/:?] at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:511) [netty-common-4.1.30.Final.jar:4.1.30.Final] at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:504) [netty-common-4.1.30.Final.jar:4.1.30.Final] at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:483) [netty-common-4.1.30.Final.jar:4.1.30.Final] at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:424) [netty-common-4.1.30.Final.jar:4.1.30.Final] at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:121) [netty-common-4.1.30.Final.jar:4.1.30.Final] at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.fulfillConnectPromise(AbstractEpollChannel.java:629) [netty-transport-native-epoll-4.1.30.Final-linux-x86_64.jar:4.1.30.Final] at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.finishConnect(AbstractEpollChannel.java:648) [netty-transport-native-epoll-4.1.30.Final-linux-x86_64.jar:4.1.30.Final] at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.epollOutReady(AbstractEpollChannel.java:522) [netty-transport-native-epoll-4.1.30.Final-linux-x86_64.jar:4.1.30.Final] at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:411) [netty-transport-native-epoll-4.1.30.Final-linux-x86_64.jar:4.1.30.Final] at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:321) [netty-transport-native-epoll-4.1.30.Final-linux-x86_64.jar:4.1.30.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897) [netty-common-4.1.30.Final.jar:4.1.30.Final] 11:23:25,362 TRACE (Test-Client-Async-141-4:[]) [ChannelInitializer] Created channel [id: 0xc20779cc] 11:28:22,793 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed: org.infinispan.client.hotrod.retry.CompleteShutdownDistRetryTest.testRetryAfterCompleteShutdown org.infinispan.client.hotrod.exceptions.HotRodClientException: java.lang.InterruptedException at org.infinispan.client.hotrod.impl.Util.await(Util.java:50) ~[classes/:?] at org.infinispan.client.hotrod.impl.RemoteCacheImpl.get(RemoteCacheImpl.java:417) ~[classes/:?] at org.infinispan.client.hotrod.retry.CompleteShutdownDistRetryTest.testRetryAfterCompleteShutdown(CompleteShutdownDistRetryTest.java:63) ~[test-classes/:?] {noformat} {{DistTopologyChangeUnderLoadTest.testPutsSucceedWhileTopologyChanges}} doesn't log the same error, but its failure also seems related to connection management. After stopping a server, the client says it got a connection reset and it's closing the channel, only to time out 60s later: {noformat} 11:22:59,339 TRACE (ForkThread-1,Test:[]) [RemoteCacheImpl] About to add (K,V): (1418, v1418) lifespan:0, maxIdle:0 11:22:59,339 TRACE (ForkThread-1,Test:[]) [RetryOnFailureOperation] Requesting channel for operation PutOperation{(default), key=[B0x034B0000058A, value=[B0x033E057631343138, flags=6} 11:22:59,339 TRACE (ForkThread-1,Test:[]) [RetryOnFailureOperation] About to start executing operation PutOperation{(default), key=[B0x034B0000058A, value=[B0x033E057631343138, flags=6} on [id: 0xf686211e, L:/127.0.0.1:38484 - R:127.0.0.1/127.0.0.1:34793] 11:22:59,403 TRACE (Test-Client-Async-109-2:[]) [RetryOnFailureOperation] (2) Requesting [id: 0xf686211e, L:/127.0.0.1:38484 - R:127.0.0.1/127.0.0.1:34793] close due to exception io.netty.channel.unix.Errors$NativeIoException: syscall:read(..) failed: Connection reset by peer 11:22:59,443 TRACE (Test-Client-Async-109-2:[]) [ChannelRecord] Closing channel [id: 0xf686211e, L:/127.0.0.1:38484 ! R:127.0.0.1/127.0.0.1:34793] 11:22:59,443 TRACE (Test-Client-Async-109-2:[]) [RetryOnFailureOperation] Exception encountered in PutOperation{(default), key=[B0x034B00000586, value=[B0x033E057631343134, flags=6}. Retry 0 out of 1 io.netty.channel.unix.Errors$NativeIoException: syscall:read(..) failed: Connection reset by peer at io.netty.channel.unix.FileDescriptor.readAddress(..)(Unknown Source) ~[netty-transport-native-unix-common-4.1.30.Final.jar:4.1.30.Final] 11:22:59,443 TRACE (Test-Client-Async-109-2:[]) [RetryOnFailureOperation] Not retrying as done (exceptionally=false), retryCount=1 11:23:59,352 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed: org.infinispan.client.hotrod.DistTopologyChangeUnderLoadTest.testPutsSucceedWhileTopologyChanges java.util.concurrent.ExecutionException: org.infinispan.client.hotrod.exceptions.TransportException:: java.net.SocketTimeoutException: PutOperation{(default), key=[B0x034B0000058A, value=[B0x033E057631343138, flags=6} timed out after 60000 ms at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?] at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?] at org.infinispan.client.hotrod.DistTopologyChangeUnderLoadTest.testPutsSucceedWhileTopologyChanges(DistTopologyChangeUnderLoadTest.java:62) ~[test-classes/:?] {noformat} I got fewer errors (and sometimes even no errors) after I reduced the number of retries in {{HitsAwareCacheManagersTest.createHotRodClientConfigurationBuilder}}. -- This message was sent by Atlassian Jira (v7.12.1#712002)