[jboss-jira] [JBoss JIRA] (JGRP-1890) Random test case failures with UNICAST2/UNICAST

Random test case failures with UNICAST2/UNICAST ----------------------------------------------- Key: JGRP-1890 URL: https://issues.jboss.org/browse/JGRP-1890 Project: JGroups Issue Type: Bug Affects Versions: 3.2.13 Reporter: Richard Janík Assignee: Bela Ban Priority: Minor I'm seeing occasional test failures concerning UNICAST2 and UNICAST with our jenkins jobs. They are quite rare (1 fail in 10 executions for each test case) and so far I've failed to reproduce them locally. The test cases in question are: org.jgroups.protocols.UNICAST2_Test.testFirstMessageDropped org.jgroups.tests.UNICAST2_ConnectionTests.testBClosingUnilaterally org.jgroups.tests.UNICAST_ConnectionTests.testAClosingUnilaterallyButLosingFirstMessage org.jgroups.protocols.UNICAST2_Test.testFirstMessageDropped: link: https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-manu-jgroups-... Assertion on the last line of the test fails - UNICAST2 connection from channel a to b is not established: {code} assert ((UNICAST2)a.getProtocolStack().findProtocol(UNICAST2.class)).connectionEstablished(b.getAddress()); {code} {code} Error Message null Stacktrace java.lang.AssertionError at org.jgroups.protocols.UNICAST2_Test.testFirstMessageDropped(UNICAST2_Test.java:95) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84) at org.testng.internal.Invoker.invokeMethod(Invoker.java:714) at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901) at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231) at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127) at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745) Standard Output 72706 [DEBUG] GMS: - address=A, cluster=UNICAST2_Test 73231 [TRACE] GMS: - A: no initial members discovered: creating group as first member 73231 [DEBUG] GMS: - A: installing view [A|0] [A] 73232 [DEBUG] GMS: - created group (first member). My view is [A|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl 73238 [DEBUG] GMS: - address=B, cluster=UNICAST2_Test 73244 [TRACE] GMS: - B: initial_mbrs are A 73244 [DEBUG] GMS: - election results: {A=1} 73244 [DEBUG] GMS: - sending JOIN(B) to A 73295 [TRACE] GMS: - A: new members=[B], suspected=[], leaving=[], new view: [A|1] [A, B] 73296 [TRACE] GMS: - A: mcasting view [A|1] [A, B] (2 mbrs) 73297 [DEBUG] GMS: - A: installing view [A|1] [A, B] 73298 [TRACE] GMS: - A: received all 1 ACKs from members for view [A|1] 73327 [TRACE] GMS: - B: JOIN-RSP=[A|1] [A, B] [size=2] 73327 [DEBUG] GMS: - B: installing view [A|1] [A, B] ------------- testFirstMessageDropped ----------- **** closing all connections **** --> A sending first message to B (dropped before it reaches B) 73329 [TRACE] UNICAST2: - A: created connection to B (conn_id=2) 73330 [TRACE] UNICAST2: - A --> DATA(B: #1, conn_id=2, first) list=[1] **** CONNECTIONS: A: send connections: B: [0 | 0 | 1] (1 elements, 0 missing), send_conn_id=2 (1145 ms old) [not acked]) B: receive connections: A: [1 | 1 | 1] (0 elements, 0 missing), recv_conn_id=2 (6 ms old) 74477 [DEBUG] GMS: - B: sending LEAVE request to A 74557 [DEBUG] GMS: - address=A, cluster=UNICAST2_Test 75119 [TRACE] GMS: - A: no initial members discovered: creating group as first member 75119 [DEBUG] GMS: - A: installing view [A|0] [A] 75120 [DEBUG] GMS: - created group (first member). My view is [A|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl 75131 [DEBUG] GMS: - address=B, cluster=UNICAST2_Test 75143 [TRACE] GMS: - B: initial_mbrs are A 75143 [DEBUG] GMS: - election results: {A=1} 75143 [DEBUG] GMS: - sending JOIN(B) to A 75239 [TRACE] GMS: - A: new members=[B], suspected=[], leaving=[], new view: [A|1] [A, B] 75259 [TRACE] GMS: - A: mcasting view [A|1] [A, B] (2 mbrs) 75260 [DEBUG] GMS: - A: installing view [A|1] [A, B] 75261 [TRACE] GMS: - A: received all 1 ACKs from members for view [A|1] 75296 [TRACE] GMS: - B: JOIN-RSP=[A|1] [A, B] [size=2] 75296 [DEBUG] GMS: - B: installing view [A|1] [A, B] ------------- testLastMessageDropped ----------- list=[1, 2, 3, 4, 5] 76340 [DEBUG] GMS: - B: sending LEAVE request to A {code} org.jgroups.tests.UNICAST2_ConnectionTests.testBClosingUnilaterally link: https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-manu-jgroups-... {code} Error Message list has 19 elements Stacktrace java.lang.AssertionError at org.jgroups.tests.UNICAST2_ConnectionTests.sendAndCheck(UNICAST2_ConnectionTests.java:232) at org.jgroups.tests.UNICAST2_ConnectionTests.testBClosingUnilaterally(UNICAST2_ConnectionTests.java:105) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84) at org.testng.internal.Invoker.invokeMethod(Invoker.java:714) at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901) at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231) at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127) at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745) Standard Output ------------- testAClosingUnilaterally ----------- l1 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 l2 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ==== Closing the connection on A list = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ------------- testAClosingUnilaterallyButLosingFirstMessage ----------- l1 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 l2 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ==== Closing the connection on A ===================== sending 5 messages from A to B 79126 [TRACE] UNICAST2: - A: created connection to B (conn_id=1) 79126 [TRACE] UNICAST2: - A --> DATA(B: #1, conn_id=1, first) 79126 [TRACE] UNICAST2: - A --> DATA(B: #2, conn_id=1) 79126 [TRACE] UNICAST2: - A --> DATA(B: #3, conn_id=1) 79126 [TRACE] UNICAST2: - A --> DATA(B: #4, conn_id=1) 79126 [TRACE] UNICAST2: - A --> DATA(B: #5, conn_id=1) 79127 [TRACE] UNICAST2: - B <-- STABLE(A: 10-10, conn_id=0) list = m1 m2 m3 m4 m5 ===================== sending 5 messages from A to B: done ------------- testBClosingUnilaterally ----------- l1 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 l2 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ==== Closing the connection on B list = m2 m3 m4 m5 m6 m7 m8 m9 m10 m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ------------- testBothChannelsClosing ----------- l1 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 l2 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ==== Closing the connections on both sides l1 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 l2 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ------------- testMultipleConcurrentResets ----------- list = m1 ==== Closing the connection on A list = m1 ------------- testRegularMessageReception ----------- list = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 m11 m12 m13 m14 m15 m16 m17 m18 m19 m20 ... list = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 m11 m12 m13 m14 m15 m16 m17 m18 m19 m20 ... {code} org.jgroups.tests.UNICAST_ConnectionTests.testAClosingUnilaterallyButLosingFirstMessage link: https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-manu-jgroups-... {code} Error Message list has 0 elements: [] Stacktrace java.lang.AssertionError at org.jgroups.tests.UNICAST_ConnectionTests.sendAndCheck(UNICAST_ConnectionTests.java:217) at org.jgroups.tests.UNICAST_ConnectionTests.testAClosingUnilaterallyButLosingFirstMessage(UNICAST_ConnectionTests.java:125) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84) at org.testng.internal.Invoker.invokeMethod(Invoker.java:714) at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901) at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231) at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127) at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745) Standard Output ------------- testAClosingUnilaterally ----------- l1 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 l2 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ==== Closing the connection on A list = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ------------- testAClosingUnilaterallyButLosingFirstMessage ----------- list = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ==== Closing the connection on A list = ------------- testBClosingUnilaterally ----------- l1 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 l2 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ==== Closing the connection on B list = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ------------- testBothChannelsClosing ----------- l1 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 l2 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ==== Closing the connections on both sides l1 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 l2 = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 ------------- testMultipleConcurrentResets ----------- list = m1 ==== Closing the connection on A list = m1 ------------- testRegularMessageReception ----------- list = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 m11 m12 m13 m14 m15 m16 m17 m18 m19 m20 ... list = m1 m2 m3 m4 m5 m6 m7 m8 m9 m10 m11 m12 m13 m14 m15 m16 m17 m18 m19 m20 ... {code}