Intermittent failure of SocketAcceptorTest.testQuickRestartOfAcceptor

[david-gibbs-ig]

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:

• OS: Ubuntu
• Java version Java 8
• QFJ Version 3.0.0-SNAPSHOT

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]

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

[chrjohn]

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 #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]

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

[chrjohn]

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]

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