spring多个过滤器和controller接口的代码执行顺序

多个过滤器和controller接口的代码执行顺序

研究此问题的起因

• 在使用开源框架芋道时, 启用了api访问日志功能, 但是发现未能生效,
• 看源码发现是通过过滤器实现的, 并使用断点测试
• 发现在过滤器中的日志记录代码写在了 filterChain.doFilter(request, response); 后面
• 日志记录代码调用了fegin接口, 故会进入fegin的请求拦截器
• 拦截器处理逻辑是: 从 SecurityContextHolder中取出用户信息来设置到requestTemplate的header中,用于远程调用时的认证校验
• 发现问题: 在fegin拦截器中却取不到SecurityContextHolder内容
• 故进行排查

当前代码情况

1.过滤器顺序

• 当前只关注api访问过滤器和认证过滤器,顺序如下:
• api访问日志过滤器 => 认证过滤器

2.ApiAccessLogFilter中核心代码

在filterChain.doFilter(request, response);后执行日志插入操作

@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
        throws ServletException, IOException {
    // 获得开始时间
    LocalDateTime beginTime = LocalDateTime.now();
    // 提前获得参数，避免 XssFilter 过滤处理
    Map<String, String> queryString = ServletUtils.getParamMap(request);
    String requestBody = ServletUtils.isJsonRequest(request) ? ServletUtils.getBody(request) : null;

    try {
        log.debug("======{} api访问日志过滤器处理 前线程：{} =====",request.getRequestURI() ,Thread.currentThread().getName());
        // 继续过滤器
        filterChain.doFilter(request, response);
        // 正常执行，记录日志
        
        log.debug("======{} api访问日志过滤器处理 后线程：{} =====",request.getRequestURI() ,Thread.currentThread().getName());
        createApiAccessLog(request, beginTime, queryString, requestBody, null);
        log.debug("======{} api访问日志过滤器处理 后后线程：{} =====",request.getRequestURI() ,Thread.currentThread().getName());
    } catch (Exception ex) {
        // 异常执行，记录日志, 方法中调用了Fegin接口,担心篇幅太长就不帖出
        createApiAccessLog(request, beginTime, queryString, requestBody, ex);
        throw ex;
    }
}

3.认证逻辑

简单写下:
获取token => 校验token有效性 => 获取用户信息并设置到SecurityContextHolder中

4.feign拦截器

简单写下:
通过SecurityContextHolder获取用户信息包括token, 并设置到requestTemplate的header中,便于后续接口认证使用

排查结果

1.拦截器和controller代码执行顺序:

1. api访问日志过滤器中filterChain.doFilter(request, response)之前代码
2. => 认证过滤器中filterChain.doFilter(request, response)之前代码
3. => controller代码执行完成
4. => 认证过滤器中filterChain.doFilter(request, response)之后代码
5. => api访问日志过滤器中filterChain.doFilter(request, response)之后代码

2.问题原因:

• 在api访问日志过滤器的日志记录代码是在controller接口返回完成后执行的, 同时debug是看到SecurityContextHolder被清除了
  
• 翻看源码发现SecurityContextHolder.clearContext();是在chain.doFilter(holder.getRequest(), holder.getResponse());之后的代码, 故会在我添加日志的代码之前执行, 所以就取不到SecurityContextHolder

@Override
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
		throws IOException, ServletException {
	doFilter((HttpServletRequest) request, (HttpServletResponse) response, chain);
}

private void doFilter(HttpServletRequest request, HttpServletResponse response, FilterChain chain)
		throws IOException, ServletException {
	// ensure that filter is only applied once per request
	if (request.getAttribute(FILTER_APPLIED) != null) {
		chain.doFilter(request, response);
		return;
	}
	request.setAttribute(FILTER_APPLIED, Boolean.TRUE);
	if (this.forceEagerSessionCreation) {
		HttpSession session = request.getSession();
		if (this.logger.isDebugEnabled() && session.isNew()) {
			this.logger.debug(LogMessage.format("Created session %s eagerly", session.getId()));
		}
	}
	HttpRequestResponseHolder holder = new HttpRequestResponseHolder(request, response);
	SecurityContext contextBeforeChainExecution = this.repo.loadContext(holder);
	try {
		SecurityContextHolder.setContext(contextBeforeChainExecution);
		if (contextBeforeChainExecution.getAuthentication() == null) {
			logger.debug("Set SecurityContextHolder to empty SecurityContext");
		}
		else {
			if (this.logger.isDebugEnabled()) {
				this.logger
						.debug(LogMessage.format("Set SecurityContextHolder to %s", contextBeforeChainExecution));
			}
		}
		chain.doFilter(holder.getRequest(), holder.getResponse());
	}
	finally {
		SecurityContext contextAfterChainExecution = SecurityContextHolder.getContext();
		// Crucial removal of SecurityContextHolder contents before anything else.
		// 此处删除了SecurityContextHolder
		SecurityContextHolder.clearContext();
		this.repo.saveContext(contextAfterChainExecution, holder.getRequest(), holder.getResponse());
		request.removeAttribute(FILTER_APPLIED);
		this.logger.debug("Cleared SecurityContextHolder to complete request");
	}
}

• 同时还发现了日志记录的方法上加了@Async进行异步处理, 从而是的当前请求和日志记录不是同一个线程, 也会导致没法获取到同一个SecurityContextHolder, 故将@Async更换到了Fegin接口的实现方法上, 使Fegin拦截器和当前请求是同一个线程

总结

例如有两个过滤器, 过滤器a 和 过滤器b ,顺序为: a => b
spring多个过滤器和controller接口的代码执行顺序如下:

1. 过滤器a 中 filterChain.doFilter 之前代码
2. 过滤器b中 filterChain.doFilter 之前代码
3. controller 代码执行完成
4. 过滤器b 中 filterChain.doFilter 之后代码
5. 过滤器a 中 filterChain.doFilter 之后代码