我是这么学习 nginx 499 的,从抓包到内核源码终于真相大白

概要

从nginx的499着手,分析整个过程中是怎么产生499行为的,以及各种往返网络包出现的原因。说说我通过这个499问题一步一步分析的整个过程,作为一个web服务端程序员,但很有意思。

故事背景

前几天同组的应届生同事在排查线上问题的时候突然问我,这个499的错误码是什么?我轻描淡写的回复了就是客户端设置的超时时间到了,nginx自己记录的内部错误码。这样草草打发之后,我的内心久久不能平复,499的背后nginx和客户端以及upstream到底发什么了什么,不得而知。事实上,当时我还认为的这样一个事实:

即使client断开了,最后nginx还是会把返回的网络包发过来,站在网络流量资源的角度来看,超不超时貌似没有区别。

接着我去查了一下nginx对499对定义,只说明了这是client关闭连接的code,没有其他更深入的信息。

/
HTTP does not define the code for the case when a > client closed
the connection while we are processing its request > so we introduce
own code to log such situation when a client has closed the connection
before we even try to send the HTTP header to it
/

define NGX_HTTP_CLIENT_CLOSED_REQUEST 499

为了搞清楚我的猜想是正确的,我做了一系列实验,查看了相关源码,最后才知道这个事实是多么的错误。

实验

os:mac
服务:golang+nginx+(php)fpm
调用:golang作为client,发起http调用,设置1秒超时,php对应接口sleep 3秒之后响应,nginx作为反向代理(和fpm使用tcp socket通信)

代码:

// main.go
package main
import (
"net/http"
"time"
)

func main() {
c := http.DefaultClient
c.Timeout = 1 * time.Second
c.Get("http://localhost:6100/index.php")
}
// inedx.go
<?php
sleep(3);
echo "i sleep 3 seconds";

6100 端口是 nginx 代理的端口,运行 main.go,果然在 access.go 里面出现了一条 499 的日志。

127.0.0.1 - - [29/Dec/2019:14:14:43 +0800] "GET /index.php HTTP/1.1" 499 0 "-" "Go-http-client/1.1"
看看这背后究竟发生了什么?既然我在本地运行,那么直接上 wiresharks 抓包看看就好了。

Laravel

整个过程会用到2个tcp连接,4个端口

Laravel

  1. [26-27] 14:14:42 client第一次握手被nginx rst

  2. [28-31] client和nginx三次握手

  3. [32-33] client发送http,nginx确认收到

  4. [34-37] nginx和fpm三次握手

  5. [38-39] nginx发送请求到fpm(fcgi协议)

  6. [44,45,48,49] 因为client设置了1秒超时,这里刚好1秒过去,时间是14:14:43,断开链接,这4个包是一次完整的四次挥手

  7. [46, 47] 在nginx收到client断开,接着给fpm发送了断开,同时fpm响应了ack,nginx进入finwait-2状态,这里通过 netstat 可以确认

  8. [52-55] 2秒之后14:14:45,fpm处理完逻辑返回,写回数据到 nginx,同时响应 fin+ack,这里nginx给了两次 RST

抓包到这里我们可以得到如下结论:

  1. nginx接受client的get请求完之后,会接着开始转发到upstream
  2. client断开之后,nginx马上同意关闭tcp连接
  3. 499的日志记录时间就是tcp断开的时间
    让人费解的是最后两个RST是怎么产生的,整理这篇文章的时候我已经不记得当初为什么又这个疑问了,这里假设我们还是对这个问题很好奇,不然接下来的文字好像没法继续写了。

实验分析

通过46,47两个包我们知道了nginx的61394端口tcp处理finwait-2的状态,于是我找来了【相关文档 RFC793】对tcp状态转化的定义:

Laravel

在FINWAIT-2的状态没有snd rst的相关说明,这个图只是正常流程的tcp状态扭转说明,那接着向下看。不过有经验的同学应该已经猜到大概是因为在FINWAIT-2的状态下收到数据,主动关闭的一方会直接发送RST,我很想找到某个官方文档上有相关的定论,这样这个问题就到此为止了。运气很差,翻了几篇RFC文档没有找到,那我只能自己从TCP源码找找线索了。

