使用 nginx 作反向代理,启用 keepalive 时,遇到 502 错误的调查过程

Tags: nginx 

本篇目录

现象

结论见 《kubernetes ingress-nginx 启用 upstream 长连接,需要注意,否则容易 502》。

nginx 的访问日志间歇性出现 502 响应,查看 nginx 的 error.log,发现是 upstream 返回了 reset:

2019/06/13 04:57:54 [error] 3429#3429: *21983075 upstream prematurely closed connection while reading 
response header from upstream, client: 10.19.167.120, server: XXXX.com, request: "POST XXXX HTTP/1.0",
upstream: "http://11.0.29.4:8080/XXXXXX", host: "XXXX.com"

2019/06/13 04:58:34 [error] 3063#3063: *21989359 recv() failed (104: Connection reset by peer) while 
reading response header from upstream, client: 10.19.138.139, server: XXXX.com, request: 
"POST /api/v1/XXXX HTTP/1.1", upstream: "http://11.0.145.9:8080/api/v1/XXXX", host: "XXXX.com"

调查

在 nginx 上抓包,nginx 向 upstream 发送请求后,upstream 直接返回 reset,nginx 回应 502,触发 reset 的请求的发送时间比上次晚了 1 分钟以上:

nginx 104 reset

检查其它正常响应的连接,发现服务端会在连接闲置 1 分20 秒的时候,主动断开连接:

nginx 104 reset

奇怪的是 nginx 设置的 keepalive_timeout 为 60 秒,为什么不是 nginx 主动断开连接?

验证第一个假设:服务端 idle 先超时会引发 reset

猜测 upstream 对应的服务端也设置了超时时间,并且比 nginx 先超时,因此出现了服务端率先断开连接情况。如果服务端断开连接时,nginx 正好向 upstream 发送了请求,就可能出现 reset 的情况。

部署一个服务端容器,服务端的 idle 超时设置为 10 秒,小于 nginx 中配置的 keepalive_timeout (60秒)。用 httpperf 模拟 100 个会话,每个会话以每间隔 9 秒发送 100 个请求的方式累计发送 300 个请求,会话创建速率是每秒 10 个。

httperf --server webshell.example.test --port 80 --wsess 100,300,9 --burst-len 100 --rate 10
./httperf --server webshell.example.test --port 80 --wsess 1,256,9 --burst-len 128 --rate 1

遗憾的是 httperf 太老旧支持的量太少,没能复现出来。假设的场景本身也很难复现,必须恰好在连接因为超时关闭时发送请求,比较难复现。

另外找到三篇文章都在讨论这个问题:

  1. 104: Connection reset by peer while reading response header from upstream
  2. HTTP 502 response generated by a proxy after it tries to send data upstream to a partially closed connection (reset packet)
  3. Analyze ‘Connection reset’ error in nginx upstream with keep-alive enabled

发现新情况

有用户反应能够稳定复现 502,且是在压测期间发现的,这就奇怪了。idle 超时导致的 502 应该很难出现,能稳定复现 502 肯定是有其它原因。

在继续调查的过程中,首先想到的是「长连接中的最大请求数」,服务端会不会设置了单个连接中能够处理的请求数上限,并且该上限小于 nginx 中的配置?

公司的业务系统主要是 tomcat 服务,因此优先调查 tomcat 的配置,发现了下面的参数:

tomcat config maxKeepAliveRequests

tomcat 默认每个连接中最多 100 个请求,而 nginx 中配置的 keepalive_requests 超过了 100,这会不会是问题根源?需要测试验证一下。

同时发现 tomcat 默认的 idle 超时时间是 60s,和前面提出的超时假设能够相呼应,tomcat 7 和 tomcat 8 的使用的是相同的默认配置。Tomcat Config

tomcat config maxKeepAliveRequests

tomcat config maxKeepAliveRequests

验证第二个假设:服务端率先断开连接导致502

部署一个 tomcat 服务,idle 超时时间为 60s,maxKeepAliveRequests 为 100,nginx 的 idle 超时为 60s,keepalive_requests 为 2000,用下面的命令压测:

./wrk -t 4  -c 10000 -d 90s http://ka-test-tomcat.example.test/ping

