Nondeterministic test failures in DynamicFederatedServiceCollectionImplTest

[barbeau]

When running mvn clean test, we're seeing the DynamicFederatedServiceCollectionImplTest sometimes fail and sometimes pass in sequential executions on the exact same code. Here's the stack trace of the failure:

-------------------------------------------------------------------------------
Test set: org.onebusaway.federations.impl.DynamicFederatedServiceCollectionImplTest
-------------------------------------------------------------------------------
Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 30.466 sec <<< FAILURE!
test(org.onebusaway.federations.impl.DynamicFederatedServiceCollectionImplTest)  Time elapsed: 30.461 sec  <<< FAILURE!
java.lang.AssertionError: 
    at org.junit.Assert.fail(Assert.java:91)
    at org.junit.Assert.assertTrue(Assert.java:43)
    at org.junit.Assert.assertTrue(Assert.java:54)
    at org.onebusaway.federations.impl.DynamicFederatedServiceCollectionImplTest.test(DynamicFederatedServiceCollectionImplTest.java:119)
    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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
    at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
    at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:59)
    at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:115)
    at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:102)
    at org.apache.maven.surefire.Surefire.run(Surefire.java:180)
    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.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:350)
    at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:1021)

Here's the code that causes the failure:

Set<FederatedService> services = _collection.getAllServices();
    assertTrue(services.isEmpty());

    _registry.addService("http://localhost:" + PORT + "/service-A/service",
        SimpleFederatedService.class.getName(), new HashMap<String, String>());

    Thread.sleep(TIMEOUT);

    services = _collection.getAllServices();
    assertEquals(1, services.size());

    SimpleFederatedService service = (SimpleFederatedService) _collection.getServiceForAgencyId("A");
    assertEquals("A", service.getValueForId(""));

    _registry.addService("http://localhost:" + PORT + "/service-B/service",
        SimpleFederatedService.class.getName(), new HashMap<String, String>());

    Thread.sleep(TIMEOUT);

    services = _collection.getAllServices();
    assertEquals(2, services.size());

    service = (SimpleFederatedService) _collection.getServiceForAgencyId("A");
    assertEquals("A", service.getValueForId(""));

    service = (SimpleFederatedService) _collection.getServiceForAgencyId("B");
    assertEquals("B", service.getValueForId(""));

    // Simulate a server crash
    _server.stop();
    _server = null;

    Thread.sleep(TIMEOUT);

    services = _collection.getAllServices();
    assertTrue(services.isEmpty());

The final assertTrue(services.isEmpty()); is what triggers the failure.

[sheldonabrown]

I've seen this on a newer laptop whereas the build server can't reproduce it. I wonder if the TIMEOUT just needs to be adaptive to the class of hardware.

[barbeau]

Yeah, Travis always seems to pass too. I've noticed that Travis does a mvn install -DskipTests=true following by a mvn test -B (which always seems to pass), so it might be that when running mvn test from scratch (or 'mvn clean test`), the time required to build the project interferes with this somehow and causes the failure.

[barbeau]

Or, Travis is just superslow and gives it the time needed to pass.

[sheldonabrown]

To continue the anecdote, my older work laptop does not reproduce it either -- that's why I didn't report it, I thought it was a configuration issue with one specific machine. But yes, it does seem to be speed/time related.

[barbeau]

I'm able to reproduce this fairly consistently (~80% of the time) on develop and master branch on my work machine, which is a beefy 2 CPU machine w/ 16GB RAM and an SSD. So, as Sheldon says, it seems that this problem manifests on newer machines with better hardware.

[barbeau]

FYI - adding a _server.join(); after _server.stop(); has no effect. So it doesn't seem that the issue is the server still shutting down while the last assert is called.

[barbeau]

From a quick scan of the code, I initially thought the underlying issue was that the DynamicFederatedServiceCollectionImpl has a ScheduledExecutorService that executes a Runnable every 60 seconds by default. This Runnable is what seems to clear the registration of services, if I'm understanding correctly. The simulation of the server crash in the test, and the TIMEOUT value of 10 seconds within the test, may not always give the Runnable time to clear the registered services (depending on how long it takes the server to shut down), which would be why assertTrue(services.isEmpty()); fails. If this is true, it seems like the proper fix is to call ScheduledExecutorService.awaitTermination() (which would need to be exposed by DynamicFederatedServiceCollectionImpl) from the test prior to executing assertTrue(services.isEmpty()); - this would allow the previously scheduled Runnable to clear the registered services prior to the test. However, I tried this, as well as bumping TIMEOUT up to 120 seconds, and I'm still seeing the failure.

I've noticed that we're running an old version of Jetty for this test (6.1.22), which has the old package structure org.mortbay.jetty. The problem could be connected to Jetty itself. We could also try upgrading to the newest version of Jetty, which now has the package name of org.eclipse.jetty. More upgrade details here:
https://wiki.eclipse.org/Jetty/Starting/Porting_to_Jetty_7/Packages_and_Classes