HikariPool gets re-initialized on Spring Boot shutdown and fails test query

[DarekDan]

I have created a multimodule Spring Boot, where the interaction with database is separated from the container. I am using Guice to inject a DataSource created in the container into the service module. The Hikari Pool is initialized in the InitializingBeen like so:

package com.fiserv.startup.initializers;

import com.google.inject.AbstractModule;
import com.google.inject.Guice;
import com.google.inject.Injector;
import com.zaxxer.hikari.HikariConfig;
import com.zaxxer.hikari.HikariDataSource;
import javax.sql.DataSource;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.InitializingBean;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.context.annotation.Bean;
import org.springframework.jdbc.core.JdbcTemplate;
import org.springframework.stereotype.Component;

@Component
public class ModulesInitializer implements InitializingBean {

    private static Logger log = LoggerFactory.getLogger(ModulesInitializer.class);

    @Value("${spring.datasource.hikari.jdbc-url}")
    private String jdbcUrl;

    @Value("${spring.datasource.hikari.connection-init-sql}")
    private String initCommand;

    private static Injector injector;

    private static DataSource hikari;

    @Bean
    public Injector injector() {
        return injector;
    }

    @Override
    public void afterPropertiesSet() {
        log.info(">>> afterPropertiesSet <<<");
        initializeHikariPool();
        injector = Guice.createInjector(new AbstractModule() {
            @Override
            protected void configure() {
                bind(DataSource.class).toInstance(hikari);
                bind(JdbcTemplate.class).toProvider(() -> new JdbcTemplate(hikari));
            }
        });
    }

    synchronized void initializeHikariPool() {
        log.info(">>> initializeHikariPool");
        if (hikari == null) {
            log.info(">>> initializeHikariPool >>> hikari was null");
            HikariConfig config = new HikariConfig();
            config.setJdbcUrl(jdbcUrl);
            config.setConnectionInitSql(initCommand);
            config.validate();
            hikari = new HikariDataSource(config);
        }
    }
}

I am using H2 in-memory database with DB2 compatibility mode:

spring.datasource.hikari.jdbc-url=jdbc:h2:mem:
spring.datasource.hikari.connection-init-sql=SET MODE DB2
spring.datasource.hikari.connection-test-query=SELECT CURRENT_TIMESTAMP FROM SYSIBM.SYSDUMMY1

I can confirm that the SELECT query runs just fine inside the service module.

package com.fiserv.services;

import com.google.inject.Inject;
import com.google.inject.Singleton;
import java.sql.Timestamp;
import java.util.Optional;
import javax.sql.DataSource;
import org.springframework.jdbc.core.JdbcTemplate;

@Singleton
class DatabaseServiceImplementation implements com.fiserv.services.DatabaseService {

    public static final String SELECT_CURRENT_TIMESTAMP = "SELECT CURRENT_TIMESTAMP FROM SYSIBM.SYSDUMMY1";

    @Inject
    DataSource dataSource;

    @Inject
    private JdbcTemplate template;

    @Override
    public Optional<Timestamp> getDatabaseTimestamp() {
        Timestamp timestamp = template.queryForObject(SELECT_CURRENT_TIMESTAMP, Timestamp.class);
        return Optional.ofNullable(timestamp);
    }
}

When the Spring Boot application is being shutdown, I am getting a new pool initialized, for reasons unknown, and it seems that the session initialization statement is being ignored because I get an error:

2021-03-03 08:24:48.721  INFO 58675 --- [  restartedMain] c.f.s.MultiModuleStartupApplication      : Starting MultiModuleStartupApplication using Java 11.0.10 on ML-C02YG0TWJGH6 with PID 58675 (/Users/fbg9jma/Scratch/MultiModuleLearning/multi-module-startup/target/classes started by fbg9jma in /Users/fbg9jma/Scratch/MultiModuleLearning)
2021-03-03 08:24:48.723  INFO 58675 --- [  restartedMain] c.f.s.MultiModuleStartupApplication      : The following profiles are active: mem
2021-03-03 08:24:48.778  INFO 58675 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
2021-03-03 08:24:48.778  INFO 58675 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : For additional web related logging consider setting the 'logging.level.web' property to 'DEBUG'
2021-03-03 08:24:49.739  INFO 58675 --- [  restartedMain] c.f.s.initializers.ModulesInitializer    : >>> afterPropertiesSet <<<
2021-03-03 08:24:49.740  INFO 58675 --- [  restartedMain] c.f.s.initializers.ModulesInitializer    : >>> initializeHikariPool
2021-03-03 08:24:49.740  INFO 58675 --- [  restartedMain] c.f.s.initializers.ModulesInitializer    : >>> initializeHikariPool >>> hikari was null
2021-03-03 08:24:49.744  INFO 58675 --- [  restartedMain] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2021-03-03 08:24:49.868  INFO 58675 --- [  restartedMain] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2021-03-03 08:24:50.042  INFO 58675 --- [  restartedMain] c.f.s.c.DatabaseStatsController          : Using com.fiserv.services.DatabaseServiceImplementation
2021-03-03 08:24:50.425  INFO 58675 --- [  restartedMain] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 2 endpoint(s) beneath base path '/actuator'
2021-03-03 08:24:50.589  INFO 58675 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2021-03-03 08:24:50.693  INFO 58675 --- [  restartedMain] o.s.b.web.embedded.netty.NettyWebServer  : Netty started on port 8080
2021-03-03 08:24:50.710  INFO 58675 --- [  restartedMain] c.f.s.MultiModuleStartupApplication      : Started MultiModuleStartupApplication in 2.295 seconds (JVM running for 2.938)
2021-03-03 08:41:58.429  INFO 58675 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-2 - Starting...
2021-03-03 08:41:58.434 ERROR 58675 --- [extShutdownHook] com.zaxxer.hikari.pool.PoolBase          : HikariPool-2 - Failed to execute connection test query (Schema "SYSIBM" not found; SQL statement:
SELECT CURRENT_TIMESTAMP FROM SYSIBM.SYSDUMMY1 [90079-200]).
2021-03-03 08:41:58.437 ERROR 58675 --- [extShutdownHook] com.zaxxer.hikari.pool.HikariPool        : HikariPool-2 - Error thrown while acquiring connection from data source

org.h2.jdbc.JdbcSQLSyntaxErrorException: Schema "SYSIBM" not found; SQL statement:
SELECT CURRENT_TIMESTAMP FROM SYSIBM.SYSDUMMY1 [90079-200]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:576) ~[h2-1.4.200.jar:1.4.200]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:429) ~[h2-1.4.200.jar:1.4.200]

Is this a newly discovered "undocumented feature" or a user error?

[wilkinsona]

It's not clear to me exactly what's happening from the information you've shared thus far. You don't seem to have defined the DataSource that you're creating as a bean so Spring Boot may be auto-configuring a DataSource for you.

It would appear that something is attempting to use Hikari when the application context is being closed by the shutdown hook. You could identify what that is by using the debugger with a breakpoint in HikariDataSource where it logs the "Starting..." message. Alternatively, if you would like us to spend some more time investigating, please spend some time providing a complete yet minimal sample that reproduces the problem. You can share it with us by pushing it to a separate repository on GitHub or by zipping it up and attaching it to this issue.

[spring-projects-issues]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

[DarekDan]

Apologies. It was a user error. I had a really weird way of setting the DataSource configuration. It's all good. Closing as false positive.