OB 运维 | 14 天蹲守，数据库连接超时“疑案”最终破获

爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

本文约 1000 字，预计阅读需要 3 分钟。

相较于 MySQL 这样的单机数据库，OceanBase 数据库的访问链路会稍长一些。当出现连接异常的情况，排查起来会多一些思考步骤。下面通过一个案例来分享 OceanBase 中如何抓包分析应用连接超时的问题。

1问题描述

这是一个生产环境，访问链路大概是这样的：

应用 -> VIP -> 3 节点 OBProxy -> 3 节点 OBServer

其中，VIP 是用 keepalived 来进行漂移的，所用版本为 OBServer 4.2.1.1、OBProxy 4.2.2.0。应用偶尔会出现连接数据库超时的报错：pymysql.err.OperationalError) (2003, "Can't connect to MySQL server on ' xx.xx.xx.9' (timed out)"，大概每天 1-2 次，日志如下：

2分析过程

1. 分析 OBProxy 日志

思路 1：VIP 在 xx.xx.xx.12 绑在这个 OBProxy 节点上，所以所有应用访问 xx.xx.xx.9:3306 时实际上都是访问的 xx.xx.xx.12，因此先分析 xx.xx.xx.12 节点上的 obproxy.log 即可。

思路 2：分析 OBProxy 日志的目的是什么？

1. 是看应用到 OBProxy 的前端连接处理是不是异常了。
2. 如果应用到 OBProxy 连接正常，继续看 OBProxy 到 OBServer 的后端连接是不是建成功了。

由于日志回收，只保留了 03-11 08:14 这个时间段的日志。按照上述思路通过以下几个维度搜索日志：

1. 过滤 VC_EVENT_EOS 关键字，看有没有异常断开的前端连接。结果返回空，说明没有。

grep VC_EVENT_EOS obproxy.log.* |egrep -i 'tenant_name=[a-z].*'

1. 继续看 OBProxy 到 OBServer 的后端连接状况。这里需要用一点统计方法，先过滤 03-11 08:14 时间点来自客户端 xx.xx.xx.12 访问 xx.xx.xx.9:3306 的请求，将客户端 IP:PORT 输出出来。

grep 'xx.xx.xx.9:3306' obproxy.log.20240311084410  |egrep '2024-03-11 08:14:[0-2].*' | egrep 'caddr=\{xx.xx.xx.12' | awk -F'caddr={' '{print $2}' |awk -F'}' '{print $1}'

1. 然后过滤 succ to set proxy_sessid 事件。这个事件说明连接建立成功，输出内容与上一步完全一致，说明所有连接都正常。

grep 'succ to set proxy_sessid' obproxy.log.20240311084410 | egrep '2024-03-11 08:14:[0-2].*' | awk -F'client_addr=' '{print $2}' |awk -F'"' '{print $2}' |grep 'xx.xx.xx.12'

1. 继续输出创建连接成功后 server_sessid，输出结果全部不为 0。说明所有连接都正常建立了后端连接。

grep 'succ to set proxy_sessid' obproxy.log.20240311084410 | egrep '2024-03-11 08:14:[0-2].*' | egrep 'client_addr="xx.xx.xx.12' | awk -F'server_sessid=' '{print $2}' |awk -F',' '{print $1}'

小结

OBProxy 日志正常，大概率 OBProxy 没有收到应用端的请求，这个连接超时问题可能和网络有关。下一步的建议：在应用服务器上抓包。

2. 抓包分析

由于这是一个偶发问题，无法预期故障时间，因此只能长时间抓包，需要注意两个两点：

• 每个包文件不能太大，因此需要自动切换结果文件。
• 抓的包不宜过多，降低可能对系统的影响，因此需要尽可能过滤包。

本案例的抓包命令如下：

tcpdump -X -s 0 -C 50 -W 500 -Z root -i lo -w /tmp/cap/obproxy.cap host xx.xx.xx.9

参数解释

1. 应用与 OBProxy 在同一台服务器上，抓包时需要指定回环接口 -i lo。
2. -w /tmp/cap/obproxy.cap 指定结果文件路径。
3. -C 50 表示结果文件满 50M 就自动切换新的文件。
4. -W 500 表示一共 500 个结果文件，当写满 500 个会循环到第 1 个继续写。
5. host xx.xx.xx.9 过滤访问 VIP 的网络包，减少抓包数量。

发现 3.14 15:52:57 应用发生了报错：

既然抓到包了，现在面对的一个问题是怎么分析这些网络包，并找到我们需要的信息？

思路 3：利用 Wireshark 的专家信息（入口：分析 -> 专家信息）快速找到可能异常的包。

在 Note 中看到有重传（retransmission），我们只需要找 3306 端口的包就行，只有 4232 > 3306 这一个连接发生了重传：

然后点开第一个重传的包，也就是第 8517 号包，查看这个连接的所有包（操作：右键 -> 追踪流 -> TCP 流）：

由于客户端、服务端在一台服务器上，所以上面展示的包有来有回。

从客户端的角度来看过程

1. 15:52:47 向 xx.xx.xx.9:3306 发起 TCP 连接请求（三次握手的 SYN），即 8359 号包。
2. 15:52:48 向 xx.xx.xx.9:3306 重发 8517 号 SYN 包，TCP Retransmission 表示重传，TCP Port numbers reused 表示端口重用（net.ipv4.tcp_tw_reuse=1），这是 Wireshark 打的标记，因为和第一个 SYN 包的四元组一样。
3. 15:52:50 继续重发 SYN 包，9075。
4. 15:52:54 继续重发 SYN 包，10140。

服务端角度来看过程

1. 15:52:47 向 1xx.xx.xx.12:4232 发 SYN+ACK 包，即 8360 号包。
2. 15:52:48 重发 SYN、ACK 包，即 8517 号包。
3. ...

这里面还有 ICMP 协议的包，信息是 Destination unreachable(Port unreachable)，从前面的信息来看是服务端到客户端的 4232 端口发 SYN+ACK 包时报的，因此客户端没收到服务端的 ACK 包一直重发 SYN 包。

应用报错是在 15:52:57，也就是客户端发起 TCP 连接的 10 秒后，Connector/Python 默认的 connection_timeout 就是 10秒，这个是吻合的。应用报错 timeout 就是丢包重传导致的，但是为什么会丢包？

查到这里僵住了，直接原因有了，但是根因还差一步。好在随着下一次报错，问题迎来了转机。

3. 第二次抓包分析

时隔 13 天后在 3 月 22 日，我们再次抓到一个故障时间点的包。再次祭出 Wireshark 三板斧，问题包如下：

这个异常包简直和 3 月 9 日的一模一样，最重要的是连客户端使用的随机端口一样都是 4232。这还有啥好说的，直接拿着这个证据问了下网络部门，这回终于得到证实：

3结论

网络禁止了 4232 端口外部访问，因此当客户端连接 OBProxy、或者 OBProxy 连接 OBServer 时使用了 4232 随机端口，服务端回包到 4232 端口将导致丢包无法建立连接。

4解决方案

设置内核参数 ip_local_port_range，限制服务器本地随机端口的范围，防止使用到被禁止的端口：

sysctl -w net.ipv4.ip_local_port_range="10000 60999"

小提示：在部署 OB 集群时，OBServer 服务器初始化时会自动设置 net.ipv4.ip_local_port_range = 3500 65535，需要格外注意网络策略是否会有影响。

本文关键字：#OceanBase# #网络# #Wireshark# #TCP#