apolloconfig / apollo-use-cases

Show various usage scenarios and sample codes of the Apollo configuration center, welcome to share more configuration use cases in your daily work!
Apache License 2.0
944 stars 401 forks source link

dynamic-datasource如果之前数据库连接错误,无法关闭,直至达到最大重试次数。 #19

Open coreyho opened 5 years ago

coreyho commented 5 years ago

如果出现数据库连接错误,比如url写错了,会实例化一个HikariDataSource(null),在重新配置新数据库设置后,将关闭上一个连接,进入terminateHikariDataSource()方法,执行poolMXBean.softEvictConnections()时抛会异常,致使不断循环直到达到最大重试次数,在terminate()方法中的if (dataSource instanceof HikariDataSource )添加一个非空检查可以避免不断重试。

nobodyiam commented 5 years ago

我理解你的意思,不过我本地貌似无法复现这个场景,你能提供一个可以复现的步骤吗?

  1. 如果启动时url就是错的,那启动就失败了
  2. 如果启动时是正常的,后续改错了,那么新的连接也不会成功,后续也不会terminate
coreyho commented 5 years ago

我的程序中ORM用的是Mybatis,在Apollo中配置错误的url,启动程序,会在建立mysql连接时报错,生成空的datasource,Mybatis生成空的sqlSessionFactory和sqlSessionTemplate,但程序不会停止,然后在Apollo中更改正确的配置,就出现了上述场景。

我试了下你提供的实例,启动错误的url,建立mysql连接时报错,会在hibernate处报错并退出。

nobodyiam commented 5 years ago

这个应该和mybatis没啥关系,和datasource的创建逻辑有关,如果连接失败的话,datasource应该创建失败,可以看下你这边空的datasource是怎么出现的?

soulmz commented 4 years ago

@nobodyiam @coreyho 我今天碰到了类似的问题。

日志如下

2020-08-11 14:48:09,985  INFO 33838 --- [)-192.168.10.11] com.zaxxer.hikari.HikariDataSource      [110] : HikariPool-1 - Starting...
2020-08-11 14:48:11,333 ERROR 33838 --- [)-192.168.10.11] com.zaxxer.hikari.pool.HikariPool       [593] : HikariPool-1 - Exception during pool initialization.

java.sql.SQLException: Access denied for user 'root'@'192.168.20.122' (using password: YES)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:965)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3976)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3912)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:871)
    at com.mysql.jdbc.MysqlIO.proceedHandshakeWithPluggableAuthentication(MysqlIO.java:1714)
    at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1224)
    at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2190)
    at com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2221)
    at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2016)
    at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:776)
    at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
    at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:386)
    at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:330)
    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138)
    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:358)
    at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206)
    at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:477)
    at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:560)
    at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:115)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:112)
    at com.example.config.apollo.datasource.DynamicDataSource.getConnection(DynamicDataSource.java:31)
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158)
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116)
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:324)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.getProduct(DataSourceHealthIndicator.java:122)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.doDataSourceHealthCheck(DataSourceHealthIndicator.java:105)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.doHealthCheck(DataSourceHealthIndicator.java:100)
    at org.springframework.boot.actuate.health.AbstractHealthIndicator.health(AbstractHealthIndicator.java:82)
    at org.springframework.boot.actuate.health.HealthIndicator.getHealth(HealthIndicator.java:37)
    at org.springframework.boot.actuate.health.HealthEndpoint.getHealth(HealthEndpoint.java:71)
    at org.springframework.boot.actuate.health.HealthEndpoint.getHealth(HealthEndpoint.java:39)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getContribution(HealthEndpointSupport.java:99)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getAggregateHealth(HealthEndpointSupport.java:110)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getContribution(HealthEndpointSupport.java:96)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getHealth(HealthEndpointSupport.java:74)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getHealth(HealthEndpointSupport.java:61)
    at org.springframework.boot.actuate.health.HealthEndpoint.health(HealthEndpoint.java:65)
    at org.springframework.boot.actuate.health.HealthEndpoint.health(HealthEndpoint.java:55)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:282)
    at org.springframework.boot.actuate.endpoint.invoke.reflect.ReflectiveOperationInvoker.invoke(ReflectiveOperationInvoker.java:77)
    at org.springframework.boot.actuate.endpoint.annotation.AbstractDiscoveredOperation.invoke(AbstractDiscoveredOperation.java:60)
    at org.springframework.boot.actuate.endpoint.jmx.EndpointMBean.invoke(EndpointMBean.java:121)
    at org.springframework.boot.actuate.endpoint.jmx.EndpointMBean.invoke(EndpointMBean.java:96)
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801)
    at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1468)
    at javax.management.remote.rmi.RMIConnectionImpl.access$300(RMIConnectionImpl.java:76)
    at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1309)
    at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1401)
    at javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:829)
    at sun.reflect.GeneratedMethodAccessor197.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357)
    at sun.rmi.transport.Transport$1.run(Transport.java:200)
    at sun.rmi.transport.Transport$1.run(Transport.java:197)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.Transport.serviceCall(Transport.java:196)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