// linux/net/ipv4/tcp_input.c#L6129
/*
* This function implements the receiving procedure of RFC 793 for
* all states except ESTABLISHED and TIME_WAIT.
* It's called from both tcp_v4_rcv and tcp_v6_rcv and should be
* address independent.
*/
int tcp_rcv_state_process(struct sock *sk, struct sk_buff *skb)
{
    struct tcp_sock *tp = tcp_sk(sk);
    struct inet_connection_sock *icsk = inet_csk(sk);
    const struct tcphdr *th = tcp_hdr(skb);
    ...
    switch (sk->sk_state) {
        ...
        case TCP_FIN_WAIT2:
        /* RFC 793 says to queue data in these states,
        * RFC 1122 says we MUST send a reset.
        * BSD 4.4 also does reset.
        */
        if (sk->sk_shutdown & RCV_SHUTDOWN) {
            if (TCP_SKB_CB(skb)->end_seq != TCP_SKB_CB(skb)->seq &&
            after(TCP_SKB_CB(skb)->end_seq - th->fin, tp->rcv_nxt)) {
                NET_INC_STATS(sock_net(sk), LINUX_MIB_TCPABORTONDATA);
                tcp_reset(sk);
                return 1;
            }
        }

        ...
    }
    ...
}

这是tcp收到数据包的处理函数,省略了大部分代码(因为读起来很费劲且不是这个问题的关键点),找到了在TCP_FIN_WAIT2状态下唯一一处发送RST的代码,这段代码两个if条件大概是:

  1. 当前sk(tcp socket)关闭了读取通道(RCV_SHUTDOWN)

  2. 函数收到的数据包有内容且检测seq序列号是正确的(可能某个很早包在网络世界中漫游到现在才收到,这种情况要走其他逻辑处理)

看来事情已经很简单了,我只要找到 sk->sk_shutdown |= RCV_SHUTDOWN 这行代码,我的问题就可以得到解决了。在接近真相的时候我们往往会掉入另外一个坑,是的,只知道了一行不相关的代码。

很苦恼,我深信RST就是通过这行代码发送出去的,于是我用strace(mac下使用dtruss)把这几个关键进程的系统调用打了出来。


# golang 部分
## 过期主动断开tcp
1541/0x1a35ce3: 23140 6 2 close(0x5) = 0 0

# nginx 部分
90320/0x1a30d81: 13045 34 21 write(0xA, "2019/12/29 16:07:27 [info] 90320#0: *62 kevent() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 127.0.0.1, server: _, request: .GET /index.php HTTP/1.1., upstream: .fastcg", 0x12C) = 300 0

## close对upstram的socket
90320/0x1a30d81: 13267 50 37 close(0x4) = 0 0

## nginx 499日志
write(0xB, "127.0.0.1 - - [29/Dec/2019:16:07:27 +0800] .GET /index.php HTTP/1.1. 499 0 .-. .Go-http-client/1.1...", 0x64) = 100 0

## close client socket
90320/0x1a30d81: 13773 39 30 close(0x3) = 0 0

# fpm部分
## 处理完成之后http响应
78089/0x1a2b512: 17360 101 77 write(0x3, ".01.06.", 0x70) = 112 0
## shutdown tcp
78089/0x1a2b512: 17410 397 9 shutdown(0x3, 0x1, 0x0) = -1 Err#57

这部分其实系统调用都是关于tcp连接断开的:

  1. go client 调用超时之后直接 close socket
  2. nginx 捕获到这个 close io,响应的进行 socket 关闭
    1. 先关闭对 upstream 的 socket
    2. 然后关闭对 client 的 socket
  3. fpm 超时之后继续处理逻辑,完成之后进行write输出数据,输出之后调用 shutdown 关闭 socket

Laravel

看到shutdown函数,我迅速翻开了垫在电脑下的TCP/IP卷一,TCP/IP卷一如下描述TCP半关闭:

tcp的半关闭操作是指仅关闭数据流的一个传输方向,而两个半关闭操作合在一起就能够关闭整个连接。为了实现这一特性,API为程序提供一种表达方式,使用 shutdown() 函数来代替基本的 close() 函数。

