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);
                    }
                }
            }
        };
    }
}