likes
comments
collection
share

SpringMVC日志如何完善

作者站长头像
站长
· 阅读数 2

一、问题

调用方反馈接口异常，报 400 错误，查看日志只有 1 条信息：

2024-02-21 18:49:14,123 zb-third WARN  [] o.s.w.s.m.s.DefaultHandlerExceptionResolver - Resolved [org.springframework.web.bind.MissingServletRequestParameterException: Required request parameter 'content' for method parameter type String is not present]

看日志是请求缺少入参 content，调用方坚持肯定传了，由于没有更多日志，不好确认到底是谁的问题。

项目的日志通过 @Aspect 注解，针对 Controller 下的所有接口进行了请求参数和相应结果的打印。由于入参校验都没通过，所以在框架层面，SpringMVC 直接就把请求报错返回了，代码没走到日志打印这一块。

本文探讨下如何完善项目的日志，有利于甩锅时做到有理有据。

二、源码分析

首先需要弄清楚接收到请求后，整个流转过程是怎样的。SpringMVC 框架层面做了哪些拦截？aop 日志代理类什么时候开始执行？可以通过源码弄清楚这些问题。

以下为源码分析，分析过程直接在源码注释上，没兴趣的可以直接跳过。

从 http 请求的控制核心类 DispatcherServlet 开始。

// DispatcherServlet
public abstract class HttpServlet extends GenericServlet {   
    /**
     * 处理具体的 http 请求，比如 GET 请求，则走 doGet 方法，HEAD 请求，走 doHead 方法，POST 请求，走 doPost 方法。
     */
    protected void service(HttpServletRequest req, HttpServletResponse resp)
        throws ServletException, IOException {

        String method = req.getMethod();

        if (method.equals(METHOD_GET)) {
            long lastModified = getLastModified(req);
            // servlet 不支持 if-modified-since，lastModified 默认返回 -1，所以肯定会执行 doGet
            if (lastModified == -1) {
                doGet(req, resp);
            } else {
                //...省略代码
            }
        } else if (method.equals(METHOD_HEAD)) {
            long lastModified = getLastModified(req);
            maybeSetLastModified(resp, lastModified);
            doHead(req, resp);
        } else if (method.equals(METHOD_POST)) {
            doPost(req, resp);
        } else if (method.equals(METHOD_PUT)) {
            doPut(req, resp);
        } else if (method.equals(METHOD_DELETE)) {
            doDelete(req, resp);
        } else if (method.equals(METHOD_OPTIONS)) {
            doOptions(req,resp);
        } else if (method.equals(METHOD_TRACE)) {
            doTrace(req,resp);
        } else {
            //...省略代码
        }
    }
}

public abstract class FrameworkServlet extends HttpServletBean implements ApplicationContextAware {
  @Override
	protected final void doPost(HttpServletRequest request, HttpServletResponse response)
			throws ServletException, IOException {
		processRequest(request, response);
	}

  protected final void processRequest(HttpServletRequest request, HttpServletResponse response)
			throws ServletException, IOException {

		//...省略代码

		try {
			doService(request, response);
		}
		finally {
			//...省略代码
      //注：这里也会打印请求日志，设置为 TRACE 等级即可
			logResult(request, response, failureCause, asyncManager);
			publishRequestHandledEvent(request, response, startTime, failureCause);
		}
	}
}

// 处理 Http 请求的核心控制类
public class DispatcherServlet extends FrameworkServlet {

  protected void doService(HttpServletRequest request, HttpServletResponse response) throws Exception {
		//注：这里也会打印请求日志，设置为 TRACE 等级即可
		logRequest(request);

    //省略代码...

		try {
			doDispatch(request, response);
		}
		finally {
			//省略代码...
		}
	}

