In Spring Boot v2.7.3, automatic configuration of H2's console leaves (on shutdown) dangling thread 'HikariPool-1 housekeeper', likely leading to a memory-leak, as seen here:
2022-09-15 02:59:17.947-Z INFO PTIF-1.0.0 13608 --- [on(3)-127.0.0.1] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
2022-09-15 02:59:25.907-Z INFO PTIF-1.0.0 13608 --- [on(5)-127.0.0.1] inMXBeanRegistrar$SpringApplicationAdmin : Application shutdown requested.
2022-09-15 02:59:25.910-Z INFO PTIF-1.0.0 13608 --- [on(5)-127.0.0.1] o.s.b.w.e.tomcat.GracefulShutdown : Commencing graceful shutdown. Waiting for active requests to complete
2022-09-15 02:59:26.160-Z INFO PTIF-1.0.0 13608 --- [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown : Graceful shutdown complete
2022-09-15 02:59:26.160-Z INFO PTIF-1.0.0 13608 --- [on(5)-127.0.0.1] o.apache.catalina.core.StandardService : Stopping service [Tomcat]
2022-09-15 02:59:26.175-Z INFO PTIF-1.0.0 13608 --- [on(5)-127.0.0.1] o.a.c.c.C.[Tomcat].[localhost].[/PTIF] : Destroying Spring FrameworkServlet 'dispatcherServlet'
2022-09-15 02:59:30.926-Z **_WARN PTIF-1.0.0 13608 --- [on(5)-127.0.0.1] o.a.c.loader.WebappClassLoaderBase : The web application [PTIF] appears to have started a thread named [HikariPool-1 housekeeper] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:_**
java.base@11/jdk.internal.misc.Unsafe.park(Native Method)
java.base@11/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
java.base@11/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
java.base@11/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
java.base@11/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
java.base@11/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
java.base@11/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
java.base@11/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
java.base@11/java.lang.Thread.run(Thread.java:834)
Datasource is left entirely to auto-configuration: H2 on classpath, and no specification of URL.
I've already done a fair bit of sleuthing, and am fairly confident (though not certain) that the cause is this: #28204, seemingly introduced in v2.6.11.
The relevant code is:
if (logger.isInfoEnabled()) {
logDataSources(dataSource, path);
}
Two clues:
1. Merely raising, through application.properties, the logging-level of the associated logger to 'WARN' (logging.level.org.springframework.boot.autoconfigure.h2=WARN) does away with the problem.
2. The code that was replaced predicates the call on the datasource being available (dataSource.ifAvailable()...); it seems that that may be missing from the substituting code.
Comment From: wilkinsona
Thanks for the report. Performing the logging during the creation of a ServletRegistrationBean means that Tomcat's web app class loader is the thread context class loader when Hikari's pool is initialized. This results in the pool's threads using Tomcat's web app class loader as their TCCL. Subsequently, this results in Tomcat logging a warning about the thread having been left running when, in fact, it will be stopped as part of the context being closed.
Regardless of Tomcat's logging, we don't want Hikari's pool's threads to be using Tomcat's web app class loader as their TCCL so we should perform the logging at a different time or with a different TCCL set.