Skip to content

Commit 92a6a42

Browse files
therepanictherepanic
committed
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 <andrey1010102008@gmail.com>
1 parent 4a5379e commit 92a6a42

12 files changed

Lines changed: 88 additions & 38 deletions

File tree

‎access/src/main/java/org/springframework/security/web/access/channel/ChannelProcessingFilter.java‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -129,7 +129,9 @@ public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain)
129129
FilterInvocation filterInvocation = new FilterInvocation(request, response, chain);
130130
Collection<ConfigAttribute> attributes = this.securityMetadataSource.getAttributes(filterInvocation);
131131
if (attributes != null) {
132-
this.logger.debug(LogMessage.format("Request: %s; ConfigAttributes: %s", filterInvocation, attributes));
132+
if (this.logger.isDebugEnabled()) {
133+
this.logger.debug(LogMessage.format("Request: %s; ConfigAttributes: %s", filterInvocation, attributes));
134+
}
133135
this.channelDecisionManager.decide(filterInvocation, attributes);
134136
@Nullable HttpServletResponse channelResponse = filterInvocation.getResponse();
135137
Assert.notNull(channelResponse, "HttpServletResponse is required");

‎core/src/main/java/org/springframework/security/authentication/ProviderManager.java‎

Lines changed: 13 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -188,24 +188,31 @@ public Authentication authenticate(Authentication authentication) throws Authent
188188
}
189189
catch (AccountStatusException ex) {
190190
prepareException(ex, authentication);
191-
logger.debug(LogMessage.format("Authentication failed for user '%s' since their account status is %s",
192-
authentication.getName(), ex.getMessage()), ex);
191+
if (logger.isDebugEnabled()) {
192+
logger
193+
.debug(LogMessage.format("Authentication failed for user '%s' since their account status is %s",
194+
authentication.getName(), ex.getMessage()), ex);
195+
}
193196
// SEC-546: Avoid polling additional providers if auth failure is due to
194197
// invalid account status
195198
throw ex;
196199
}
197200
catch (InternalAuthenticationServiceException ex) {
198201
prepareException(ex, authentication);
199-
logger.debug(LogMessage.format("Authentication service failed internally for user '%s'",
200-
authentication.getName()), ex);
202+
if (logger.isDebugEnabled()) {
203+
logger.debug(LogMessage.format("Authentication service failed internally for user '%s'",
204+
authentication.getName()), ex);
205+
}
201206
// SEC-546: Avoid polling additional providers if auth failure is due to
202207
// invalid account status
203208
throw ex;
204209
}
205210
catch (AuthenticationException ex) {
206211
ex.setAuthenticationRequest(authentication);
207-
logger.debug(LogMessage.format("Authentication failed with provider %s since %s",
208-
provider.getClass().getSimpleName(), ex.getMessage()));
212+
if (logger.isDebugEnabled()) {
213+
logger.debug(LogMessage.format("Authentication failed with provider %s since %s",
214+
provider.getClass().getSimpleName(), ex.getMessage()));
215+
}
209216
lastException = ex;
210217
}
211218
}