2020-08-11 14:48:11,338  WARN 33838 --- [)-192.168.10.11] o.s.b.a.jdbc.DataSourceHealthIndicator  [87] : DataSource health check failed

org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLException: Access denied for user 'root'@'192.168.20.122' (using password: YES)
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:82)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:324)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.getProduct(DataSourceHealthIndicator.java:122)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.doDataSourceHealthCheck(DataSourceHealthIndicator.java:105)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.doHealthCheck(DataSourceHealthIndicator.java:100)
    at org.springframework.boot.actuate.health.AbstractHealthIndicator.health(AbstractHealthIndicator.java:82)
    at org.springframework.boot.actuate.health.HealthIndicator.getHealth(HealthIndicator.java:37)
    at org.springframework.boot.actuate.health.HealthEndpoint.getHealth(HealthEndpoint.java:71)
    at org.springframework.boot.actuate.health.HealthEndpoint.getHealth(HealthEndpoint.java:39)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getContribution(HealthEndpointSupport.java:99)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getAggregateHealth(HealthEndpointSupport.java:110)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getContribution(HealthEndpointSupport.java:96)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getHealth(HealthEndpointSupport.java:74)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getHealth(HealthEndpointSupport.java:61)
    at org.springframework.boot.actuate.health.HealthEndpoint.health(HealthEndpoint.java:65)
    at org.springframework.boot.actuate.health.HealthEndpoint.health(HealthEndpoint.java:55)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:282)
    at org.springframework.boot.actuate.endpoint.invoke.reflect.ReflectiveOperationInvoker.invoke(ReflectiveOperationInvoker.java:77)
    at org.springframework.boot.actuate.endpoint.annotation.AbstractDiscoveredOperation.invoke(AbstractDiscoveredOperation.java:60)
    at org.springframework.boot.actuate.endpoint.jmx.EndpointMBean.invoke(EndpointMBean.java:121)
    at org.springframework.boot.actuate.endpoint.jmx.EndpointMBean.invoke(EndpointMBean.java:96)
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801)
    at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1468)
    at javax.management.remote.rmi.RMIConnectionImpl.access$300(RMIConnectionImpl.java:76)
    at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1309)
    at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1401)
    at javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:829)
    at sun.reflect.GeneratedMethodAccessor197.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357)
    at sun.rmi.transport.Transport$1.run(Transport.java:200)
    at sun.rmi.transport.Transport$1.run(Transport.java:197)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.Transport.serviceCall(Transport.java:196)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.sql.SQLException: Access denied for user 'root'@'192.168.20.122' (using password: YES)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:965)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3976)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3912)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:871)
    at com.mysql.jdbc.MysqlIO.proceedHandshakeWithPluggableAuthentication(MysqlIO.java:1714)
    at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1224)
    at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2190)
    at com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2221)
    at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2016)
    at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:776)
    at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
    at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:386)
    at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:330)
    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138)
    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:358)
    at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206)
    at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:477)
    at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:560)
    at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:115)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:112)
    at com.example.config.apollo.datasource.DynamicDataSource.getConnection(DynamicDataSource.java:31)
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158)
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116)
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79)
    ... 47 common frames omitted

2020-08-11 14:48:59,600  INFO 33838 --- [Apollo-Config-2] c.d.c.a.datasource.DataSourceRefresher  [53] : Refreshing data source
2020-08-11 14:48:59,887  INFO 33838 --- [Apollo-Config-2] com.zaxxer.hikari.HikariDataSource      [110] : HikariPool-2 - Starting...
2020-08-11 14:49:00,140  INFO 33838 --- [Apollo-Config-2] com.zaxxer.hikari.HikariDataSource      [123] : HikariPool-2 - Start completed.
2020-08-11 14:49:00,150  INFO 33838 --- [Apollo-Config-2] c.d.c.a.datasource.DataSourceRefresher  [62] : Finished refreshing data source
2020-08-11 14:49:00,150  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:00,150  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:05,155  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:05,156  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:10,160  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:10,162  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:15,165  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:15,165  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:20,167  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:20,167  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:25,173  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:25,173  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:30,179  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:30,179  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:35,183  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:35,184  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:40,188  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:40,188  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:45,193  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:45,193  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:50,198  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:50,199  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:49:55,203  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:49:55,204  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null
2020-08-11 14:50:00,209  INFO 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [45] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 14:50:33,853  WARN 33838 --- [l-2 housekeeper] com.zaxxer.hikari.pool.HikariPool       [787] : HikariPool-2 - Thread starvation or clock leap detected (housekeeper delta=1m3s605ms).
2020-08-11 14:50:46,661  WARN 33838 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [53] : Terminating data source HikariDataSource (null) failed, will retry in 5000 ms, error message: null

