zoukankan      html  css  js  c++  java
  • Springboot通过@WebFilter日志双份打印BUG分享

    最近在做DCS_FunTester分布式性能测试框架开发的时候,需要实现一个自定义的过滤器,主要用来打印HTTP请求的参数和响应日志。

    但是在项目迁移之后的一次测试中却发现了一个奇怪的现象,每次接口请求的日志都被打印了两遍。

    WrappingFilter实现代码如下:

    @Component
    @WebFilter(urlPatterns = "/*", filterName = "WrappingFilter")
    public class WrappingFilter implements Filter {
    
        private static Logger logger = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
    
        public void init(FilterConfig config) throws ServletException {
        }
    
        public void destroy() {
        }
    
        @Override
        public void doFilter(ServletRequest request, ServletResponse response,
                             FilterChain chain) throws IOException, ServletException {
    
            HttpServletRequest req = (HttpServletRequest) request;
            String ipAddress = getIpAddress(req);
            HttpServletResponse resp = (HttpServletResponse) response;
            ResponseWrapper responseWrapper = new ResponseWrapper(resp);
            RequestWrapper requestWrapper = new RequestWrapper(req);
            String url = requestWrapper.getRequestURI();
            String queryArgs = requestWrapper.getQueryString();
            queryArgs = queryArgs == null ? DecodeEncode.unicodeToString(requestWrapper.getBody()) : queryArgs;
            String method = requestWrapper.getMethod();
            long start = Time.getTimeStamp();
            chain.doFilter(requestWrapper == null ? request : requestWrapper, responseWrapper);
            long end = Time.getTimeStamp();
            byte[] bytes = responseWrapper.getContent();
            String respContent = new String(bytes, Constant.UTF_8);
            logger.info("请求:{},耗时:{} ms,参数:{},响应:{},来源:{}", url, end - start, queryArgs, respContent, ipAddress);
    
            response.getOutputStream().write(respContent.getBytes(Constant.UTF_8));
        }
    }
    
    

    一开始发现的控制台日志如下:

    INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:1 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1
    INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:1 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1
    INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:1 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1
    INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:1 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1
    INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:1 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1
    INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:1 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1
    
    

    由于都是本地调试,所以请求时间基本都是1ms~2ms,所以一开始我还以为是自己多点了一次。但是在后面的观察中几乎都是两倍的日志量,我开始产生怀疑了。

    看着每次打印日志的类和行数都一样,于是我开始怀疑是我log4j2的配置有问题了,在重新检查过本地log4j2.xml文件之后,我断了这个念想。

    这个过程中不断重启本地服务,然后再通过浏览器访问某个GET接口,我突然看到了服务重启后的最新的请求日志信息(如下)。同样是成对出现的,唯一不同的是响应耗时不同,我开始怀疑代码里面的BUG

    INFO com.funtester.config.Constant:228 当前用户:oker,工作目录:/Users/oker/IdeaProjects/dcs_funtester/,系统编码格式:UTF-8,系统Mac OS X版本:10.16
    INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:67 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1
    INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:69 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1
    INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos/fdsa,耗时:5 ms,参数:,响应:,来源:0:0:0:0:0:0:0:1
    INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos/fdsa,耗时:6 ms,参数:,响应:,来源:0:0:0:0:0:0:0:1
    

    时间不同,应该是两个不同的地方打印的日志,但是又是同样的类和同行的代码行数,又让我迷惑了。所以又开始了搜索学习的过程。

    最终找到了原因所在,也弥补了一个知识点盲区。

    注册的过滤器除了使用filterName = "WrappingFilter"显式注册的外,还隐式注册了一个类名首字母为小写的过滤器(wrappingFilter)

    解决方案:filterName = "wrappingFilter"设置覆盖掉隐试注册的过滤器,这样就可以避免注册多个过滤器。

    PS:其实还有一个隐藏的BUG现象没有被发现,就是如果没有覆盖掉隐式注册的过滤器配置,那么隐式注册的过滤器中urlPatterns参数是将所有的接口都放入隐式过滤器。

    Have Fun ~ Tester !


    点击阅读阅文,查看FunTester历史原创集合

  • 相关阅读:
    hlgoj 1766 Cubing
    Reverse Linked List
    String to Integer
    Bitwise AND of Numbers Range
    Best Time to Buy and Sell Stock III
    First Missing Positive
    Permutation Sequence
    Next Permutation
    Gray Code
    Number of Islands
  • 原文地址:https://www.cnblogs.com/FunTester/p/15163328.html
Copyright © 2011-2022 走看看