问题排查:nginx的反向代理感觉失效了一样

问题,排查,nginx,反向,代理,感觉,失效,一样 · 浏览次数 : 1751

小编点评

**问题:** 为什么服务端nginx在location众多时,到底发给了哪个后端upstream呢? **解决方案:** 在access_log中,默认包含了一个日志format为combined,内容:The configuration always includes the predefined “combined” format:log_format combined '$remote_addr - $remote_user [$time_local] ' '\"$request\" $status $body_bytes_sent ' '\"$http_referer\" \"$http_user_agent\"';我们可以增加一个属性$upstream_addr,即可展示转发到哪个upstream了。 **代码:** ```nginx access_log logs/access.log combined1; log_format combined1 '$remote_addr - $remote_user [$time_local] ' '\"$request\" $status $body_bytes_sent ' '\"$http_referer\" \"$http_user_agent\" $upstream_addr; ``` **效果:** 在location众多时,服务端nginx会自动根据配置的backlog值,选择转发请求到哪个后端upstream。

正文

背景

最近,负责基础设施的同事,要对一批测试环境机器进行回收,回收就涉及到应用迁移,问题是整个过程一团乱。比如服务器A上一堆应用要调用服务器B上一堆服务,结果服务器B被回收了,然后服务器A上一堆应用报错。

今天就是负责查一个问题,app上一个头像上传的接口,之前都好好的,不知道怎么就不能访问了,报错现象是在请求后等待n秒超时,然后服务端报错502。

这个服务也不知道谁维护的,可能维护的人早已离职了也说不定,这也是这边的常态吧,人走了,负责的服务还在服务器上跑,也没有交接文档。

问题现象

链路梳理

先上个图,再解释整个链路:

image-20230824200723942

现象就是,app端调用外网ip(记作A): xxxx端口的某个接口,超时后报502错误,因为是http协议,能从响应中看出来是Apache。

然后,就是去找网络同事,问外网ip:xxx端口对应的内网ip和端口,得到了内网ip(记作B):80端口。接下来,又是找负责服务器的同事,要服务器B的密码,一开始以为是linux机器,没想到还是windows的。vnc登录进去后,根据端口号找到对应的进程,发现是Apache HTTP Server,这个东西我也不熟悉,知道它类似于nginx,功能类似,但是几乎一直没用过,所幸,在程序的根目录下,找到了一个配置文件,配置文件中配置了反向代理,将请求反向代理到了服务器C:8088端口。

这个服务器C,基本就是今天的主角了。

于是,又去找同事要服务器C的密码,这次还好,是个linux机器,查询8088端口对应的服务,是个nginx进程,然后查看该进程的配置文件,发现请求被反向代理到了本机的9901端口。

问题现象

梳理完整个链路后,我决定去看看最后的java服务的日志,因为是第一次看到这个服务,也不知道日志文件在哪里。cd到/proc/服务pid/fd目录下,看到了其打开的文件,里面有个日志文件,但是,打开日志文件,发现里面空空如也。

我又去调了调日志级别,然后app发起请求,发现还是没啥日志。

然后开始怀疑请求没到服务这里,行吧,那还是跟着链路排查下,看看怎么回事。

于是在linux机器上开启java服务的9901端口的抓包,然后重试,发现还是空空如也,什么包都没有。

tcpdump -i any tcp port 9901 -Ann

这就奇怪了,没到java服务,那到了nginx没有呢?然后开始抓nginx这块:

tcpdump -i any tcp port 8808 -Ann

这次发现包还挺多的,于是根据接口名(url包括Upload关键字)加了个过滤条件:

tcpdump -i any tcp port 8808 -Ann |grep Upload

这次发现,能抓到包。这,意思是,看起来nginx是收到包了,但是,没往java服务发啊。这倒是奇了怪了,看起来,反正是nginx的问题,于是,去看nginx的access日志和error日志,发现access日志里并没有该接口的记录,error日志里也啥都没有。

于是我调整了nginx error日志级别为info,如下(从上而下,越来越详细):

alert - 系统级别紧急信息
critical - 关键错误信息
error - 一般性错误信息
warn - 警告信息
notice - 一些特殊信息
info - 一般信息
debug - 调试信息

error_log /var/log/nginx/error.log info;

结果,发现error日志还是啥都没有。

然后,我想着是不是我配置文件没看对,我以为会走某个location,该不会没匹配上,走到别的location了,然后转发到其他后端去了?

后面仔细观察了请求接口的url,感觉还是没问题。

当时,基于两个原因,决定采用strace去看看nginx的系统调用:

  • 看看是不是我把location看错了,nginx把请求发到其他机器去了,所以在9901的java服务才看不到日志
  • 看看是不是nginx内部报啥错了,error日志没体现出来

然后找到nginx的pid后,使用如下命令查看网络调用:

strace -p nginx-pid -q -f  -s 10000 -e trace=network
命令我也是查了自己当年的文章,不然谁记得住:
https://www.cnblogs.com/grey-wolf/articles/13139308.html

结果,发现系统感觉有问题,执行命令后,啥结果都没有。

换了nginx的worker进程的pid,还是没效果。后边再换了个pid,直接卡死了,ctrl c也没用。