重现步骤:

一开始 apollo 配置的 账户密码是错误的。无法正常建立MySQL连接。

后面 改成正确的正确密码,后发现旧数据源 poolMXBean is null 因没正确的建立连接池。 无法关闭。一直重试。

/**
     * 优雅的终止 HikariCP线程池
     *
     * @see <a href="https://github.com/brettwooldridge/HikariCP/issues/742">Support graceful shutdown of connection
     * pool</a>
     */
    private boolean terminateHikariDataSource(HikariDataSource dataSource) {
        HikariPoolMXBean poolMXBean = dataSource.getHikariPoolMXBean();
        // 增加判断
        if (Objects.isNull(poolMXBean)) {
            dataSource.close();
            return true;
        }
        //evict idle connections
        poolMXBean.softEvictConnections();
        if (poolMXBean.getActiveConnections() > 0 && retryTimes < MAX_RETRY_TIMES) {
            logger.warn("Data source {} still has {} active connections, will retry in {} ms.", dataSource,
                    poolMXBean.getActiveConnections(), RETRY_DELAY_IN_MILLISECONDS);
            return false;
        }
        if (poolMXBean.getActiveConnections() > 0) {
            logger.warn("Retry times({}) >= {}, force closing data source {}, with {} active connections!", retryTimes,
                    MAX_RETRY_TIMES, dataSource, poolMXBean.getActiveConnections());
        }
        dataSource.close();
        return true;
    }

增加 Objects.isNull(poolMXBean) 判断,空则直接关闭。

2020-08-11 15:00:21,330  INFO 41627 --- [on(2)-127.0.0.1] com.zaxxer.hikari.HikariDataSource      [110] : HikariPool-1 - Starting...
2020-08-11 15:00:22,697 ERROR 41627 --- [on(2)-127.0.0.1] com.zaxxer.hikari.pool.HikariPool       [593] : HikariPool-1 - Exception during pool initialization.

java.sql.SQLException: Access denied for user 'root'@'192.168.20.122' (using password: YES)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:965)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3976)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3912)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:871)
    at com.mysql.jdbc.MysqlIO.proceedHandshakeWithPluggableAuthentication(MysqlIO.java:1714)
    at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1224)
    at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2190)
    at com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2221)
    at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2016)
    at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:776)
    at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
    at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:386)
    at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:330)
    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138)
    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:358)
    at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206)
    at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:477)
    at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:560)
    at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:115)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:112)
    at com.example.config.apollo.datasource.DynamicDataSource.getConnection(DynamicDataSource.java:31)
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158)
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116)
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:324)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.getProduct(DataSourceHealthIndicator.java:122)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.doDataSourceHealthCheck(DataSourceHealthIndicator.java:105)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.doHealthCheck(DataSourceHealthIndicator.java:100)
    at org.springframework.boot.actuate.health.AbstractHealthIndicator.health(AbstractHealthIndicator.java:82)
    at org.springframework.boot.actuate.health.HealthIndicator.getHealth(HealthIndicator.java:37)
    at org.springframework.boot.actuate.health.HealthEndpoint.getHealth(HealthEndpoint.java:71)
    at org.springframework.boot.actuate.health.HealthEndpoint.getHealth(HealthEndpoint.java:39)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getContribution(HealthEndpointSupport.java:99)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getAggregateHealth(HealthEndpointSupport.java:110)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getContribution(HealthEndpointSupport.java:96)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getHealth(HealthEndpointSupport.java:74)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getHealth(HealthEndpointSupport.java:61)
    at org.springframework.boot.actuate.health.HealthEndpoint.health(HealthEndpoint.java:65)
    at org.springframework.boot.actuate.health.HealthEndpoint.health(HealthEndpoint.java:55)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:282)
    at org.springframework.boot.actuate.endpoint.invoke.reflect.ReflectiveOperationInvoker.invoke(ReflectiveOperationInvoker.java:77)
    at org.springframework.boot.actuate.endpoint.annotation.AbstractDiscoveredOperation.invoke(AbstractDiscoveredOperation.java:60)
    at org.springframework.boot.actuate.endpoint.jmx.EndpointMBean.invoke(EndpointMBean.java:121)
    at org.springframework.boot.actuate.endpoint.jmx.EndpointMBean.invoke(EndpointMBean.java:96)
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801)
    at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1468)
    at javax.management.remote.rmi.RMIConnectionImpl.access$300(RMIConnectionImpl.java:76)
    at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1309)
    at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1401)
    at javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:829)
    at sun.reflect.GeneratedMethodAccessor196.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357)
    at sun.rmi.transport.Transport$1.run(Transport.java:200)
    at sun.rmi.transport.Transport$1.run(Transport.java:197)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.Transport.serviceCall(Transport.java:196)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

