search

quickfix-j / quickfixj

QuickFIX/J is a full featured messaging engine for the FIX protocol. - This is the official project repository.
http://www.quickfixj.org
Other
955 stars 611 forks source link

Intermittent failure of SocketAcceptorTest.testQuickRestartOfAcceptor #471

Open david-gibbs-ig opened 2 years ago

david-gibbs-ig commented 2 years ago

Describe the bug Intermittent failure of SocketAcceptorTest.testQuickRestartOfAcceptor, fails on one build for Ubuntu with Java 8 while the same commit builds successfully for a FORK of the project.

To Reproduce unknown, monitor successive builds for recurrence

Expected behavior Test should reliably pass:

system information:

2022-02-27T13:25:32.4065047Z Current runner version: '2.287.1' 2022-02-27T13:25:32.4099171Z ##[group]Operating System 2022-02-27T13:25:32.4099872Z Ubuntu 2022-02-27T13:25:32.4100321Z 20.04.3 2022-02-27T13:25:32.4100597Z LTS 2022-02-27T13:25:32.4100946Z ##[endgroup] 2022-02-27T13:25:32.4101289Z ##[group]Virtual Environment 2022-02-27T13:25:32.4101743Z Environment: ubuntu-20.04 2022-02-27T13:25:32.4102091Z Version: 20220220.1

Additional context Successful build for same commit : https://github.com/david-gibbs-ig/quickfixj/runs/5350219283?check_suite_focus=true

2022-02-27T13:39:42.7868949Z [ERROR] Failures: 2022-02-27T13:39:42.7869984Z [ERROR] SocketAcceptorTest.testQuickRestartOfAcceptor:139->checkThreads:291 Exactly 1 'QFJ Message Processor' thread(s) expected expected:<1> but was:<2>

https://pipelines.actions.githubusercontent.com/7eda7kc3IwuQzNQDxD4f8n9xTdvjzuElZE7QnUuDQetQPGeGNR/_apis/pipelines/1/runs/1377/signedlogcontent/10?urlExpires=2022-02-28T13%3A34%3A46.1334786Z&urlSigningMethod=HMACV1&urlSignature=ZaHspFWuQud6aZo%2B6uEv%2BD%2ByEgB%2FVsB7C34wpZRfjts%3D

2022-02-27T13:33:09.8460658Z [INFO] Running quickfix.SocketAcceptorTest 2022-02-27T13:33:09.9079833Z <20220227-13:33:09, FIX.4.4:SENDER->TARGET, event> (Session FIX.4.4:SENDER->TARGET schedule is daily, 00:00:00-UTC - 00:00:00-UTC) 2022-02-27T13:33:09.9081468Z <20220227-13:33:09, FIX.4.4:SENDER->TARGET, event> (Created session: FIX.4.4:SENDER->TARGET) 2022-02-27T13:33:09.9089348Z <20220227-13:33:09, FIX.4.4:FOO->BAR, event> (Session FIX.4.4:FOO->BAR schedule is daily, 00:00:00-UTC - 00:00:00-UTC) 2022-02-27T13:33:09.9090688Z <20220227-13:33:09, FIX.4.4:FOO->BAR, event> (Created session: FIX.4.4:FOO->BAR) 2022-02-27T13:33:19.3971070Z [ERROR] Tests run: 7, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 9.55 s <<< FAILURE! - in quickfix.SocketAcceptorTest 2022-02-27T13:33:19.4029568Z [ERROR] testQuickRestartOfAcceptor(quickfix.SocketAcceptorTest) Time elapsed: 3.528 s <<< FAILURE! 2022-02-27T13:33:19.4097280Z java.lang.AssertionError: Exactly 1 'QFJ Message Processor' thread(s) expected expected:<1> but was:<2> 2022-02-27T13:33:19.4097806Z at org.junit.Assert.fail(Assert.java:89) 2022-02-27T13:33:19.4098177Z at org.junit.Assert.failNotEquals(Assert.java:835) 2022-02-27T13:33:19.4098555Z at org.junit.Assert.assertEquals(Assert.java:647) 2022-02-27T13:33:19.4099018Z at quickfix.SocketAcceptorTest.checkThreads(SocketAcceptorTest.java:291) 2022-02-27T13:33:19.4099598Z at quickfix.SocketAcceptorTest.testQuickRestartOfAcceptor(SocketAcceptorTest.java:139) 2022-02-27T13:33:19.4100163Z at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2022-02-27T13:33:19.4100692Z at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 2022-02-27T13:33:19.4101311Z at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 2022-02-27T13:33:19.4101834Z at java.lang.reflect.Method.invoke(Method.java:498) 2022-02-27T13:33:19.4102312Z at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59) 2022-02-27T13:33:19.4102904Z at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) 2022-02-27T13:33:19.4103533Z at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56) 2022-02-27T13:33:19.4104148Z at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) 2022-02-27T13:33:19.4104986Z at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) 2022-02-27T13:33:19.4105531Z at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) 2022-02-27T13:33:19.4106347Z at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100) 2022-02-27T13:33:19.4107015Z at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366) 2022-02-27T13:33:19.4107672Z at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103) 2022-02-27T13:33:19.4108411Z at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63) 2022-02-27T13:33:19.4109062Z at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) 2022-02-27T13:33:19.4109622Z at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) 2022-02-27T13:33:19.4110236Z at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) 2022-02-27T13:33:19.4110850Z at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) 2022-02-27T13:33:19.4111420Z at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) 2022-02-27T13:33:19.4112010Z at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) 2022-02-27T13:33:19.4112590Z at org.junit.runners.ParentRunner.run(ParentRunner.java:413) 2022-02-27T13:33:19.4113233Z at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365) 2022-02-27T13:33:19.4114438Z at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273) 2022-02-27T13:33:19.4115293Z at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238) 2022-02-27T13:33:19.4116711Z at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159) 2022-02-27T13:33:19.4117635Z at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384) 2022-02-27T13:33:19.4118530Z at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345) 2022-02-27T13:33:19.4119287Z at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126) 2022-02-27T13:33:19.4119989Z at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)

david-gibbs-ig commented 2 years ago

This appears to be related to https://www.quickfixj.org/jira/browse/QFJ-825 .

chrjohn commented 2 years ago

I think this could be a false positive. The check for the MessageProcessor threads is rather dumb since it simply checks for the occurrence of a String in a stack dump. Having run numerous tests in the course of https://github.com/quickfix-j/quickfixj/pull/423 I think this is somehow related to usage of ProtocolFactory.VM_PIPE. It seems that sometimes there still is a connector hanging around that cannot be stopped. Sometimes this also leads to failures in the Acceptance Test suite because the VM_PIPE connector cannot be correctly started and does not accept Logons.

chrjohn commented 2 years ago

Maybe the existing test's check can be improved to correctly determine the thread status.

chrjohn commented 2 years ago

BTW, to add to my former comments, you could use ProtocolFactory.SOCKET in the test to see if the problem goes away. However, since the problem is not reproducible every time you cannot be really sure if it fixes the problem reliably. Maybe after a dozen runs or so....

chrjohn commented 2 years ago

BTW, to add to my former comments, you could use ProtocolFactory.SOCKET in the test to see if the problem goes away.

Changed on master via #475