OpenResty与ceph连接broken pipe异常

Posted 2021-07-30 sysu_lluozh

一、问题描述

在对OpenResty+ceph自建存储服务进行压测：

维度	数值
节点数	1
并发数	10 * 3

压测结果

error rate：0.01%(四舍五入的结果，其实error rate仅为0.006%)

其中客户端status code为500

二、日志分析

查看OpenResty服务日志，其中出现以下两种错误的日志信息

2021/05/13 14:20:08 [error] 1828#1828: *2512017 send() failed (32: Broken pipe), client: 172.28.10.17, server: public.lluozh.com, request: "POST / HTTP/1.1", host: "store-pub.lluozh.com"
2021/05/13 14:20:08 [error] 1828#1828: *2512017 (...penresty/lualib/resty/apigateway/callback_content_by.lua):817: trace_id: 06a702c60ffcda2331ce994f3afd6053 , broken pipe, client: 172.28.10.17, server: public.lluozh.com, request: "POST / HTTP/1.1", host: "store-pub.lluozh.com"
2021/05/13 14:20:08 [error] 1828#1828: *2512017 (...penresty/lualib/resty/apigateway/callback_content_by.lua):1097: trace_id: 06a702c60ffcda2331ce994f3afd6053 , form upload failed!, rgw endpoint:   10.180.1.18:80 , Error:  broken pipe, client: 172.28.10.17, server: public.lluozh.com, request: "POST / HTTP/1.1", host: "store-pub.lluozh.com"

2021/05/13 11:27:42 [error] 1790#1790: *2231405 (...penresty/lualib/resty/apigateway/callback_content_by.lua):817: trace_id: ed11a8747461a3a0f5a76e3bdcedbf1e , closed, client: 172.28.12.15, server: public.lluozh.com, request: "POST / HTTP/1.1", host: "store-pub.lluozh.com"
2021/05/13 11:27:42 [error] 1790#1790: *2231405 (...penresty/lualib/resty/apigateway/callback_content_by.lua):1097: trace_id: ed11a8747461a3a0f5a76e3bdcedbf1e , form upload failed!, rgw endpoint:   10.180.1.19:80 , Error:  closed, client: 172.28.12.15, server: public.lluozh.com, request: "POST / HTTP/1.1", host: "store-pub.lluozh.com"
2021/05/13 11:27:42 [error] 1790#1790: *2231405 (...penresty/lualib/resty/apigateway/callback_content_by.lua):1154: trace_id: ed11a8747461a3a0f5a76e3bdcedbf1e , filekey:  test-lluozh-pub/6174bcea21324953a935fbcb3b2b1131 , Failed to write ceph. call_ceph_res.status:  nil, client: 172.28.12.15, server: public.lluozh.com, request: "POST / HTTP/1.1", host: "store-pub.lluozh.com"

即连接broken pipe或者closed

三、OpenResty连接配置

连接broken pipe或者closed然后发数据包异常，猜测可能的原因及尝试：

3.1 连接超时

在OpenResty配置的连接超时时间

local keepalive_timeout = 10000 -- 单位毫秒

在ceph中配置的连接超时时间

request_timeout_ms=50000

感觉不太像是超时连接关闭

3.2 数据包发送超时

暂时未有方式可以定位排查该可能性

3.3 数据包数量达到一定的限度

在OpenResty中修改发送次数，当发送超过20次则断开连接

if err then
        ngx_log(ngx.WARN, err)
elseif times > 20 then
   httpc:close()
   return
end

尝试后发现问题依旧存在，故并未是应该包发送数量达到一定的限度导致该问题

3.4 一段时间未收到数据包

在OpenResty中有请求超时时间配置

local request_timeout = 10000 -- 单位毫秒

如果将该时间设置的足够短，是否可以避免潜在的超时断开的异常出现？

将该值修改为200后发现请求1000w次均未出现以上的异常，但是将该值修改为600、1000等异常仍存在

3.5 数据解析异常

OpenResty日志中未捕获到异常，但在ceph源码中看到如果数据处理异常确实会有closed connection的操作

且在OpenResty中：

在form_body_reader中设置

local chunk_size = 1024*2

而在proxy_request中设置

local chunksize = 1024 * 1024
res, err = httpc:proxy_request(chunksize, body_reader)

修改form_body_reader以及proxy_request中chunk_size的大小，发现完全不起作用，且在3.4中的验证信息，大概率并不是数据包解析异常导致

四、抓包分析

只能通过异常的数据包确认问题，如下是一个完整TCP包的异常部分

172.28.52.212为OpenResty的地址，10.180.1.19为Ceph的地址，可以明显看到是Ceph主动发起了FIN包

那为什么Ceph主动发起了FIN包呢？

针对几个完整的正常和异常TCP数据包，统计相应的数据看看异常原因：

