[
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}}.
Hotrod client error releasing channel after server cache stop
-------------------------------------------------------------
Key: ISPN-10236
URL:
https://issues.jboss.org/browse/ISPN-10236
Project: Infinispan
Issue Type: Bug
Components: Test Suite - Server
Affects Versions: 10.0.0.Beta3
Reporter: Dan Berindei
Priority: Major
Labels: testsuite_stability
Fix For: 10.0.0.Beta4
Attachments:
ISPN-10137_package_private_scope_20190524-1732_ServerFailureRetryTest-infinispan-client-hotrod.log.gz
Random failure in {{ServerFailureRetryTest.testRetryCacheStopped}} caused by an assert
statement in {{ChannelPool.release()}}.
{noformat}
17:37:36,562 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed:
org.infinispan.client.hotrod.retry.ServerFailureRetryTest.testRetryCacheStopped
java.lang.AssertionError: Error releasing [id: 0x5d9755e6, L:/127.0.0.1:42472 !
R:127.0.0.1/127.0.0.1:44865]
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:297)
~[classes/:?]
at
org.infinispan.client.hotrod.impl.operations.AbstractKeyOperation.fetchChannelAndInvoke(AbstractKeyOperation.java:41)
~[classes/:?]
at
org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.execute(RetryOnFailureOperation.java:61)
~[classes/:?]
at org.infinispan.client.hotrod.impl.RemoteCacheImpl.putAsync(RemoteCacheImpl.java:366)
~[classes/:?]
at org.infinispan.client.hotrod.impl.RemoteCacheImpl.put(RemoteCacheImpl.java:334)
~[classes/:?]
at org.infinispan.client.hotrod.impl.RemoteCacheSupport.put(RemoteCacheSupport.java:79)
~[classes/:?]
at
org.infinispan.client.hotrod.retry.ServerFailureRetryTest.testRetryCacheStopped(ServerFailureRetryTest.java:63)
~[test-classes/:?]
{noformat}
I investigated a bit and I couldn't find an obvious mistake in the way
{{ChannelPool.created}} is incremented and decremented, but I think it would help if
access to it and {{ChannelPool.active}} were centralized in a smaller number of methods.
--
This message was sent by Atlassian Jira
(v7.12.1#712002)