nginx + tomcat实现请求链跟踪

    我们很多时候需要排查HTTP请求的问题，比如请求的响应延迟的原因、跟踪请求的转发链等，这个时候我们需要nginx和tomcat配合调整日志格式来实现。

    1）在nginx层面，对所有的请求添加一个特殊的header，header的值为一个有意义的（或者无意义）的值，本例则在request转发给upstream server之前，添加一个“X-Request-Track-Seed”，其值为一个随机字符串。我们在nginx日志中打印此值。

    2）在tomcat层面，开启access log功能，并将nginx的此header打印在日志中。

    经过上述配合，我们就可以跟踪一个请求从nginx到tomcat的访问情况。

 

一、nginx调整

    1、开启access log（简单样例）

 

http {
    server_tokens       off;
    include               /etc/nginx/mime.types;
    default_type          application/octet-stream;

   ##我们可以在log_format中使用$request_trace_id
   ##这个变量，我们可以在access_log运行时上下文之前的任何地方定义即可。
    log_format  trace_main  '$remote_addr|$remote_user|$time_local|$request|'
                      '$status|$body_bytes_sent|$http_referer|$request_trace_id|'
                      '$http_user_agent|$http_x_forwarded_for|$request_time|$upstream_response_time|$upstream_addr';

    

    access_log        /var/log/nginx/access.log  main;
    
}

upstream www_main {
    server 10.1.1.100:8080 weight=10 max_fails=3 fail_timeout=3s;
    server 10.1.2.100:8080 weight=10 max_fails=3 fail_timeout=3s;
    keepalive 32;
  }

server {
    listen       80 default_server;
    server_name  www.domain.com domain.com;
    ##定义$request_trace_id的值，在1.11.x之前，我们可以使用类似的方式声明，只要能确保
    ##其值出现重复的可能性尽可能的小即可。
    set      $request_trace_id trace-id-$pid-$connection-$bytes_sent-$msec;
    access_log  /var/log/nginx/www.log  trace_main;

    location / {
          proxy_pass         http://$request_type;
          proxy_set_header   Host             $host;
          proxy_set_header   X-Real-IP        $remote_addr;
          proxy_set_header   X-Forwarded-For  $proxy_add_x_forwarded_for;
          proxy_http_version 1.1;
          proxy_set_header Connection "";
          ##将此trace_id传递给后端的server，通过header方式，此后我们既可以在
          ##tomcat(servlet)环境中获取此header
          proxy_set_header X-Request-ID $request_trace_id;
 
    }

}

 

    上述配置样例是基于1.8.x版本，因为在1.11.x版本nginx才提供内置的$request_id属性，所以为了获取“唯一”的trace_id，我们只能通过使用nginx现有的内置变量互相拼接才行，主要目的就是尽可能避免$request_trace_id值的重复性。

    1）$pid：nginx worker进程号

    2）$connection：与upstream server链接id数。

    3）$bytes_sent：发送字节数。

    4）$msec：当前时间，即此变量获取的时间，包含秒、毫秒数（中间以.分割）

    

    在nginx 1.10.x之后，对于proxy模块，还增加了如下几个非常重要的参数，应该将它们也打印在access log中，便于我们排查nginx的性能问题：

    1）$upstream_connect_time：nginx与后端upstream server建立链接的耗时，用于评估nginx与upstream server之间的网络链路是否快速，时间为秒和毫秒数。

    2）$upstream_response_time：nginx与后端upstream server建立链接后、请求发送完毕后，在接收response阶段的耗时（即响应开始到结束的耗时）。

 

    此外我们还注意到两个参数$request_time、$time_local，前者表示整个请求处理所消耗的时间（包括与upstream建立链接、请求发送、响应接收），后者表示打印log的时间。

 

    在1.11.x之后，nginx就提供了内置的$request_id参数，此参数用于标记每个请求，全局唯一，为16字节的字符串（随机，16进制），有了此参数，我们就不需要自己再生成，而且能保证唯一性，非常适合作为trace_id，在排查问题时很有效。