端口	SYN开始时间	FIN时间	持续时间/ms	包数量	是否异常
33598	10:53:24.321477	10:53:25.259571	938.094	22	否
35690	10:53:32.632794	10:53:33.468011	835.217	22	否
33646	10:53:24.653875	10:53:26.062256	1408.381	8	是
37050	10:53:23.980141	10:53:25.815086	1834.945	22	否
53468	15:10:14.712058	15:10:15.829086	1117.028	22	是

可以很明显看出：

1. 并未是因为持续时间过长导致断开连接
2. 与包数量无关

到这里似乎找不到任何的信息，只能通过ceph服务端查看是否有什么异常或者配置信息，均没有定位到问题的原因

五、抓包分析2.0

还是回到数据包上，再次比对有异常的数据包发现有个奇怪的信息

1. openresty上个数据包回复ACK
2. 下一次openresty发送数据包请求
3. ceph直接发送FIN包

我们看看其中的时间间隔

• 1和2的时间间隔为：956.878ms(10:53:26.059031 - 10:53:25.102153)
• 1和3的时间间隔为：959.803ms(10:53:26.062256 - 10:53:25.102153)

时间基本上间隔为1s，也就是说OpenResty发送上一个包成功结束后，再次发起下一个包的时间恰好间隔了1s

这个是否是巧合呢？我们抓包看看另外一个异常的完整TCP数据包

这个时间间隔为1000.817ms(15:10:15.829886 - 15:10:14.829069)

ps：其实这个包更明显，间隔时间1s后ceph主动发起FIN包，在基本同一时刻点(时间间隔0.024ms)OpenResty发起下一次的数据包传输

那是否是空闲等待时间1s后ceph发起FIN包断开连接？可以通过发送单个请求验证

可以明显看到，静待1001.337ms后ceph主动FIN关闭连接

综上，基本可以断定是因为OpenResty上一次数据包发送后间隔空闲时间1s，ceph发起FIN包，同时OpenResty发起数据包传输导致异常

六、ceph配置

由于OpenResty并未设置空闲超时时间，而且这个超时FIN包是由ceph发起，故接下来重点排查ceph的配置项

6.1 rgw_curl_wait_timeout_ms配置

拉取查看ceph生效的所有配置项：

"rgw_curl_wait_timeout_ms": "1000",
"rgw_exit_timeout_secs": "120",
"rgw_frontends": "civetweb port=0.0.0.0:80 num_threads=1024 enable_keep_alive=yes request_timeout_ms=50000",
"rgw_init_timeout": "300",
"rgw_inject_notify_timeout_probability": "0.000000",
"rgw_olh_pending_timeout_sec": "3600",
"rgw_op_thread_suicide_timeout": "0",
"rgw_op_thread_timeout": "600",

当前生效的timeout参数rgw_curl_wait_timeout_ms，且设置的时间为1000ms，可能性极大

由于OpenResty中配置request_timeout = 10000ms，将ceph中rgw_curl_wait_timeout_ms设置为12000，讲道理不会再次触发间隔时间超时导致ceph主动关闭连接，重启再次运行

问题同样存在，抓包发现依旧是1s后ceph发起FIN包导致

那其实并不是rgw_curl_wait_timeout_ms参数引起，看看这个参数的定义

限制的是curl调用的超时时间，确实并未是这个参数导致

6.2 HTTP Frontends

重新过一遍所有的ceph rgw官方参数配置列表 ，所有相关timeout等配置项均没有设定空闲超时时间，但有一个HTTP Frontends的配置项

配置HTTP前端，提供多个前端的配置，那跳转看看该配置信息述

查看了HTTP Frontends中的Civetweb配置(项目中使用的是该方式)，类似有timeout的配置信息仅仅有request_timeout_ms

很明显并未我们需要的设置项，且默认时间为30000ms，也并不符合

6.3 keep_alive_timeout_ms

发现其实还有一个隐藏的Civetweb User Manual，即Civetweb的用户手册

查看了一遍所有参数后发现有一个很疑似的配置参数keep_alive_timeout_ms

一个保持活动连接中两个请求之间的空闲超时，且我们在现在的rgw_frontends配置中有配置

enable_keep_alive=yes

但是有个疑问点在于默认的时间为500ms，但是我们显示的却是1000ms，因为设置的是一来一回等待时间则double？接下来试试将该值改为300ms，如果ceph超时600ms则发起FIN包说明验证正确

间隔时间559.247ms(17:01:06.197149 - 17:01:06.756396)，基本为600ms，验证正确

七、解决问题

由于OpenResty的连接超时时间为10000ms，将ceph的keep_alive_timeout_ms参数设置为6000ms，并发发送请求1000w次，均未出现异常，问题解决

接下来需要验证不同的配置参数下对于性能的影响

其实还有一个疑问点，并发线程数为30，qps 750+，为什么高并发下还会出现连接超过1s并未发起数据包传输