DPVS下引发的TCP-ConnectionReset问题排查


背景

线上某个中台服务在资源创建时如果执行过程超长,就会触发服务端响应 ('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer')),导致资源创建失败。


排查过程

1、抓包分析

在出现这个问题之初是因为近期更了新版本才出现了这个问题,回滚旧版本后问题消失,因此本次的排查是在部署新版本后进行抓包分析。

基本信息:

  • 服务网关(enovy):

    • 10.20.30.93
    • 10.20.30.237
  • 服务端:

    • 10.20.30.52
  • 中台服务:

    • 10.20.30.73
  • 请求链路:

    • 客户端(页面) -> DPVS(外网) -> Nginx -> 中台服务 -> DPVS(内网) -> Nginx -> 服务网关 -> 服务端

    即”用户”在中台页面发起资源创建后,会先经过外网 DPVS 透传至 Nginx 并转发至”中台服务”,再由”中台服务”发起 HTTP 请求向内网 DPVS 透传至 Nginx 并转发至”服务网关”,最终由”服务网关”路由到目标”服务端”发起资源创建。

抓包详情如下:

当请求服务端正常接口时表现如下:

从上面几个完整连接过程来看,基本都在 HTTP 响应后,如果超过60s没有继续请求就会触发 FIN,ACK (结束连接)。

当请求服务端耗时超长的接口时表现如下:

而从上面的请求过程来看,当请求超过 90s 没有响应后,就会触发网关 FIN,ACK (结束连接),但因为此时服务端没有回应 FIN,ACK 进而导致网关在 45s 后触发 RST (强制中断)。

已知信息:

  • 服务端与服务网关的 TCP Keep-alive 是每 15s 一次,由服务端主动发起
  • HTTP正常响应后 60s 的闲置连接就会触发主动中断,由服务端主动发起
  • HTTP未能立即响应(响应超时)后 90s 就会触发异常中断,由网关主动发起

如果同时拿”客户端”与”服务端”的抓包结果对比观察:

可以看出客户端和服务端都是在 90s 分别收到来自网关和 DPVS 的 RST 报文,此时有理由怀疑网关或 DPVS 存在超时相关设置问题

2、检查enovy信息

  • 当前配置

    admin:
      access_log_path: /log/admin_access.log
      address:
        socket_address: { address: 0.0.0.0, port_value: 1023 }
    static_resources:
      listeners:
      - name: listener_0
        address:
          socket_address: { address: 0.0.0.0, port_value: 1024 }
        filter_chains:
        - filters:
          - name: envoy.http_connection_manager
            config:
              upgrade_configs:
              - upgrade_type: websocket
              stat_prefix: ingress_http
              idle_timeout: 600s
              codec_type: AUTO
              access_log:
              - name: envoy.file_access_log
                config:
                  path: "/log/info.log"
              route_config:
                name: local_route
                # 已忽略其余配置
                virtual_hosts:
                - name: web_service
                  domains: ["*"]
                  # 已忽略其余配置
                  routes:
                  - match:
                      prefix: "/upstream_server/"
                    route:
                      cluster: upstream_server_apiserver_service
                      timeout: 6000s
              http_filters:
              - name: envoy.router
      clusters:
      - name: upstream_server_apiserver_service
        connect_timeout: 5s
        type: LOGICAL_DNS
        lb_policy: ROUND_ROBIN
        hosts: [ { socket_address: { address: upstream_server-apiserver-service, port_value: 9113 } } ]
        common_http_protocol_options:
          idle_timeout: 180s

https://www.bookstack.cn/read/envoyproxy-1.10/144d336a80f65388.md

排查几项超时参数都是远大于 90s,与本次问题无关,初步排除网关问题

3、本地复现

在初步排除服务网关后,于是尝试在本地通过模拟请求的方式复现并排查问题触发时机,本次分别使用 curl 与 Python requests 进行对比测试。(因为线上使用的是 Python requests)

requests版本:

省略测试过程。

测试结果:

  • 在 curl 测试中,无论域名请求 DPVS VIP 还是直接请求 Nginx,都无法复现请求超过 90s 后因为 RST 原因导致连接异常断开的现象。测试结果均为 300s 服务端未响应而触发的客户端请求超时(408 Rquest Timeout),但这种连接中断不是因为 Nginx 响应 RST 而触发异常断开,而是正常的 “TCP挥手” 流程。

  • 在 Python requests 测试中,当客户端直接向 Nginx 请求时,不会出现 Connection Reset 的问题,与 curl 请求结果一致;但如果目标地址为 DPVS VIP 时就会在 90s 时复现 RST 问题。

    requests.exceptions.ConnectionError: ('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer'))

