brettwooldridge / HikariCP

光 HikariCP・A solid, high-performance, JDBC connection pool at last.
Apache License 2.0
20.02k stars 2.94k forks source link

Connection com.mysql.cj.jdbc.ConnectionImpl marked as broken because of SQLSTATE(08S01), ErrorCode(0) => Communications link failure #2117

Open JWebDev opened 1 year ago

JWebDev commented 1 year ago

Hi,

Help me to understand and solve this error. I've been trying to figure out different options for days/weeks now. I probably read everything that is on the Internet and tried all kinds of options and combinations. HikariCP refuses to work as expected.

So, I have HikariCP-5.0.1 and MySQL 8.1

Pods are located in Kubernetes in various namespaces. There are no proxies, firewalls or service meshes between them. I run a task that runs 20-30 minutes. That is, at startup there is a connection to the database, then the logic works, and then I need to save the results in the database. It's simple case.

In the debug output I can see that Hikari pings the database every 30 seconds and says that everything is ok.

06:35:52.890 [HikariPool-1 housekeeper] DEBUG [       com.zaxxer.hikari.pool.HikariPool:414.logPoolState()] - HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0) 
06:35:52.890 [HikariPool-1 housekeeper] DEBUG [       com.zaxxer.hikari.pool.HikariPool:521.fillPool()] - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth=0). 

Here are the HIkariCP settings in Spring Autoconfiguration:

spring.datasource.hikari.jdbc-url=jdbc:mysql://mysql.mysql:3306/dev
spring.datasource.type=com.zaxxer.hikari.HikariDataSource
spring.datasource.hikari.username=${DB_USER}
spring.datasource.hikari.password=${DB_PASSWORD}
spring.datasource.hikari.driver-class-name=com.mysql.cj.jdbc.Driver
spring.datasource.hikari.data-source-properties.maxAllowedPacket=534773760
spring.datasource.hikari.data-source-properties.allowPublicKeyRetrieval=YES
spring.datasource.hikari.data-source-properties.useSSL=NO
spring.datasource.hikari.connection-test-query=SELECT 1

#This is my experiments, which i set in different combinations and values. Но данный пример я описываю со значениями, которые активны. Здесь только закомментированный пример.
#To hold connection
#spring.datasource.hikari.max-lifetime=120000
#spring.datasource.hikari.validation-timeout=864000000
#spring.datasource.hikari.data-source-properties.autoReconnect=true
#Keep connection for 10 days
#spring.datasource.hikari.keepalive-time=864000000
#spring.datasource.hikari.idle-timeout=864000000
#spring.datasource.hikari.validation-timeout=864000000

Here are the HikariCP settings in debug mode:

06:33:21.946 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:968.attemptFromContextLoader()] - Driver class org.hsqldb.jdbc.JDBCDriver found in Thread context class loader org.springframework.boot.loader.LaunchedURLClassLoader@7291c18f 
06:33:21.961 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:968.attemptFromContextLoader()] - Driver class com.mysql.cj.jdbc.Driver found in Thread context class loader org.springframework.boot.loader.LaunchedURLClassLoader@7291c18f 
06:33:22.070 [main] INFO  [rg.hibernate.jpa.internal.util.LogHelper:31.logPersistenceUnitInformation()] - HHH000204: Processing PersistenceUnitInfo [name: default] 
Waiting for starting Guardius Owasp Worker Agent...
06:33:22.132 [main] INFO  [                   org.hibernate.Version:44.logVersion()] - HHH000412: Hibernate ORM core version 6.1.5.Final 
06:33:22.491 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1100.logConfiguration()] - HikariPool-1 - configuration: 
06:33:22.493 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - allowPoolSuspension.............false 
06:33:22.493 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - autoCommit......................true 
06:33:22.493 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - catalog.........................none 
06:33:22.493 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - connectionInitSql...............none 
06:33:22.494 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - connectionTestQuery............."SELECT 1" 
06:33:22.494 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - connectionTimeout...............30000 
06:33:22.494 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - dataSource......................none 
06:33:22.494 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - dataSourceClassName.............none 
06:33:22.495 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - dataSourceJNDI..................none 
06:33:22.495 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - dataSourceProperties............{maxAllowedPacket=534773760, password=<masked>, allowPublicKeyRetrieval=YES, useSSL=NO} 
06:33:22.495 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - driverClassName................."com.mysql.cj.jdbc.Driver" 
06:33:22.495 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - exceptionOverrideClassName......none 
06:33:22.496 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - healthCheckProperties...........{} 
06:33:22.496 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - healthCheckRegistry.............none 
06:33:22.496 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - idleTimeout.....................600000 
06:33:22.496 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - initializationFailTimeout.......1 
06:33:22.497 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - isolateInternalQueries..........false 
06:33:22.497 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - jdbcUrl.........................jdbc:mysql://mysql.mysql:3306/dev 
06:33:22.497 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - keepaliveTime...................0 
06:33:22.497 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - leakDetectionThreshold..........0 
06:33:22.497 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - maxLifetime.....................1800000 
06:33:22.498 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - maximumPoolSize.................10 
06:33:22.498 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - metricRegistry..................none 
06:33:22.498 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - metricsTrackerFactory...........none 
06:33:22.498 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - minimumIdle.....................10 
06:33:22.498 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - password........................<masked> 
06:33:22.498 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - poolName........................"HikariPool-1" 
06:33:22.498 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - readOnly........................false 
06:33:22.499 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - registerMbeans..................false 
06:33:22.499 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - scheduledExecutor...............none 
06:33:22.499 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - schema..........................none 
06:33:22.499 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - threadFactory...................internal 
06:33:22.499 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - transactionIsolation............default 
06:33:22.500 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - username........................"dev" 
06:33:22.500 [main] DEBUG [          com.zaxxer.hikari.HikariConfig:1132.logConfiguration()] - validationTimeout...............5000 
06:33:22.500 [main] INFO  [      com.zaxxer.hikari.HikariDataSource:110.getConnection()] - HikariPool-1 - Starting... 
06:33:22.720 [main] INFO  [       com.zaxxer.hikari.pool.HikariPool:565.checkFailFast()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@61e7bf2f 
06:33:22.722 [main] INFO  [      com.zaxxer.hikari.HikariDataSource:123.getConnection()] - HikariPool-1 - Start completed. 
06:33:22.744 [main] INFO  [                             SQL dialect:66.logSelectedDialect()] - HHH000400: Using dialect: org.hibernate.dialect.MySQLDialect 
06:33:22.822 [HikariPool-1 housekeeper] DEBUG [       com.zaxxer.hikari.pool.HikariPool:414.logPoolState()] - HikariPool-1 - Pool stats (total=1, active=0, idle=1, waiting=0) 
06:33:22.826 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:738.call()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@bd80a7 
06:33:22.839 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:738.call()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@41808a9c 
06:33:22.852 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:738.call()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@708b2c9f 
06:33:22.865 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:738.call()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@21af75d3 
06:33:22.878 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:738.call()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@6dab02dc 
06:33:22.890 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:738.call()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@25e1a8d5 
06:33:22.903 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:738.call()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@3da1f629 
06:33:22.916 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:738.call()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@38e18d72 
06:33:22.928 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:738.call()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@4fef7aea 
06:33:22.939 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:414.logPoolState()] - HikariPool-1 - After adding stats (total=10, active=0, idle=10, waiting=0) 

Here is my my.cnf:

[mysqld]
default_authentication_plugin=mysql_native_password
skip-name-resolve
explicit_defaults_for_timestamp
basedir=/opt/bitnami/mysql
plugin_dir=/opt/bitnami/mysql/lib/plugin
port=3306
socket=/opt/bitnami/mysql/tmp/mysql.sock
datadir=/bitnami/mysql/data
tmpdir=/opt/bitnami/mysql/tmp
max_allowed_packet=512M
bind-address=*
pid-file=/opt/bitnami/mysql/tmp/mysqld.pid
log-error=/opt/bitnami/mysql/logs/mysqld.log
character-set-server=UTF8
collation-server=utf8_general_ci
slow_query_log=0
slow_query_log_file=/opt/bitnami/mysql/logs/mysqld.log
long_query_time=10.0
default-time-zone = '+02:00'
wait_timeout=2592000
interactive_timeout=2592000

