郑州博大泌尿外科医院网站推广优化外包公司
本文作者：胡呈清，爱可生 DBA 团队成员，擅长故障分析、性能优化
与MySQL这类单机数据库相比，OceanBase分布式数据库的访问链路相对较长，因此在遇到连接异常时，排查过程需要额外考虑更多环节。接下来，我们将通过一个具体案例，探讨在OceanBase中，如何抓包分析并解决应用连接超时的问题。
案例问题描述
这是一个生产环境，访问链路大概是这样的：
应用 -> 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 次，日志如下：
分析过程
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 日志的目的是什么？
- 是看应用到 OBProxy 的前端连接处理是不是异常了。
- 如果应用到 OBProxy 连接正常，继续看 OBProxy 到 OBServer 的后端连接是不是建成功了。
由于日志回收，只保留了 03-11 08:14 这个时间段的日志。按照上述思路通过以下几个维度搜索日志：
- 过滤 VC_EVENT_EOS 关键字，看有没有异常断开的前端连接。结果返回空，说明没有。
grep VC_EVENT_EOS obproxy.log.* |egrep -i 'tenant_name=[a-z].*'
- 继续看 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}'
- 然后过滤 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'
- 继续输出创建连接成功后
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
参数解释
- 应用与 OBProxy 在同一台服务器上，抓包时需要指定回环接口
-i lo。 -w /tmp/cap/obproxy.cap指定结果文件路径。-C 50表示结果文件满 50M 就自动切换新的文件。-W 500表示一共 500 个结果文件，当写满 500 个会循环到第 1 个继续写。host xx.xx.xx.9过滤访问 VIP 的网络包，减少抓宝数量。
发现 3.14 15:52:57 应用发生了报错：
既然抓到包了，现在面对的一个问题是怎么分析这些网络包，并找到我们需要的信息？
思路 3：利用 Wireshark 的专家信息（入口：分析 -> 专家信息）快速找到可能异常的包。
在 Note 中看到有重传（retransmission），我们只需要找 3306 端口的包就行，只有 4232 > 3306 这一个连接发生了重传：
然后点开第一个重传的包，也就是第 8517 号包，查看这个连接的所有包（操作：右键 -> 追踪流 -> TCP 流）：
由于客户端、服务端在一台服务器上，所以上面展示的包有来有回。
从客户端的角度来看过程
- 15:52:47 向
xx.xx.xx.9:3306发起 TCP 连接请求（三次握手的 SYN），即 8359 号包。 - 15:52:48 向
xx.xx.xx.9:3306重发 8517 号 SYN 包，TCP Retransmission 表示重传，TCP Port numbers reused 表示端口重用（net.ipv4.tcp_tw_reuse=1），这是 Wireshark 打的标记，因为和第一个 SYN 包的四元组一样。 - 15:52:50 继续重发 SYN 包，9075。
- 15:52:54 继续重发 SYN 包，10140。
服务端角度来看过程
- 15:52:47 向
1xx.xx.xx.12:4232发 SYN+ACK 包，即 8360 号包。 - 15:52:48 重发 SYN、ACK 包，即 8517 号包。
- ...
这里面还有 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。这还有啥好说的，直接拿着这个证据问了下网络部门，这回终于得到证实：
结论
网络禁止了 4232 端口外部访问，因此当客户端连接 OBProxy、或者 OBProxy 连接 OBServer 时使用了 4232 随机端口，服务端回包到 4232 端口将导致丢包无法建立连接。
解决方案
设置内核参数 ip_local_port_range，限制服务器本地随机端口的范围，防止使用到被禁止的端口：
sysctl -w net.ipv4.ip_local_port_range="10000 60999"
小提示：在部署 OB 集群时，OBServer 服务器初始化时会自动设置 net.ipv4.ip_local_port_range = 3500 65535，需要格外注意网络策略是否会有影响。