10000 并发压测 90s 时,出现 502 响应:

1000并发压测出现502响应

然而从报文发现:服务端直接 reset 的连接数是 24 个,数量远远低于 502 响应的数量。

服务端发起的reset

怀疑还有其它原因,检查 nginx 发现大量下面的日志:

2019/06/17 09:35:46 [crit] 28805#28805: *9114394 connect() to 10.12.4.197:8080 failed (99: Cannot assign requested address) while connecting to upstream, client: 10.10.173.203, server: ka-test-tomcat.example.test, request: "GET /ping HTTP/1.1", upstream: "http://10.12.4.197:8080/ping", host: "ka-test-tomcat.example.test"
2019/06/17 09:35:46 [crit] 28806#28806: *9114649 connect() to 10.12.4.197:8080 failed (99: Cannot assign requested address) while connecting to upstream, client: 10.10.173.203, server: ka-test-tomcat.example.test, request: "GET /ping HTTP/1.1", upstream: "http://10.12.4.197:8080/ping", host: "ka-test-tomcat.example.test"
2019/06/17 09:35:46 [crit] 28804#28804: *9114172 connect() to 10.12.4.197:8080 failed (99: Cannot assign requested address) while connecting to upstream, client: 10.10.173.203, server: ka-test-tomcat.example.test, request: "GET /ping HTTP/1.1", upstream: "http://10.12.4.197:8080/ping", host: "ka-test-tomcat.example.test"

统计了一下,crit 日志数和 502 响应的数量级相同,断定本次压测中产生 大部分 502 是 nginx 上的端口不足导致的又发现了一种导致 502 原因:nginx 的端口耗尽

尝试降低并发数量,排除端口耗尽的情况:

./wrk -t 4  -c 500 -d 300s http://ka-test-tomcat.example.test/ping

结果比较悲催,无论如何也没有 502,检查报文发现有少量服务端回应的 RST 报文,是在发起了 FIN 连接后再次回应的。 而在多次压测过程中,又的确出现过两次总计100多条的 104: Connection reset by peer日志,但就是复现不出来,不知道是它们在什么情况下产生的……

新的发现

有点陷入僵局,回头审视反应能够稳定复现 502 的用户的系统,最后一个请求与上一个请求的间隔时间是 2 秒。

最后一个请求与上一个请求间隔时间2秒

这个 2 秒的时间差一开始带来了困扰,也正是这个 2 秒的时间差,让我怀疑之前的超时断开假设不成立,调头去查 maxKeepAliveRequests 的问题。

进入用户的系统后,发现后端服务是用 Gunicorn 启动的 python 服务,查阅 Gunicorn 的配置,发现它默认的 keepalive 时间是 2秒,正好和报文中的情况对应。

Gunicorn 默认的 keepalive 配置是 2 秒

也就是说,能够稳定复现的 502 也是因为服务端先触发 idle 超时,之所以能够稳定触发,因为后端服务的配置的超时时间只有 2秒,而请求端又恰好制造出静默两秒后发送下一个请求的场景。

超时断开应该比超过 maxKeepAliveRequests 断开更容易引发 502,因为超过 maxKeepAliveRequests 时,会在最后一个请求结束后立即发送 FIN 断开连接,不容易与 nginx 正在转发的请求「撞车」,而超时断开可能在任意时刻发生,可能正好是 nginx 收到新的请求的时候,转发新请求时与服务端关闭连接的操作「撞车」。

初步结论

根据日志和原理进行推测,提出两个可能有效的方案:

  1. nginx 的 keep-alive 的 idle 超时要小于 upstream 的 idle 超时;
  2. nginx 的 keepalive_request 要小于 upstream 的相关设置。

以上两个配置可以保证连接断开都是 nginx 发起的,从而可以避免向一个已经关闭的连接发送请求。

参考

  1. 李佶澳的博客笔记

推荐阅读

Copyright @2011-2019 All rights reserved. 转载请添加原文连接,合作请加微信lijiaocn或者发送邮件: [email protected],备注网站合作

友情链接:  系统软件  程序语言  运营经验  水库文集  网络课程  微信网文  发现知识星球