From 92a6a421e648026b0a1d35b500e66a77988198de Mon Sep 17 00:00:00 2001 From: Andrey Litvitski Date: Mon, 1 Jun 2026 17:53:47 +0300 Subject: [PATCH] Guard debug/trace LogMessage calls in hot paths The main issue is that if we don't use `isDebugEnabled` or `isTraceEnabled` to check, we end up allocating `LogMessage` instances. In this commit, I want to fix what I believe are performance bottlenecks that may occur frequently. Closes: gh-19251 Signed-off-by: Andrey Litvitski --- .../channel/ChannelProcessingFilter.java | 4 ++- .../authentication/ProviderManager.java | 19 +++++++++----- ...ractUserDetailsAuthenticationProvider.java | 4 ++- .../switchuser/SwitchUserFilter.java | 23 ++++++++++++----- .../AnonymousAuthenticationWebFilter.java | 10 +++++--- .../AuthenticationWebFilter.java | 7 ++++-- .../authentication/SwitchUserWebFilter.java | 25 +++++++++++++------ ...elegatingReactiveAuthorizationManager.java | 8 +++--- .../matcher/AndServerWebExchangeMatcher.java | 7 ++++-- .../NegatedServerWebExchangeMatcher.java | 8 +++--- .../matcher/OrServerWebExchangeMatcher.java | 7 ++++-- .../web/util/matcher/RegexRequestMatcher.java | 4 ++- 12 files changed, 88 insertions(+), 38 deletions(-) diff --git a/access/src/main/java/org/springframework/security/web/access/channel/ChannelProcessingFilter.java b/access/src/main/java/org/springframework/security/web/access/channel/ChannelProcessingFilter.java index ee2982fc64c..2bc65da6f88 100644 --- a/access/src/main/java/org/springframework/security/web/access/channel/ChannelProcessingFilter.java +++ b/access/src/main/java/org/springframework/security/web/access/channel/ChannelProcessingFilter.java @@ -129,7 +129,9 @@ public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain) FilterInvocation filterInvocation = new FilterInvocation(request, response, chain); Collection attributes = this.securityMetadataSource.getAttributes(filterInvocation); if (attributes != null) { - this.logger.debug(LogMessage.format("Request: %s; ConfigAttributes: %s", filterInvocation, attributes)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Request: %s; ConfigAttributes: %s", filterInvocation, attributes)); + } this.channelDecisionManager.decide(filterInvocation, attributes); @Nullable HttpServletResponse channelResponse = filterInvocation.getResponse(); Assert.notNull(channelResponse, "HttpServletResponse is required"); diff --git a/core/src/main/java/org/springframework/security/authentication/ProviderManager.java b/core/src/main/java/org/springframework/security/authentication/ProviderManager.java index d90bfe5bad4..a3703afac1f 100644 --- a/core/src/main/java/org/springframework/security/authentication/ProviderManager.java +++ b/core/src/main/java/org/springframework/security/authentication/ProviderManager.java @@ -188,24 +188,31 @@ public Authentication authenticate(Authentication authentication) throws Authent } catch (AccountStatusException ex) { prepareException(ex, authentication); - logger.debug(LogMessage.format("Authentication failed for user '%s' since their account status is %s", - authentication.getName(), ex.getMessage()), ex); + if (logger.isDebugEnabled()) { + logger + .debug(LogMessage.format("Authentication failed for user '%s' since their account status is %s", + authentication.getName(), ex.getMessage()), ex); + } // SEC-546: Avoid polling additional providers if auth failure is due to // invalid account status throw ex; } catch (InternalAuthenticationServiceException ex) { prepareException(ex, authentication); - logger.debug(LogMessage.format("Authentication service failed internally for user '%s'", - authentication.getName()), ex); + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("Authentication service failed internally for user '%s'", + authentication.getName()), ex); + } // SEC-546: Avoid polling additional providers if auth failure is due to // invalid account status throw ex; } catch (AuthenticationException ex) { ex.setAuthenticationRequest(authentication); - logger.debug(LogMessage.format("Authentication failed with provider %s since %s", - provider.getClass().getSimpleName(), ex.getMessage())); + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("Authentication failed with provider %s since %s", + provider.getClass().getSimpleName(), ex.getMessage())); + } lastException = ex; } } diff --git a/core/src/main/java/org/springframework/security/authentication/dao/AbstractUserDetailsAuthenticationProvider.java b/core/src/main/java/org/springframework/security/authentication/dao/AbstractUserDetailsAuthenticationProvider.java index a45ef173580..8113ecb045e 100644 --- a/core/src/main/java/org/springframework/security/authentication/dao/AbstractUserDetailsAuthenticationProvider.java +++ b/core/src/main/java/org/springframework/security/authentication/dao/AbstractUserDetailsAuthenticationProvider.java @@ -145,7 +145,9 @@ public Authentication authenticate(Authentication authentication) throws Authent user = retrieveUser(username, (UsernamePasswordAuthenticationToken) authentication); } catch (UsernameNotFoundException ex) { - this.logger.debug(LogMessage.format("Failed to find user '%s'", username)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Failed to find user '%s'", username)); + } String message = this.messages.getMessage("AbstractUserDetailsAuthenticationProvider.badCredentials", "Bad credentials"); if (!this.hideUserNotFoundExceptions) { diff --git a/web/src/main/java/org/springframework/security/web/authentication/switchuser/SwitchUserFilter.java b/web/src/main/java/org/springframework/security/web/authentication/switchuser/SwitchUserFilter.java index c6910250cdb..bcfe4207e9b 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/switchuser/SwitchUserFilter.java +++ b/web/src/main/java/org/springframework/security/web/authentication/switchuser/SwitchUserFilter.java @@ -192,7 +192,9 @@ private void doFilter(HttpServletRequest request, HttpServletResponse response, SecurityContext context = this.securityContextHolderStrategy.createEmptyContext(); context.setAuthentication(targetUser); this.securityContextHolderStrategy.setContext(context); - this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", targetUser)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", targetUser)); + } this.securityContextRepository.saveContext(context, request, response); // redirect to target url this.successHandler.onAuthenticationSuccess(request, response, targetUser); @@ -210,14 +212,19 @@ private void doFilter(HttpServletRequest request, HttpServletResponse response, SecurityContext context = this.securityContextHolderStrategy.createEmptyContext(); context.setAuthentication(originalUser); this.securityContextHolderStrategy.setContext(context); - this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", originalUser)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", originalUser)); + } this.securityContextRepository.saveContext(context, request, response); // redirect to target url this.successHandler.onAuthenticationSuccess(request, response, originalUser); return; } - this.logger.trace(LogMessage.format("Did not attempt to switch user since request did not match [%s] or [%s]", - this.switchUserMatcher, this.exitUserMatcher)); + if (this.logger.isTraceEnabled()) { + this.logger + .trace(LogMessage.format("Did not attempt to switch user since request did not match [%s] or [%s]", + this.switchUserMatcher, this.exitUserMatcher)); + } chain.doFilter(request, response); } @@ -236,7 +243,9 @@ protected Authentication attemptSwitchUser(HttpServletRequest request) throws Au UsernamePasswordAuthenticationToken targetUserRequest; String username = request.getParameter(this.usernameParameter); username = (username != null) ? username : ""; - this.logger.debug(LogMessage.format("Attempting to switch to user [%s]", username)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Attempting to switch to user [%s]", username)); + } UserDetails targetUser = this.userDetailsService.loadUserByUsername(username); this.userDetailsChecker.check(targetUser); // OK, create the switch user token @@ -350,7 +359,9 @@ private UsernamePasswordAuthenticationToken createSwitchUserToken(HttpServletReq // check for switch user type of authority if (auth instanceof SwitchUserGrantedAuthority) { original = ((SwitchUserGrantedAuthority) auth).getSource(); - this.logger.debug(LogMessage.format("Found original switch user granted authority [%s]", original)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Found original switch user granted authority [%s]", original)); + } } } return original; diff --git a/web/src/main/java/org/springframework/security/web/server/authentication/AnonymousAuthenticationWebFilter.java b/web/src/main/java/org/springframework/security/web/server/authentication/AnonymousAuthenticationWebFilter.java index 05ae8a44b75..21556a0cbfe 100644 --- a/web/src/main/java/org/springframework/security/web/server/authentication/AnonymousAuthenticationWebFilter.java +++ b/web/src/main/java/org/springframework/security/web/server/authentication/AnonymousAuthenticationWebFilter.java @@ -81,13 +81,17 @@ public Mono filter(ServerWebExchange exchange, WebFilterChain chain) { return ReactiveSecurityContextHolder.getContext().switchIfEmpty(Mono.defer(() -> { Authentication authentication = createAuthentication(exchange); SecurityContext securityContext = new SecurityContextImpl(authentication); - logger.debug(LogMessage.format("Populated SecurityContext with anonymous token: '%s'", authentication)); + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("Populated SecurityContext with anonymous token: '%s'", authentication)); + } return chain.filter(exchange) .contextWrite(ReactiveSecurityContextHolder.withSecurityContext(Mono.just(securityContext))) .then(Mono.empty()); })).flatMap((securityContext) -> { - logger.debug(LogMessage.format("SecurityContext contains anonymous token: '%s'", - securityContext.getAuthentication())); + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("SecurityContext contains anonymous token: '%s'", + securityContext.getAuthentication())); + } return chain.filter(exchange); }); } diff --git a/web/src/main/java/org/springframework/security/web/server/authentication/AuthenticationWebFilter.java b/web/src/main/java/org/springframework/security/web/server/authentication/AuthenticationWebFilter.java index 3bbbdb108cf..366b89ca0c4 100644 --- a/web/src/main/java/org/springframework/security/web/server/authentication/AuthenticationWebFilter.java +++ b/web/src/main/java/org/springframework/security/web/server/authentication/AuthenticationWebFilter.java @@ -124,8 +124,11 @@ private Mono authenticate(ServerWebExchange exchange, WebFilterChain chain .defer(() -> Mono.error(new IllegalStateException("No provider found for " + token.getClass())))) .flatMap( (authentication) -> onAuthenticationSuccess(authentication, new WebFilterExchange(exchange, chain))) - .doOnError(AuthenticationException.class, - (ex) -> logger.debug(LogMessage.format("Authentication failed: %s", ex.getMessage()), ex)); + .doOnError(AuthenticationException.class, (ex) -> { + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("Authentication failed: %s", ex.getMessage()), ex); + } + }); } protected Mono onAuthenticationSuccess(Authentication authentication, WebFilterExchange webFilterExchange) { diff --git a/web/src/main/java/org/springframework/security/web/server/authentication/SwitchUserWebFilter.java b/web/src/main/java/org/springframework/security/web/server/authentication/SwitchUserWebFilter.java index 2735993ce9d..12ebb1ee310 100644 --- a/web/src/main/java/org/springframework/security/web/server/authentication/SwitchUserWebFilter.java +++ b/web/src/main/java/org/springframework/security/web/server/authentication/SwitchUserWebFilter.java @@ -159,9 +159,11 @@ public Mono filter(ServerWebExchange exchange, WebFilterChain chain) { final WebFilterExchange webFilterExchange = new WebFilterExchange(exchange, chain); return switchUser(webFilterExchange).switchIfEmpty(Mono.defer(() -> exitSwitchUser(webFilterExchange))) .switchIfEmpty(Mono.defer(() -> { - this.logger - .trace(LogMessage.format("Did not attempt to switch user since request did not match [%s] or [%s]", - this.switchUserMatcher, this.exitUserMatcher)); + if (this.logger.isTraceEnabled()) { + this.logger.trace( + LogMessage.format("Did not attempt to switch user since request did not match [%s] or [%s]", + this.switchUserMatcher, this.exitUserMatcher)); + } return chain.filter(exchange).then(Mono.empty()); })) .flatMap((authentication) -> onAuthenticationSuccess(authentication, webFilterExchange)) @@ -220,7 +222,9 @@ protected Mono exitSwitchUser(WebFilterExchange webFilterExchang private @NonNull Mono attemptSwitchUser(Authentication currentAuthentication, @Nullable String userName) { Assert.notNull(userName, "The userName can not be null."); - this.logger.debug(LogMessage.format("Attempting to switch to user [%s]", userName)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Attempting to switch to user [%s]", userName)); + } return this.userDetailsService.findByUsername(userName) .switchIfEmpty(Mono.error(this::noTargetAuthenticationException)) .doOnNext(this.userDetailsChecker::check) @@ -239,8 +243,11 @@ protected Mono exitSwitchUser(WebFilterExchange webFilterExchang private Mono onAuthenticationSuccess(Authentication authentication, WebFilterExchange webFilterExchange) { ServerWebExchange exchange = webFilterExchange.getExchange(); SecurityContextImpl securityContext = new SecurityContextImpl(authentication); - return this.securityContextRepository.save(exchange, securityContext) - .doOnSuccess((v) -> this.logger.debug(LogMessage.format("Switched user to %s", authentication))) + return this.securityContextRepository.save(exchange, securityContext).doOnSuccess((v) -> { + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Switched user to %s", authentication)); + } + }) .then(this.successHandler.onAuthenticationSuccess(webFilterExchange, authentication)) .contextWrite(ReactiveSecurityContextHolder.withSecurityContext(Mono.just(securityContext))); } @@ -256,8 +263,10 @@ private Authentication createSwitchUserToken(UserDetails targetUser, Authenticat Optional sourceAuthentication = extractSourceAuthentication(currentAuthentication); if (sourceAuthentication.isPresent()) { // SEC-1763. Check first if we are already switched. - this.logger.debug( - LogMessage.format("Found original switch user granted authority [%s]", sourceAuthentication.get())); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Found original switch user granted authority [%s]", + sourceAuthentication.get())); + } currentAuthentication = sourceAuthentication.get(); } GrantedAuthority switchAuthority = new SwitchUserGrantedAuthority(ROLE_PREVIOUS_ADMINISTRATOR, diff --git a/web/src/main/java/org/springframework/security/web/server/authorization/DelegatingReactiveAuthorizationManager.java b/web/src/main/java/org/springframework/security/web/server/authorization/DelegatingReactiveAuthorizationManager.java index 3ba7078cb16..0f8476dc222 100644 --- a/web/src/main/java/org/springframework/security/web/server/authorization/DelegatingReactiveAuthorizationManager.java +++ b/web/src/main/java/org/springframework/security/web/server/authorization/DelegatingReactiveAuthorizationManager.java @@ -58,9 +58,11 @@ public Mono authorize(Mono authentication, .filter(MatchResult::isMatch) .map(MatchResult::getVariables) .flatMap((variables) -> { - logger.debug(LogMessage.of(() -> "Checking authorization on '" - + exchange.getRequest().getPath().pathWithinApplication() + "' using " - + mapping.getEntry())); + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.of(() -> "Checking authorization on '" + + exchange.getRequest().getPath().pathWithinApplication() + "' using " + + mapping.getEntry())); + } return mapping.getEntry().authorize(authentication, new AuthorizationContext(exchange, variables)); })) .next() diff --git a/web/src/main/java/org/springframework/security/web/server/util/matcher/AndServerWebExchangeMatcher.java b/web/src/main/java/org/springframework/security/web/server/util/matcher/AndServerWebExchangeMatcher.java index 4bd7a02d39a..97a10742d29 100644 --- a/web/src/main/java/org/springframework/security/web/server/util/matcher/AndServerWebExchangeMatcher.java +++ b/web/src/main/java/org/springframework/security/web/server/util/matcher/AndServerWebExchangeMatcher.java @@ -57,8 +57,11 @@ public AndServerWebExchangeMatcher(ServerWebExchangeMatcher... matchers) { public Mono matches(ServerWebExchange exchange) { return Mono.defer(() -> { Map variables = new HashMap<>(); - return Flux.fromIterable(this.matchers) - .doOnNext((matcher) -> logger.debug(LogMessage.format("Trying to match using %s", matcher))) + return Flux.fromIterable(this.matchers).doOnNext((matcher) -> { + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("Trying to match using %s", matcher)); + } + }) .flatMap((matcher) -> matcher.matches(exchange)) .doOnNext((matchResult) -> variables.putAll(matchResult.getVariables())) .all(MatchResult::isMatch) diff --git a/web/src/main/java/org/springframework/security/web/server/util/matcher/NegatedServerWebExchangeMatcher.java b/web/src/main/java/org/springframework/security/web/server/util/matcher/NegatedServerWebExchangeMatcher.java index 6b687ef038e..e97e9f7b19f 100644 --- a/web/src/main/java/org/springframework/security/web/server/util/matcher/NegatedServerWebExchangeMatcher.java +++ b/web/src/main/java/org/springframework/security/web/server/util/matcher/NegatedServerWebExchangeMatcher.java @@ -45,9 +45,11 @@ public NegatedServerWebExchangeMatcher(ServerWebExchangeMatcher matcher) { @Override public Mono matches(ServerWebExchange exchange) { - return this.matcher.matches(exchange) - .flatMap(this::negate) - .doOnNext((matchResult) -> logger.debug(LogMessage.format("matches = %s", matchResult.isMatch()))); + return this.matcher.matches(exchange).flatMap(this::negate).doOnNext((matchResult) -> { + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("matches = %s", matchResult.isMatch())); + } + }); } private Mono negate(MatchResult matchResult) { diff --git a/web/src/main/java/org/springframework/security/web/server/util/matcher/OrServerWebExchangeMatcher.java b/web/src/main/java/org/springframework/security/web/server/util/matcher/OrServerWebExchangeMatcher.java index 84f2b1dfc30..543f45fbb1d 100644 --- a/web/src/main/java/org/springframework/security/web/server/util/matcher/OrServerWebExchangeMatcher.java +++ b/web/src/main/java/org/springframework/security/web/server/util/matcher/OrServerWebExchangeMatcher.java @@ -53,8 +53,11 @@ public OrServerWebExchangeMatcher(ServerWebExchangeMatcher... matchers) { @Override public Mono matches(ServerWebExchange exchange) { - return Flux.fromIterable(this.matchers) - .doOnNext((matcher) -> logger.debug(LogMessage.format("Trying to match using %s", matcher))) + return Flux.fromIterable(this.matchers).doOnNext((matcher) -> { + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("Trying to match using %s", matcher)); + } + }) .flatMap((matcher) -> matcher.matches(exchange)) .filter(MatchResult::isMatch) .next() diff --git a/web/src/main/java/org/springframework/security/web/util/matcher/RegexRequestMatcher.java b/web/src/main/java/org/springframework/security/web/util/matcher/RegexRequestMatcher.java index 6f9f9e642f9..4c5bb66aa4b 100644 --- a/web/src/main/java/org/springframework/security/web/util/matcher/RegexRequestMatcher.java +++ b/web/src/main/java/org/springframework/security/web/util/matcher/RegexRequestMatcher.java @@ -133,7 +133,9 @@ public boolean matches(HttpServletRequest request) { } url = sb.toString(); } - logger.debug(LogMessage.format("Checking match of request : '%s'; against '%s'", url, this.pattern)); + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("Checking match of request : '%s'; against '%s'", url, this.pattern)); + } return this.pattern.matcher(url).matches(); }