[client]
port=3306
socket=/opt/bitnami/mysql/tmp/mysql.sock
default-character-set=UTF8
plugin_dir=/opt/bitnami/mysql/lib/plugin

[manager]
port=3306
socket=/opt/bitnami/mysql/tmp/mysql.sock
pid-file=/opt/bitnami/mysql/tmp/mysqld.pid

Here are the results of the database queries:

show global variables LIKE "%timeout%"; image

show global variables LIKE "%wait%"; image

show global variables LIKE "%conn%"; image

Here is the complete Stacktrace::

06:53:46.114 [http-nio-0.0.0.0-9999-exec-2] WARN  [  com.zaxxer.hikari.pool.ProxyConnection:177.checkException()] - HikariPool-1 - Connection com.mysql.cj.jdbc.ConnectionImpl@61e7bf2f marked as broken because of SQLSTATE(08S01), ErrorCode(0) 

com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet successfully received from the server was 1,214,276 milliseconds ago. The last packet sent successfully to the server was 1,214,276 milliseconds ago.
    at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
    at com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2050)
    at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:401)
    at com.zaxxer.hikari.pool.HikariProxyConnection.setAutoCommit(HikariProxyConnection.java)
    at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:72)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:276)
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246)
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:164)
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:421)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:595)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:382)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:752)
    at org.springframework.retry.interceptor.RetryOperationsInterceptor$1.doWithRetry(RetryOperationsInterceptor.java:102)
    at org.springframework.retry.support.RetryTemplate.doExecute(RetryTemplate.java:329)
    at org.springframework.retry.support.RetryTemplate.execute(RetryTemplate.java:209)
    at org.springframework.retry.interceptor.RetryOperationsInterceptor.invoke(RetryOperationsInterceptor.java:135)
    at org.springframework.retry.annotation.AnnotationAwareRetryOperationsInterceptor.invoke(AnnotationAwareRetryOperationsInterceptor.java:160)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:752)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:703)
    at io.my.services.StorageService$$SpringCGLIB$$0.saveReport(<generated>)
    at io.my.services.ReportService.persistsReports(ReportService.java:110)
    at io.my.services.MyActiveScanService.activeScan(MyActiveScanService.java:219)
    at io.my.controllers.MyController.activeAttack(MyController.java:35)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    at java.base/java.lang.reflect.Method.invoke(Method.java:578)
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:207)
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:152)
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:884)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:797)
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1080)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:973)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1003)
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:895)
    at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:705)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:880)
    at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:814)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:223)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:109)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:119)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
    at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:741)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:400)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:861)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1739)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
    at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
    at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.base/java.lang.Thread.run(Thread.java:1589)
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failure

The last packet successfully received from the server was 1,214,276 milliseconds ago. The last packet sent successfully to the server was 1,214,276 milliseconds ago.
    at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:67)
    at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500)
    at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:484)
    at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)
    at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
    at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)
    at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)
    at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:581)
    at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:761)
    at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:700)
    at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:1051)
    at com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:997)
    at com.mysql.cj.NativeSession.execSQL(NativeSession.java:663)
    at com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2033)
    ... 80 common frames omitted
Caused by: java.net.SocketException: Connection reset
    at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:313)
    at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:340)
    at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:789)
    at java.base/java.net.Socket$SocketInputStream.read(Socket.java:1025)
    at com.mysql.cj.protocol.ReadAheadInputStream.fill(ReadAheadInputStream.java:107)
    at com.mysql.cj.protocol.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:150)
    at com.mysql.cj.protocol.ReadAheadInputStream.read(ReadAheadInputStream.java:180)
    at java.base/java.io.FilterInputStream.read(FilterInputStream.java:119)
    at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64)
    at com.mysql.cj.protocol.a.SimplePacketReader.readHeaderLocal(SimplePacketReader.java:81)
    at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
    at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
    at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)
    at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)
    at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54)
    at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44)
    at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:575)
    ... 86 common frames omitted