  protected void doDispatch(HttpServletRequest request, HttpServletResponse response) throws Exception {
		HttpServletRequest processedRequest = request;
		HandlerExecutionChain mappedHandler = null;
		boolean multipartRequestParsed = false;

		WebAsyncManager asyncManager = WebAsyncUtils.getAsyncManager(request);

		try {
			ModelAndView mv = null;
			Exception dispatchException = null;

			try {
				processedRequest = checkMultipart(request);
				multipartRequestParsed = (processedRequest != request);

				// 获取 HandlerExecutionChain，比如基于 RequestMappingHandlerMapping 查找是否能处理该请求
				mappedHandler = getHandler(processedRequest);
        // 如果没有匹配，直接返回404(默认)或者抛异常
        if (mappedHandler == null) {
					noHandlerFound(processedRequest, response);
					return;
				}

				// 获取 handler 的适配器，比如 HandlerMethod
				// 返回实际处理请求的 HandlerAdapter，比如 RequestMappingHandlerAdapter，可以处理 @RequestMapping 注解的 API
				HandlerAdapter ha = getHandlerAdapter(mappedHandler.getHandler());

				//...省略代码

        // 获取 handler 的拦截器，并执行拦截器的 preHandle 方法
				if (!mappedHandler.applyPreHandle(processedRequest, response)) {
					return;
				}

        // 此处会直接执行 API 的代码
		    // 注：如果通过 @Aspect 注解等代理了 Controller 类，实际执行的是目标 Controller 的代理类
				mv = ha.handle(processedRequest, response, mappedHandler.getHandler());

				//...省略代码

        // 获取 handler 的拦截器，并执行拦截器的 preHandle 方法
				mappedHandler.applyPostHandle(processedRequest, response, mv);
			}
			catch (Exception ex) {
				dispatchException = ex;
			}
			catch (Throwable err) {
				// As of 4.3, we're processing Errors thrown from handler methods as well,
				// making them available for @ExceptionHandler methods and other scenarios.
				dispatchException = new NestedServletException("Handler dispatch failed", err);
			}
			processDispatchResult(processedRequest, response, mappedHandler, mv, dispatchException);
		}
		catch (Exception ex) {
			// 执行拦截器的 afterCompletion 方法
			triggerAfterCompletion(processedRequest, response, mappedHandler, ex);
		}
		catch (Throwable err) {
      // 执行拦截器的 afterCompletion 方法
			triggerAfterCompletion(processedRequest, response, mappedHandler,
					new NestedServletException("Handler processing failed", err));
		}
		finally {
			//...省略代码
		}
	}

  // 获取 HandlerExecutionChain
	protected HandlerExecutionChain getHandler(HttpServletRequest request) throws Exception {
		if (this.handlerMappings != null) {
			for (HandlerMapping mapping : this.handlerMappings) {
			  // 基于 HandlerMapping 获取 HandlerExecutionChain
				HandlerExecutionChain handler = mapping.getHandler(request);
				if (handler != null) {
					return handler;
				}
			}
		}
		return null;
	}
}

// 处理 @RequestMapping 的适配器类
public class RequestMappingHandlerAdapter extends AbstractHandlerMethodAdapter
		implements BeanFactoryAware, InitializingBean {

  protected ModelAndView handleInternal(HttpServletRequest request,
			HttpServletResponse response, HandlerMethod handlerMethod) throws Exception {

		ModelAndView mav;

    //...省略代码

		if (this.synchronizeOnSession) {
			//...省略代码
		}
		else {
			// 实际的方法调用
			mav = invokeHandlerMethod(request, response, handlerMethod);
		}

		//...省略代码

		return mav;
	}

  protected ModelAndView invokeHandlerMethod(HttpServletRequest request,
			HttpServletResponse response, HandlerMethod handlerMethod) throws Exception {

		ServletWebRequest webRequest = new ServletWebRequest(request, response);
		try {
			//...省略代码

      ServletInvocableHandlerMethod invocableMethod = createInvocableHandlerMethod(handlerMethod);
      ModelAndViewContainer mavContainer = new ModelAndViewContainer();
      // 实际的方法调用
			invocableMethod.invokeAndHandle(webRequest, mavContainer);
			
      //...省略代码

			return getModelAndView(mavContainer, modelFactory, webRequest);
		}
		finally {
			webRequest.requestCompleted();
		}
	}
}

// 扩展 InvocableHandlerMethod 类，增加了对相应的处理
public class ServletInvocableHandlerMethod extends InvocableHandlerMethod {

