Restructure SwitchUserFilter Logs

Issue gh-6311

Author: jzheaux

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

@@ -178,6 +178,7 @@ private void doFilter(HttpServletRequest request, HttpServletResponse response,
 				SecurityContext context = SecurityContextHolder.createEmptyContext();
 				context.setAuthentication(targetUser);
 				SecurityContextHolder.setContext(context);
+				this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", targetUser));
 				// redirect to target url
 				this.successHandler.onAuthenticationSuccess(request, response, targetUser);
 			}
@@ -194,10 +195,13 @@ private void doFilter(HttpServletRequest request, HttpServletResponse response,
 			SecurityContext context = SecurityContextHolder.createEmptyContext();
 			context.setAuthentication(originalUser);
 			SecurityContextHolder.setContext(context);
+			this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", originalUser));
 			// 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));
 		chain.doFilter(request, response);
 	}
 
@@ -216,12 +220,11 @@ protected Authentication attemptSwitchUser(HttpServletRequest request) throws Au
 		UsernamePasswordAuthenticationToken targetUserRequest;
 		String username = request.getParameter(this.usernameParameter);
 		username = (username != null) ? username : "";
-		this.logger.debug(LogMessage.format("Attempt to switch to user [%s]", username));
+		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
 		targetUserRequest = createSwitchUserToken(request, targetUser);
-		this.logger.debug(LogMessage.format("Switch User Token [%s]", targetUserRequest));
 		// publish event
 		if (this.eventPublisher != null) {
 			this.eventPublisher.publishEvent(new AuthenticationSwitchUserEvent(
@@ -250,9 +253,9 @@ protected Authentication attemptExitUser(HttpServletRequest request)
 		// if so, get the original source user so we can switch back
 		Authentication original = getSourceAuthentication(current);
 		if (original == null) {
-			this.logger.debug("Could not find original user Authentication object!");
-			throw new AuthenticationCredentialsNotFoundException(this.messages.getMessage(
-					"SwitchUserFilter.noOriginalAuthentication", "Could not find original Authentication object"));
+			this.logger.debug("Failed to find original user");
+			throw new AuthenticationCredentialsNotFoundException(this.messages
+					.getMessage("SwitchUserFilter.noOriginalAuthentication", "Failed to find original user"));
 		}
 		// get the source user details
 		UserDetails originalUser = null;
@@ -327,7 +330,7 @@ private Authentication getSourceAuthentication(Authentication current) {
 			// check for switch user type of authority
 			if (auth instanceof SwitchUserGrantedAuthority) {
 				original = ((SwitchUserGrantedAuthority) auth).getSource();
-				this.logger.debug("Found original switch user granted authority [" + original + "]");
+				this.logger.debug(LogMessage.format("Found original switch user granted authority [%s]", original));
 			}
 		}
 		return original;

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

@@ -158,8 +158,12 @@ public SwitchUserWebFilter(ReactiveUserDetailsService userDetailsService, String
 	public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
 		final WebFilterExchange webFilterExchange = new WebFilterExchange(exchange, chain);
 		return switchUser(webFilterExchange).switchIfEmpty(Mono.defer(() -> exitSwitchUser(webFilterExchange)))
-				.switchIfEmpty(Mono.defer(() -> chain.filter(exchange).then(Mono.empty())))
-				.flatMap((authentication) -> onAuthenticationSuccess(authentication, 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));
+					return chain.filter(exchange).then(Mono.empty());
+				})).flatMap((authentication) -> onAuthenticationSuccess(authentication, webFilterExchange))
 				.onErrorResume(SwitchUserAuthenticationException.class, (exception) -> Mono.empty());
 	}
 
@@ -211,7 +215,7 @@ protected String getUsername(ServerWebExchange exchange) {
 	@NonNull
 	private Mono<Authentication> attemptSwitchUser(Authentication currentAuthentication, String userName) {
 		Assert.notNull(userName, "The userName can not be null.");
-		this.logger.debug(LogMessage.format("Attempt to switch to user [%s]", userName));
+		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)
@@ -222,7 +226,7 @@ private Mono<Authentication> attemptSwitchUser(Authentication currentAuthenticat
 	private Authentication attemptExitUser(Authentication currentAuthentication) {
 		Optional<Authentication> sourceAuthentication = extractSourceAuthentication(currentAuthentication);
 		if (!sourceAuthentication.isPresent()) {
-			this.logger.debug("Could not find original user Authentication object!");
+			this.logger.debug("Failed to find original user");
 			throw noOriginalAuthenticationException();
 		}
 		return sourceAuthentication.get();
@@ -232,13 +236,14 @@ private Mono<Void> onAuthenticationSuccess(Authentication authentication, WebFil
 		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)))
 				.then(this.successHandler.onAuthenticationSuccess(webFilterExchange, authentication))
 				.subscriberContext(ReactiveSecurityContextHolder.withSecurityContext(Mono.just(securityContext)));
 	}
 
 	private Mono<Void> onAuthenticationFailure(AuthenticationException exception, WebFilterExchange webFilterExchange) {
 		return Mono.justOrEmpty(this.failureHandler).switchIfEmpty(Mono.defer(() -> {
-			this.logger.error("Switch User failed", exception);
+			this.logger.debug("Failed to switch user", exception);
 			return Mono.error(exception);
 		})).flatMap((failureHandler) -> failureHandler.onAuthenticationFailure(webFilterExchange, exception));
 	}
@@ -247,7 +252,7 @@ private Authentication createSwitchUserToken(UserDetails targetUser, Authenticat
 		Optional<Authentication> sourceAuthentication = extractSourceAuthentication(currentAuthentication);
 		if (sourceAuthentication.isPresent()) {
 			// SEC-1763. Check first if we are already switched.
-			this.logger.info(
+			this.logger.debug(
 					LogMessage.format("Found original switch user granted authority [%s]", sourceAuthentication.get()));
 			currentAuthentication = sourceAuthentication.get();
 		}