问题得到复现,抓包过程与线上一致不再重复贴图。

4、尝试解决

通过查找相似问题的 issue 可以看出,在代码前增加如下片段可以解决这类问题,因此对请求样例头部添加相关代码,然后再次进行请求验证:

#!/usr/bin/python3
# -*- coding: UTF-8 -*-
import requests
import json
import time
import socket
from urllib3.connection import HTTPConnection

HTTPConnection.default_socket_options = (
    HTTPConnection.default_socket_options + [
        (socket.SOL_SOCKET, socket.SO_KEEPALIVE, 1),
        (socket.SOL_TCP, socket.TCP_KEEPIDLE, 45),
        (socket.SOL_TCP, socket.TCP_KEEPINTVL, 10),
        (socket.SOL_TCP, socket.TCP_KEEPCNT, 6)
    ]
)

# 省略业务代码
...

print(time.strftime("%Y-%m-%d %H:%M:%S", time.localtime()))
response = requests.request("POST", url, headers=headers, data=payload, timeout=360)
print(response.text)
print(time.strftime("%Y-%m-%d %H:%M:%S", time.localtime()))

客户端输出:

2023-10-20 10:37:56
stream timeout
2023-10-20 10:42:56

从结果可以看出,即便还是请求 DPVS VIP,但在添加了相关代码后不再出现 RST 问题,也能够像 curl 一样超过 90s 最终触发客户端请求超时(408 Rquest Timeout)。

至此,已经可以确认问题是由 DPVS 产生的,并且有了临时的解决方式,但仍不知根本原因。


模拟环境

为了进一步验证其根本原因,即为何添加了相关代码后能够不会复现问题,并且为什么只有请求 DPVS VIP 时才会出现这个问题,由此进行了模拟环境测试。

0. 基本信息

  • 客户端: 192.168.7.91
  • Nginx: 192.168.7.27
  • 服务端: 192.168.7.92
  • DPVS: 192.168.7.82
  • VIP: 192.168.7.182
  • LIP: 192.168.7.185

注:

  • VIP: 作为DPVS的高可用IP,用于接收客户端请求的入口IP
  • LIP: 作为DPVS的转发IP,用于转发流量时向后端(RS)通信用的Local IP,而不是用DPVS IP向后端建连

1. 客户端请求VIP-requests下表现

客户端使用 Python requests 方式请求测试域名,分别在观察几个网络阶段的表现。

客户端侧抓包

  • 客户端 -> DPVS

  • 客户端输出

    Traceback (most recent call last):
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 803, in urlopen
        **response_kw,
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 537, in _make_request
        response = conn.getresponse()
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connection.py", line 461, in getresponse
        httplib_response = super().getresponse()
      File "/usr/local/python-3.7.11/lib/python3.7/http/client.py", line 1373, in getresponse
        response.begin()
      File "/usr/local/python-3.7.11/lib/python3.7/http/client.py", line 319, in begin
        version, status, reason = self._read_status()
      File "/usr/local/python-3.7.11/lib/python3.7/http/client.py", line 280, in _read_status
        line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
      File "/usr/local/python-3.7.11/lib/python3.7/socket.py", line 589, in readinto
        return self._sock.recv_into(b)
    ConnectionResetError: [Errno 104] Connection reset by peer
    
    During handling of the above exception, another exception occurred:
    
    Traceback (most recent call last):
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/requests/adapters.py", line 497, in send
        chunked=chunked,
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 846, in urlopen
        method, url, error=new_e, _pool=self, _stacktrace=sys.exc_info()[2]
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/util/retry.py", line 470, in increment
        raise reraise(type(error), error, _stacktrace)
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/util/util.py", line 38, in reraise
        raise value.with_traceback(tb)
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 803, in urlopen
        **response_kw,
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 537, in _make_request
        response = conn.getresponse()
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connection.py", line 461, in getresponse
        httplib_response = super().getresponse()
      File "/usr/local/python-3.7.11/lib/python3.7/http/client.py", line 1373, in getresponse
        response.begin()
      File "/usr/local/python-3.7.11/lib/python3.7/http/client.py", line 319, in begin
        version, status, reason = self._read_status()
      File "/usr/local/python-3.7.11/lib/python3.7/http/client.py", line 280, in _read_status
        line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
      File "/usr/local/python-3.7.11/lib/python3.7/socket.py", line 589, in readinto
        return self._sock.recv_into(b)
    urllib3.exceptions.ProtocolError: ('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer'))
    
    During handling of the above exception, another exception occurred:
    
    Traceback (most recent call last):
      File "clientTest.py", line 45, in <module>
        response = requests.request("POST", url, headers=headers, data=payload, stream=True, timeout=360)
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/requests/api.py", line 59, in request
        return session.request(method=method, url=url, **kwargs)
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/requests/sessions.py", line 589, in request
        resp = self.send(prep, **send_kwargs)
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/requests/sessions.py", line 703, in send
        r = adapter.send(request, **kwargs)
      File "/usr/local/python-3.7.11/lib/python3.7/site-packages/requests/adapters.py", line 501, in send
        raise ConnectionError(err, request=request)
    requests.exceptions.ConnectionError: ('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer'))