    public void invokeAndHandle(ServletWebRequest webRequest, ModelAndViewContainer mavContainer,
			Object... providedArgs) throws Exception {
      // 实际的方法调用
		  Object returnValue = invokeForRequest(webRequest, mavContainer, providedArgs);
		  setResponseStatus(webRequest);

      //...省略代码
	}
}

// 扩展 HandlerMethod 类，增加了解析请求参数的功能
public class InvocableHandlerMethod extends HandlerMethod {

    public Object invokeForRequest(NativeWebRequest request, @Nullable ModelAndViewContainer mavContainer,
            Object... providedArgs) throws Exception {
        
        // 获取参数，同时也是参数校验的过程，比如是否缺少入参，校验不通过时抛出异常
        Object[] args = getMethodArgumentValues(request, mavContainer, providedArgs);
        // 实际的方法调用
        return doInvoke(args);
    }

    protected Object doInvoke(Object... args) throws Exception {
		  Method method = getBridgedMethod();
		  try {
			  //...省略代码

        // getBean() 获取的是代理类，如果采用了 @Aspect 注解的话，此时会执行 @Around 等方法
			  return method.invoke(getBean(), args);
		  }
		  //...省略代码
	  }
}

由以上代码可知：

A、请求进来后，DispatcherServlet.doService 会打印日志(包括参数等)，FrameworkServlet.processRequest 会打印响应结果(Http状态码等)，前提是日志等级设置为 TRACE。

B、请求的实际处理是 DispatcherServlet.doDispatch 方法，步骤是：

  1. 确认是否可以处理该请求(获取 HandlerExecutionChain，内部一般包括适配器 handler 和 拦截器 intercept)，如果不可以，返回 404；
  2. 获取 handler 的适配器，比如 HandlerMethod，返回实际处理请求的 HandlerAdapter，比如 RequestMappingHandlerAdapter，可以处理 @RequestMapping 注解的 API；
  3. 执行拦截器的 preHandle 方法；
  4. 实际的方法调用，获取请求参数并校验，如果缺少入参，校验不通过时直接抛出异常；如果方法被代理(cglib 等方式)，则实际执行的是代理类的方法。
  5. 执行拦截器的 postHandle 方法。

三、解决办法

1、直接使用 DispatcherServlet 的日志

logback-spring.xml 文件增加配置即可，设置 org.springframework.web.servlet.DispatcherServlet 日志等级为 TRACE。

<springProfile name="test">
    <logger name="org.springframework.web.servlet.DispatcherServlet" level="TRACE" additivity="false">
        <appender-ref ref="console"/>
    </logger>
</springProfile>

当入参不完整时，可以看到入参只有 mobile，缺少 content，最终返回 400 错误。当设置 FrameworkServlet.enableLoggingRequestDetails 为 true 时，可以打印更详细的请求信息（参数、请求头等）。

2024-02-21 19:28:50,301 zb-third TRACE [] o.s.web.servlet.DispatcherServlet - POST "/zb-third/b/sms/bopSendMessage?mobile=13312345678", parameters={masked}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2024-02-21 19:28:50,321 zb-third WARN  [] o.s.w.s.m.s.DefaultHandlerExceptionResolver - Resolved [org.springframework.web.bind.MissingServletRequestParameterException: Required request parameter 'content' for method parameter type String is not present]
2024-02-21 19:28:50,321 zb-third TRACE [] o.s.web.servlet.DispatcherServlet - No view rendering, null ModelAndView returned.
2024-02-21 19:28:50,321 zb-third DEBUG [] o.s.web.servlet.DispatcherServlet - Completed 400 BAD_REQUEST, headers={}
2024-02-21 19:28:50,323 zb-third TRACE [] o.s.web.servlet.DispatcherServlet - "ERROR" dispatch for POST "/zb-third/error?mobile=13312345678", parameters={masked}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2024-02-21 19:28:50,325 zb-third TRACE [] o.s.web.servlet.DispatcherServlet - No view rendering, null ModelAndView returned.
2024-02-21 19:28:50,325 zb-third DEBUG [] o.s.web.servlet.DispatcherServlet - Exiting from "ERROR" dispatch, status 400, headers={masked}

