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

关注

发布于: 3 小时前

最近在做 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:1INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:1 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:1 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:1 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:1 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1INFO 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.16INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:67 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos,耗时:69 ms,参数:,响应:{"code":0,"data":{}},来源:0:0:0:0:0:0:0:1INFO com.funtester.master.common.wapper.WrappingFilter:65 请求:/m/infos/fdsa,耗时:5 ms,参数:,响应:,来源:0:0:0:0:0:0:0:1INFO 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 历史原创集合

发布于: 3 小时前阅读数: 2

原文链接:【http://xie.infoq.cn/article/76a6bc4cf9b9578a5ebc20f1a】。文章转载请联系作者。

FunTester

关注

公众号：FunTester，Have Fun, Tester！ 2020.10.20 加入

Have Fun,Tester！

发布

暂无评论

创作场景

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

Have Fun ~ Tester ！

FunTester

评论