最近在前台导入3000条记录时,经常发现只导入大概500条记录,然后就会报ERROR TransactionInterceptor – Application exception overridden by rollback exception的问题。下面记录一下解决过程,以作备忘!
思路
这里主要是由于连接时间过长,失效所致。即,程序获取到的连接已经失效了,而拿一个失效的连接再次请求就会报那样的异常。
1. 查看应用日志
可以看到都是在跟后端数据库连接时断开导致。
具体信息如下:
java.sql.SQLNonTransientConnectionException:Nooperationsallowedafterconnectionclosed. atcom.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:73)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1875)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.zaxxer.hikari.pool.ProxyConnection.rollback(ProxyConnection.java:370)~[HikariCP-3.2.0.jar!/:na] atcom.zaxxer.hikari.pool.HikariProxyConnection.rollback(HikariProxyConnection.java)[HikariCP-3.2.0.jar!/:na] atorg.springframework.jdbc.datasource.DataSourceTransactionManager.doRollback(DataSourceTransactionManager.java:344)[spring-jdbc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] atorg.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:838)[spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] atorg.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:812)[spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] atorg.springframework.transaction.support.TransactionTemplate.rollbackOnException(TransactionTemplate.java:168)[spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] atorg.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:144)[spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] atlogwire.web.service.ActionContext$TransactionExecutor.doWithoutResult(ActionContext.java:716)[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.ActionContext.doInNewTransactionWithoutResult(ActionContext.java:561)[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.task.run.impl.DefaultTaskRunner.doTaskInner(DefaultTaskRunner.java:85)[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.task.run.impl.DefaultTaskRunner.doTaskInnerWithMetric(DefaultTaskRunner.java:130)[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.task.run.impl.DefaultTaskRunner.doTask(DefaultTaskRunner.java:176)[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.task.execute.TaskExecuteService.doTask(TaskExecuteService.java:35)[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.task.execute.redisson.impl.RedissonTaskImpl.doTask(RedissonTaskImpl.java:22)[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atsun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethod)~[na:1.8.0_102] atsun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)~[na:1.8.0_102] atsun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)~[na:1.8.0_102] atjava.lang.reflect.Method.invoke(Method.java:498)~[na:1.8.0_102] atorg.redisson.RedissonRemoteService.invokeMethod(RedissonRemoteService.java:360)[redisson-3.11.3.jar!/:3.11.3] atorg.redisson.RedissonRemoteService.lambda$executeMethod$4(RedissonRemoteService.java:329)[redisson-3.11.3.jar!/:3.11.3] atjava.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)~[na:1.8.0_102] atjava.util.concurrent.FutureTask.run(FutureTask.java:266)~[na:1.8.0_102] atjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)~[na:1.8.0_102] atjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)~[na:1.8.0_102] atjava.lang.Thread.run(Thread.java:745)~[na:1.8.0_102] Causedby:com.mysql.cj.exceptions.ConnectionIsClosedException:Nooperationsallowedafterconnectionclosed. atsun.reflect.GeneratedConstructorAccessor129.newInstance(UnknownSource)~[na:na] atsun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)~[na:1.8.0_102] atjava.lang.reflect.Constructor.newInstance(Constructor.java:423)~[na:1.8.0_102] atcom.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.NativeSession.checkClosed(NativeSession.java:1259)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:575)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1829)~[mysql-connector-java-8.0.13.jar!/:8.0.13] ...25commonframesomitted Causedby:com.mysql.cj.exceptions.CJCommunicationsException:Communicationslinkfailure Thelastpacketsuccessfullyreceivedfromtheserverwas35,661millisecondsago.Thelastpacketsentsuccessfullytotheserverwas35,662millisecondsago. atsun.reflect.GeneratedConstructorAccessor126.newInstance(UnknownSource)~[na:na] atsun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)~[na:1.8.0_102] atjava.lang.reflect.Constructor.newInstance(Constructor.java:423)~[na:1.8.0_102] atcom.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:555)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:725)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:664)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:979)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.NativeSession.execSQL(NativeSession.java:1153)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:951)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1113)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1061)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1381)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.jdbc.ClientPreparedStatement.executeUpdate(ClientPreparedStatement.java:1046)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)~[HikariCP-3.2.0.jar!/:na] atcom.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)~[HikariCP-3.2.0.jar!/:na] atorg.springframework.jdbc.core.JdbcTemplate.lambda$update$0(JdbcTemplate.java:867)~[spring-jdbc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] atorg.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:617)~[spring-jdbc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] atorg.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:862)~[spring-jdbc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] atorg.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:917)~[spring-jdbc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] atlogwire.web.service.query.sql.QueryDataSetManager.insertModelRow(QueryDataSetManager.java:419)~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.query.sql.QueryDataSetManager.saveModelDataSet(QueryDataSetManager.java:140)~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.query.sql.QueryDataSetManager.saveModelDataSet(QueryDataSetManager.java:104)~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.query.sql.QueryDataSetManager.insert(QueryDataSetManager.java:272)~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.query.QueryService.insert(QueryService.java:183)~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.query.QueryService.insert(QueryService.java:163)~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atjdk.nashorn.internal.scripts.Script$Recompilation$203$16161AAAAAAA$importHandlers.L:1$insertLog(config/custom_js/importHandlers.js:449)~[na:na] atjdk.nashorn.internal.scripts.Script$Recompilation$198$9472A$tasks.L:1$handleImport$L:256(config/custom_js/tasks.js:273)~[na:na] atjdk.nashorn.javaadapters.java.util.function.Consumer.accept(UnknownSource)~[na:na] atjava.util.ArrayList.forEach(ArrayList.java:1249)~[na:1.8.0_102] atjdk.nashorn.internal.scripts.Script$Recompilation$196$9015AAA$tasks.L:1$handleImport(config/custom_js/tasks.js:256)~[na:na] atjdk.nashorn.internal.scripts.Script$Recompilation$195$8841AAA$tasks.L:1$partsImportDD(config/custom_js/tasks.js:239)~[na:na] atjdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:643)~[nashorn.jar:na] atjdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:494)~[nashorn.jar:na] atjdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:393)~[nashorn.jar:na] atjdk.nashorn.api.scripting.ScriptObjectMirror.callMember(ScriptObjectMirror.java:199)~[nashorn.jar:na] atlogwire.core.meta.task.ScriptTask.doTask(ScriptTask.java:24)~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atlogwire.web.service.task.run.impl.DefaultTaskRunner$1.doInTransactionWithoutResult(DefaultTaskRunner.java:88)~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] atorg.springframework.transaction.support.TransactionCallbackWithoutResult.doInTransaction(TransactionCallbackWithoutResult.java:36)~[spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] atorg.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140)[spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] ...18commonframesomitted Causedby:java.io.EOFException:Cannotreadresponsefromserver.Expectedtoread4bytes,read0bytesbeforeconnectionwasunexpectedlylost. atcom.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:67)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44)~[mysql-connector-java-8.0.13.jar!/:8.0.13] atcom.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:549)~[mysql-connector-java-8.0.13.jar!/:8.0.13] ...53commonframesomitted
2. 直连mysql测试
由于后端数据库是用mycat+mysql主从做的读写分离,影响因素比较多,所以需先去掉影响的一些因素,这里先直连mysql数据库测试,绕过mycat。
经过业务测试发现可以导入成功,这样问题就在mycat上了。
3. mycat关闭读写分离
关闭mycat的读写分离后导入3000条可以导入2700条,但还有部分失败。
mycat日志如下:
INFO[$_NIOREACTOR-1-RW](io.mycat.net.AbstractConnection.close(AbstractConnection.java:520))-closeconnection,reason:streamclosed,ServerConnection[id=55,schema=tms_prod,host=,u ser=root,txIsolation=3,autocommit=true,schema=tms_prod,executeSql=null] INFO[$_NIOREACTOR-2-RW](io.mycat.net.AbstractConnection.close(AbstractConnection.java:520))-closeconnection,reason:streamclosed,ServerConnection[id=56,schema=tms_prod,host=,u
4、. 改应用配置
经过查找资料和分析,得出该问题主要是由于连接时间过长,失效所致,既然程序获取的连接已经失效了,那么对于失效的连接就不应该使用,而应该再次获取有效的连接。增加配置如下:
spring.datasource.validation-query=SELECT1
修改后让业务重新测试,导入正常,问题解决。
总结
当数据库连接池中的连接被创建而长时间不使用的情况下,该连接会自动回收并失效,但客户端并不知道,在进行数据库操作时仍然使用的是无效的数据库连接,这样,就导致客户端程序报“ java.sql.SQLException: Io 异常: Connection reset by peer”或“java.sql.SQLException 关闭的连接”异常,加上spring.datasource.validation-query=SELECT 1配置后,客户端在使用一个无效的连接时会先对该连接进行测试,如果发现该连接已经无效,则重新从连接池获取有效数据库连接来使用。