当 url 不存在时，返回 404 错误。

2024-02-21 19:28:17,438 zb-third TRACE [] o.s.web.servlet.DispatcherServlet - POST "/zb-third/b/sms/bopSendMessage1?mobile=13312345678", parameters={masked}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2024-02-21 19:28:17,448 zb-third TRACE [] o.s.web.servlet.DispatcherServlet - No view rendering, null ModelAndView returned.
2024-02-21 19:28:17,448 zb-third DEBUG [] o.s.web.servlet.DispatcherServlet - Completed 404 NOT_FOUND, headers={masked}
2024-02-21 19:28:17,452 zb-third TRACE [] o.s.web.servlet.DispatcherServlet - "ERROR" dispatch for POST "/zb-third/error?mobile=13312345678", parameters={masked}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2024-02-21 19:28:17,471 zb-third TRACE [] o.s.web.servlet.DispatcherServlet - No view rendering, null ModelAndView returned.
2024-02-21 19:28:17,471 zb-third DEBUG [] o.s.web.servlet.DispatcherServlet - Exiting from "ERROR" dispatch, status 404, headers={masked}

2、自定义拦截器记录日志

配置日志拦截器，

@Configuration
public class SpringMvcInterceptorConfig extends WebMvcConfigurationSupport {

    @Autowired
    private HandlerInterceptor handlerInterceptor;

    @Override
    protected void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(handlerInterceptor).addPathPatterns("/**");
    }
}

@Component
@Slf4j
public class LogInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        // 打印请求信息
        StringBuilder sb = new StringBuilder();
        String contentType = request.getContentType();
        if (contentType == null || !contentType.contains("application/json")) {
            List<String> params = request.getParameterMap().entrySet().stream().map(entry -> entry.getKey() + ": " + entry.getValue()[0]).collect(Collectors.toList());
            sb.append(String.join(", ", params));
        }
        log.info("req-> x-forwarded-for: {}, url: {}, param: {}",
                request.getHeader("X-Forwarded-For"),
                request.getServletPath(),
                sb);
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
                           @Nullable ModelAndView modelAndView) {
        int status = response.getStatus();
        if (status >= 500) {
            log.error("resp-> url: {}, http status: {}", request.getServletPath(), status);
        } else if (status >= 400) {
            log.warn("resp-> url: {}, http status: {}", request.getServletPath(), status);
        } else {
            log.info("resp-> url: {}, http status: {}", request.getServletPath(), status);
        }
    }
}

当入参不完整时，日志如下：

2024-02-21 20:25:32,105 zb-third INFO  [] c.g.glzb.third.config.LogInterceptor - req-> x-forwarded-for: null, url: /b/sms/bopSendMessage, param: mobile: 13312345678
2024-02-21 20:25:32,115 zb-third WARN  [] o.s.w.s.m.s.DefaultHandlerExceptionResolver - Resolved [org.springframework.web.bind.MissingServletRequestParameterException: Required request parameter 'content' for method parameter type String is not present]
2024-02-21 20:25:32,120 zb-third INFO  [] c.g.glzb.third.config.LogInterceptor - req-> x-forwarded-for: null, url: /error, param: mobile: 13312345678
2024-02-21 20:25:32,142 zb-third WARN  [] c.g.glzb.third.config.LogInterceptor - resp-> url: /error, http status: 400

当 404 错误时，日志如下：

2024-02-21 20:48:41,034 zb-third WARN  [] o.s.web.servlet.PageNotFound - No mapping for POST /zb-third/b/sms/bopSendMessage1
2024-02-21 20:48:41,040 zb-third INFO  [] c.g.glzb.third.config.LogInterceptor - req-> x-forwarded-for: null, url: /error, param: mobile: 13312345678
2024-02-21 20:48:41,078 zb-third WARN  [] c.g.glzb.third.config.LogInterceptor - resp-> url: /error, http status: 404

3、监听ServletRequestHandledEvent 事件