06:53:46.116 [HikariPool-1 connection closer] DEBUG [         com.zaxxer.hikari.pool.PoolBase:132.quietlyCloseConnection()] - HikariPool-1 - Closing connection com.mysql.cj.jdbc.ConnectionImpl@61e7bf2f: (connection is broken) 
06:53:46.167 [HikariPool-1 connection adder] DEBUG [       com.zaxxer.hikari.pool.HikariPool:738.call()] - HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@28017506 
06:53:50.118 [http-nio-0.0.0.0-9999-exec-2] ERROR [my.services.MyActiveScanService:226.activeScan()] - =#= Execution Error. RunId=53. Error=Could not open JPA EntityManager for transaction 
org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:467)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:595)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:382)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:752)
    at org.springframework.retry.interceptor.RetryOperationsInterceptor$1.doWithRetry(RetryOperationsInterceptor.java:102)
    at org.springframework.retry.support.RetryTemplate.doExecute(RetryTemplate.java:329)
    at org.springframework.retry.support.RetryTemplate.execute(RetryTemplate.java:209)
    at org.springframework.retry.interceptor.RetryOperationsInterceptor.invoke(RetryOperationsInterceptor.java:135)
    at org.springframework.retry.annotation.AnnotationAwareRetryOperationsInterceptor.invoke(AnnotationAwareRetryOperationsInterceptor.java:160)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:752)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:703)
    at io.my.services.StorageService$$SpringCGLIB$$0.saveReport(<generated>)
    at io.my.services.ReportService.persistsReports(ReportService.java:110)
    at io.my.services.MyActiveScanService.activeScan(MyActiveScanService.java:219)
    at io.my.controllers.MyController.activeAttack(MyController.java:35)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    at java.base/java.lang.reflect.Method.invoke(Method.java:578)
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:207)
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:152)
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:884)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:797)
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1080)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:973)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1003)
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:895)
    at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:705)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:880)
    at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:814)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:223)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:109)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:119)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
    at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:741)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:400)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:861)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1739)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
    at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
    at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.base/java.lang.Thread.run(Thread.java:1589)
Caused by: org.hibernate.TransactionException: JDBC begin transaction failed: 
    at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:78)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:276)
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246)
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:164)
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:421)
    ... 72 common frames omitted
Caused by: java.sql.SQLException: Connection is closed
    at com.zaxxer.hikari.pool.ProxyConnection$ClosedConnection.lambda$getClosedConnection$0(ProxyConnection.java:502)
    at jdk.proxy3/jdk.proxy3.$Proxy127.setAutoCommit(Unknown Source)
    at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:401)
    at com.zaxxer.hikari.pool.HikariProxyConnection.setAutoCommit(HikariProxyConnection.java)
    at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:72)
    ... 77 common frames omitted

Here is the application start and its end time.

startedAt: '2023-10-02T04:33:05Z'
finishedAt: '2023-10-02T04:53:52Z'

Almost 21 minutes in total.

As you can see from the stacktrace message, the last successful connection to the database was 1,214,276 milliseconds ago, which is equivalent to 20.2379 minutes.

And I think that this is some kind of incomprehensible bug, because I have a running application for clients and it works great, there are no glitches. With the same settings and versions.

I would be grateful for your help. I have already seen many similar topics on the Internet and here, but not a single proposed solution helped.

Thanks!

balin998 commented 1 year ago

I encountered the same error, which requires the following conditions to be met at the same time:

  1. Using azure-cloud-mysql (version: 5.7.32-log/5.6.50-log), manually installed mysql-5.7.28 on Azure virtual machine shows no issues.
  2. Optimization parameters for MySQL have been configured in Hikari: useServerPrepStmts=true.
  3. The version of mysql-connector-j must be: 8.0.32.

Breaking any of the above conditions will not cause the problem, for example:

  1. Using a self-installed MySQL instance, even if it is installed on an Azure virtual machine.
  2. Removing the parameter configuration of useServerPrepStmts=true. Other parameters may also cause this problem.
  3. Use new version of mysql-connector later than 8.0.32, for example, 8.0.33

