DataSource logging in H2 console auto-configuration causes Hikari's threads to have the wrong thread context class loader

[masked-dancer]

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.

[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.