spring-projects / spring-boot

Spring Boot
https://spring.io/projects/spring-boot
Apache License 2.0
74.7k stars 40.57k forks source link

When using Jetty, the JVM does not exit until Jetty's thread idle timeout has elapsed #26634

Closed Artur- closed 3 years ago

Artur- commented 3 years ago

Not sure if this is a Spring Boot problem or a Vaadin problem but upgrading from Spring Boot 2.4.5 to 2.4.6 causes our integration tests to fail (https://github.com/vaadin/spring/issues/810) because the RMI port (9001) remains in use even after spring-boot:stop has executed.

The server process seems to be left running:

61070 s018  S      0:13.03 /Library/Java/JavaVirtualMachines/amazon-corretto-8.jdk/Contents/Home/jre/bin/java -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=9001 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Djava.rmi.server.hostname=127.0.0.1 -cp lots-of-classes-here com.vaadin.flow.spring.scan.test.TestServletInitializer --spring.application.admin.enabled=true --spring.application.admin.jmx-name=org.springframework.boot:type=Admin,name=SpringApplication

and it only goes away after waiting for some time.

I cannot immediate see the reason for the server staying up from the Java stack trace or anything else.

It seems to reproduce with any of our test modules only by having

     <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
                <executions>
                    <execution>
                        <id>pre-integration-test</id>
                        <goals>
                            <goal>start</goal>
                        </goals>
                    </execution>
                    <execution>
                        <id>post-integration-test</id>
                        <goals>
                            <goal>stop</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>

and doing e.g. mvn install

Any ideas?

Artur- commented 3 years ago

The same happens also with Spring Boot 2.5.0

mbhave commented 3 years ago

@Artur- Nothing comes to mind immediately on what could have caused this. Could you provide a small sample application that we can run to reproduce the issue?

spring-projects-issues commented 3 years ago

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

spring-projects-issues commented 3 years ago

Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open the issue.

snicoll commented 3 years ago

@Artur- would you be able to share the sample application we've requested so that we can hopefully make progress here? Something might be preventing the server to stop and I really can't see what it could be, especially in a maintenance release.

Artur- commented 3 years ago

I was not able to reproduce this in a standalone project. Only in https://github.com/vaadin/spring as described in https://github.com/vaadin/spring/issues/810.

Artur- commented 3 years ago

I did a git bisect between spring boot v2.4.5 and v2.4.6 with the result

b6e860b2d431b104f47b20feae4c49c3446c3cb6 is the first bad commit
commit b6e860b2d431b104f47b20feae4c49c3446c3cb6
Author: Andy Wilkinson <wilkinsona@vmware.com>
Date:   Wed May 19 19:02:24 2021 +0100

    Prevent Jetty from delaying shutdown beyond grace period

    Fixes gh-22689

I also tried checking out v2.4.7, reverting b6e860b2d431b104f47b20feae4c49c3446c3cb6 and that allows our test to pass

wilkinsona commented 3 years ago

That's an odd one. Reducing the timeout should cause Jetty to shutdown more not less aggressively. Unfortunately, I don't think reverting b6e860b2 is a good option for us to make in Boot itself. Users can configure the timeout themselves so changing the default would just mask the problem rather than fixing it, leaving it lurking for anyone who tunes the timeout themselves.

I'd really like to understand why Jetty isn't shutting down as it should. To that end, I think we're really going to need some steps that we can follow that will reproduce the problem. @Artur- how difficult would it be for us to get things setup to run the relevant part of Vaadin's build (I think that's what the various mvn commands in https://github.com/vaadin/spring/issues/810 are doing) to reproduce the problem?

Artur- commented 3 years ago

I tested it as follows using Java 8:

git clone git@github.com:vaadin/spring.git
cd spring
# edit pom.xml to change Spring Boot version to 2.4.6
mvn install -DskipTests 

It takes a while and fails in one of the test modules, e.g.:

[INFO] --- spring-boot-maven-plugin:2.4.6:start (pre-integration-test) @ test-ts-services ---
[INFO] Attaching agents: []
Error: Exception thrown by the agent : java.rmi.server.ExportException: Port already in use: 9001; nested exception is: 
    java.net.BindException: Address already in use (Bind failed)
sun.management.AgentConfigurationError: java.rmi.server.ExportException: Port already in use: 9001; nested exception is: 
    java.net.BindException: Address already in use (Bind failed)
    at sun.management.jmxremote.ConnectorBootstrap.startRemoteConnectorServer(ConnectorBootstrap.java:480)
    at sun.management.Agent.startAgent(Agent.java:262)
    at sun.management.Agent.startAgent(Agent.java:452)
Caused by: java.rmi.server.ExportException: Port already in use: 9001; 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:412)
    at sun.rmi.transport.LiveRef.exportObject(LiveRef.java:147)
    at sun.rmi.server.UnicastServerRef.exportObject(UnicastServerRef.java:237)
    at sun.rmi.registry.RegistryImpl.setup(RegistryImpl.java:213)
    at sun.rmi.registry.RegistryImpl.<init>(RegistryImpl.java:173)
    at sun.management.jmxremote.SingleEntryRegistry.<init>(SingleEntryRegistry.java:49)
    at sun.management.jmxremote.ConnectorBootstrap.exportMBeanServer(ConnectorBootstrap.java:816)
    at sun.management.jmxremote.ConnectorBootstrap.startRemoteConnectorServer(ConnectorBootstrap.java:468)
    ... 2 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:390)
    at java.net.ServerSocket.<init>(ServerSocket.java:252)
    at java.net.ServerSocket.<init>(ServerSocket.java:143)
    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:670)
    at sun.rmi.transport.tcp.TCPTransport.listen(TCPTransport.java:335)
    ... 11 more
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary for vaadin-spring-parent 18.0-SNAPSHOT:
[INFO] 
[INFO] vaadin-spring-parent ............................... SUCCESS [  0.281 s]
[INFO] vaadin-spring ...................................... SUCCESS [  5.697 s]
[INFO] Vaadin Spring tests ................................ SUCCESS [  0.353 s]
[INFO] Flow Spring Common UI components ................... SUCCESS [  1.418 s]
[INFO] Vaadin Spring Boot integration tests ............... SUCCESS [ 30.510 s]
[INFO] Vaadin Spring Boot integration tests with custom packages to scan SUCCESS [ 28.188 s]
[INFO] Vaadin Spring Boot deployable integration tests .... SUCCESS [ 48.002 s]
[INFO] Vaadin Spring Boot integration tests when deployed using a context path SUCCESS [ 37.195 s]
[INFO] Integration tests for V15+ endpoints ............... FAILURE [01:00 min]
[INFO] Integration tests for V15+ endpoints (custom Connect client) SKIPPED
[INFO] Integration tests for a Spring MVC project without using endpoints SKIPPED
[INFO] Integration tests for Vaadin Spring Security and Flow SKIPPED
[INFO] Integration tests for Vaadin Spring Security and Flow With Context Path SKIPPED
[INFO] Integration tests for Vaadin Spring Security and Fusion SKIPPED
[INFO] Integration tests for Vaadin Spring Security and Fusion With Context Path SKIPPED
[INFO] Keep this module as the last one in the list ....... SKIPPED
wilkinsona commented 3 years ago

Thanks, @Artur-.

The cause appears to be a bug in Jetty's QueuedThreadPool. With a stop timeout of zero it leaves its threads running. They'll eventually exit after 60 seconds which is the default idle timeout. With a stop timeout of just 1ms, the JVM exists nigh-on immediately. I've opened https://github.com/eclipse/jetty.project/issues/6400.

Let's see what the Jetty team say. If I've misunderstood how QueuedThreadPool should behave or a fix won't be available in time for the next Spring Boot release, we could change from 0ms to 1ms for the default stop timeout in Boot. In the meantime, the problem can be worked around using a customizer bean to increase the timeout:

@Bean
JettyServerCustomizer stopTimeoutCustomizer() {
    return (server) -> server.setStopTimeout(1);
}
wilkinsona commented 3 years ago

I've assigned this to 2.4.8 so that we don't forget to do something with it before our next release.

wilkinsona commented 3 years ago

Jetty 9.4.43, to which we'll upgrade in due course, will fix the QueuedThreadPool problem. It doesn't look like it will be released in time for tomorrow's Boot releases, but, rather than changing the timeout in one release and changing it back again in the next, we recommend that anyone affected by the problem temporarily configures the workaround described above.

Artur- commented 3 years ago

Jetty 9.4.43 is now out