背景

在一个APP的需求中，我需要调用某个业务的的接口去获取用户的数据，而该业务的数据存储在 https://www.starrocks.com/zh-CN/index 中，在需求上线后，每天都能收到 异常操作的告警，使用 traceId查询错误之后，发现问题是 The last packet successfully received from the server was 1,660 milliseconds ago. The last packet sent successfully to the server was 1,660 milliseconds ago。
the error may exist in URL [jar:file:/app/app.jar!/BOOT-INF/classes!/mapper/OrderAnalysisMapper.xml]

具体的表现问题如下所示。

具体问题【Communications link failure】

  1. The last packet successfully received from the server was 1,660 milliseconds ago. The last packet sent successfully to the server was 1,660 milliseconds ago.
  2. the error may exist in URL [jar:file:/app/app.jar!/BOOT-INF/classes!/mapper/OrderAnalysisMapper.xml]
  3. ....
  4. The last packet successfully received from the server was 1,660 milliseconds ago. The last packet sent successfully to the server was 1,660 milliseconds ago.
  5.     at sun.reflect.GeneratedConstructorAccessor238.newInstance(Unknown Source)
  6.     at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
  7.     at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
  8.     at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)
  9.     at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
  10.     at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)
  11.     at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)
  12.     at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:546)
  13.     at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:710)
  14.     at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:649)
  15.     at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:951)
  16.     at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1075)
  17.     at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:930)
  18.     ... 169 common frames omitted
  19. Caused by: java.net.SocketException: Socket closed
  20.     at java.net.SocketInputStream.socketRead0(Native Method)
  21.     at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
  22.     at java.net.SocketInputStream.read(SocketInputStream.java:171)
  23.     at java.net.SocketInputStream.read(SocketInputStream.java:141)
  24.     at com.mysql.cj.protocol.ReadAheadInputStream.fill(ReadAheadInputStream.java:107)
  25.     at com.mysql.cj.protocol.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:150)
  26.     at com.mysql.cj.protocol.ReadAheadInputStream.read(ReadAheadInputStream.java:180)
  27.     at java.io.FilterInputStream.read(FilterInputStream.java:133)
  28.     at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64)
  29.     at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
  30.     at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
  31.     at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)
  32.     at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)
  33.     at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54)
  34.     at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44)
  35.     at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:540)
  36.     ... 174 common frames omitted

一开始没有仔细查看堆栈，网上随便找了找，都说主要问题集中在链接过期了，要么需要autoConnect活着是需要设置 MySQL服务器的链接保活时间。

而在企业开发当中，设置MySQL服务器的时间是少之又少的。

欲解决，首先需要定义问题。准备的定义是解决问题的必要条件。 为什么会有 Caused by: java.net.SocketException: Socket closed 这个错误

又仔细的看了下堆栈，根据堆栈对源mysql-connector-j 的源码进行对比，首先 Communications link failure 出现在配置文件中，然后根据配置文件往回走，定位到 NativeProtocol， 从这里开始和堆栈对应上。根据 Caused by: java.net.SocketException: Socket closed 基本上可以推断出，链接由于什么操作被断开了，当链接断开的时候，MySQL客户端会从socket中读取配置(MultiPacketReader#readHeader)，在读取的过程中，发现对端(服务器端)的Socket已经关闭了，然后报出了该异常。

什么会导致socket关闭

socket关闭基本上要么服务端close掉了，要么是客户端自己主动close掉。根据当时的情况，不可能是服务端关闭了socket，那么关闭的操作只能在客户端发生。

什么情况下客户端会主动关闭连接

  • 关闭进程的时候
  • 主动调用了close方法

当时正是业务高峰期，显然当时没有人在高峰期重启tomcat，那就只有代码中主动close了。 然后根据反馈在代码中查找到了如下代码
image.png
🙈🙈🙈 缓存了DataSource，然后在30分钟后过期，过期的时候直接close掉了，很明显，如果在close的时候还有连接在执行sql，那么会直接报错。

验证问题

找到问题之后，需要验证问题，按照如下思路即可直接验证

  • 在http接口A中调用Mapper文件的sleep方法执行sql语句， select sleep(120) 执行sql语句，休眠120秒
  • 在http接口B中close掉datasource

按照这个思路即可找到该问题

解决思路

找到问题之后快速解决的方法有一个，利用Tomcat的classloader，将jar包中的包.class拷贝到项目中，将分钟修改为天可暂时解决该问题。

如果长久的解决，需要考虑到close的时候是否有sql正在执行。 可以根据datasource的active去进行处理。