php脚本处理完之后,马上会执行shutdown来关闭socket的写入通道,很合理,毕竟逻辑已经处理完了,不需要再向nginx返回数据了。注意,这里通过系统调用可以看到参数和返回值 shutdown(0x3, 0x1, 0x0) Err#57

#define SHUT_RD 0 /* shutdown for reading */
#define SHUT_WR 1 /* shutdown for writing */
#define SHUT_RDWR 2 /* shutdown for reading and writing */

马上联想到想到前面我通过 sk->sk_shutdown |= RCV_SHUTDOWN 来搜索线索,对于位运算太久没用已经麻木了,读写通道肯定是读和写两个位的组合,我打开了 linux 的源码,在我 14 年的mac本上有点卡,迅速搜索关键词,终于真相了

//linux/include/net/sock.h
#define SHUTDOWN_MASK 3
#define RCV_SHUTDOWN 1
#define SEND_SHUTDOWN 2

//linux/net/ipv4/tcp.c
void tcp_close(struct sock *sk, long timeout)
{
    struct sk_buff *skb;
    int data_was_unread = 0;
    int state;
    lock_sock(sk);
    sk->sk_shutdown = SHUTDOWN_MASK;
    ...
}

执行close函数,当socket的引用计数位0的时候,会真正去断开连接,这个系统调用背后执行了 tcp_close 函数。关于close可以在百度上看看和shutdown有哪些细节上的区别,这里就不细说了。

通过以上分析,第一个RST产生的原因就比较明确了,处于finwait-2且关闭了读写通道,收到数据包的时候会直接产生RST。同时会直接丢弃到这个TCP连接,不会进入TIME_WAIT了。

那么,第二个RST怎么产生的,为什么fpm发送一个fin包会被再次RST,熟悉网络编程的人应该已经知道答案了,在nginx上这个连接已经丢弃了,所以直接予以RST。其实写这段文字,是因为我在验证这个逻辑的时候掉入了一个有意思的陷阱。

一个陷阱

回过头看看fpm shutdown系统调用的错误码Err#57shutdown可能产生的错误码文档上已经列出来了。

errno 含义
EBADF The socket argument is not a valid file descriptor.
EINVAL The how argument is invalid.
ENOTCONN The socket is not connected.
ENOTSOCK The socket argument does not refer to a socket.

我切换到linux项目,搜索ENOTCONN(看起来当前场景的错误码),结果让人大失所望

#define ENOTCONN 107 /* Transport endpoint is not connected */
#define ENOTSOCK 88 /* Socket operation on non-socket */

后来,我花了很久才意识到,我用mac本在测试代码,而我打开的内核代码是linux的,所以我很快在freebsd的代码找到了我想要的答案

#define ENOTCONN 57 /* Socket is not connected */

一点思考

整个过程并没有文章上这么顺利,很多知识点上我都看到了自己的欠缺,深感网络编程的不易。在我本地调试的过程中,我还进行了下面的实验:

  1. 重新编译nginx,把所有debug日志打开,这样整个过程会非常清晰。
  2. 去掉nginx代理,直接请求后端go服务或者tomcat超时
  3. 在超时期间,模拟upstream断电,nginx的FINWAIT-2会怎么处理

限于篇幅,这篇文章就不再展开了,关于499的了解到这一步应该已经足够深入了。

参考

TCP协议超时详解

TCP 之 FIN_WAIT_2状态处理流程

tcp_rcv_state_process 源码

RFC793

shutdown(3) - Linux man page

freebad errno

TCP/IP详解-卷一-TCP连接管理


最后欢迎大家关注我的公众号,我给自己定个每个目标达成之后都会有实体书赠送抽奖活动。
Laravel

本帖已被设为精华帖!
本帖由系统于 4个月前 自动加精
《L01 基础入门》
我们将带你从零开发一个项目并部署到线上,本课程教授 Web 开发中专业、实用的技能,如 Git 工作流、Laravel Mix 前端工作流等。
《L04 微信小程序从零到发布》
从小程序个人账户申请开始,带你一步步进行开发一个微信小程序,直到提交微信控制台上线发布。
讨论数量: 2

我们这也遇到这个问题,正好学习下

4个月前 评论

请勿发布不友善或者负能量的内容。与人为善,比聪明更重要!