DiagStatusCommandTest failures on build servers, passing locally

Description

The DiagStatusCommandTest introduced in https://git.opendaylight.org/gerrit/#/c/76341/ which passed for the past 8 days since being merge suddenly started failing since the last Patch Set 8 of https://git.opendaylight.org/gerrit/#/c/76532.

The weird thing is that https://git.opendaylight.org/gerrit/#/c/76532/7..8 didn't change anything that could reasonably have anything to do with this. So this sporadic - it failed again on c/76532 (x2) after a "recheck", but on https://git.opendaylight.org/gerrit/#/c/76827 (which is based on c/76532) it failed once and on recheck passed!! Locally it always passes, of course.

Environment

None

Activity

Show:

Robert Varga July 23, 2020 at 9:59 AM

Well, the tests are in place and we do not see any failures, closing.

Michael Vorburger October 10, 2018 at 8:59 PM

For the very short term and just to get the respective patches FINALLY merged, I'll @Ignore ...

Michael Vorburger October 10, 2018 at 8:58 PM

The failure is this, from https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/infrautils-maven-verify-neon-mvn35-openjdk8/138/console.log.gz:

Running org.opendaylight.infrautils.diagstatus.shell.DiagStatusCommandTest
Tests run: 2, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 1.095 sec <<< FAILURE! - in org.opendaylight.infrautils.diagstatus.shell.DiagStatusCommandTest
testGetRemoteStatusSummary_IPv6(org.opendaylight.infrautils.diagstatus.shell.DiagStatusCommandTest)  Time elapsed: 0.039 sec  <<< ERROR!
java.lang.IllegalStateException: SystemReadyListener.onSystemBootReady() threw Exception; rethrowing to fail test
	at org.opendaylight.infrautils.ready.testutils.TestSystemReadyMonitor.registerListener(TestSystemReadyMonitor.java:54)
	at org.opendaylight.infrautils.diagstatus.internal.DiagStatusServiceMBeanImpl.<init>(DiagStatusServiceMBeanImpl.java:69)
	at org.opendaylight.infrautils.diagstatus.shell.DiagStatusCommandTest.checkGetRemoteStatusSummary(DiagStatusCommandTest.java:61)
	at org.opendaylight.infrautils.diagstatus.shell.DiagStatusCommandTest.testGetRemoteStatusSummary_IPv6(DiagStatusCommandTest.java:39)
	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:47)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:283)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:173)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:128)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:203)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:155)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
Caused by: java.rmi.server.ExportException: Port already in use: 6886; nested exception is: 
	java.net.BindException: Address already in use (Bind failed)
	at sun.rmi.transport.tcp.TCPTransport.listen(TCPTransport.java:346)
	at sun.rmi.transport.tcp.TCPTransport.exportObject(TCPTransport.java:254)
	at sun.rmi.transport.tcp.TCPEndpoint.exportObject(TCPEndpoint.java:411)
	at sun.rmi.transport.LiveRef.exportObject(LiveRef.java:147)
	at sun.rmi.server.UnicastServerRef.exportObject(UnicastServerRef.java:236)
	at sun.rmi.registry.RegistryImpl.setup(RegistryImpl.java:213)
	at sun.rmi.registry.RegistryImpl.<init>(RegistryImpl.java:198)
	at java.rmi.registry.LocateRegistry.createRegistry(LocateRegistry.java:203)
	at org.opendaylight.infrautils.diagstatus.MBeanUtils.startRMIConnectorServer(MBeanUtils.java:81)
	at org.opendaylight.infrautils.diagstatus.internal.DiagStatusServiceMBeanImpl.onSystemBootReady(DiagStatusServiceMBeanImpl.java:75)
	at org.opendaylight.infrautils.ready.testutils.TestSystemReadyMonitor.registerListener(TestSystemReadyMonitor.java:52)
	... 27 more
Caused by: java.net.BindException: Address already in use (Bind failed)
	at java.net.PlainSocketImpl.socketBind(Native Method)
	at java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:387)
	at java.net.ServerSocket.bind(ServerSocket.java:375)
	at java.net.ServerSocket.<init>(ServerSocket.java:237)
	at java.net.ServerSocket.<init>(ServerSocket.java:128)
	at sun.rmi.transport.proxy.RMIDirectSocketFactory.createServerSocket(RMIDirectSocketFactory.java:45)
	at sun.rmi.transport.proxy.RMIMasterSocketFactory.createServerSocket(RMIMasterSocketFactory.java:345)
	at sun.rmi.transport.tcp.TCPEndpoint.newServerSocket(TCPEndpoint.java:666)
	at sun.rmi.transport.tcp.TCPTransport.listen(TCPTransport.java:335)
	... 37 more

What is strange is that the JMX server listener clearly did shut down, see https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/infrautils-maven-verify-neon-mvn35-openjdk8/138/diagstatus/shell/target/surefire-reports/org.opendaylight.infrautils.diagstatus.shell.DiagStatusCommandTest-output.txt.gz :

[main] INFO org.opendaylight.infrautils.diagstatus.MBeanUtils - MBean registration for org.opendaylight.infrautils.diagstatus:type=SvcStatus SUCCESSFUL.
[main] INFO org.opendaylight.infrautils.diagstatus.MBeanUtils - JMX Connector Server started for url service:jmx:rmi://127.0.0.1/jndi/rmi://127.0.0.1:6886/server
[main] INFO org.opendaylight.infrautils.diagstatus.shell.DiagStatusCommand - invokeRemoteJMXOperation() JMX service URL: service:jmx:rmi://127.0.0.1/jndi/rmi://127.0.0.1:6886/server
[main] INFO org.opendaylight.infrautils.diagstatus.MBeanUtils - JMX Connector Server stopped (javax.management.remote.rmi.RMIConnectorServer@56de6d6b,RegistryImpl[UnicastServerRef [liveRef: [endpoint:[10.30.170.154:6886](local),objID:[0:0:0, 0]]]])
[main] INFO org.opendaylight.infrautils.diagstatus.MBeanUtils - MBean registration for org.opendaylight.infrautils.diagstatus:type=SvcStatus SUCCESSFUL.

I'm wondering if it's possible that after JMXConnectorServer.stop() stays open for an instant? Should MBeanUtils.stopRMIConnectorServer() do something like this:

JMXConnectorServer server = jmxConnector.getLeft();
            int port = server.getAddress().getPort();
            server.stop();
            // TODO wait for "port" to really be closed

Cannot Reproduce

Details

Assignee

Unassigned

Reporter

Michael Vorburger

Priority

Medium

Created October 10, 2018 at 8:53 PM

Updated July 23, 2020 at 9:59 AM

Resolved July 23, 2020 at 9:59 AM

Configure