Suppress logging from HandlerMapping when used for Spring Security's mvcRequestMatcher

[xak2000]

Affects: spring-web 6.0.7, probably any other version too, as the root cause is mvcMatchers and HandlerMappingIntrospector.

When autorization configuration in HttpSecurity contains many request matchers and org.springframework.web logger is set to debug, then logs are spammed with message about selected handler mapper on each request (i.e. "Mapped to package.Controller#handler()"). The more requestMatchers configured (or even individual URLs in the same request matcher), the more log lines with the same mapping message appears.

Example (spring-boot 3.0.5, spring-security 6.0.2):

@SpringBootApplication
public class DemoApplication {

	public static void main(String[] args) {
		SpringApplication.run(DemoApplication.class, args);
	}

	@Bean
	SecurityFilterChain securityFilterChain(HttpSecurity http) throws Exception {
		return http
				.authorizeHttpRequests(authz -> authz
						.requestMatchers(PathRequest.toStaticResources().atCommonLocations()).permitAll()
						.requestMatchers("/error").permitAll()
						.requestMatchers("/swagger-ui.html", "/swagger-ui/**", "/v3/api-docs/**").permitAll()
						.requestMatchers("/livez", "/readyz").permitAll()
						.requestMatchers("/actuator/**").authenticated()
						.requestMatchers("/management-api/**").hasRole("ADMIN")
						.requestMatchers("/api/v2/config/**", "/api/v2/preferences/**").permitAll()
						.anyRequest().permitAll()
				)
				.build();
	}

	@RestController
	public static class MyController {

		@GetMapping("/test")
		public String test() {
			return "OK";
		}

	}

}

Then curl -v "http://localhost:8080/test" will result with these logs:

2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] o.s.web.servlet.DispatcherServlet        : GET "/test", parameters={}
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.302+02:00 DEBUG 7304 --- [nio-8080-exec-6] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/plain', given [*/*] and supported [text/plain, */*, application/json, application/*+json]
2023-04-17T21:56:51.302+02:00 DEBUG 7304 --- [nio-8080-exec-6] m.m.a.RequestResponseBodyMethodProcessor : Writing ["OK"]
2023-04-17T21:56:51.302+02:00 DEBUG 7304 --- [nio-8080-exec-6] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

While the last Mapped to log message (that is after DispatcherServlet log) is useful, other 10 are confusing and "spamming". And also totally useless. Why would I want to know what controller is matched to the current request every time when MvcRequestMatcher checks current request's url against each configured URL? If the log would display something like "/readyz is not matched against /test" (even for each matcher) it would be useful, but resolving current request to a controller's method is just a side effect of the request matching algorithm and the result of such resolving should not be shown on the debug level, IMHO. Especially for each request matcher in the scope of the same request.

The root cause is probably the usage of MvcRequestMatcher by default and its delegation to HandlerMappingIntrospector that calls handlerMapping.getHandler(request). AbstractHandlerMapping.getHandler(HttpServletRequest) then logs that message.

Changing requestMatchers(String) to requestMatchers(AntPathRequestMatcher) solves the problem.

E.g. changing

.requestMatchers("/livez", "/readyz").permitAll()

with

.requestMatchers(antMatcher("/livez"), antMatcher("/readyz")).permitAll()

makes 2 less Mapped to messages to be logged (9 instead of 11).

To be honest, I don't know how to solve this. Probably AbstractHandlerMapping.getHandler(HttpServletRequest) should not log on debug level? And the caller of this method (e.g. DispatcherServlet) should log the resolved mapping instead, if it's appropriate. This way if the resolving is done not for the purpose of request dispatching but for e.g. comparison with security rule, the result of resolving will not be logged. HandlerMappingIntrospector could also log the result, if needed, but probably on a trace level.

This problem probably exists for a long time, but previously most popular request matcher was antMatcher. Now the mvcMatcher is the default if spring-webmvc is on classpath (like 99% of the time) so the problem just came to the surface.

[simonbasle]

Briefly looking at it, it appears that piece of code uses a logger instance (from ApplicationObjectSupport) while the class has a second logger this.mappingsLogger which is "hidden" using LogDelegateFactory.getHiddenLog.

To quote getHiddenLog's javadoc:

Create a "hidden" logger with a category name prefixed with "_", thus precluding it from being enabled together with other log categories from the same package. This is useful for specialized output that is either too verbose or otherwise optional or unnecessary to see all the time.

I think that would fit the bill, @rstoyanchev any insight?

(if that's the case, this issue would be ideal-for-contribution too)

[rstoyanchev]

Indeed this is due to the use of HandlerMappingIntrospector to help mvcRequestMatcher make the same pattern matching decisions as the HandlerMapping that matches the request. However, I am surprised that it happens so many times. @rwinch is this expected? Conceptually, Spring Security should not have to do this more than once per request. So, if anything the goal should be to ensure that, rather than change the logging.

[xak2000]

@rstoyanchev

So, if anything the goal should be to ensure that, rather than change the logging.

Maybe both?

Even if resolving will be done only once by Spring Security, the log will look like:

2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] o.s.web.servlet.DispatcherServlet        : GET "/test", parameters={}
2023-04-17T21:56:51.301+02:00 DEBUG 7304 --- [nio-8080-exec-6] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$MyController#test()

The first Mapped to is still excessive.

At the moment the code for logging this looks like this:

		if (logger.isTraceEnabled()) {
			logger.trace("Mapped to " + handler);
		}
		else if (logger.isDebugEnabled() && !DispatcherType.ASYNC.equals(request.getDispatcherType())) {
			logger.debug("Mapped to " + executionChain.getHandler());
		}

Probably, we could use mappingsLogger instead of logger if TRACE level is disabled, but DEBUG level is enabled, like @simonbasle suggested?

For example there is a similar pattern in the AbstractDetectingUrlHandlerMapping.detectHandlers():

		if (mappingsLogger.isDebugEnabled()) {
			mappingsLogger.debug(formatMappingName() + " " + getHandlerMap());
		}
		else if ((logger.isDebugEnabled() && !getHandlerMap().isEmpty()) || logger.isTraceEnabled()) {
			logger.debug("Detected " + getHandlerMap().size() + " mappings in " + formatMappingName());
		}

But this will make even second Mapped to message to be hidden on DEBUG level of org.springframework.web logger, that is also not optimal, as it's really useful to see what controller's method is selected to handle the request right after GET "/test", parameters={} log message. By replacing logger with mappingsLogger this message will appear only if _org.springframework.web.servlet.HandlerMapping logger is explicitly configured on DEBUG level or org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping is configured on TRACE level. And both variants will still enable both Mapped to messages (the garbage one and the desired one). :(

[rstoyanchev]

Logging is now suppressed with a request attribute as the trigger.

[xak2000]

Wow, very creative solution! Thanks! 👍