adamretter
commented
4 years ago The java.lang.IllegalStateException: Shutdown in progress error comes from JettyStart#shutdown() when it tries to removeShutdownHook.
The stack trace to the JettyStart#shutdown() function looks like:
java.lang.IllegalStateException: Shutdown in progress
at java.lang.ApplicationShutdownHooks.remove(ApplicationShutdownHooks.java:82) ~[?:1.8.0_252]
at java.lang.Runtime.removeShutdownHook(Runtime.java:239) ~[?:1.8.0_252]
at org.exist.jetty.JettyStart.lambda$9(JettyStart.java:537) ~[classes/:?]
at java.util.Optional.ifPresent(Optional.java:159) [?:1.8.0_252]
at org.exist.jetty.JettyStart.shutdown(JettyStart.java:535) [classes/:?]
at org.exist.test.ExistWebServer.after(ExistWebServer.java:148) [classes/:?]
at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:59) [junit-4.13.jar:4.13]
at org.junit.rules.RunRules.evaluate(RunRules.java:20) [junit-4.13.jar:4.13]
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) [junit-4.13.jar:4.13]
at org.junit.runners.ParentRunner.run(ParentRunner.java:413) [junit-4.13.jar:4.13]
at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:364) [surefire-junit4-3.0.0-M5.jar:3.0.0-M5]
at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:272) [surefire-junit4-3.0.0-M5.jar:3.0.0-M5]
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:237) [surefire-junit4-3.0.0-M5.jar:3.0.0-M5]
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:158) [surefire-junit4-3.0.0-M5.jar:3.0.0-M5]
at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:428) [surefire-booter-3.0.0-M5.jar:3.0.0-M5]
at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162) [surefire-booter-3.0.0-M5.jar:3.0.0-M5]
at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:562) [surefire-booter-3.0.0-M5.jar:3.0.0-M5]
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:548) [surefire-booter-3.0.0-M5.jar:3.0.0-M5]
reinhapa
joewiz
Initially discovered in https://github.com/eXist-db/exist/pull/3341
Problem 1 (running single test):
Shows that
JmxRemoteTestexecutes and passes 2 tests quickly, but then the command appears to do nothing for a long period of time. This is due to the timeout above being extended. Whilst waiting for the timeout thejstackfor the process reports the following interesting threads:After the command completes, the following log files are available:
exist-core/target/surefire-reports/2020-08-18T16-22-21_644-jvmRun1.dumpstream:exist-core/target/surefire-reports/org.exist.management.JmxRemoteTest.txt:Even though all the tests passed, both the large delay until the timeout is met and the
2020-08-18T16-22-21_644-jvmRun1.dumpstreamfile indicates that the test did not behave correctly. The test should shutdown nicely without needing to have Surefire wait for a long timeout and then kill the process.Problem 2 (running all tests):
Shows that many tests (including
JmxRemoteTest) executed ok, but then the command appears to do nothing for a long period of time. This is due to the timeout above being extended. Whilst waiting for the timeout thejstackfor the process reports the following interesting threads:After the command completes, the following log files are available:
exist-core/target/surefire-reports/2020-08-18T16-39-44_995-jvmRun6.dumpstream:exist-core/target/surefire-reports/org.exist.management.JmxRemoteTest.txt:Even though all the tests passed, both the large delay until the timeout is met and the
2020-08-18T16-39-44_995-jvmRun6.dumpstreamfile indicates that a test did not behave correctly. Each test should shutdown nicely without needing to have Surefire wait for a long timeout and then kill the process.We can offer further evidence that the underlying issue is likely exhibited via the
JmxRemoteTestby adding the line:to the bottom of
maven-surefire-plugin's excludes configuration inexist-core/pom.xml, and then re-running all the tests using the commands given above. When this is done, running the tests exhibits no larger delay (because there is no wait for the timeout), and there are no*.dumpstreamfiles generated.Problem 3 (running single test / Updated surefire: 3.0.0-M5):
This repeats the process of Problem 1, however the
surefire-maven-pluginversion inexist-parent/pom.xmlis updated from3.0.0-M4to3.0.0-M5. This results in a different set of errors:After the command completes, the following log files are available:
exist-core/target/surefire-reports/2020-08-18T17-10-04_899-jvmRun1.dump:exist-core/target/surefire-reports/2020-08-18T17-10-04_899-jvmRun1.dumpstream:exist-core/target/surefire-reports/org.exist.management.JmxRemoteTest.txt:The
java.lang.IllegalStateException: Shutdown in progressmessages seem to be originating from something calling eitherjava.lang.Runtime#addShutdownHook(Thread)orjava.lang.Runtime#removeShutdownHook(Thread).exist-core/target/test-logs-20200818171030221/exist.log:exist-core/target/test-logs-20200818171030221/urlrewrite.log:Problem 4 (running all tests / Updated surefire: 3.0.0-M5):
This repeats the process of Problem 2, however the
surefire-maven-pluginversion inexist-parent/pom.xmlis updated from3.0.0-M4to3.0.0-M5. This results in a very similar set of errors to Problem 3.Working Theories
Perhaps there is some concurrency problem with eXist-db JMX code, where some shared-state may not correctly synchronized. The JMX code is quite messy, especially the setup of the MBeans and Remote Server (Servlet).
We add/remove JVM Shutdown Hooks in eXist-db from
JettyStartand BrokerPools`. I think that Surefire also makes use of Shutdown hooks, so perhaps we are interfering with those somehow.java.lang.IllegalStateException: Shutdown in progressmessages.