Managed JDBC driver is not deregistered on context shutdown

[peterboni]

Hi,

I created a new Spring Starter Project in STS (3.6.3.SR1 for Mac) with no code changes and ...

pom.xml

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>org.test</groupId>
    <artifactId>demo</artifactId>
    <version>0.0.1-SNAPSHOT</version>
    <packaging>war</packaging>

    <name>demo</name>
    <description>Demo project for Spring Boot</description>

    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>1.2.2.RELEASE</version>
        <relativePath/> <!-- lookup parent from repository -->
    </parent>

    <properties>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <start-class>demo.DemoApplication</start-class>
        <java.version>1.8</java.version>
    </properties>

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-security</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-data-jpa</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-jdbc</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-tomcat</artifactId>
            <scope>provided</scope>
        </dependency>

        <dependency>
            <groupId>mysql</groupId>
            <artifactId>mysql-connector-java</artifactId>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>

</project>

application.properties

spring.datasource.driverClassName=com.mysql.jdbc.Driver
spring.datasource.url=jdbc:mysql://localhost:3306/test
spring.datasource.username=test
spring.datasource.password=test

Tomcat Web Application Manager: 'Reload' button

catalina.out

07-Mar-2015 05:42:27.043 INFO [ajp-nio-8009-exec-14] org.apache.catalina.core.StandardContext.reload Reloading Context with name [/demo] has started
2015-03-07 05:42:27.045  INFO 18046 --- [io-8009-exec-14] ationConfigEmbeddedWebApplicationContext : Closing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@2775c3b4: startup date [Sat Mar 07 05:41:41 GMT 2015]; root of context hierarchy
2015-03-07 05:42:27.047  INFO 18046 --- [io-8009-exec-14] o.s.j.e.a.AnnotationMBeanExporter        : Unregistering JMX-exposed beans on shutdown
2015-03-07 05:42:27.049  INFO 18046 --- [io-8009-exec-14] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
07-Mar-2015 05:42:27.058 WARNING [ajp-nio-8009-exec-14] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [/demo] registered the JDBC driver [com.mysql.jdbc.Driver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
07-Mar-2015 05:42:27.060 WARNING [ajp-nio-8009-exec-14] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [/demo] appears to have started a thread named [Abandoned connection cleanup thread] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Object.wait(Native Method)
 java.lang.ref.ReferenceQueue.remove(Unknown Source)
 com.mysql.jdbc.AbandonedConnectionCleanupThread.run(AbandonedConnectionCleanupThread.java:43)

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

2015-03-07 05:42:28.611  INFO 18046 --- [io-8009-exec-14] o.s.boot.SpringApplication               : Starting application on au005060 with PID 18046 (/opt/apache-tomcat-8.0.14/webapps/demo/WEB-INF/lib/spring-boot-1.2.2.RELEASE.jar started by root in /)
2015-03-07 05:42:28.687  INFO 18046 --- [io-8009-exec-14] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@f423998: startup date [Sat Mar 07 05:42:28 GMT 2015]; root of context hierarchy
2015-03-07 05:42:29.462  INFO 18046 --- [io-8009-exec-14] o.s.b.f.s.DefaultListableBeanFactory     : Overriding bean definition for bean 'beanNameViewResolver': replacing [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=org.springframework.boot.autoconfigure.web.ErrorMvcAutoConfiguration$WhitelabelErrorViewConfiguration; factoryMethodName=beanNameViewResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [org/springframework/boot/autoconfigure/web/ErrorMvcAutoConfiguration$WhitelabelErrorViewConfiguration.class]] with [Root bean: class [null]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=org.springframework.boot.autoconfigure.web.WebMvcAutoConfiguration$WebMvcAutoConfigurationAdapter; factoryMethodName=beanNameViewResolver; initMethodName=null; destroyMethodName=(inferred); defined in class path resource [org/springframework/boot/autoconfigure/web/WebMvcAutoConfiguration$WebMvcAutoConfigurationAdapter.class]]
2015-03-07 05:42:30.295  INFO 18046 --- [io-8009-exec-14] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [class org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$f37a67e] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2015-03-07 05:42:30.330  INFO 18046 --- [io-8009-exec-14] trationDelegate$BeanPostProcessorChecker : Bean 'transactionAttributeSource' of type [class org.springframework.transaction.annotation.AnnotationTransactionAttributeSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2015-03-07 05:42:30.343  INFO 18046 --- [io-8009-exec-14] trationDelegate$BeanPostProcessorChecker : Bean 'transactionInterceptor' of type [class org.springframework.transaction.interceptor.TransactionInterceptor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2015-03-07 05:42:30.350  INFO 18046 --- [io-8009-exec-14] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.config.internalTransactionAdvisor' of type [class org.springframework.transaction.interceptor.BeanFactoryTransactionAttributeSourceAdvisor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2015-03-07 05:42:30.372  INFO 18046 --- [io-8009-exec-14] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 1685 ms
2015-03-07 05:42:31.875  INFO 18046 --- [io-8009-exec-14] b.a.s.AuthenticationManagerConfiguration : 

Using default security password: 6c955ae4-dd3b-41e4-ab0b-2077b00a1253

2015-03-07 05:42:31.952  INFO 18046 --- [io-8009-exec-14] o.s.s.web.DefaultSecurityFilterChain     : Creating filter chain: Ant [pattern='/css/**'], []
2015-03-07 05:42:31.952  INFO 18046 --- [io-8009-exec-14] o.s.s.web.DefaultSecurityFilterChain     : Creating filter chain: Ant [pattern='/js/**'], []
2015-03-07 05:42:31.952  INFO 18046 --- [io-8009-exec-14] o.s.s.web.DefaultSecurityFilterChain     : Creating filter chain: Ant [pattern='/images/**'], []
2015-03-07 05:42:31.953  INFO 18046 --- [io-8009-exec-14] o.s.s.web.DefaultSecurityFilterChain     : Creating filter chain: Ant [pattern='/**/favicon.ico'], []
2015-03-07 05:42:31.953  INFO 18046 --- [io-8009-exec-14] o.s.s.web.DefaultSecurityFilterChain     : Creating filter chain: Ant [pattern='/error'], []
2015-03-07 05:42:32.003  INFO 18046 --- [io-8009-exec-14] o.s.s.web.DefaultSecurityFilterChain     : Creating filter chain: OrRequestMatcher [requestMatchers=[Ant [pattern='/**']]], [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@478918e6, org.springframework.security.web.context.SecurityContextPersistenceFilter@4d233316, org.springframework.security.web.header.HeaderWriterFilter@5368ca35, org.springframework.security.web.authentication.logout.LogoutFilter@7ae91079, org.springframework.security.web.authentication.www.BasicAuthenticationFilter@4a40ebc9, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@455d38c6, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@4a987a0, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@606bbef1, org.springframework.security.web.session.SessionManagementFilter@2546be26, org.springframework.security.web.access.ExceptionTranslationFilter@669a01b0, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@2194b041]
2015-03-07 05:42:32.076  INFO 18046 --- [io-8009-exec-14] b.a.w.TomcatWebSocketContainerCustomizer : NonEmbeddedServletContainerFactory detected. Websockets support should be native so this normally is not a problem.
2015-03-07 05:42:32.134  INFO 18046 --- [io-8009-exec-14] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'errorPageFilter' to: [/*]
2015-03-07 05:42:32.134  INFO 18046 --- [io-8009-exec-14] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'characterEncodingFilter' to: [/*]
2015-03-07 05:42:32.135  INFO 18046 --- [io-8009-exec-14] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'springSecurityFilterChain' to: [/*]
2015-03-07 05:42:32.135  INFO 18046 --- [io-8009-exec-14] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2015-03-07 05:42:32.135  INFO 18046 --- [io-8009-exec-14] o.s.b.c.e.ServletRegistrationBean        : Mapping servlet: 'dispatcherServlet' to [/]
2015-03-07 05:42:33.209  INFO 18046 --- [io-8009-exec-14] j.LocalContainerEntityManagerFactoryBean : Building JPA container EntityManagerFactory for persistence unit 'default'
2015-03-07 05:42:33.228  INFO 18046 --- [io-8009-exec-14] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [
    name: default
    ...]
2015-03-07 05:42:33.402  INFO 18046 --- [io-8009-exec-14] org.hibernate.Version                    : HHH000412: Hibernate Core {4.3.8.Final}
2015-03-07 05:42:33.431  INFO 18046 --- [io-8009-exec-14] org.hibernate.cfg.Environment            : HHH000206: hibernate.properties not found
2015-03-07 05:42:33.465  INFO 18046 --- [io-8009-exec-14] org.hibernate.cfg.Environment            : HHH000021: Bytecode provider name : javassist
2015-03-07 05:42:33.788  INFO 18046 --- [io-8009-exec-14] o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {4.0.5.Final}
2015-03-07 05:42:33.922  INFO 18046 --- [io-8009-exec-14] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.MySQL5Dialect
2015-03-07 05:42:34.035  INFO 18046 --- [io-8009-exec-14] o.h.h.i.ast.ASTQueryTranslatorFactory    : HHH000397: Using ASTQueryTranslatorFactory
2015-03-07 05:42:34.580  INFO 18046 --- [io-8009-exec-14] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@f423998: startup date [Sat Mar 07 05:42:28 GMT 2015]; root of context hierarchy
2015-03-07 05:42:34.701  INFO 18046 --- [io-8009-exec-14] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],methods=[],params=[],headers=[],consumes=[],produces=[text/html],custom=[]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest)
2015-03-07 05:42:34.702  INFO 18046 --- [io-8009-exec-14] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],methods=[],params=[],headers=[],consumes=[],produces=[],custom=[]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2015-03-07 05:42:34.769  INFO 18046 --- [io-8009-exec-14] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2015-03-07 05:42:34.769  INFO 18046 --- [io-8009-exec-14] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2015-03-07 05:42:34.818  INFO 18046 --- [io-8009-exec-14] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2015-03-07 05:42:35.176  INFO 18046 --- [io-8009-exec-14] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2015-03-07 05:42:35.199  INFO 18046 --- [io-8009-exec-14] o.s.boot.SpringApplication               : Started application in 6.9 seconds (JVM running for 531.623)
07-Mar-2015 05:42:35.209 INFO [ajp-nio-8009-exec-14] org.apache.catalina.core.StandardContext.reload Reloading Context with name [/demo] is completed

Tomcat Web Application Manager - Diagnostics - 'Find leaks' button

The following web applications were stopped (reloaded, undeployed), but their
classes from previous runs are still loaded in memory, thus causing a memory
leak (use a profiler to confirm):
/demo

[snicoll]

Interesting. We could deregister the driver on context shutdown since we know about it through configuration.

See also this thread

[peterboni]

@snicoll thanks for the link. Tried this ...

DemoApplication.java

package demo;

import java.sql.Driver;
import java.sql.DriverManager;
import java.sql.SQLException;
import java.util.Enumeration;

import javax.servlet.ServletContextEvent;
import javax.servlet.ServletContextListener;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.Bean;

@SpringBootApplication
public class DemoApplication {

    public static void main(String[] args) {
        SpringApplication.run(DemoApplication.class, args);
    }

    @Bean
    protected ServletContextListener listener() {
        return new ServletContextListener() {
            @Override
            public void contextInitialized(ServletContextEvent sce) {
            }

            @Override
            public final void contextDestroyed(ServletContextEvent sce) {
                // ... First close any background tasks which may be using the DB ...
                // ... Then close any DB connection pools ...

                // Now deregister JDBC drivers in this context's ClassLoader:
                // Get the webapp's ClassLoader
                ClassLoader cl = Thread.currentThread().getContextClassLoader();
                // Loop through all drivers
                Enumeration<Driver> drivers = DriverManager.getDrivers();
                while (drivers.hasMoreElements()) {
                    Driver driver = drivers.nextElement();
                    if (driver.getClass().getClassLoader() == cl) {
                        // This driver was registered by the webapp's ClassLoader, so deregister it:
                        try {
                            System.out.println("Deregistering JDBC driver {}" + driver);
                            DriverManager.deregisterDriver(driver);
                        } catch (SQLException ex) {
                            System.out.println("Error deregistering JDBC driver {}" + ex);
                        }
                    } else {
                        // driver was not registered by the webapp's ClassLoader and may be in use elsewhere
                        System.out.println("Not deregistering JDBC driver {} as it does not belong to this webapp's ClassLoader" + driver);
                    }
                }
            }
        };
    }
}

Still causes leak ...

07-Mar-2015 07:19:04.402 INFO [ajp-nio-8009-exec-8] org.apache.catalina.core.StandardContext.reload Reloading Context with name [/demo] has started
2015-03-07 07:19:04.406  INFO 19323 --- [nio-8009-exec-8] ationConfigEmbeddedWebApplicationContext : Closing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@7ec3e600: startup date [Sat Mar 07 07:18:47 GMT 2015]; root of context hierarchy
2015-03-07 07:19:04.414  INFO 19323 --- [nio-8009-exec-8] o.s.j.e.a.AnnotationMBeanExporter        : Unregistering JMX-exposed beans on shutdown
2015-03-07 07:19:04.424  INFO 19323 --- [nio-8009-exec-8] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
Deregistering JDBC driver {}com.mysql.jdbc.Driver@1495a5ca
07-Mar-2015 07:19:04.463 WARNING [ajp-nio-8009-exec-8] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [/demo] appears to have started a thread named [Abandoned connection cleanup thread] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Object.wait(Native Method)
 java.lang.ref.ReferenceQueue.remove(Unknown Source)
 com.mysql.jdbc.AbandonedConnectionCleanupThread.run(AbandonedConnectionCleanupThread.java:43)

[peterboni]

@snicoll Calling the MySQL AbandonedConnectionCleanupThread shutdown() before deregistering the JDBC drivers seems to work...

package demo;

import java.sql.Driver;
import java.sql.DriverManager;
import java.sql.SQLException;
import java.util.Enumeration;

import javax.servlet.ServletContextEvent;
import javax.servlet.ServletContextListener;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.Bean;

@SpringBootApplication
public class DemoApplication {

    private final Logger log = LoggerFactory.getLogger(DemoApplication.class);

    public static void main(String[] args) {
        SpringApplication.run(DemoApplication.class, args);
    }

    @Bean
    protected ServletContextListener listener() {

        return new ServletContextListener() {

            @Override
            public void contextInitialized(ServletContextEvent sce) {
                log.info("Initialising Context...");
            }

            @Override
            public final void contextDestroyed(ServletContextEvent sce) {

                log.info("Destroying Context...");

                try {
                    log.info("Calling MySQL AbandonedConnectionCleanupThread shutdown");
                    com.mysql.jdbc.AbandonedConnectionCleanupThread.shutdown();

                } catch (InterruptedException e) {
                    log.error("Error calling MySQL AbandonedConnectionCleanupThread shutdown {}", e);
                }

                ClassLoader cl = Thread.currentThread().getContextClassLoader();

                Enumeration<Driver> drivers = DriverManager.getDrivers();
                while (drivers.hasMoreElements()) {
                    Driver driver = drivers.nextElement();

                    if (driver.getClass().getClassLoader() == cl) {

                        try {
                            log.info("Deregistering JDBC driver {}", driver);
                            DriverManager.deregisterDriver(driver);

                        } catch (SQLException ex) {
                            log.error("Error deregistering JDBC driver {}", driver, ex);
                        }

                    } else {
                        log.trace("Not deregistering JDBC driver {} as it does not belong to this webapp's ClassLoader", driver);
                    }
                }
            }
        };
    }
}

[ZaytsevMM]

Thanks, helped me

[sis-yoshiday]

Latest MySQL Connector seems to be fixed this problem.
https://dev.mysql.com/doc/relnotes/connector-j/5.1/en/news-5-1-41.html

I notice it after updating spring-boot 1.5.2.RELEASE
(mysql-connector version also update from 5.1.40 to 5.1.41)

[wilkinsona]

That's good news. Thanks, @sis-yoshiday. That makes this a duplicate of #8447 and it was fixed by d7a1244.

[marcelstoer]

The problem with this approach (forcefully deregistering in context listener) is that some drivers maintain an internal registration state. That means that while the driver is then removed from the DriverManager by the listener its internal state thinks it's still registered. This in turn means it will fail to reregister upon reload. Ouch!

H2 and PostgreSQL are two drivers which behave like that (links point to relevant source line). MySQL and MariaDB drivers don't show such behavior. They leave managing the registration state solely to the DriverManager.

[wilkinsona]

@marcelstoer There was no approach taken for this issue. It was closed as a duplicate of #8447 which simply upgraded the MySQL driver version.

[marcelstoer]

I know, it was meant as a comment for @peterboni et.al. who use or used to use a listener to work around shortcomings.

[ixtli]

... PostgreSQL are two drivers which behave like that (links point to relevant source line). MySQL and MariaDB drivers don't show such behavior. They leave managing the registration state solely to the DriverManager.

I just found this comment while trying to debug a warning tomcat9 gives you about PGSimpleDataSource not being unregistered when the context is destroyed. However, it's not clear from the link whether or not the source has changed since this comment was made! It looks as though deregister() has been included specifically to conform with the intent of the standard.

[BenICE]

I would like to relive this thread...what is the reason why Spring Boot does not unregister the JDBC drivers that are used? Sure I can do it myself (more or less with the code provided here) or let tomcat take care of it, but I cannot really see the reason.
If spring boot registers something, it should deregister it, shouldn't it?

Especially if you run in application servers without memory leak protection, it is quite a hassle to find out, what causes the memory leak as I was convinced Spring Boot would never on purpose leave something around.

Let me know your thoughts on it

[wilkinsona]

@BenICE This issue was tracking a problem that was caused by the MySQL driver. That problem was fixed in the MySQL driver itself so there was nothing for Spring Boot to do. If you believe that you have found a scenario where Spring Boot should be doing something, please open a new issue with a detailed description of that situation and a small sample project that reproduces it.