女主宣言
nginx日志分为access_log和error_log，可以用于业务的访问统计、服务排障等。我们可以自定义设置log_format，来记录关注的各项指标。本文主要讲述了一次nginx日志中$request_time时间异常问题的排查过程，希望可以对遇到类似问题的同学有所帮助。
PS：丰富的一线技术、多元化的表现形式，尽在“360云计算”，点关注哦！
1
问题描述
业务反馈自己的服务实际响应速度很快，nginx作为反向代理，在它的access_log中看到的$request_time却在5s以上，而$upstream_response_time不到1s。这之间的时间差是从何而来？
2
排查过程
业务的请求路径
client -> LVS -> nginx -> upstream客户端访问业务域名，解析到LVS的VIP后，转发给后端的nginx反向代理，再由nginx转发给后端真实的服务器。
在LVS上抓包查看实际请求时间
下图只截取了整个流程中连接断开的部分数据包，nginx发出的是端口为80的数据包，客户端请求是端口为23883的数据包。从图中可以看出，nginx的80端口在发送完所有数据后，立即发送了Fin包断开连接，整个过程不超过1s。客户端在收到所有数据后，迟迟没有发出Fin包，而是在大约40s后发送了Rst包将连接断开。
现象分析
从抓包数据来看，nginx确实快速响应了请求，而异常之处在于客户端没有正常断开连接。确认服务本身没有问题之后，access_log中的$request_time与实际请求响应时间存在5s左右差异，该参数表示的到底是什么时间呢？
官方文档对$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发送最后一个字节与收到第一个字节间隔很短，那日志中多出的5s差异问题就在于写入日志的时间。因为该请求的异常点是客户端没有正常断开连接，由此怀疑连接的不正常断开，会影响日志写入时间的准确性。
问题确认
为了验证我们的怀疑，查看了nginx源码(版本: nginx-1.16.1)中$request_time变量相关的函数ngx_http_log_request_time。通过gdb调试，简单查看调用该函数的调用栈，内容如下：
#0 ngx_http_log_request_time (r=0x1ee21a0, buf=0x203b410 "0.010\"\n\"0.000\"\n", op=0x1f49e78)
#1 0x0000000000456f2d in ngx_http_log_handler (r=0x1ee21a0)
#2 0x000000000044cea7 in ngx_http_log_request (r=0x1ee21a0, rc=<value optimized out>)
#3 ngx_http_free_request (r=0x1ee21a0, rc=<value optimized out>)
#4 0x000000000044d11b in ngx_http_close_request (r=0x1ee21a0, rc=0)
#5 0x000000000044e3e2 in ngx_http_lingering_close_handler (rev=0x204ee90)
#6 0x000000000044f040 in ngx_http_set_lingering_close (r=0x1ee21a0)
#7 ngx_http_finalize_connection (r=0x1ee21a0)从调用栈的内容中可以看出，在打印日志前首先调用ngx_http_finalize_connection函数，然后进入了ngx_http_set_lingering_close，最终通过ngx_http_log_handler触发日志写入，记录了$request_time的时间。
依次看一下调用栈中涉及的函数逻辑，其中nginx配置文件中如果不设置lingering_close，默认为on。
static void
ngx_http_finalize_connection(ngx_http_request_t *r)
{
......
if (clcf->lingering_close == NGX_HTTP_LINGERING_ALWAYS
|| (clcf->lingering_close == NGX_HTTP_LINGERING_ON
&& (r->lingering_close
|| r->header_in->pos < r->header_in->last
|| r->connection->read->ready)))
{
ngx_http_set_lingering_close(r);
return;
}
ngx_http_close_request(r, 0);
}ngx_http_set_lingering_close函数是用来设置延迟关闭的，为了接收客户端发送来的剩余数据, 接收完数据后再关闭tcp连接与释放http请求。该函数中设置了lingering_timeout超时时间和定时任务，所以超时或者接收到数据都会触发ngx_http_lingering_close_handler函数，官方文档中lingering_timeout默认为5s。
static void
ngx_http_set_lingering_close(ngx_http_request_t *r)
{
......
rev = c->read;
rev->handler = ngx_http_lingering_close_handler;
r->lingering_time = ngx_time() + (time_t) (clcf->lingering_time / 1000);
ngx_add_timer(rev, clcf->lingering_timeout);
if (ngx_handle_read_event(rev, 0) != NGX_OK) {
ngx_http_close_request(r, 0);
return;
}
......
if (rev->ready) {
ngx_http_lingering_close_handler(rev);
}
}
static void
ngx_http_lingering_close_handler(ngx_event_t *rev)
{
......
if (rev->timedout) {
ngx_http_close_request(r, 0);
return;
}
......
}在前面抓包的结果中可以看到客户端将近40s左右没有给nginx发送任何数据，触发了超时的逻辑，最终执行ngx_http_close_request释放http请求并记录日志。
3
结论
通过抓包排查和源码分析，日志中request_time异常的原因是：客户端访问nginx的连接没有正常关闭，进而触发了nginx的延迟关闭逻辑。由于默认的lingering_timeout为5s，因此日志中记录的时间比实际请求时间多5s。
4
参考文章
1. http://nginx.org/en/docs/http/ngx_http_core_module.html#
2. http://shibing.github.io/2016/11/18/nginx%E7%9A%84%E5%BB%B6%E8%BF%9F%E5%85%B3%E9%97%AD-lingering-close/
