最近在做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 历史原创集合