##1.11.x版本
##http块
log_format  trace_main  '$remote_addr|$remote_user|$time_local|$request|'
                      '$status|$body_bytes_sent|$http_referer|$request_id|'
                      '$http_user_agent|$http_x_forwarded_for|$request_time|$upstream_response_time|$upstream_addr|$upstream_connect_time';
#####set      $request_trace_id trace-id-$pid-$connection-$bytes_sent-$msec;
##server-location块
proxy_set_header X-Request-ID $request_id;

 

 

二、tomcat访问日志

    我们在nginx层面，我们已经对每个请求增加了一个特殊的header：X-Request-ID，其值为一个“全局唯一”的字符串（不保证绝对唯一，只是冲突的可能性很小）；那么我们就可以通过在tomcat access日志中打印此值即可。

    我们只需要在tomcat conf目录下的server.xml文件中增加（调整）如下配置即可：

<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
               prefix="localhost_access_log" suffix=".txt"
               pattern="%h %m %t %D %F &quot;%r&quot; %s %S %b %{X-Request-ID}i %{Referer}i %{User-Agent} %{begin:msec}t %{end:msec}t" />

 

    pattern属性即为access log答应的格式，基于log4j，别忘了在pattern中增加%{X-Request-ID}字段。

    

%a - Remote IP address（远端IP，上游为nginx，此处为nginx IP）
%A - Local IP address
%b - Bytes sent, excluding HTTP headers, or '-' if zero
%B - Bytes sent, excluding HTTP headers
%h - Remote host name (or IP address if enableLookups for the connector is false)
%H - Request protocol
%l - Remote logical username from identd (always returns '-')
%m - Request method (GET, POST, etc.)（http方法）
%p - Local port on which this request was received. See also %{xxx}p below.
%q - Query string (prepended with a '?' if it exists)
%r - First line of the request (method and request URI)（http请求的首行，通常为HTTP协议、URI等）
%s - HTTP status code of the response（响应的状态码）
%S - User session ID
%t - Date and time, in Common Log Format（access log打印的时刻）
%u - Remote user that was authenticated (if any), else '-'
%U - Requested URL path
%v - Local server name
%D - Time taken to process the request, in millis（很重要，表示请求处理的时间）
%T - Time taken to process the request, in seconds
%F - Time taken to commit the response, in millis（此参数似乎有误）
%I - Current request thread name (can compare later with stacktraces)

 

    此外，tomcat还支持类似于nginx的特殊格式：

%{xxx}i write value of incoming header with name xxx（请求中包括header值，xxx替换为header的名称）
%{xxx}o write value of outgoing header with name xxx（响应中header）
%{xxx}c write value of cookie with name xxx（cookie值）
%{xxx}r write value of ServletRequest attribute with name xxx（此请求中的attribute参数值）
%{xxx}s write value of HttpSession attribute with name xxx
%{xxx}p write local (server) port (xxx==local) or remote (client) port (xxx=remote)
%{xxx}t write timestamp at the end of the request formatted using the enhanced SimpleDateFormat pattern xxx（与时间有关，格式化输出请求结束的时间，xxx值可以为“yyyy-MM-dd HH:mm:ss”）

 

    在%{xxx}t这一个选项中，还有两个比较特殊的可选项，xxx的可替代值，比如“%{sec}t”：

sec - number of seconds since the epoch（时间戳，秒数）
msec - number of milliseconds since the epoch（时间戳，毫秒数）
msec_frac - millisecond fraction

  

    此外，我们可以在上述可选项的前增加如下2个标识：

begin or prefix begin: chooses the request start time（请求开始的时间，比如%{begin:msec}t）
end or prefix end: chooses the response finish time（响应结束的时间，比如%{end:msec}t）

 

    此后，我们即可在tomcat logs目录下查看access log了，文件名为server.xml中Valve中定义。