Springboot通过@WebFilter日志双份打印BUG分享

FunTester

发布于 2021-08-20 12:10:09

5720

发布于 2021-08-20 12:10:09

文章被收录于专栏：FunTester FunTesterFunTester

最近在做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参数是将所有的接口都放入隐式过滤器。