偶发性出现Connection is closed异常排查

type

status

date

slug

summary

SqlSession来源

我们在日志中全局去找DefaultSqlSession@2582c282 ，看看它是从什么时候被创建的，以及在什么时候被使用过

关键日志信息：

可以具体按这个时间去找创建时的上下文日志信息：

上图中标注了事务创建的过程打印的对应日志记录。

分析代码

通过日志的Trace ID 找到对应的接口与方法，通过Trace ID排查，这个接口调用链路中确实发生了异常。

在Service方法中，使用到了手动控制事务，并且异常是在事务开启之后，提交之前发生的，方法的整体结构如下

这个结构会导致

事务开启 → functionB方法出现异常 → 程序直接退出，事务未提交或回滚，一直保留在当前线程(http-nio-8412-exec-10 )中运行，并占用该连接 → 线程释放回线程池中，等待执行下次操作

于是我们按照Connection is closed异常去全局查找日志，可以发现出现异常的日志都是http-nio-8412-exec-10 这个线程下的，并且使用的SqlSession都是DefaultSqlSession@2582c282 ，也就是说出现异常的操作都是用到了同一个线程里、同一个事务里的Sqlsession，即同一个数据库连接。

可以翻一下获取SqlSession的源码：

在下次使用这个线程执行其它操作时，会继续使用这个线程里的事务，因为这个事务没有被提交，如果方法没有要求使用新事务，则默认会加入当前线程中的事务，但是操作的数据不会生效，因为事务还是一直没有被提交。我们后续也确实发现了有数据丢失的情况，并且使用的线程ID与出现异常的线程相同。

异常原因

我们按照Connection is closed异常去全局查找日志时，发现异常都是从15号才开始出现的。

首先我们查一下Mysql wait_timeout的配置，具体转换小时为 8小时，即如果连接在8小时进行任何活动，Mysql就会关闭连接，以节省资源。

所以猜测是，因为14号是周日，没有用户使用系统，DefaultSqlSession@2582c282 中持有的 Connection 在8小时内没有活动从而被Mysql关闭，从而导致Connection is closed异常的发生。

因此可以找下DefaultSqlSession@2582c282 从创建到8小时之后的使用记录，看是否有Connection is closed异常。

从前面我们找到的DefaultSqlSession@2582c282创建时间是14号19点34分左右，因此8小时后即大概15号3点半左右。

因此我找了一个4点多的DefaultSqlSession@2582c282使用记录，但通过时间点找到具体日志发现，这里是一个调度任务，从当前线程事务中获取到DefaultSqlSession@2582c282 后马上又释放了，并且打印了调度任务结束的日志，说明调度任务没有可用的更新数据所以很快退出了，没有进行实际的数据库连接，所以也没有异常产生。

为了更高效排查，使用Grep 加上异常信息查找，日志中出现DefaultSqlSession@2582c282 同时后10行出现Connection is closed的日志前20行，锁定时间在15号的10点21分，这个时间也满足大于8小时的条件

总结

由于事务的使用不当，导致事务在线程中一直没有提交，从而导致后续线程中的事务一直占用该数据库连接。待连接空闲超过Wait_timeout时，Mysql又会将连接进行关闭，但我们应用服务这边里的SqlSession还持有这个连接，并不知道连接已经关闭。因此如果后续使用线程http-nio-8412-exec-10 进行其它操作时，如果方法的事务没有要求必须新建事务，则默认会加入到当前线程上下文中的事务，并使用这个DefaultSqlSession@2582c282 进行数据库操作，这时则会发生Connection is closed的异常。

如果这个事务一直不结束，可能会一直持有DefaultSqlSession@2582c282 ，只有应用服务重启时才会被释放。