Application Shutdown Hangs with graphql-spring-boot-starter

[andrewkcarter]

Describe the bug
A Spring Boot application doesn't shutdown cleanly with graphql-spring-boot-starter on the classpath. I've tested with Spring Boot 2.2.4 and 2.3.4, and graphql-spring-boot-starter 7.x and 8.0.0.

To Reproduce
Steps to reproduce the behavior:

1. Start a vanilla spring boot application.
2. The application runs but shuts down on it's own without anything to do.
3. Add graphql-spring-boot-starter to the dependencies.
4. Start the application, observe it remains running as expected.
5. Issue a SIGINT. The logs show the shutdown was initiated, but it never completes.

14:55:18.501 [SpringContextShutdownHook] INFO  o.s.s.c.ThreadPoolTaskExecutor - Shutting down ExecutorService 'applicationTaskExecutor'

6. Issue a SIGKILL to terminate the application.

Expected behavior
On a SIGINT, the application will complete a full clean shutdown.

Additional context
I've tried debugging to figure out what is being held open or blocked, but I have not been able to track it down.

[oliemansm]

We have a lot of products running using these libraries and none have this problem. Do you experience this with one of the sample projects of this library? Or one of your own projects?

[andrewkcarter]

Interesting. It's my own project, but literally nothing but the bare minimum Spring boot + this library. I'll spin up one of your samples and see what I can discover.

[andrewkcarter]

I was able to reproduce using the example project. I'm on the v8.0.0 tag.

andrew.carter@mbp graphql-spring-boot [(HEAD detached at v8.0.0)] $ cd example
andrew.carter@mbp example [(HEAD detached at v8.0.0)] $ ../gradlew clean bootjar
...
> Task :example:compileJava
Note: /Users/andrew.carter/data/workspace-ist/graphql-spring-boot/example/src/main/java/graphql/kickstart/spring/web/boot/sample/ApplicationBootConfiguration.java uses or overrides a deprecated API.
Note: Recompile with -Xlint:deprecation for details.

BUILD SUCCESSFUL in 2s
30 actionable tasks: 4 executed, 26 up-to-date
andrew.carter@mbp example [(HEAD detached at v8.0.0)] $ java -jar build/libs/example-8.0.0.jar

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.3.4.RELEASE)

2020-11-14 15:05:05.004  INFO 73670 --- [           main] g.k.s.w.b.s.ApplicationBootConfiguration : Starting ApplicationBootConfiguration on CartersMBP with PID 73670 (/Users/andrew.carter/data/workspace-ist/graphql-spring-boot/example/build/libs/example-8.0.0.jar started by andrew.carter in /Users/andrew.carter/data/workspace-ist/graphql-spring-boot/example)
2020-11-14 15:05:05.009  INFO 73670 --- [           main] g.k.s.w.b.s.ApplicationBootConfiguration : No active profile set, falling back to default profiles: default
2020-11-14 15:05:06.479  INFO 73670 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 9000 (http)
2020-11-14 15:05:06.488  INFO 73670 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-11-14 15:05:06.488  INFO 73670 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.38]
2020-11-14 15:05:06.575  INFO 73670 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-11-14 15:05:06.575  INFO 73670 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1514 ms
2020-11-14 15:05:06.828  INFO 73670 --- [           main] g.k.s.w.b.GraphQLWebAutoConfiguration    : Building GraphQLObjectMapper including errorHandler: null
2020-11-14 15:05:07.066  INFO 73670 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-11-14 15:05:07.539  INFO 73670 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 3 endpoint(s) beneath base path '/actuator'
2020-11-14 15:05:07.602  INFO 73670 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 9000 (http) with context path ''
2020-11-14 15:05:07.612  INFO 73670 --- [           main] g.k.s.w.b.s.ApplicationBootConfiguration : Started ApplicationBootConfiguration in 3.095 seconds (JVM running for 3.472)
^C2020-11-14 15:05:11.366  INFO 73670 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
^C

After the application is running, I issue a CTRL-C from the terminal and the Shutting down ExecutorService 'applicationTaskExecutor' messages is logged, but the application never exits. I must find the PID and send a kill -9 to terminate it. I have the same experience running this example, and my application, from within an IDE.

[andrewkcarter]

In case this matters...

andrew.carter@mbp example [(HEAD detached at v8.0.0)] $ java --version
openjdk 11.0.8 2020-07-14
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.8+10)
Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.21.0, JRE 11 Mac OS X amd64-64-Bit Compressed References 20200715_677 (JIT enabled, AOT enabled)
OpenJ9   - 34cf4c075
OMR      - 113e54219
JCL      - 95bb504fbb based on jdk-11.0.8+10)

[oliemansm]

I just followed the same steps on the same example project. I'm on Java 14 and using Fedora, but even so... It's working as expected for me.

[michieloliemans@scopisto-oliemans example]$ java -jar build/libs/example-8.1.0-SNAPSHOT.jar 

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.3.4.RELEASE)

2020-11-18 15:20:36.169  INFO 518825 --- [           main] g.k.s.w.b.s.ApplicationBootConfiguration : Starting ApplicationBootConfiguration on scopisto-oliemans with PID 518825 (/home/michieloliemans/IdeaProjects/GraphQL/graphql-spring-boot/example/build/libs/example-8.1.0-SNAPSHOT.jar started by michieloliemans in /home/michieloliemans/IdeaProjects/GraphQL/graphql-spring-boot/example)
2020-11-18 15:20:36.172  INFO 518825 --- [           main] g.k.s.w.b.s.ApplicationBootConfiguration : No active profile set, falling back to default profiles: default
2020-11-18 15:20:37.171  INFO 518825 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 9000 (http)
2020-11-18 15:20:37.179  INFO 518825 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-11-18 15:20:37.179  INFO 518825 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.38]
2020-11-18 15:20:37.223  INFO 518825 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-11-18 15:20:37.223  INFO 518825 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1007 ms
2020-11-18 15:20:37.529  INFO 518825 --- [           main] g.k.s.w.b.GraphQLWebAutoConfiguration    : Building GraphQLObjectMapper including errorHandler: null
2020-11-18 15:20:37.733  INFO 518825 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-11-18 15:20:38.170  INFO 518825 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 3 endpoint(s) beneath base path '/actuator'
2020-11-18 15:20:38.217  INFO 518825 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 9000 (http) with context path ''
2020-11-18 15:20:38.235  INFO 518825 --- [           main] g.k.s.w.b.s.ApplicationBootConfiguration : Started ApplicationBootConfiguration in 2.49 seconds (JVM running for 2.849)
^C2020-11-18 15:20:41.949  INFO 518825 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
[michieloliemans@scopisto-oliemans example]$

Java version:

[michieloliemans@scopisto-oliemans example]$ java --version
java 14 2020-03-17
Java(TM) SE Runtime Environment (build 14+36-1461)
Java HotSpot(TM) 64-Bit Server VM (build 14+36-1461, mixed mode, sharing)
[michieloliemans@scopisto-oliemans example]$

You seem to be on MacOS and using a different JDK vendor. Perhaps try another JDK vendor to see if that helps?

[andrewkcarter]

Sounds good. Thanks @oliemansm. I'll let you know what I find out.

[oliemansm]

I've converted it into a discussion since it's specific to your case atm and we haven't identified a clear reproducible bug (yet).

[andrewkcarter]

Just to close the loop on this one, I finally updated the JDK I was using to 11.0.10 (Eclipse OpenJ9 openj9-0.24.0) and the shutdown problem is no longer present. It was definitely related to the particular JVM.

[oliemansm]

Thanks for reporting what solved it for you in the end!