‎core/src/main/java/org/springframework/security/authentication/dao/AbstractUserDetailsAuthenticationProvider.java‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -145,7 +145,9 @@ public Authentication authenticate(Authentication authentication) throws Authent
145145
user = retrieveUser(username, (UsernamePasswordAuthenticationToken) authentication);
146146
}
147147
catch (UsernameNotFoundException ex) {
148-
this.logger.debug(LogMessage.format("Failed to find user '%s'", username));
148+
if (this.logger.isDebugEnabled()) {
149+
this.logger.debug(LogMessage.format("Failed to find user '%s'", username));
150+
}
149151
String message = this.messages.getMessage("AbstractUserDetailsAuthenticationProvider.badCredentials",
150152
"Bad credentials");
151153
if (!this.hideUserNotFoundExceptions) {

‎web/src/main/java/org/springframework/security/web/authentication/switchuser/SwitchUserFilter.java‎

Lines changed: 17 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -192,7 +192,9 @@ private void doFilter(HttpServletRequest request, HttpServletResponse response,
192192
SecurityContext context = this.securityContextHolderStrategy.createEmptyContext();
193193
context.setAuthentication(targetUser);
194194
this.securityContextHolderStrategy.setContext(context);
195-
this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", targetUser));
195+
if (this.logger.isDebugEnabled()) {
196+
this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", targetUser));
197+
}
196198
this.securityContextRepository.saveContext(context, request, response);
197199
// redirect to target url
198200
this.successHandler.onAuthenticationSuccess(request, response, targetUser);
@@ -210,14 +212,19 @@ private void doFilter(HttpServletRequest request, HttpServletResponse response,
210212
SecurityContext context = this.securityContextHolderStrategy.createEmptyContext();
211213
context.setAuthentication(originalUser);
212214
this.securityContextHolderStrategy.setContext(context);
213-
this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", originalUser));
215+
if (this.logger.isDebugEnabled()) {
216+
this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", originalUser));
217+
}
214218
this.securityContextRepository.saveContext(context, request, response);
215219
// redirect to target url
216220
this.successHandler.onAuthenticationSuccess(request, response, originalUser);
217221
return;
218222
}
219-
this.logger.trace(LogMessage.format("Did not attempt to switch user since request did not match [%s] or [%s]",
220-
this.switchUserMatcher, this.exitUserMatcher));
223+
if (this.logger.isTraceEnabled()) {
224+
this.logger
225+
.trace(LogMessage.format("Did not attempt to switch user since request did not match [%s] or [%s]",
226+
this.switchUserMatcher, this.exitUserMatcher));
227+
}
221228
chain.doFilter(request, response);
222229
}
223230

@@ -236,7 +243,9 @@ protected Authentication attemptSwitchUser(HttpServletRequest request) throws Au
236243
UsernamePasswordAuthenticationToken targetUserRequest;
237244
String username = request.getParameter(this.usernameParameter);
238245
username = (username != null) ? username : "";
239-
this.logger.debug(LogMessage.format("Attempting to switch to user [%s]", username));
246+
if (this.logger.isDebugEnabled()) {
247+
this.logger.debug(LogMessage.format("Attempting to switch to user [%s]", username));
248+
}
240249
UserDetails targetUser = this.userDetailsService.loadUserByUsername(username);
241250
this.userDetailsChecker.check(targetUser);
242251
// OK, create the switch user token
@@ -350,7 +359,9 @@ private UsernamePasswordAuthenticationToken createSwitchUserToken(HttpServletReq
350359
// check for switch user type of authority
351360
if (auth instanceof SwitchUserGrantedAuthority) {
352361
original = ((SwitchUserGrantedAuthority) auth).getSource();
353-
this.logger.debug(LogMessage.format("Found original switch user granted authority [%s]", original));
362+
if (this.logger.isDebugEnabled()) {
363+
this.logger.debug(LogMessage.format("Found original switch user granted authority [%s]", original));
364+
}
354365
}
355366
}
356367
return original;

‎web/src/main/java/org/springframework/security/web/server/authentication/AnonymousAuthenticationWebFilter.java‎

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -81,13 +81,17 @@ public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
8181
return ReactiveSecurityContextHolder.getContext().switchIfEmpty(Mono.defer(() -> {
8282
Authentication authentication = createAuthentication(exchange);
8383
SecurityContext securityContext = new SecurityContextImpl(authentication);
84-
logger.debug(LogMessage.format("Populated SecurityContext with anonymous token: '%s'", authentication));
84+
if (logger.isDebugEnabled()) {
85+
logger.debug(LogMessage.format("Populated SecurityContext with anonymous token: '%s'", authentication));
86+
}
8587
return chain.filter(exchange)
8688
.contextWrite(ReactiveSecurityContextHolder.withSecurityContext(Mono.just(securityContext)))
8789
.then(Mono.empty());
8890
})).flatMap((securityContext) -> {
89-
logger.debug(LogMessage.format("SecurityContext contains anonymous token: '%s'",
90-
securityContext.getAuthentication()));
91+
if (logger.isDebugEnabled()) {
92+
logger.debug(LogMessage.format("SecurityContext contains anonymous token: '%s'",
93+
securityContext.getAuthentication()));
94+
}
9195
return chain.filter(exchange);
9296
});
9397
}

‎web/src/main/java/org/springframework/security/web/server/authentication/AuthenticationWebFilter.java‎

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -124,8 +124,11 @@ private Mono<Void> authenticate(ServerWebExchange exchange, WebFilterChain chain
124124
.defer(() -> Mono.error(new IllegalStateException("No provider found for " + token.getClass()))))
125125
.flatMap(
126126
(authentication) -> onAuthenticationSuccess(authentication, new WebFilterExchange(exchange, chain)))
127-
.doOnError(AuthenticationException.class,
128-
(ex) -> logger.debug(LogMessage.format("Authentication failed: %s", ex.getMessage()), ex));
127+
.doOnError(AuthenticationException.class, (ex) -> {
128+
if (logger.isDebugEnabled()) {
129+
logger.debug(LogMessage.format("Authentication failed: %s", ex.getMessage()), ex);
130+
}
131+
});
129132
}
130133