DPVS侧抓包

  • 客户端 -> DPVS

  • DPVS -> Nginx

Nginx侧抓包

  • DPVS -> Nginx

  • 请求日志:

    192.168.7.185:1026 80 - [21/Oct/2023:15:20:40 +0800] "POST /test HTTP/1.1" 499 0 434 "-" "python-requests/2.27.1" - 192.168.7.92:51020 - 90.817 90.818 opstest.nestealin.com "- - -" "192.168.7.185"

从上述抓包表现可以看出,在客户端请求后 90s 左右,DPVS分别向客户端、服务端发送了 RST 致使连接中断。

2. 客户端请求VIP-curl下表现

客户端侧抓包

DPVS侧抓包

  • 客户端 -> DPVS

  • DPVS -> Nginx

Nginx侧抓包

将本次测试请求的抓包过程与前一次使用 requests 方法对比可以发现,客户端在使用 curl 请求的第 60s 时会发送一次 TCP Keep-Alive 请求,而客户端使用 Python requests 方法请求时全程没有发起 TCP Keep-Alive 请求;而这种”请求保活”的方式也是客户端在使用 curl 时连接过程得以延续的关键。

3. 客户端直接请求Nginx

在客户端下继续使用 requests 向 Nginx 直接发起请求。

客户端侧抓包

Nginx侧抓包

当客户端直接向 Nginx 请求时,请求过程仍旧没有发送,但不会触发 Connection Reset 能够完成 HTTP 请求。

此时可以确认本次”异常断开”的行为是与 DPVS 有直接关系。

4. 客户端增加Keep-Alive

在客户端下继续使用 requests 向 DPVS VIP 发起请求,但本次在代码中添加”临时方法”,实现定期发送 Keep-Alive 请求,并抓取请求过程。

客户端侧抓包

DPVS侧抓包

  • 客户端 -> DPVS

  • DPVS -> Nginx

Nginx侧抓包

可见,在客户端开启 Keep-Alive 后,DPVS 也不会主动终止 TCP 连接,进而确认本次异常与 DPVS 的连接管理有关。(缩小问题范围)

5. 源码分析

通过源码分析可以大致看出在 DPVS 的 TCP 连接管理中是有一个定时器来实现超时处理的,再结合 dpvs/src/ipvs/ip_vs_proto_tcp.c at master · iqiyi/dpvs 初始化方法可以看出”监听状态”的超时参数是由 /etc/dpvs.conf 中的 ipvs_defs.tcp.timeout.established 定义的。

接下来为了进一步验证配置有效性,通过修改相关文件增加日志输出:

# 以下均为编辑tcp_send_rst方法
vi src/ipvs/ip_vs_proto_tcp.c +999
    if (conn->state != DPVS_TCP_S_ESTABLISHED) {
        RTE_LOG(WARNING, IPVS, "%s: only RST in ESTABLISHED.\n", __func__);
        return EDPVS_OK;
    }
    
// 方法末行增加
    RTE_LOG(WARNING, IPVS, "%s: IDLE ESTABLISHED RST Sended.\n", __func__);
    return EDPVS_OK;
}

重新编译并重启DPVS

cd /usr/local/dpvs-1.9.0
export DPVS_PATH=/usr/local/dpvs-1.9.0
export PKG_CONFIG_PATH=$DPVS_PATH/dpdk/dpdklib/lib64/pkgconfig:/usr/lib64/pkgconfig
export LIBDPDKPC_PATH=$DPVS_PATH/dpdk/dpdklib/lib64/pkgconfig/libdpdk.pc
make -j 20
make install -j 20

