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

背景

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

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

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

问题现象

链路梳理

先上个图，再解释整个链路：

现象就是，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之间的网络包打开分析了一会。

包的前面几个报文如下：

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

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

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

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

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

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

我想了半天，终于想差不多了，看来是客户端的第三次握手的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

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

基本认定这个问题后，就是修改了，我是直接将内核参数改成了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.

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

补充

如需查看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;

效果如下：