131134
protected Mono<Void> onAuthenticationSuccess(Authentication authentication, WebFilterExchange webFilterExchange) {

‎web/src/main/java/org/springframework/security/web/server/authentication/SwitchUserWebFilter.java‎

Lines changed: 17 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -159,9 +159,11 @@ public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
159159
final WebFilterExchange webFilterExchange = new WebFilterExchange(exchange, chain);
160160
return switchUser(webFilterExchange).switchIfEmpty(Mono.defer(() -> exitSwitchUser(webFilterExchange)))
161161
.switchIfEmpty(Mono.defer(() -> {
162-
this.logger
163-
.trace(LogMessage.format("Did not attempt to switch user since request did not match [%s] or [%s]",
164-
this.switchUserMatcher, this.exitUserMatcher));
162+
if (this.logger.isTraceEnabled()) {
163+
this.logger.trace(
164+
LogMessage.format("Did not attempt to switch user since request did not match [%s] or [%s]",
165+
this.switchUserMatcher, this.exitUserMatcher));
166+
}
165167
return chain.filter(exchange).then(Mono.empty());
166168
}))
167169
.flatMap((authentication) -> onAuthenticationSuccess(authentication, webFilterExchange))
@@ -220,7 +222,9 @@ protected Mono<Authentication> exitSwitchUser(WebFilterExchange webFilterExchang
220222
private @NonNull Mono<Authentication> attemptSwitchUser(Authentication currentAuthentication,
221223
@Nullable String userName) {
222224
Assert.notNull(userName, "The userName can not be null.");
223-
this.logger.debug(LogMessage.format("Attempting to switch to user [%s]", userName));
225+
if (this.logger.isDebugEnabled()) {
226+
this.logger.debug(LogMessage.format("Attempting to switch to user [%s]", userName));
227+
}
224228
return this.userDetailsService.findByUsername(userName)
225229
.switchIfEmpty(Mono.error(this::noTargetAuthenticationException))
226230
.doOnNext(this.userDetailsChecker::check)
@@ -239,8 +243,11 @@ protected Mono<Authentication> exitSwitchUser(WebFilterExchange webFilterExchang
239243
private Mono<Void> onAuthenticationSuccess(Authentication authentication, WebFilterExchange webFilterExchange) {
240244
ServerWebExchange exchange = webFilterExchange.getExchange();
241245
SecurityContextImpl securityContext = new SecurityContextImpl(authentication);
242-
return this.securityContextRepository.save(exchange, securityContext)
243-
.doOnSuccess((v) -> this.logger.debug(LogMessage.format("Switched user to %s", authentication)))
246+
return this.securityContextRepository.save(exchange, securityContext).doOnSuccess((v) -> {
247+
if (this.logger.isDebugEnabled()) {
248+
this.logger.debug(LogMessage.format("Switched user to %s", authentication));
249+
}
250+
})
244251
.then(this.successHandler.onAuthenticationSuccess(webFilterExchange, authentication))
245252
.contextWrite(ReactiveSecurityContextHolder.withSecurityContext(Mono.just(securityContext)));
246253
}
@@ -256,8 +263,10 @@ private Authentication createSwitchUserToken(UserDetails targetUser, Authenticat
256263
Optional<Authentication> sourceAuthentication = extractSourceAuthentication(currentAuthentication);
257264
if (sourceAuthentication.isPresent()) {
258265
// SEC-1763. Check first if we are already switched.
259-
this.logger.debug(
260-
LogMessage.format("Found original switch user granted authority [%s]", sourceAuthentication.get()));
266+
if (this.logger.isDebugEnabled()) {
267+
this.logger.debug(LogMessage.format("Found original switch user granted authority [%s]",
268+
sourceAuthentication.get()));
269+
}
261270
currentAuthentication = sourceAuthentication.get();
262271
}
263272
GrantedAuthority switchAuthority = new SwitchUserGrantedAuthority(ROLE_PREVIOUS_ADMINISTRATOR,

‎web/src/main/java/org/springframework/security/web/server/authorization/DelegatingReactiveAuthorizationManager.java‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -58,9 +58,11 @@ public Mono<AuthorizationResult> authorize(Mono<Authentication> authentication,
5858
.filter(MatchResult::isMatch)
5959
.map(MatchResult::getVariables)
6060
.flatMap((variables) -> {
61-
logger.debug(LogMessage.of(() -> "Checking authorization on '"
62-
+ exchange.getRequest().getPath().pathWithinApplication() + "' using "
63-
+ mapping.getEntry()));
61+
if (logger.isDebugEnabled()) {
62+
logger.debug(LogMessage.of(() -> "Checking authorization on '"
63+
+ exchange.getRequest().getPath().pathWithinApplication() + "' using "
64+
+ mapping.getEntry()));
65+
}
6466
return mapping.getEntry().authorize(authentication, new AuthorizationContext(exchange, variables));
6567
}))
6668
.next()

‎web/src/main/java/org/springframework/security/web/server/util/matcher/AndServerWebExchangeMatcher.java‎

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -57,8 +57,11 @@ public AndServerWebExchangeMatcher(ServerWebExchangeMatcher... matchers) {
5757
public Mono<MatchResult> matches(ServerWebExchange exchange) {
5858
return Mono.defer(() -> {
5959
Map<String, Object> variables = new HashMap<>();
60-
return Flux.fromIterable(this.matchers)
61-
.doOnNext((matcher) -> logger.debug(LogMessage.format("Trying to match using %s", matcher)))
60+
return Flux.fromIterable(this.matchers).doOnNext((matcher) -> {
61+
if (logger.isDebugEnabled()) {
62+
logger.debug(LogMessage.format("Trying to match using %s", matcher));
63+
}
64+
})
6265
.flatMap((matcher) -> matcher.matches(exchange))
6366
.doOnNext((matchResult) -> variables.putAll(matchResult.getVariables()))
6467
.all(MatchResult::isMatch)

‎web/src/main/java/org/springframework/security/web/server/util/matcher/NegatedServerWebExchangeMatcher.java‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -45,9 +45,11 @@ public NegatedServerWebExchangeMatcher(ServerWebExchangeMatcher matcher) {
4545

4646
@Override
4747
public Mono<MatchResult> matches(ServerWebExchange exchange) {
48-
return this.matcher.matches(exchange)
49-
.flatMap(this::negate)
50-
.doOnNext((matchResult) -> logger.debug(LogMessage.format("matches = %s", matchResult.isMatch())));
48+
return this.matcher.matches(exchange).flatMap(this::negate).doOnNext((matchResult) -> {
49+
if (logger.isDebugEnabled()) {
50+
logger.debug(LogMessage.format("matches = %s", matchResult.isMatch()));
51+
}
52+
});
5153
}
5254

5355
private Mono<MatchResult> negate(MatchResult matchResult) {

0 commit comments

Comments
 (0)