Py学习  »  NGINX

Nginx一次奇怪的502 报错探究

hainuo • 5 年前 • 487 次点击  

荆天佑,新房研发部,17年3月加入链家,任职PHP研发工程师,负责新房link的研发工作。

之前遇到的一个偶发的错误,探讨下到底是怎么肥四~ 

1

一次奇怪的线上问题

之前遇到nginx报出了如下的error,upstream sent too big header while reading response from upstream,导致服务502 bad gateway, 但是奇怪的是某些特定的请求稳定复现,但是其他请求却一直没有问题,正常返回。

一时之间,还真不知道什么原因,唯一的异常是观察到warninig日志较多,我们知道正常情况下,php的warning并不会导致流程的中断。结合报错信息,推测可能是php-fpm会把warning日志加到response header头里,导致头部过大而报错。

首先我们看下报错代码是什么样子的,php代码中存在类似以下的错误片段:

此时会报warning的错误,类似于:

大量的warning如果会被加到header头里的话,会触发nginx的相关配置(如果有的话),导致报错,看起来解释的通。但是还是存在疑问:

1). 是否真的是因为response header过大导致的呢,

2). 是否像网上说的那样,提高fastcgi_buffer_size配置的大小就可以解决这个问题呢?

接下来我们探讨一下

2

简单分析一次请求的日志行为

由于该问题是线上发生的,无法抓取到问题发生时php-fpm与nginx之间到底发生了什么,所以计划在自己的开发环境复现, 不过首先需要能够对nginx与php-fpm进程间通信的数据进行抓取。

2.1 抓取php-fpm与nginx之间的通信数据

 

2.1.1 php监听端口通信方式的监听

速度较unix socket较慢,但是支持跨机器调用,我们可以通过tcpdump进行抓取。

ps:开放php端口对外提供fastcgi服务的方法

2.1.2 以unix socket方式通信数据的抓取

该方法速度较快,性能高,可以通过监听socket通道得到数据。

2.1.3 抓取到的数据大概的样子

2.2 简单分析

让我们观察下日志, 首先可以看到tcp的建立连接的数据,可以顺便直观了解下tcp的三次握手:P

2.2.1 一次请求的nginx-error日志(nginx-error)

2.2.2 一次请求的tcpdump的日志(tcpdump-log)

2.2.3 简单结论

观察到的现象

•php-fpm确实将warning与error日志都传给了nginx

•tcpdump的日志,明显响应头大于fastcgi_buffer_size设置的大小,但是并未报错

•nginx-error日志,可以明显的发现,日志是一段一段的并且有截断,大小和fastcgi_buffer_size的大小相当

得到的初步结论

对比nginx日志与tcpdump的日志的量,我们能看到:

1).php-fpm确实会将warning与error传递给nginx

2).不管fastcgi_buffer_size设置了多少,其实是根据fastcgi_buffer_size的大小来一段一段的读取php-fpm的响应头,不管传了多少的header,都会按照fastcgi_buffer_size的大小,一段一段的读取,然后写入到nginx的日志。

得到了上述结论,我们大致可以确定,并不是因为header头过大,或者说php-fpm传递给nginx的数据超过fastcgi_buffer_size的值才报出的502,那到底是为什么会报相关错误呢?

接下来探讨一下nginx内部

3

nginx内部发生了什么

首先我们知道:

 nginx发送请求数据与接收来自后端服务器的响应可以同时进行,是一种全双工方式;而对于不同的接收数据;nginx传递数据给后端的方式也不同,对于response header,只有在完全接收response header之后,才会转发给client,而对于response body,则是一边接收数据,一边转发给client。

3.1 fastcgi_buffer_size

我们知道,fastcgi_buffer_size与proxy_buffer_size这两个参数会影响到响应头, 其中proxy_buffer_size影响的是nginx作为反向代理时的参数 对于nginx配置文件中的fastcgi_buffer_size,文档中是这么写的:

文档,其中 the first part of the response received from the FastCGI server.,这个参数指定的是接受到fastcgi-server端的第一部分的响应(一般是response header),在lnmp的场景里,fastcgi-server就是php部分 其中这个first part的含义是这样子的,由于upstream是一个通用的组件,它不知道后端的协议,而对于http场景来说,由于http是需要header的,而后端的协议不一定有头,此时就需要我们通过解析后端的协议,然后来设置好发送给client的头,最终发送给client,通过上面的观察,我们发现php的错误信息也会包含其中。

以下是所谓的正常情况下的the first part of the response的结构(header):

  • 接收到的upstream header的格式如上,我们可以看到,存在两种header,种是fastcgi的header,一种是http的header,因此需要两个状态机进行解析;

  •  一个fastcgi的header,后面可能跟随一个或多个http header;

  •  一个fastcgi header与对个http header组成一个组,这个也是nginx解析header的  最小单位,每一个组使用两种状态机,从而获取响应头信息。

3.2 nginx代码报错分析

源码中报错的位置如下&error:

可以看到,当处理头部的会调函数process_header返回NGX_AGAIN,同时已经读取到了response的末尾,则会报错。

3.2.1处理头部的回调函数process_header伪代码

以上是流程代码,具体细节未展示, 以上代码会对http与fastcgi的header分别进行解析

当两个状态机对fastcgi与http头解析如果出错的话(比如header头缺失或者格式不正确),也会返回NGX_AGAIN,如果此时读取到php-fpm返回的header的尾部时,也会报错, 那到底是否是这个原因呢?php-fpm传送了残缺的或者没有传递response header才导致的报错?

向前迈步,牛刀小试

4

尝试复现

如果可以复现出502,我们就能验证我们的猜想。 我们可以不断的增大warning数目的同时监听端口与日志。当502发生时,截取php-fpm到底传了什么样的数据给nginx ,是否是因为过多的warning写入到了fastcgi_buffer_size中导致的,我们可以按着这个思路,进行强行复现。

4.1 php脚本

我们可以尝试着一步步加大error的size,来观察发送502时的日志情况,按照这个思路,可以采用以下类似脚本:

4.2 日志监听

脚本运行的同时监听php绑定的端口,得到tcpdmp日志(此时,fastcgi_buffer_size 4K)。

4.3 压测方法

使用循环对脚本进行请求,不断的增加单条日志的size与迭代次数 ,使其向日志里写入更多的字节,同时过滤返回的502以及报错时的迭代次数与每次日志的大小。

以上是php-fpmnginx是使用的端口通信。

顺便说下,unix socket通信方式性能真的很高,同样的测试方法,对于unix socket方式通信的lnmp,测试语句运行完了也没有报502。 由上可知,我们复现了502,下面我们对日志进行紧张的分析。

4.4 结果分析

报错的nginx日志:

可以看到我们成功复现了too big header报错:P

正常的nginx-error日志:

紧张分析

上面的日志,一个是39:01,一个是39:02的,按照我们的测试脚本,时间越靠后,传递的日志量会越大(至少是之前的3倍),但是为什么数据量较小的39:01秒的日志触发了502,而数据量较大的39:02没有报错?而且,nginx记录的日志的量也是相同的,明显有截断,明显超出了4K,这也能验证我们的推测,其实fastcgi_buffer_size并不是一个检查值,超过这个值并不会报错。而更像是一个暂存的空间的大小。

进一步紧张分析

我们回去看下之前监控的tcpdump的日志,发现了一些有趣的现象。

一次正常请求的tcp日志:

一次502请求的tcp日志:

发现了吗,502报错的情况下,tcpdump抓到的包中,末尾缺少了http的response header,这正验证了我们之前的推测,php-fpm在返回body之前,并没有传递完整的response header给nginx,导致nginx报出来错误。

4.5 暂时的结论

观察上面的日志,报错最后的响应头不完整或者根本就没有,这个正好会进入到nginx中未解析到header头并且已到header尾部的情况触发报错, 所以暂时现在可以推断的是:

php-fpm会在一定的情况下向nginx传送不完整的响应头数据,导致nginx解析fastcgihttpheader时出错,导致报出502。 

这看起来不可思议,竟然是下游服务出了差错,而不是因为nginx内的fastcgi_buffer_size太小导致的错误,不过该问题并不是不可能发生:

展开新一轮探讨,技术嘛!