待编译通过后重启 DPVS 及 Keepalived 。

6. 效果验证

客户端直接请求VIP

curl 192.168.7.182 -v

# 因为没有携带域名请求不会命中测试配置,会立刻得到Nginx响应,连接终止
  • DPVS日志

    # 待请求完成后约7s出现如下日志
    tailf /data/logs/dpvs/dpvs.log
    IPVS: tcp_send_rst: only RST in ESTABLISHED.
    IPVS: tcp_send_rst: only RST in ESTABLISHED.

7s后进行连接回收是受限于 ipvs_defs.tcp.timeout.time_wait 参数,默认值为7

此处验证日志输出有效。

接下来开始请求测试域名

python3 clientTest.py
  • DPVS日志

    # 待请求发起后90s出现如下日志
    tailf /data/logs/dpvs/dpvs.log
    IPVS: tcp_send_rst: IDLE ESTABLISHED RST Sended.
    IPVS: tcp_send_rst: IDLE ESTABLISHED RST Sended.
    • 代表没能正常断开连接,而是让 DPVS 双向删除连接状态
  • Nginx日志

    192.168.7.185:1046 80 - [23/Oct/2023:14:08:13 +0800] "POST /test HTTP/1.1" 499 0 434 "-" "python-requests/2.31.0" - 192.168.7.92:51020 - 90.640 90.641 opstest.nestealin.com "- - -" "192.168.7.185"
    • 此时客户端触发 Connection Reset 异常复现问题,中断的时长为 90s

进而修改 DPVS 配置,延长 TCP 超时时间

vim /etc/dpvs.conf

修改内容如下:

仅展示关键配置

! ipvs config
ipvs_defs {
    ...
    tcp {
        ! defence_tcp_drop
        timeout {
            ...
            established 90
            established 100
            ...
        }
    }
    ...
}

对 IPVS 中 TCP established 状态的空闲连接超时设置从 90s 调高至 100s

并对 DPVS 执行配置重加载

kill -SIGHUP ${DPVS_PID}

客户端重新发起测试请求

  • DPVS日志

    tailf /data/logs/dpvs/dpvs.log
    
    # Reload日志简要输出,能够确认配置加载生效
    CFG_FILE: load dpvs configuation file at 2023/10/23 14:40:11 Monday
    IPVS: tcp_timeout_established = 100
    
    # 新的测试请求过程中,依旧因为"空闲"连接导致DPVS主动断开
    IPVS: tcp_send_rst: IDLE ESTABLISHED RST Sended.
    IPVS: tcp_send_rst: IDLE ESTABLISHED RST Sended.
  • Nginx日志

    192.168.7.185:1048 80 - [23/Oct/2023:14:28:24 +0800] "POST /test HTTP/1.1" 499 0 434 "-" "python-requests/2.31.0" - 192.168.7.92:51020 - 101.077 101.076 opstest.nestealin.com "- - -" "192.168.7.185"

虽然本次客户端仍会触发 Connection Reset 异常,但中断的时长已经变为 101s,基本与 DPVS 配置调整的预期一致,证明配置有效。

小结

  • curl 请求比 Python 的 requests 方法在客户端请求第 60s 时多发送了一次 TCP Keep-Alive 请求,让 TCP 连接保活、请求过程得以继续
  • DPVS 对 TCP 连接有设置定时器,对各种阶段的连接进行单独处理,最终由 /etc/dpvs.conf 配置中的 ipvs_defs.tcp.timeout 相关参数独立控制

关于408问题

在解决客户端 Connection Reset 问题之后,继续出现了下方的 Read timed out 问题:

2023-10-24 13:02:49
Traceback (most recent call last):
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 426, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 421, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/local/python-3.7.11/lib/python3.7/http/client.py", line 1373, in getresponse
    response.begin()
  File "/usr/local/python-3.7.11/lib/python3.7/http/client.py", line 319, in begin
    version, status, reason = self._read_status()
  File "/usr/local/python-3.7.11/lib/python3.7/http/client.py", line 280, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/local/python-3.7.11/lib/python3.7/socket.py", line 589, in readinto
    return self._sock.recv_into(b)
