499 这个错误码是 nginx 独有的,nginx server 已经接受到了客户端的请求,但是还没有处理完成,客户端主动断开了连接,一般是客户端超时时间到了。客户端得到的错误是 Read Timeout。
我们先解释下 nginx 下几个相关参数的含义。
request_time
接受客户请求的第一个字节到发送完响应数据的时间,这包括用户请求数据的时间(请求body大,需要多个包传输),后端程序响应时间,发送数据时间。
upstream_response_time
指的是 nginx 向后端程序建立连接,并接收完数据关闭连接的时间。
upstream_status
后端程序处理完请求的返回码。
时间序列参考如下
从上面的描述中,request_time 一般要比 upstream_response_time 大。request_time 相当于 nginx 处理请求的时间,但不包括握手时间。
正常日志
1 2 |
1.202.240.198 - - [19/Nov/2018:07:41:21 +0800] "GET / HTTP/1.1" 200 79 "-" "curl/7.21.4 (x86_64-apple-darwin12.2.0) libcurl/7.21.4 OpenSSL/0.9.8} zlib/1.2.11 libidn/1.20" "-" "0.002" "0.002" "200" 106.185.34.251 - - [19/Nov/2018:07:41:21 +0800] "GET / HTTP/1.0" 200 68 "-" "curl/7.21.4 (x86_64-apple-darwin12.2.0) libcurl/7.21.4 OpenSSL/0.9.8} zlib/1.2.11 libidn/1.20" "-" "0.001" "0.001" "200" |
我们看到一次客户请求有两条数据,第一条是客户请求的记录,第二条是与后端 server 建立连接的记录。这里用的是代理模式,所以看到了两条记录。后三个值,分别对应 request_time ,upstream_response_time, upstream_status。request_time = upstream_response_time。我们再发送一个请求体数据量大的情况看下:
1 2 |
1.202.240.198 - - [19/Nov/2018:07:46:45 +0800] "POST / HTTP/1.1" 200 104 "-" "curl/7.21.4 (x86_64-apple-darwin12.2.0) libcurl/7.21.4 OpenSSL/0.9.8} zlib/1.2.11 libidn/1.20" "-" "0.172" "0.001" "200" 106.185.34.251 - - [19/Nov/2018:07:46:45 +0800] "POST / HTTP/1.0" 200 68 "-" "curl/7.21.4 (x86_64-apple-darwin12.2.0) libcurl/7.21.4 OpenSSL/0.9.8} zlib/1.2.11 libidn/1.20" "-" "0.001" "0.001" "200" |
可以看到, request_time 明显要比 upstream_response_time,nginx 需要接收多个数据包,网络耗时比较长。
异常日志
1 |
1.202.240.198 - - [19/Nov/2018:07:48:36 +0800] "POST / HTTP/1.1" 502 197 "-" "curl/7.21.4 (x86_64-apple-darwin12.2.0) libcurl/7.21.4 OpenSSL/0.9.8} zlib/1.2.11 libidn/1.20" "-" "0.175" "0.001" "502" |
我们把后端的 server 变成不可用状态, 发现 upstream_status 返回了 502 的错误码, POST / HTTP/1.1" 502 197 用户的请求,也是看到的 502 的错误码。
我们把后端的 server 处理时间变长,用户请求设置个超时时间为 1s。 可以看到如下的日志。
1 2 |
1.202.240.198 - - [19/Nov/2018:07:53:53 +0800] "POST / HTTP/1.1" 499 25 "-" "curl/7.21.4 (x86_64-apple-darwin12.2.0) libcurl/7.21.4 OpenSSL/0.9.8} zlib/1.2.11 libidn/1.20" "-" "0.915" "-" "-" 106.185.34.251 - - [19/Nov/2018:07:53:53 +0800] "POST / HTTP/1.0" 499 0 "-" "curl/7.21.4 (x86_64-apple-darwin12.2.0) libcurl/7.21.4 OpenSSL/0.9.8} zlib/1.2.11 libidn/1.20" "-" "0.741" "-" "-" |
upstream_response_time 和 upstream_status 都是空的,nginx 在规定的时间内没有拿到后端 server 的响应。request_time 接近于 我们设置的超时时间,为什么是接近于? 用户请求的 1s 是包括 整个连接时间的,nginx 的 request_time 是不包括握手时间的。
这里的日志也记录了 499 的错误码,但是客户端是拿不到请求的。客户端看到是如下的报错
1 |
curl: (28) Operation timed out after 1001 milliseconds with 0 bytes received |