Problem recurrence

build.gradle

plugins {
    id('java')

}

sourceCompatibility = JavaVersion.VERSION_17

dependencies {
    implementation 'com.zaxxer:HikariCP:5.0.1'

    // conditon2: mysql-connector-j version should be 8.0.32
    // It is recommended to use "com.mysql:mysql-connector-java" instead of "mysql:mysql-connector-java".
    runtimeOnly 'com.mysql:mysql-connector-j:8.0.32'  
}

test table: t1

CREATE TABLE `t1` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `fld1` varchar(50) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8mb4;

test code: A1.java

import com.zaxxer.hikari.HikariConfig;  
import com.zaxxer.hikari.HikariDataSource;  

import java.sql.SQLException;  
import java.time.Duration;  
import java.util.Properties;  

 public class A1 {  
    public static void main(String[] args) throws SQLException {  
        final var config = new HikariConfig();  
        // condition 1: use an azure-cloud-mysql instance
        config.setJdbcUrl("jdbc:mysql://yourHost:3306/yourDatabase");  
        config.setUsername("yourUser");  
        config.setPassword("yourPass");  
        // Make sure that maxLifetime/connectionTimeout is less than the relevant configuration in MySQL.
        config.setMaxLifetime(Duration.ofSeconds(30).toMillis());  
        config.setConnectionTimeout(Duration.ofSeconds(3).toMillis());  
        Properties properties = new Properties();  
        // condition 3: useServerPrepStmts=true
        properties.setProperty("useServerPrepStmts", "true");  
        config.setDataSourceProperties(properties);  

        try (var pool = new HikariDataSource(config)) {  
            try (var conn = pool.getConnection();  
                 var pst = conn.prepareStatement("INSERT INTO t1(fld1) values(?) ")) {  
                pst.setString(1, System.currentTimeMillis() + "");  

                final var insert = pst.executeUpdate();  
                System.out.println("insert = " + insert);  
            }  
        }  
    }  
}

btw The correspondence between Springboot version and the default included mysql-connector-j version may be unordered, and the correspondence can be viewed in the official website instructions. The tested correspondence is as follows:

springboot mysql-connector-j match condition-2?
2.7.16 8.0.33 NO
3.0.2 8.0.32 YES
3.1.4 8.0.33 NO

As described above, under the premise of meeting conditions 1 and 3, when using Springboot 3.0.2 and not explicitly declaring the version of mysql-connector-j, mysql-connector-j-8.0.32 was introduced, thus meeting condition 2 and triggering the Communications link failure error. However, When downgraded to Springboot 2.7.16 or using Springboot 3.1.4, mysql-connector-j-8.0.33 will be introduced, which does not meet condition 2, and the program can run normally. When using Springboot 3.0.2, if you wish to circumvent condition 2, you need to explicitly specify the version of mysql-connector-j to 8.0.33.

runtimeOnly 'com.mysql:mysql-connector-j:8.0.33'

However, I don't know if this is a bug in HikariCp or a problem with mysql-connector-j?

balin998 commented 1 year ago

It's not a problem of HikariCP. The problem occurs when using jdk to directly connect to the database.

public class A2 {
    public static void main(String[] args) throws ClassNotFoundException, SQLException {
        // condition2: Set useServerPrepStmts=true in the url
        final var url = "jdbc:mysql://yourHost:3306/yourDatabase?useServerPrepStmts=true";
        final var user = "yourUser";
        final var pass = "yourPass";
        final var sql = "INSERT INTO t1(fld1) values(?) ";

//        Class.forName("com.mysql.cj.jdbc.Driver");
        try (var conn = DriverManager.getConnection(url, user, pass);
             var pst = conn.prepareStatement(sql)) {
            pst.setString(1, System.currentTimeMillis() + "");

            final var insert = pst.executeUpdate();
            System.out.println("insert = " + insert);
        }
    }
}
JWebDev commented 1 year ago

Hi. It was the Spring. Not Hikari. In my application properties was spring.jpa.open-in-view=true, after changing to the false, everything works as expected.