Attila Doroszlai created RATIS-1497:
---------------------------------------
Summary: TestRaftAsyncWithGrpc timeout
Key: RATIS-1497
URL: https://issues.apache.org/jira/browse/RATIS-1497
Project: Ratis
Issue Type: Bug
Affects Versions: 2.3.0
Reporter: Attila Doroszlai
TestRaftAsyncWithGrpc times out locally (but not in CI) since RATIS-1415.
{code}
-------------------------------------------------------------------------------
Test set: org.apache.ratis.grpc.TestRaftAsyncWithGrpc
-------------------------------------------------------------------------------
Tests run: 13, Failures: 0, Errors: 7, Skipped: 0, Time elapsed: 490.435 s <<<
FAILURE! - in org.apache.ratis.grpc.TestRaftAsyncWithGrpc
testWithLoadAsync(org.apache.ratis.grpc.TestRaftAsyncWithGrpc) Time elapsed:
100.017 s <<< ERROR!
org.junit.runners.model.TestTimedOutException: test timed out after 100 seconds
at java.lang.Thread.sleep(Native Method)
at org.apache.ratis.RaftBasicTests.testWithLoad(RaftBasicTests.java:402)
at
org.apache.ratis.RaftAsyncTests.lambda$testWithLoadAsync$6(RaftAsyncTests.java:271)
at org.apache.ratis.RaftAsyncTests$$Lambda$946/230474748.accept(Unknown
Source)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:125)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:113)
at
org.apache.ratis.RaftAsyncTests.testWithLoadAsync(RaftAsyncTests.java:270)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:748)
testRequestTimeout(org.apache.ratis.grpc.TestRaftAsyncWithGrpc) Time elapsed:
100.002 s <<< ERROR!
org.junit.runners.model.TestTimedOutException: test timed out after 100 seconds
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at
java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1693)
at
java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
at
java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1729)
at
java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
at
org.apache.ratis.RaftBasicTests.testRequestTimeout(RaftBasicTests.java:444)
at
org.apache.ratis.RaftAsyncTests.lambda$testRequestTimeout$11(RaftAsyncTests.java:362)
at
org.apache.ratis.RaftAsyncTests$$Lambda$985/1750840351.accept(Unknown Source)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:125)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:113)
at
org.apache.ratis.RaftAsyncTests.testRequestTimeout(RaftAsyncTests.java:362)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:748)
testAsyncRequestSemaphore(org.apache.ratis.grpc.TestRaftAsyncWithGrpc) Time
elapsed: 100.001 s <<< ERROR!
org.junit.runners.model.TestTimedOutException: test timed out after 100 seconds
at java.lang.Thread.sleep(Native Method)
at
org.apache.ratis.RaftAsyncTests.runTestAsyncRequestSemaphore(RaftAsyncTests.java:234)
at org.apache.ratis.RaftAsyncTests$$Lambda$987/96135248.accept(Unknown
Source)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:125)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:113)
at
org.apache.ratis.RaftAsyncTests.testAsyncRequestSemaphore(RaftAsyncTests.java:200)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:748)
testBasicAppendEntriesAsync(org.apache.ratis.grpc.TestRaftAsyncWithGrpc) Time
elapsed: 100.006 s <<< ERROR!
org.junit.runners.model.TestTimedOutException: test timed out after 100 seconds
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at
java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1693)
at
java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
at
java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1729)
at
java.util.concurrent.CompletableFuture.join(CompletableFuture.java:1934)
at
org.apache.ratis.RaftBasicTests.runTestBasicAppendEntries(RaftBasicTests.java:160)
at
org.apache.ratis.RaftAsyncTests.lambda$runTestBasicAppendEntriesAsync$5(RaftAsyncTests.java:255)
at org.apache.ratis.RaftAsyncTests$$Lambda$907/371775439.accept(Unknown
Source)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:125)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:113)
at
org.apache.ratis.RaftAsyncTests.runTestBasicAppendEntriesAsync(RaftAsyncTests.java:254)
at
org.apache.ratis.RaftAsyncTests.testBasicAppendEntriesAsync(RaftAsyncTests.java:260)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:748)
testNoRetryWaitOnNotLeaderException(org.apache.ratis.grpc.TestRaftAsyncWithGrpc)
Time elapsed: 5.486 s <<< ERROR!
java.util.concurrent.TimeoutException
at
java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
at
java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
at org.apache.ratis.util.TimeDuration.apply(TimeDuration.java:294)
at
org.apache.ratis.RaftAsyncTests.runTestNoRetryWaitOnNotLeaderException(RaftAsyncTests.java:476)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:125)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:113)
at
org.apache.ratis.RaftAsyncTests.testNoRetryWaitOnNotLeaderException(RaftAsyncTests.java:461)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:748)
testRequestAsyncWithRetryFailureAfterInitialMessages(org.apache.ratis.grpc.TestRaftAsyncWithGrpc)
Time elapsed: 13.49 s <<< ERROR!
java.util.concurrent.TimeoutException
at
java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
at
java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
at
org.apache.ratis.RaftTestUtil.assertSuccessReply(RaftTestUtil.java:512)
at
org.apache.ratis.RaftAsyncTests.runTestRequestAsyncWithRetryFailure(RaftAsyncTests.java:142)
at
org.apache.ratis.RaftAsyncTests.lambda$runTestRequestAsyncWithRetryFailure$0(RaftAsyncTests.java:123)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:125)
at
org.apache.ratis.RaftAsyncTests.runTestRequestAsyncWithRetryFailure(RaftAsyncTests.java:123)
at
org.apache.ratis.RaftAsyncTests.testRequestAsyncWithRetryFailureAfterInitialMessages(RaftAsyncTests.java:118)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:748)
testCheckLeadershipFailure(org.apache.ratis.grpc.TestRaftAsyncWithGrpc) Time
elapsed: 55.569 s <<< ERROR!
java.lang.IllegalStateException:
No leader yet : printing ALL groups
s0: RUNNING FOLLOWER s0@group-B94298B6D27D:t6, leader=s2, voted=s2,
raftlog=s0@group-B94298B6D27D-SegmentedRaftLog:OPENED:c-1, conf=5:
[s0|rpc:localhost:52827|admin:localhost:52828|client:localhost:52829|dataStream:localhost:52830|priority:0,
s1|rpc:localhost:52831|admin:localhost:52832|client:localhost:52833|dataStream:localhost:52834|priority:0,
s2|rpc:localhost:52835|admin:localhost:52836|client:localhost:52837|dataStream:localhost:52838|priority:0],
old=null RUNNING
s1: RUNNING FOLLOWER s1@group-B94298B6D27D:t6, leader=s2, voted=s2,
raftlog=s1@group-B94298B6D27D-SegmentedRaftLog:OPENED:c-1, conf=5:
[s0|rpc:localhost:52827|admin:localhost:52828|client:localhost:52829|dataStream:localhost:52830|priority:0,
s1|rpc:localhost:52831|admin:localhost:52832|client:localhost:52833|dataStream:localhost:52834|priority:0,
s2|rpc:localhost:52835|admin:localhost:52836|client:localhost:52837|dataStream:localhost:52838|priority:0],
old=null RUNNING
s2: RUNNING FOLLOWER s2@group-B94298B6D27D:t6, leader=s2, voted=s2,
raftlog=s2@group-B94298B6D27D-SegmentedRaftLog:OPENED:c0, conf=5:
[s0|rpc:localhost:52827|admin:localhost:52828|client:localhost:52829|dataStream:localhost:52830|priority:0,
s1|rpc:localhost:52831|admin:localhost:52832|client:localhost:52833|dataStream:localhost:52834|priority:0,
s2|rpc:localhost:52835|admin:localhost:52836|client:localhost:52837|dataStream:localhost:52838|priority:0],
old=null RUNNING
at
org.apache.ratis.server.impl.MiniRaftCluster.newIllegalStateExceptionForNoLeaders(MiniRaftCluster.java:533)
at
org.apache.ratis.RaftTestUtil.lambda$waitForLeader$1(RaftTestUtil.java:104)
at
org.apache.ratis.server.impl.MiniRaftCluster.getLeader(MiniRaftCluster.java:567)
at
org.apache.ratis.server.impl.MiniRaftCluster.getLeader(MiniRaftCluster.java:560)
at
org.apache.ratis.RaftTestUtil.lambda$waitForLeader$3(RaftTestUtil.java:112)
at org.apache.ratis.util.JavaUtils.attempt(JavaUtils.java:166)
at org.apache.ratis.util.JavaUtils.attemptRepeatedly(JavaUtils.java:152)
at org.apache.ratis.RaftTestUtil.waitForLeader(RaftTestUtil.java:111)
at org.apache.ratis.RaftTestUtil.waitForLeader(RaftTestUtil.java:92)
at org.apache.ratis.RaftTestUtil.waitForLeader(RaftTestUtil.java:87)
at
org.apache.ratis.RaftAsyncTests.runTestCheckLeadershipFailure(RaftAsyncTests.java:449)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:125)
at
org.apache.ratis.server.impl.MiniRaftCluster$Factory$Get.runWithNewCluster(MiniRaftCluster.java:113)
at
org.apache.ratis.RaftAsyncTests.testCheckLeadershipFailure(RaftAsyncTests.java:414)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
at
org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:748)
{code}
{noformat:title=git bisect log}
git bisect start
# bad: [394b47313216f0892ca36a1b17d0081cb212bee1] RATIS-1412. Add ratis-shell
snapshot command (#580)
git bisect bad 394b47313216f0892ca36a1b17d0081cb212bee1
# good: [b98ff4065811b0d3aeaa747b4d05df958ee8ef07] RATIS-1414. In TaskQueue, a
task future should be completed only after the task is polled. (#517)
git bisect good b98ff4065811b0d3aeaa747b4d05df958ee8ef07
# bad: [1f4ec88041856c5e92a3f6f2e27a2b180c8403e3] RATIS-1436.Add ratis-shell
GroupInfo command (#540)
git bisect bad 1f4ec88041856c5e92a3f6f2e27a2b180c8403e3
# bad: [2739eb6883458395aef1f901e3e4b6825f02d658] RATIS-1434. Add iterator()
and remove(..) methods to DataQueue and DataBlockingQueue (#533)
git bisect bad 2739eb6883458395aef1f901e3e4b6825f02d658
# bad: [1dec9dcebfc87833be1c2dc9a127b03eaf62f129] RATIS-1424.
NettyClientStreamRpc#workerGroup Can cause too much nioEventLoopGroup object
(#527)
git bisect bad 1dec9dcebfc87833be1c2dc9a127b03eaf62f129
# bad: [d62117a2163d9c3027a6b5f7b18da36fb4e4a0ab] RATIS-1418. Leader step down
for not sending out heartbeat promptly (#521)
git bisect bad d62117a2163d9c3027a6b5f7b18da36fb4e4a0ab
# bad: [a6c07100d9155f2bed137bebce05e6da17d73328] RATIS-1416. Update Ratis
master version to 2.3.0-SNAPSHOT (#519)
git bisect bad a6c07100d9155f2bed137bebce05e6da17d73328
# bad: [64a4f0ac2426d1d2c61806f262767a84b425aa38] RATIS-1415. Avoid follower
gap limitation for watch requests (#518)
git bisect bad 64a4f0ac2426d1d2c61806f262767a84b425aa38
# first bad commit: [64a4f0ac2426d1d2c61806f262767a84b425aa38] RATIS-1415.
Avoid follower gap limitation for watch requests (#518)
{noformat}
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
