对nginx 日志$request_time 字段的详细理解

nginx 日志的疑问

有一个接收高并发请求的接口做了错误报警，首先访问a.x.com，访问失败的时候会访问b.x.com，两个域名分别部署在不同的机房，使用不同的nginx（下文用ngx-a ngx-b 分别指代两个域名）。正常的话ngx-a 每天会接收10亿次左右的请求量，ngx-b 会收到少量因网络问题带来的请求，每天在10万请求以内（万分之一）都是正常的。
最近发现ngx-b 每天收到的请求量超过了150万，检查日志分析结果发现绝大部分请求来自相同网段，所以怀疑这个网段到机房的链路网络质量可能不太好，涉及到的客户端量比较大需要排查。

分别检查两台nginx 日志发现有一部分client 请求会先请求ngx-a，ngx-a 记录的日志是正常的1秒内完成响应，此client 在约30秒以后会继续请求ngx-b。client 程序的逻辑是请求ngx-a 后判断状态码如果不是200则请求ngx-b，请求超时时间是30秒。
至此事件已经相对清晰了，很大概率是ngx-a 收到并正常处理了请求，但是client 因某些原因并未收到响应所以又请求了ngx-b。

现在最大的疑问是ngx-a 记录的日志为何是正常响应的，状态码200 且响应时间1秒以内：

59.83.198.155|-|[03/Jan/2019:11:16:33 +0800]|GET /he?xx=xx HTTP/1.1|200|17|-|Dalvik/2.1.0 (Linux;)|-|-|0.000|0.000|xx.x.com|-|172.30.30.54:8090

日志中的11、12列两个0.000 分别是$request_time 和 $upstream_response_time

$request_time 这个字段，按照官方文档的解释：

$request_time
request processing time in seconds with a milliseconds resolution; time elapsed between the first bytes were read from the client and the log write after the last bytes were sent to the client

这个字段记录的是nginx 开始收到client 请求，到将请求发回给client 期间过去的时间。也就是说ngx-a 认为client 已经收到了自己的响应内容才会记录下来这条日志？如果是这样就和看到的现象矛盾了。

分析$request_time

模拟测试

想要分析nginx 如何记录的日志需要模拟事件的经过，假设了对方的网络不太好，并没有收到nginx 响应的内容，也并没有在tcp 层给出ack 最终确认收到响应。这需要一个比较特殊的环境，首先要client 成功的发送了get 请求，nginx 给出响应，client 未收到响应，这时候看一下nginx 日志的记录情况。

模拟这个过程只要将client 最后一步的ack 拦截即可，测试过程开始！

1. 部署一台nginx，主要修改参数如下：
   keepalive_timeout 7;
   proxy_connect_timeout 5;
   proxy_read_timeout 50;
   proxy_send_timeout 50;
   然后配置一个域名，指向后端flask。

2. 后端运行一段flask 脚本，将响应时间变慢，一来方便后面的操作，二来也方便查看日志的问题，代码如下：

#!/usr/bin/env python2.7
# encoding: utf-8
import time
from flask import Flask
node = Flask(__name__)
@node.route('/s5.txt')
def index():
    time.sleep(2)
    return 'this is index after slept 5s'

if __name__ == '__main__':
    node.run(host='0.0.0.0', port=8900, debug=True)

3. 使用socket 模拟客户端完成请求，请求发出以后执行系统命令用iptables 将ack 拦截，代码如下：

#!/usr/bin/env python2.7
# encoding: utf-8
import socket
import ssl
from urlparse import urlparse
import time
import os

url = 'http://www.x.com/s5.txt'
port = 80
obj_urlinfo = urlparse(url)

if obj_urlinfo.scheme == 'https':
    sock = ssl.wrap_socket(socket.socket())
    if not port: port = 443
elif obj_urlinfo.scheme == 'http':
    sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
    if not port: port = 80


request_url = 'GET {uri} HTTP/1.1\r\nHost: {domain}\r\nConnection: keep-alive\r\n\r\n'.format(
    uri=obj_urlinfo.path,
    domain=obj_urlinfo.netloc,
)
sock.connect((obj_urlinfo.netloc, port))
sock.send(request_url.encode())
os.system('iptables -I OUTPUT -p tcp --tcp-flags ALL ACK -d 192.168.200.1 -j DROP')

time.sleep(80)
rec = sock.recv(10000)
print rec

其实我是在ipython 内手动执行的，执行的整个过程代码基本就是这些。
执行期间需要在nginx 端进行抓包，然后分析数据包就行了，分别进行一次没有拦截ack 和拦截ack 的测试，对比分析。

测试结果

日志：

192.168.200.89|-|[03/Jan/2019:10:35:53 +0800]|GET /s5.txt HTTP/1.1|200|28|-|-|-|-|2.003|2.003|tt.x.com|-|127.0.0.1:8900
192.168.200.89|-|[03/Jan/2019:10:36:45 +0800]|GET /s5.txt HTTP/1.1|200|28|-|-|-|-|2.004|2.004|tt.x.com|-|127.0.0.1:8900

抓包截图（正常请求）：

抓包截图（拦截ACK 的请求）：

结果分析

从日志可以看到，两次日志记录的时间分别是10:35:53，10:36:45，日志记录的$request_time 都是2秒，也就是后端程序处理的时间。
这两个日志记录的时间点对应数据包的时间是nginx 将响应发送出来的时间，通过正常请求和拦截ACK 的请求做对比就能看到，nginx 将数据包发送给本地协议栈就不会再跟进后续的数据处理了，后面将数据包发送到对端的过程由tcp 协议完成，与nginx无关。

结论

经过上面的分析可以得出结论，记录日志的时间点是nginx 将数据包发送到本地网卡的时间，$request_time 代表的时间是nginx 收到请求开始到将响应数据包发送到本地网卡的时间，与客户端是否收到响应无关。