通过wireshark分析tcpdump网络数据包进而快速排查解决某环境OceanBase频现的TCP连接异常断开问题
1.问题现象
某客户反馈，在其某个验收环境，业务同学在进行普通的业务测试时（非性能压测场景），某个微服务在进行数据库操作时频繁出现异常，微服务日志提示其底层原因是：
复制
com.alipay.oceanbase.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure\n\nThe last packet successfully received from the server was 9 milliseconds ago. The last packet sent successfully to the server was 2 milliseconds ago.
at sun.reflect.GeneratedConstructorAccessor143.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.alipay.oceanbase.jdbc.Util.handleNewInstance(Util.java:439)
at com.alipay.oceanbase.jdbc.SQLError.createCommunicationsException(SQLError.java:1236)
at com.alipay.oceanbase.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:4394)
at com.alipay.oceanbase.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:4252)
at com.alipay.oceanbase.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4789)
at com.alipay.oceanbase.jdbc.MysqlIO.sendCommand(MysqlIO.java:2993)
at com.alipay.oceanbase.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1396)
at com.alipay.oceanbase.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:831)
at com.alipay.oceanbase.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2042)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:696)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:638)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:688)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:720)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:730)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:798)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:817)1.2.3.4.5.6.7.8.9.10.11.12.13.14.15.16.17.18.19.20.21.22.
2.问题背景
该环境数据库服务端OceanBase 版本为observer 4.2.1.x，而微服务使用的OceanBase JDBC驱动版本为1.1.7。从OB官方了解到，1.1.7及之前版本的OceanBase JDBC驱动，是容易有这个连接异常断开的问题，OB 官方给的方案是升级 JDBC 驱动，建议至少使用2.4.x以上的版本。 但客户反馈，其它环境包括生产环境，有些微服务使用了相同版本的 OceanBase JDBC 驱动，数据库服务端也使用了相同版本的OceanBase，但基本都没有出现该问题，或出现该问题的频率很低，仍希望我们能排查下是否有其它原因，比如是否跟数据库或操作系统的具体配置，甚至网络状况有关，希望能够在短时间内不升级驱动的情况下，通过调整参数缓解该问题。
3.问题初步分析
异常com.alipay.oceanbase.jdbc.exceptions.jdbc4.CommunicationsException:Communications link failure 其实指的就是 TCP 连接异常断开，但从从上述报错日志来看，微服务上次成功收到来自obproxy的数据包是 15 毫秒之前，微服务上次成功发送数据包到 obproxy是1毫秒之前，时间都很短，而且我们业务流量不大（场景是正常业务测试，非性能压测），初步推测可能不是网络丢包问题，而是 obproxy 或 服务器的配置问题。为排除网络问题，我们通过 ping 初步测试了下该环境的网络状况，结果数据如下，可以看到，内网环境网络状况良好，延迟很低且没有丢包：复制
ping -c 10 -i 1 172.253.34.74
PING 172.253.34.74 (172.253.34.74) 56(84) bytes of data.
64 bytes from 172.253.34.74: icmp_seq=1 ttl=61 time=0.727 ms
64 bytes from 172.253.34.74: icmp_seq=2 ttl=61 time=0.231 ms
64 bytes from 172.253.34.74: icmp_seq=3 ttl=61 time=0.278 ms
64 bytes from 172.253.34.74: icmp_seq=4 ttl=61 time=0.227 ms
64 bytes from 172.253.34.74: icmp_seq=5 ttl=61 time=0.219 ms
64 bytes from 172.253.34.74: icmp_seq=6 ttl=61 time=0.227 ms
64 bytes from 172.253.34.74: icmp_seq=7 ttl=61 time=0.384 ms
64 bytes from 172.253.34.74: icmp_seq=8 ttl=61 time=0.235 ms
64 bytes from 172.253.34.74: icmp_seq=9 ttl=61 time=0.232 ms
64 bytes from 172.253.34.74: icmp_seq=10 ttl=61 time=0.331 ms
--- 172.253.34.74 ping statistics ---
10 packets transmitted, 10 received, 0% packet loss, time 9000ms
rtt min/avg/max/mdev = 0.219/0.309/0.727/0.148 ms。1.2.3.4.5.6.7.8.9.10.11.12.13.14.15.
4.问题原因
TCP 连接异常断开的原因比较复杂，除了跟客户端 jdbc 驱动版本和服务端obproxy 版本有关，也跟数据库的具体配置，客户端与服务端的操作系统的具体配置，甚至网络情况有关。由于相关配置参数太多，为快速排查确认问题，我们准备先从网络数据包上进行分析。经过协调，我们首先在微服务端使用 “tcpdump -i any port 2883 -w 2883.pcap” 抓取了约5分钟的网络包，通过微服务日志可以确认，5分钟内出现了上述问题，即 com.alipay.oceanbase.jdbc.exceptions.jdbc4.CommunicationsException:Communications link failure。通过 wireshark 打开上述命令抓取的 pcap网络包后，查看发现有些TCP连接确实是通过 RST 异常关闭的，如下图所示，注意这里的 2883端口即服务端 obproxy的监听端口：
图片
图片
按照客户端抓包结果来梳理下：
在TCP连接成功创建并正常使用的过程中，微服务通过ob jdbc驱动发送了SQL请求到服务端 obproxy；在约0.001448秒后，服务端 obproxy (2883端口）主动发送了 [FIN,ACK] 信号来关闭该 tcp 连接，这是第一个不太正常的地方，因为正常情况下，obproxy 不会主动关闭 tcp 连接；在约0.03107秒后，微服务收到了来自 obproxy 的 [FIN,ACK] 的关闭连接信号后，并回复了 [PUSH,ACK] 信号以确认收到了关闭连接的信号；在约 0.000033秒后，微服务[FIN,ACK] 来关闭该 TCP 连接，这是第二个不太正常的地方，因为正常情况下，微服务在等待来自服务端的SQL执行结果时，是不会主动关闭 tcp 连接的；在约0.000172秒和0.000043秒后，服务端 obproxy (2883端口）主动发送了两个 [RST] 信号来重置该 tcp 连接；(结合服务端抓包可知，这两个 [RST] 其实分别是对客户端发送的[PUSH,ACK] 和 [FIN,ACK] 数据包的响应)；至此问题的直接原因确认了，不是网络超时或网络丢包引起的，而是 obproxy 因为某种原因，主动发送了[FIN,ACK]来断开连接！
进一步跟踪该TCP流，发现 obproxy 在此之前其实有回复异常信息给客户端：“HY000ORA-01000: maximum open cursors exceeded“，如下图所示：
图片
图片
5.问题解决
在该验收环境中，使用命令“alter system set open_cursors=1500;”，将该参数open_cursors的值从50改到1500，问题成功解决。另经咨询DBA，相关规范如下：
参数open_cursors:【租户级别生效】，用于设置单个session打开的游标数量，默认是50，太小容易出现ORA-01000 maxium open cursors exceeded ，可根据情况情况修改，计算公式如下：租户内存(64G)*_temporary_file_io_area_size(5%)/宏块（2m) =1600, 修改命令如下： alter system set open_cursors=1500;参数temporary_file_io_area_size：【租户级别生效】，SQL中间结果（比如hash join）在存储层能使用的总大小，可适当调大（租户级别参数，需要通过sys租户来调整），修改命令如下：alter system set "_temporary_file_io_area_size" = 5;6.问题跟进
微服务的异常日志打印逻辑需要优化下，当前的日志揭示了底层原因是 “com.alipay.oceanbase.jdbc.exceptions.jdbc4.CommunicationsException:Communications link failure\n\n The last packet successfully received from the server was 9 milliseconds ago. the last packet sent successfully to the server was 2 milliseconds ago.”, 但并没有揭示更底层的原因，即 “HY000ORA-01000: maximum open cursors exceeded”，这个最底层的原因也需要体现在日志中，以方便问题排查；后续微服务需要升级 OB JDBC 驱动版本，建议升级为官方建议的最低版本，比如 OB JDBC 驱动2.4.3；7.参考链接
https://open.oceanbase.com/blog/10900349https://www.oceanbase.com/knowledge-base/oceanbase-database-1000000000763298https://segmentfault.com/a/1190000042448986/en
THE END