我他么就是感觉这机器有点怪,之前执行lsof也卡住不动,现在strace又这样,真的服了。

一看时间,到午饭时间了,吃饭吧。

来了一点灵感

吃完饭,我又去把之前抓的windows apache和nginx之间的网络包打开分析了一会。

包的前面几个报文如下:

image-20230824205015484

前三个报文是三次握手,8088是我们的nginx服务端。因为我的包就是服务端抓的,看起来,一切正常,服务端是正常完成了三次握手了。

包4,客户端发了个报文过来,包长1516字节,这个包,其实也就是包含了http请求(见下图);理论上,下一个包应该是我们回复ack,表示包4收到了。

image-20230824205721980

但是,下面的包5、包6,看起来是客户端发生了重传,为啥要重传呢?不知道,接着看下面。

image-20230824205407186

看我上图标红的下面那一行,是我们服务端nginx往客户端发的,68个字节,也有个重传字样,看起来,意思是我们也发生了重传,重传了哪个包呢,就是包2,也就是握手时候的我方回复的syn+ack那个包。

再加个过滤,看看我方到底给对方发了些啥包:

image-20230824205620749

结果,我方貌似一直在给对方重传第二次握手的消息。

我想了半天,终于想差不多了,看来是客户端的第三次握手的ack,被我们忽略了,所以,我们这边,连接一直不是established状态,而是syn received状态。而客户端呢,发完第三次的ack后,就进入了established状态,所以就开始发http请求过来了,我方由于状态不是established,所以一直给对方重发syn + ack。

Tcp_state_diagram

为啥会忽略第三次的ack呢,我突然想起来,如果接收了ack,连接就会正式建立,连接就会放入accept队列(全连接队列),等待应用去accept了。现在反过来想,既然没往accept队列放,会不是队列满了,所以干脆就不添堵了,所以不放了,直接丢弃ack呢?

然后我开始搜索全连接队列满相关的文章,看了几篇,基本感觉有戏。

解决问题

午休结束后,去到测试机(没法在本地直接ssh)上根据文章查验。
参考文章:
https://blog.51cto.com/u_15181572/6172585
https://blog.csdn.net/Octopus21/article/details/132124481

其实全连接队列这个,几年前学习过这个,但是久了没碰到这个场景,早已淡忘,这次还真遇上了。
每一个listen状态的socket,都有个全连接队列,队列大小受到两个参数控制,一个是linux的内核参数net.core.somaxconn,可通过sysctl -a |grep somaxconn查看,我看了我们机器,值为128;另一个参数是应用执行listen时,可以指定一个叫做backlog的int类型参数,nginx中默认为512.
全连接队列大小呢,就是取min(net.core.somaxconn, 应用listen时的backlog值),我这里,两者取小,就是128.

这个值怎么查看呢,可以通过:

[root@168assi logs]# ss -lnt |egrep "State|8088"
State      Recv-Q Send-Q Local Address:Port               Peer Address:Port              
LISTEN     129    128          *:8088     

这里可以看到Send-Q的值,就表示队列的最大值为128. 而Recv-Q呢,就是当前全连接队列的长度,129,可以看到,已经大于128了,说明队列满了。

这里的Recv-Q和Send-Q的值,仅当socket处于listen时表示该意思,非listen时,表示其他意思。这里给个官方解释:

Recv-Q
Established: The count of bytes not copied by the user program connected to this socket.

Listening: Since Kernel 2.6.18  this  column
contains the current syn backlog.

Send-Q
Established:  The count of bytes not acknowledged by the remote host.  

Listening: Since Kernel 2.6.18 this column contains the maximum
size of the syn backlog.

另外,再根据文章提到的命令:

netstat -s | grep overflow

果然看到数字一直在增长,见下面网图:

image-20230824211750204

基本认定这个问题后,就是修改了,我是直接将内核参数改成了65535:

[root@168assi 12556]# vim /etc/sysctl.conf
net.core.somaxconn = 65535
然后如下命令生效:
sysctl -p

接下来,重启nginx,查看队列长度,已经是511了(nginx 默认的listen的backlog值):

[root@168assi 12556]# ss -lnt|grep 8088
LISTEN     0      511          *:8088                     *:*

另外,补充一点,再遇到该队列满时,我们的linxu机器是直接忽略了ack,也可以配置如下参数(值为1,默认为0,表示忽略报文),让其给客户端回复rst报文:

[root@168assi logs]# sysctl -a |grep tcp_abort_on_overflow
net.ipv4.tcp_abort_on_overflow = 0

官方解释如下(man tcp,如提示没安装,yum install man-pages):

tcp_abort_on_overflow (Boolean; default: disabled; since Linux 2.4)

Enable resetting connections if the listening service is too slow and unable to keep up and accept  them.   It  means  that  if overflow occurred due to a burst, the connection will recover.  Enable this option only if you are really sure that the listening daemon cannot be tuned to accept connections faster.  Enabling this option can harm the clients of your server.

改完再测试,抓包查看,报文很清爽,再没有一堆重传了:

image-20230824212737517

补充