2020-08-11 15:00:22,702  WARN 41627 --- [on(2)-127.0.0.1] o.s.b.a.jdbc.DataSourceHealthIndicator  [87] : DataSource health check failed

org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLException: Access denied for user 'root'@'192.168.20.122' (using password: YES)
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:82)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:324)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.getProduct(DataSourceHealthIndicator.java:122)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.doDataSourceHealthCheck(DataSourceHealthIndicator.java:105)
    at org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator.doHealthCheck(DataSourceHealthIndicator.java:100)
    at org.springframework.boot.actuate.health.AbstractHealthIndicator.health(AbstractHealthIndicator.java:82)
    at org.springframework.boot.actuate.health.HealthIndicator.getHealth(HealthIndicator.java:37)
    at org.springframework.boot.actuate.health.HealthEndpoint.getHealth(HealthEndpoint.java:71)
    at org.springframework.boot.actuate.health.HealthEndpoint.getHealth(HealthEndpoint.java:39)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getContribution(HealthEndpointSupport.java:99)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getAggregateHealth(HealthEndpointSupport.java:110)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getContribution(HealthEndpointSupport.java:96)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getHealth(HealthEndpointSupport.java:74)
    at org.springframework.boot.actuate.health.HealthEndpointSupport.getHealth(HealthEndpointSupport.java:61)
    at org.springframework.boot.actuate.health.HealthEndpoint.health(HealthEndpoint.java:65)
    at org.springframework.boot.actuate.health.HealthEndpoint.health(HealthEndpoint.java:55)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:282)
    at org.springframework.boot.actuate.endpoint.invoke.reflect.ReflectiveOperationInvoker.invoke(ReflectiveOperationInvoker.java:77)
    at org.springframework.boot.actuate.endpoint.annotation.AbstractDiscoveredOperation.invoke(AbstractDiscoveredOperation.java:60)
    at org.springframework.boot.actuate.endpoint.jmx.EndpointMBean.invoke(EndpointMBean.java:121)
    at org.springframework.boot.actuate.endpoint.jmx.EndpointMBean.invoke(EndpointMBean.java:96)
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801)
    at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1468)
    at javax.management.remote.rmi.RMIConnectionImpl.access$300(RMIConnectionImpl.java:76)
    at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1309)
    at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1401)
    at javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:829)
    at sun.reflect.GeneratedMethodAccessor196.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357)
    at sun.rmi.transport.Transport$1.run(Transport.java:200)
    at sun.rmi.transport.Transport$1.run(Transport.java:197)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.Transport.serviceCall(Transport.java:196)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.sql.SQLException: Access denied for user 'root'@'192.168.20.122' (using password: YES)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:965)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3976)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3912)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:871)
    at com.mysql.jdbc.MysqlIO.proceedHandshakeWithPluggableAuthentication(MysqlIO.java:1714)
    at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1224)
    at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2190)
    at com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2221)
    at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2016)
    at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:776)
    at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
    at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:386)
    at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:330)
    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138)
    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:358)
    at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206)
    at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:477)
    at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:560)
    at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:115)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:112)
    at com.example.config.apollo.datasource.DynamicDataSource.getConnection(DynamicDataSource.java:31)
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158)
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116)
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79)
    ... 47 common frames omitted

2020-08-11 15:00:31,712  INFO 41627 --- [Apollo-Config-2] c.d.c.a.datasource.DataSourceRefresher  [53] : Refreshing data source
2020-08-11 15:00:32,007  INFO 41627 --- [Apollo-Config-2] com.zaxxer.hikari.HikariDataSource      [110] : HikariPool-2 - Starting...
2020-08-11 15:00:32,277  INFO 41627 --- [Apollo-Config-2] com.zaxxer.hikari.HikariDataSource      [123] : HikariPool-2 - Start completed.
2020-08-11 15:00:32,302  INFO 41627 --- [Apollo-Config-2] c.d.c.a.datasource.DataSourceRefresher  [62] : Finished refreshing data source
2020-08-11 15:00:32,302  INFO 41627 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [46] : Trying to terminate data source: HikariDataSource (null)
2020-08-11 15:00:48,470  INFO 41627 --- [pool-5-thread-1] c.d.c.a.d.DataSourceTerminationTask     [39] : Data source HikariDataSource (null) terminated successfully!

这样正常的关闭了。

nobodyiam commented 4 years ago

@soulmz 多谢指出,https://github.com/ctripcorp/apollo-use-cases/commit/6735097aac0cfa1dd79f46f68792e8dfd61108dd