TimeoutError: [Errno 110] Connection timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/requests/adapters.py", line 449, in send
    timeout=timeout
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 727, in urlopen
    method, url, error=e, _pool=self, _stacktrace=sys.exc_info()[2]
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/util/retry.py", line 410, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/packages/six.py", line 735, in reraise
    raise value
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 677, in urlopen
    chunked=chunked,
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 428, in _make_request
    self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/urllib3/connectionpool.py", line 353, in _raise_timeout
    self, url, "Read timed out. (read timeout=%s)" % timeout_value
urllib3.exceptions.ReadTimeoutError: HTTPConnectionPool(host='192.168.7.182', port=80): Read timed out. (read timeout=None)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "clientTest.py", line 46, in <module>
    response = requests.request("POST", url, headers=headers, data=payload)
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/requests/api.py", line 60, in request
    return session.request(method=method, url=url, **kwargs)
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/requests/sessions.py", line 533, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/requests/sessions.py", line 646, in send
    r = adapter.send(request, **kwargs)
  File "/usr/local/python-3.7.11/lib/python3.7/site-packages/requests/adapters.py", line 529, in send
    raise ReadTimeout(e, request=request)
requests.exceptions.ReadTimeout: HTTPConnectionPool(host='192.168.7.182', port=80): Read timed out. (read timeout=None)

这是由于客户端在请求时设置了超时时间,去掉 timeout 参数后即可解决问题。

...
# 原代码
response = requests.request("POST", url, headers=headers, data=payload, timeout=360)
# 更改后代码,去除timeout参数即可
response = requests.request("POST", url, headers=headers, data=payload)
...

总结

1. 出现RST的原因

客观原因

  • 在 DPVS 中存在管理 TCP 连接的定时器,而对”监听状态” ( Established ) 的 TCP 连接默认设置为 90s 超时,即如果在此期间没有任何 TCP 报文传输,DPVS 就会分别向客户端与 RS 发送 RST 报文中断连接 ( 出现 RST 问题的原因1
  • 在 Python requests 方法中默认不会实现 TCP Keep-Alive 机制,需要额外增加 HTTPConnection.default_socket_options 实现”连接保活” ( 出现 RST 问题的原因2
  • 因为 DPVS 存在 TCP 空流超时设置( 原因1 ),并且 Python requests 默认没有发送 TCP 心跳( 原因2 ),导致如有请求连接超过 90s 未主动断开的,就会触达 DPVS 默认超时时间,随后 DPVS 会主动发送 RST 报文中断连接
  • Python requests 是依赖 urllib3 实现的 TCP 建连,但并没有向上暴露相关修改参数,使得用户无法在使用 requests 时直接管理 TCP 连接

主观原因

  • “中台服务”创建资源是串行执行,只有等到”服务端”资源完成创建后这个请求才算完成
  • “服务端”的资源创建流程通常需要 5、6 分钟甚至更多,导致一般的超时阈值无法覆盖整个执行过程
  • 综上,再结合”客观原因”而触发了创建中的 RST 问题

2. 为什么只在本次版本发布后出现该问题

  • 原来”中台服务”有对 RST 异常进行捕获并重试( “服务端”接口已做幂等校验 ),而在本次发版后因为框架升级忽略了相关处理,未能”捕获并重试”进而引发相关问题

3. 出现客户端请求超时(408 Rquest Timeout)的原因

  • 客户端有设置 timeout 主动超时参数,导致到了超时阈值后主动断开连接

Reference

HTTP route management - HTTP route - 《Envoy Proxy 1.10 Documentation》

https://requests.readthedocs.io/en/stable/user/advanced/#keep-alive

Connection reset by peer when sending POST · Issue #4937 · psf/requests · GitHub

Connection reset by peer · Issue #212 · edeng23/binance-trade-bot · GitHub

detection of dropped persistent connection fails if server resets connection · Issue #944 · urllib3/urllib3 · GitHub

https://urllib3.readthedocs.io/en/latest/user-guide.html#retrying-requests

连接中止: RemoteDisconnected (“没有响应的远程结束关闭连接”)在发送邮件时大约5分钟不活动之后-腾讯云开发者社区-腾讯云

python 环境配置 requests 模块使用,打开tcp keepalive解决请求长时间返回时tcp连接断开问题

http.client — HTTP protocol client — Python 3.12.0 documentation


文章作者: NesTeaLin
版权声明: 本博客所有文章除特別声明外,均采用 CC BY 4.0 许可协议。转载请注明来源 NesTeaLin !
  目录