FrameworkServlet.processRequest 方法，最后 finally 块中，发布了 ServletRequestHandledEvent 事件。

public abstract class FrameworkServlet {
    
    private void publishRequestHandledEvent(HttpServletRequest request, HttpServletResponse response,
			long startTime, @Nullable Throwable failureCause) {

		if (this.publishEvents && this.webApplicationContext != null) {
			// Whether or not we succeeded, publish an event.
			long processingTime = System.currentTimeMillis() - startTime;
			this.webApplicationContext.publishEvent(
					new ServletRequestHandledEvent(this,
							request.getRequestURI(), request.getRemoteAddr(),
							request.getMethod(), getServletConfig().getServletName(),
							WebUtils.getSessionId(request), getUsernameForRequest(request),
							processingTime, failureCause, response.getStatus()));
		}
	}
}

基于此，可以考虑监听 ServletRequestHandledEvent 事件，从而打印日志。

创建 ServletRequestHandledEventListener，

@Component
public class ServletRequestHandledEventListener implements ApplicationListener<ServletRequestHandledEvent> {

    private static final Logger logger = LoggerFactory.getLogger(ServletRequestHandledEventListener.class);

    @Override
    public void onApplicationEvent(ServletRequestHandledEvent event) {
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        if (attributes != null) {
            HttpServletRequest request = attributes.getRequest();
            String requestId = request.getHeader("requestId");
            List<String> params = request.getParameterMap().entrySet().stream().map(entry -> entry.getKey() + "=" + entry.getValue()[0]).collect(Collectors.toList());
            StringBuilder sb = new StringBuilder().append(String.join(", ", params));
            int status = event.getStatusCode();
            String url = StringUtils.hasText(sb) ? event.getRequestUrl() + "?" + sb : event.getRequestUrl();
            if (status >= 500) {
                logger.error("http requestId: {}, url: {}, response status: {}, cost: {}ms", requestId, url, status, event.getProcessingTimeMillis());
            } else if (status >= 400) {
                logger.warn("http requestId: {}, url: {}, response status: {}, cost: {}ms", requestId, url, status, event.getProcessingTimeMillis());
            } else {
                logger.info("http requestId: {}, url: {}, response status: {}, cost: {}ms", requestId, url, status, event.getProcessingTimeMillis());
            }
        }
    }
}

当入参不完整时，日志如下：

2024-02-21 21:23:28,650 zb-third WARN  [] o.s.w.s.m.s.DefaultHandlerExceptionResolver - Resolved [org.springframework.web.bind.MissingServletRequestParameterException: Required request parameter 'content' for method parameter type String is not present]
2024-02-21 21:23:28,651 zb-third WARN  [] c.g.g.t.c.ServletRequestHandledEventListener - http requestId: null, url: /zb-third/b/sms/bopSendMessage?mobile=13312345678, response status: 400, cost: 71ms
2024-02-21 21:23:28,653 zb-third WARN  [] c.g.g.t.c.ServletRequestHandledEventListener - http requestId: null, url: /zb-third/error?mobile=13312345678, response status: 400, cost: 2ms

当 404 错误时，日志如下：

2024-02-21 21:24:55,399 zb-third WARN  [] c.g.g.t.c.ServletRequestHandledEventListener - http requestId: null, url: /zb-third/b/sms/bopSendMessage1?mobile=13312345678, response status: 404, cost: 7ms
2024-02-21 21:24:55,408 zb-third WARN  [] c.g.g.t.c.ServletRequestHandledEventListener - http requestId: null, url: /zb-third/error?mobile=13312345678, response status: 404, cost: 7ms

4、三种方法的对比

最后简单对比下三种方式的优劣，个人更推荐第三种方式。

方式优势劣势
直接使用 DispatcherServlet 的日志1、无需额外配置； 2、所有请求都能捕获。1、设置为TRACE会有一些多余的日志； 2、日志内容无法自主控制。
自定义拦截器1、日志内容可自主控制。1、需要额外的配置类； 2、无法捕获 404 错误。
监听ServletRequestHandledEvent 事件1、所有请求都能捕获； 2、日志内容可自主控制。1、需要额外的配置类。