Tomcat日志记录post请求参数

公司的项目向用户提供接口，但是最近偶尔会出现超时的情况，用户的调用设置的超时时间是1分钟，所以首先要排查代码的执行时间是否超过一分钟

    @PostMapping("/updateattachment")
    public boolean post(@RequestBody OaModel oaModel, HttpServletRequest request) {
        log.info("OA接口提交{},", oaModel.getOaNo());
        //...省略逻辑代码
        log.info("OA接口返回{}", oaModel.getOaNo());
        return true;
    }

通过在代码中加上日志可以追踪到接收到用户超时请求的时间到接口返回的时间相差1S左右。那么就可以排除是代码执行时间的问题。经过沟通发现用户提交请求的时间是8：24分，但是接口提交打印的提交时间是8：28分，也就是说从用户提交到Controller层接收到请求有4分钟的延迟，那么就应该考虑：1.是否是服务器时间不同步引起的时差 2.是否是由于网络延迟导致的请求接收出现延迟 3.是否是tomcat接收到请求后没有立刻执行。

其中第三点的故障原因排查比较麻烦，因为我们都知道http协议是属于应用层的协议，它是通过TCP协议也就是传输层的协议把数据包传递到服务器。tomcat在接收到这个socket的请求以后，会从线程池中调用线程执行任务，因此就需要考虑是否是因为线程池的线程已满导致请求被加入到了任务队列所以没有立刻执行，通过查看tomcat的请求日志local_access_XXX.txt可以判断当时的并发数量并没有达到150（tomcat默认的线程数量）。

如果不是并发引起的问题，那只能考虑Servlet从接收到请求一直到controller层执行代码中间还需要经过一些参数解析和各种认证过滤器，因此就需要能记录用户post请求到servlet的时间和controller任务开始执行时间是否存在3分钟的时间差。但是tomcat的访问日志默认是只能够记录get请求的请求参数的，因此我们需要做一些改动

首先是修改conf/server.xml文件中的内容，在Host标签下加入<value>

        <Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
               prefix="localhost_access_log" suffix=".txt"
               pattern="%h %l %u %t &quot;%r&quot;  [%{postdata}r] %s %T %b" />

这里简单介绍一下pattern的几个参数的含义

%a   这是记录访问者的IP，在日志里是127.0.0.1
%A   这是记录本地服务器的IP，在日志里是192.168.254.108
%b   发送信息的字节数，不包括http头，如果字节数为0的话，显示为-
%B   发送信息的字节数，不包括http头。
%h   服务器的名称。如果resolveHosts为false的话，这里就是IP地址了，例如我的日志里是10.217.14.16
%H   访问者的协议，这里是HTTP/1.0
%l   官方解释：Remote logical username from identd (可能这样翻译：记录浏览者进行身份验证时提供的名字)(always returns '-')
%m   访问的方式，是GET还是POST
%p   本地接收访问的端口 
%q   比如你访问的是aaa.jsp?bbb=ccc，那么这里就显示?bbb=ccc，就是querystring的意思
%r   First line of the request (method and request URI) 请求的方法和URL
%s   http的响应状态码 
%S   用户的session ID,这个session ID大家可以另外查一下详细的解释，反正每次都会生成不同的session ID
%t   请求时间
%u   得到了验证的访问者，否则就是"-"
%U   访问的URL地址，我这里是/rightmainima/leftbott4.swf
%v   服务器名称，可能就是你url里面写的那个吧，我这里是localhost
%D   Time taken to process the request,in millis，请求消耗的时间，以毫秒记
%T   Time taken to process the request,in seconds，请求消耗的时间，以秒记

%r参数只能打印GET请求的URL和参数，因为GET请求的参数是在URL后面的，那用户的POST请求应该如何打印参数呢，在上面的配置中有一个配置  [%{postdata}r]  这个配置就是用来打印POST的参数的，但是这个并不是官方提供的，所以需要我们自己定义一个过滤器往request中设置这个参数，在SpringBoot中定义一个自定义过滤器只需要实现Filter接口和配置几个注解

@Component
//用来扫描Servlet的过滤器，使@WebFilter生效
@ServletComponentScan
//将类声明为一个过滤器，该注解将会在部署时被容器处理，容器将根据具体的属性配置将相应的类部署为过滤器
@WebFilter(urlPatterns = "/oa/*", filterName = "parameterFilter")
//配置过滤器的加载顺序，数值越低，表示优先级越高
@Order(Ordered.HIGHEST_PRECEDENCE)
@Slf4j
public class ParameterTakeFilter implements Filter {

    private FilterConfig filterConfig = null;

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {
        this.filterConfig = filterConfig;
    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        if (filterConfig == null)
            return;
        /*这里要注意不能用getReader()或者getInpustream()这种方法获取请求参数，
        因为这两种方法是把缓冲区的数据流读取出来，数据流是只能读一次的，
        一旦这里把流读取出来缓冲区被清空，Controller层的请求就拿不到参数了*/
        /*BufferedReader reader = request.getReader();
        String line;
        StringBuffer sb = new StringBuffer();
        while ((line = reader.readLine())!=null){
            sb.append(line);
        }*/
        //从请求头中获取需要打印到日志中的post参数
        String oaNo = ((HttpServletRequest) request).getHeader("oaNo");
        request.setAttribute("postdata", oaNo);

        chain.doFilter(request, response);
    }

    @Override
    public void destroy() {
        this.filterConfig = null;
    }
}

过滤器配置完成后可以在tomcat日志目录下看到localhost_access_log.日期.txt就是访问日志

 用postman提交post请求可以看到日志的打印内容，分别记录了我们放入的post参数，http响应状态码，执行时间（S）还有字节大小。

[26/Apr/2020:06:49:56 -0700] "POST /oa/updateattachment HTTP/1.1"  [OA_TEST20200426002] 200 0.412 55