5

不同fastcgi_buffer_size下502情况

5.1 fastcgi_buffer_size 1k

nginx日志

不会报502的错误日志:

会报502的错误日志:

tcpdump的日志

不会报502的错误日志:

会报502的错误日志:

测试结果

5.2 fastcgi_buffer_size 2k

nginx日志

不会报502的错误日志:

会报502的错误日志:

tcpdump的日志

不会报502的错误日志:

会报502的错误日志:

测试结果

5.3 fastcgi_buffer_size 4k

nginx日志

不会报502的错误日志:

会报502的错误日志:

tcpdump的日志

不会报502的错误日志:

会报502的错误日志:

测试结果

5.4 观察发现

由上1k,2k,4k的比对结果,我们可以得出以下结论:

综合以上502报错时的size与iteration的值的乘积,我们可以发现,不同fastcgi_buffer_size下,其实发生502错误时的php-fpm传给nginx的数据的大小基本是一样的, 提高fastcgi_buffer_size的大小,并不能减少too big header的发生风险, 但是依然建议设置成操作系统分页的大小。

终于出炉了,小编手要抽筋啦!

6

结论

经过探究,我们最终可以得到:

1.php-fpm确实会将warning与error传递给nginx;

2.不管fastcgi_buffer_size设置了多少,其实是根据fastcgi_buffer_size的大小来一段一段的读取php-fpm的响应头,不管传了多少的header,都会按照fastcgi_buffer_size的大小,一段一段的读取,然后写入到nginx的日志;

3.php-fpm会在一定的情况下向nginx传送不完整的响应头数据,导致nginx解析fastcgi与http的header出错,导致报出502;

4.提高fastcgi_buffer_size的大小,并不能减少too big header的发生风险。

接下来再探讨一下,你说啥~

7

疑问

经过以上的探究,我们可以看到以上的结论,但是仍有很多疑问:

1.为什么php-fpm发送的数据会缺少header

2.有没有其它情况会导致too big header报错

3.线上问题是仅有特定的请求参数会稳定复现,其他的则不会复现,到底发生了什么?是我们探究的原因导致的吗?

以上的疑问待进一步的探究。

程序猿哥哥就是执着!

8

对疑问进一步分析

经过老司机的指点,对以上压测得出的数据进行进一步的分析, 上面我们探究了在不同fastcgi_buffer_size下的502出错情况,具体的日志如下:

8.1 观察

对比上述结果,有没有发现什么诡异? 为什么三次压测的结果,得到的502次数都是10次 为什么第一次报错都是在size=121,iteration=30的情况下发生的?

8.2 进一步分析结果

我们把每一次的size与iteration进行相乘,我们可以得到如下的一些结果:(添加上开头的PHP message: 这13个字符)

我们知道1024是程序员日,那上面的数据有什么敏感的吗?

。。。。

9

甩锅

对比上面的数据,似乎是php的日志大小在某一个nk的时候(我的测试机器上很可能是4k), 会稳定复现这个问题呢? 这也很好的解释了为什么线上的某些请求会稳定复现502的现象,而其他请求,即使打了更多的php warning日志也不会触发502报警的现象。

这回,我们可以把锅甩给php-fpm,我们可以大胆猜测一下:

是否php-fpm内部也存在类似的buffer(在我的测试机器上也许是4k),也许这段buffer是tcp发送消息的缓冲区,当发送的字节很接近4k时, 就会触发某些bug,导致某些尾部数据的丢失, 而当大小与4k的整数倍的数据相差比较大的数据,则不会丢失数据, emmm,也许是在重新分配buffer的时候出了问题,导致的数据丢失:P

 

以上探究仅是个人观点,可能存在错误,欢迎交流~

 Eamil:jingtianyou@lianjia.com

作者:荆天佑


监审:蔡白银

编辑:钟   艳

网址:tech.lianjia.com

识别二维码请关注

链家产品技术团队

产品技术先行


今天看啥 - 高品质阅读平台
本文地址:http://www.jintiankansha.me/t/NIIYWHZ89f
Python社区是高质量的Python/Django开发社区
本文地址:http://www.python88.com/topic/11292
 
487 次点击