一、问题背景
最近在线上的日志巡查中,发现了如下的异常日志,应用程序不能获取JDBC连接,连接被关闭。
Request processing failed; nested exception is org.springframework.transaction.TransactionSystemException: Could not roll back JDBC transaction; nested exception is java.sql.SQLException: Connection is closed。
紧随其后,系统里日志记录信息如下:
Could not roll back JDBC transaction; nested exception is java.sql.SQLException:
Connection is closed - org.springframework.transaction.TransactionSystemException: Could not roll back JDBC transaction;
nested exception is java.sql.SQLException: Connection is closed
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doRollback(DataSourceTransactionManager.java:350)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:835)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:809)
at org.springframework.transaction.interceptor.TransactionAspectSupport.completeTransactionAfterThrowing(TransactionAspectSupport.java:649)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:370)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:118)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
数据库连接关闭,事务还不能回滚,这是一个比较严重的问题。我们的MySQL是5.7版本,隔离级别是RR,数据库引擎是Innodb。所以当下就抓紧去排查该问题发生的根因,避免发生线上事故。
二、根因分析
查看了应用的监控,从监控上看系统表现正常,无异常信息,联系DBA,反馈数据库也正常;从数据库的日志中得到了下面的日志信息。
[Note] Aborted connection 11078996 to db: '数据库名' user: '用户' host: '数据库IP' (Got an error writing communication packets)
上述日志信息中,Aborted connection 关键字到MySQL的文档中查询可知,造成Aborted_connects状态变量增加的可能原因:
- 没有数据库的权限;
- 使用了错误的密码。
- 连接包不包含正确的信息。
- 获取一个连接包需要的时间超过connect_timeout秒。
同时,文档中紧接着还介绍了Aborted clients出现时可能的原因:
- 客户端程序在退出时没有调用mysql_close()方法;
- 客户端已休眠超过wait_timeout或interactive_timeout秒,而没有向服务器发出任何请求;
- 客户端程序突然终止了传输中的数据;
导致Aborted connections或Aborted clients问题的其他原因:
- max_allowed_packet变量值太小,或者查询需要的内存比为mysqld分配的内存多;
- 客户端和服务器之间的网络原因导致;
- 线程库出现问题,导致读取中断;
- TCP/IP配置错误;
- 各种硬件故障,需要对硬件进行更换;
综上来说,Aborted connections和Aborted clients是不太可能完全避免的,在MySQL的日志里或多或少都会有一些,这需要我们程序有这种容错处理能力。
三、参数配置
为了验证“Aborted connections和Aborted clients是不太可能完全避免”这一结论,对线上的数据进行查询统计以便证实该结论。
1、SHOW GLOBAL STATUS LIKE '%abort%';
这是线上数据库累计的这2个异常的数值,说明该问题并不是第一次出现,只不过可能之前出现时业务无感知或是没有影响到业务;
2、 SHOW VARIABLES LIKE '%max_allowed_packet%';
目前是系统默认值1G,当进行修改超过1G时,数据库重启将恢复至默认值1G;
3、 SHOW VARIABLES LIKE '%timeout%';
在这组参数中,重点关注标红的几个参数,这几个参数与我们本次排查的问题相关性较高,这几个参数标识了连接超时的问题;连接在服务器端可能已超时,但在客户端的连接池里并不是马上失效导致了连接断开而事务还不能回滚的情况。
综上分析,数据库出现连接问题的情况是比较难完全避免的,需要我们的应用程序有容错性来处理这类问题。
附MySQL官方文档针对该问题的阐述:
MySQL :: MySQL 5.7 Reference Manual :: B.3.2.9 Communication Errors and Aborted Connections