如需查看nginx在location众多时,到底发给了哪个后端upstream,不用像我上面那样用strace,太复杂了,我查了下,可以这样:

http://nginx.org/en/docs/http/ngx_http_log_module.html

官方文档的access_log中,默认包含了一个日志format为combined,内容:

The configuration always includes the predefined “combined” format:

log_format combined '$remote_addr - $remote_user [$time_local] '
                    '"$request" $status $body_bytes_sent '
                    '"$http_referer" "$http_user_agent"';

我们可以增加一个属性$upstream_addr,即可展示转发到哪个upstream了:

http://nginx.org/en/docs/http/ngx_http_upstream_module.html

log_format combined1 '$remote_addr - $remote_user [$time_local] '
                '"$request" $status $body_bytes_sent '
                '"$http_referer" "$http_user_agent" $upstream_addr' ;
access_log  logs/access.log  combined1;

效果如下:

image-20230824213137598

参考文档

https://mp.weixin.qq.com/s/2qN0ulyBtO2I67NB_RnJbg

http://04007.cn/article/323.html nginx配置listen的backlog

与问题排查:nginx的反向代理感觉失效了一样相似的内容:

问题排查:nginx的反向代理感觉失效了一样

# 背景 最近,负责基础设施的同事,要对一批测试环境机器进行回收,回收就涉及到应用迁移,问题是整个过程一团乱。比如服务器A上一堆应用要调用服务器B上一堆服务,结果服务器B被回收了,然后服务器A上一堆应用报错。 今天就是负责查一个问题,app上一个头像上传的接口,之前都好好的,不知道怎么就不能访问了,

问题排查:nginx能跑,但是只能跑一会,不能跑多了

# 背景 上周都是查测试环境的问题,比如,我上一篇写的[问题排查:nginx的反向代理感觉失效了一样 ](https://www.cnblogs.com/grey-wolf/p/17655238.html),就是说这个事的。在文章里,最终查到是nginx的全连接队列满了(每个监听端口有个队列,完成三

一次nginx文件打开数的问题排查处理

现象:nginx域名配置合并之后,发现consul-template无法完成nginx重载,然后发现需要重启nginx,才能让配置生效。 注意:下次哪个服务有报错,就看重启时所有日志输出,各种情况日志输出。不要忽略细节。很多时候其实已经看到了问题,却没有深入查看问题。 查看进程最大打开文件个数 #c

[转帖]总结:nginx502:Tomcat调优之acceptCount

问题背景:UI页面点击会偶尔返回error,检查调用日志,发现nginx报502报错,因此本文即排查502报错原因。 如下红框可知,访问本机个备机的服务502了,用时3秒左右(可见并不是超时) 先给出原因:是因为tomcat8默认的acceptCount是100,请求量大的时候,会将一些来不及处理的

线上问题排查--进程重启失败,最后发现是忘了cd

# 背景 我前面写了几篇文章,讲c3p0数据库连接池发生了连接泄露,但是随机出现,难以确定根因,最终呢,为了快速解决问题,我是先写了个shell脚本,脚本主要是检测服务的接口访问日志,看看过去的30s内是不是接口几乎都超时了,如果是的话,咱们就重启服务。然后把这个shell加入到了crontab里,

问题排查---应用程序不在接收新请求

问题排查 应用程序不在接收新请求 关键词:springboot,jstack,Arthas 问题描述 查看前端网页,发现所有请求都pending,都超时。但是查看后端程序发现并没有挂掉,cpu,内存都正常。但是日志不打印了。看起来应用程序整体卡死了。 然后重启应用程序,发现又能正常运行了,但是过了半

【问题排查篇】一次业务问题对 ES 的 cardinality 原理探究

小编工作中负责业务的一个服务端系统,使用了 Elasticsearch 服务做数据存储,业务运营人员反馈,用户在使用该产品时发现,用户后台统计的订单笔数和导出的订单笔数不一致!对此进行排查并进行总结

[转帖]K8S 问题排查: cgroup 内存泄露问题 - kmem

K8S 问题排查: cgroup 内存泄露问题 - kmemhttps://www.cnblogs.com/leffss/p/15019898.html 目录 前言 现象 原因 解决方案 方案一 方案二 方案三 验证方式 影响范围 原理解释 kmem 是什么 cgroup 与 kmem 机制 kme

线上FullGC问题排查实践——手把手教你排查线上问题

作者:京东科技 韩国凯 一、问题发现与排查 1.1 找到问题原因 问题起因是我们收到了jdos的容器CPU告警,CPU使用率已经达到104% 观察该机器日志发现,此时有很多线程在执行跑批任务。正常来说,跑批任务是低CPU高内存型,所以此时考虑是FullGC引起的大量CPU占用(之前有类似情况,告知用

OpenStack 下 CentOS6.X 镜像网络初始化失败问题排查

问题表现 在我的 OpenStack 集群上迁移了一批老旧的镜像(从其他三方云平台过来的)发现这批镜像在使用 ConfigDrive 的方式注入配置初始化时无法对非首张网卡镜像初始化(后经过测试非 ConfigDrive 的数据源也不行)。 排查路径 首先检查 cloud-init 是否是正常工作的