Consistent use of log.debugf() to avoid generating too much GC overhe…

…ad (keycloak#35403) Closes keycloak#35402 Signed-off-by: Alexander Schwartz <[email protected]>
srose · Nov 28, 2024 · 83b324d · 83b324d
1 parent 015f06b
commit 83b324d
Show file tree

Hide file tree

Showing 16 changed files with 39 additions and 38 deletions.
diff --git a/services/src/main/java/org/keycloak/authentication/AuthenticationProcessor.java b/services/src/main/java/org/keycloak/authentication/AuthenticationProcessor.java
@@ -938,7 +938,7 @@ public Response authenticateClient() throws AuthenticationFlowException {
     public Response redirectToFlow() {
         URI redirect = new AuthenticationFlowURLHelper(session, realm, uriInfo).getLastExecutionUrl(authenticationSession);
 
-        logger.debug("Redirecting to URL: " + redirect.toString());
+        logger.debugf("Redirecting to URL: %s", redirect.toString());
 
         return Response.status(302).location(redirect).build();
 

diff --git a/...ycloak/authentication/authenticators/x509/AbstractX509ClientCertificateAuthenticator.java b/...ycloak/authentication/authenticators/x509/AbstractX509ClientCertificateAuthenticator.java
@@ -161,8 +161,8 @@ static UserIdentityExtractor fromConfig(X509AuthenticatorConfigModel config) {
             Function<X509Certificate[], String> func = null;
 
             UserIdentityExtractorProvider userIdExtractor = CryptoIntegration.getProvider().getIdentityExtractorProvider();
-            logger.debug("UID Source: " + userIdentitySource);
-            logger.debug("UID Extractor: " + userIdExtractor.getClass().getName());
+            logger.debugf("UID Source: %s", userIdentitySource);
+            logger.debugf("UID Extractor: %s", userIdExtractor.getClass().getName());
             switch(userIdentitySource) {
 
                 case SUBJECTDN:

diff --git a/services/src/main/java/org/keycloak/broker/oidc/AbstractOAuth2IdentityProvider.java b/services/src/main/java/org/keycloak/broker/oidc/AbstractOAuth2IdentityProvider.java
@@ -665,7 +665,7 @@ protected BrokeredIdentityContext validateExternalTokenThroughUserInfo(EventBuil
             logger.debug("Failed to invoke user info for external exchange", e);
         }
         if (status != 200) {
-            logger.debug("Failed to invoke user info status: " + status);
+            logger.debugf("Failed to invoke user info status: %d", status);
             event.detail(Details.REASON, "user info call failure");
             event.error(Errors.INVALID_TOKEN);
             throw new ErrorResponseException(OAuthErrorException.INVALID_TOKEN, "invalid token", Response.Status.BAD_REQUEST);

diff --git a/services/src/main/java/org/keycloak/broker/oidc/mappers/AbstractJsonUserAttributeMapper.java b/services/src/main/java/org/keycloak/broker/oidc/mappers/AbstractJsonUserAttributeMapper.java
@@ -204,12 +204,12 @@ protected static Object getJsonValue(IdentityProviderMapperModel mapperModel, Br
 
 
 	public static Object getJsonValue(JsonNode baseNode, String fieldPath) {
-		logger.debug("Going to process JsonNode path " + fieldPath + " on data " + baseNode);
+		logger.debugf("Going to process JsonNode path %s on data %s", fieldPath, baseNode);
 		if (baseNode != null) {
 
 			List<String> fields = splitClaimPath(fieldPath);
 			if (fields.isEmpty() || fieldPath.endsWith(".")) {
-				logger.debug("JSON path is invalid " + fieldPath);
+				logger.debugf("JSON path is invalid %s", fieldPath);
 				return null;
 			}
 
@@ -222,28 +222,28 @@ public static Object getJsonValue(JsonNode baseNode, String fieldPath) {
 				if (currentFieldName.endsWith("]")) {
 					int bi = currentFieldName.indexOf("[");
 					if (bi == -1) {
-						logger.debug("Invalid array index construct in " + currentFieldName);
+						logger.debugf("Invalid array index construct in %s", currentFieldName);
 						return null;
 					}
 					try {
 						String is = currentFieldName.substring(bi + 1, currentFieldName.length() - 1).trim();
 						arrayIndex = Integer.parseInt(is);
 						if( arrayIndex < 0) throw new ArrayIndexOutOfBoundsException();
 					} catch (Exception e) {
-						logger.debug("Invalid array index construct in " + currentFieldName);
+						logger.debugf("Invalid array index construct in %s", currentFieldName);
 						return null;
 					}
 					currentNodeName = currentFieldName.substring(0, bi).trim();
 				}
 
 				currentNode = currentNode.get(currentNodeName);
 				if (arrayIndex > -1 && currentNode.isArray()) {
-					logger.debug("Going to take array node at index " + arrayIndex);
+					logger.debugf("Going to take array node at index %d", arrayIndex);
 					currentNode = currentNode.get(arrayIndex);
 				}
 
 				if (currentNode == null) {
-					logger.debug("JsonNode not found for name " + currentFieldName);
+					logger.debugf("JsonNode not found for name %s", currentFieldName);
 					return null;
 				}
 
@@ -262,7 +262,7 @@ public static Object getJsonValue(JsonNode baseNode, String fieldPath) {
 					return values ;
 				} else if (currentNode.isNull()) {
 
-					logger.debug("JsonNode is null node for name " + currentFieldName);
+					logger.debugf("JsonNode is null node for name %s", currentFieldName);
 					return null;
 				} else if (currentNode.isValueNode()) {
 					String ret = currentNode.asText();

diff --git a/services/src/main/java/org/keycloak/protocol/oidc/TokenManager.java b/services/src/main/java/org/keycloak/protocol/oidc/TokenManager.java
@@ -48,9 +48,7 @@
 import org.keycloak.models.ClientScopeModel;
 import org.keycloak.models.ClientSessionContext;
 import org.keycloak.models.Constants;
-import org.keycloak.models.ClientScopeDecorator;
 import org.keycloak.models.KeycloakSession;
-import org.keycloak.models.OrganizationModel;
 import org.keycloak.models.ProtocolMapperModel;
 import org.keycloak.models.RealmModel;
 import org.keycloak.models.RoleModel;
@@ -314,7 +312,7 @@ public UserSessionModel getValidUserSessionIfTokenIsValid(KeycloakSession sessio
         if (realm.isRevokeRefreshToken()
                 && (tokenType.equals(TokenUtil.TOKEN_TYPE_REFRESH) || tokenType.equals(TokenUtil.TOKEN_TYPE_OFFLINE))
                 && !validateTokenReuseForIntrospection(session, realm, token)) {
-            logger.debug("Introspection access token for "+token.getIssuedFor() +" client: failed to validate Token reuse for introspection");
+            logger.debugf("Introspection access token for %s client: failed to validate Token reuse for introspection", token.getIssuedFor());
             eventBuilder.detail(Details.REASON, "Realm revoke refresh token, token type is "+tokenType+ " and token is not eligible for introspection");
             return null;
         }

diff --git a/services/src/main/java/org/keycloak/protocol/saml/SamlService.java b/services/src/main/java/org/keycloak/protocol/saml/SamlService.java
@@ -1158,8 +1158,8 @@ private SingleUseObjectProvider getSingleUseStore() {
      * @throws ProcessingException
      */
     public Response artifactResolve(ArtifactResolveType artifactResolveMessage, SAMLDocumentHolder artifactResolveHolder) throws ParsingException, ConfigurationException, ProcessingException {
-        logger.debug("Received artifactResolve message for artifact " + artifactResolveMessage.getArtifact() + "\n" +
-                "Message: \n" + DocumentUtil.getDocumentAsString(artifactResolveHolder.getSamlDocument()));
+        logger.debugf("Received artifactResolve message for artifact %s\n" +
+                "Message: \n%s", artifactResolveMessage.getArtifact(), DocumentUtil.getDocumentAsString(artifactResolveHolder.getSamlDocument()));
 
         String artifact = artifactResolveMessage.getArtifact(); // Artifact from resolve request
         if (artifact == null) {

diff --git a/services/src/main/java/org/keycloak/provider/FileSystemProviderLoaderFactory.java b/services/src/main/java/org/keycloak/provider/FileSystemProviderLoaderFactory.java
@@ -59,7 +59,7 @@ private static URLClassLoader createClassLoader(ClassLoader parent, String... fi
                 }
             }
 
-            logger.debug("Loading providers from " + urls.toString());
+            logger.debugf("Loading providers from %s", urls);
 
             return new URLClassLoader(urls.toArray(new URL[urls.size()]), parent);
         } catch (Exception e) {

diff --git a/services/src/main/java/org/keycloak/services/resources/AbstractSecuredLocalService.java b/services/src/main/java/org/keycloak/services/resources/AbstractSecuredLocalService.java
@@ -183,8 +183,8 @@ public Response redirect(UriInfo uriInfo, String redirectUri) {
             URI url = uriBuilder.build();
 
             NewCookie cookie = new NewCookie(getStateCookieName(), state, getStateCookiePath(uriInfo), null, null, -1, isSecure, true);
-            logger.debug("NewCookie: " + cookie.toString());
-            logger.debug("Oauth Redirect to: " + url);
+            logger.debugf("NewCookie: %s", cookie);
+            logger.debugf("Oauth Redirect to: %s", url);
             return Response.status(302)
                     .location(url)
                     .cookie(cookie).build();

diff --git a/services/src/main/java/org/keycloak/services/resources/admin/AdminRoot.java b/services/src/main/java/org/keycloak/services/resources/admin/AdminRoot.java
@@ -221,7 +221,9 @@ public RealmsAdminResource getRealmsAdmin() {
 
         AdminAuth auth = authenticateRealmAdminRequest(session.getContext().getRequestHeaders());
         if (auth != null) {
-            logger.debug("authenticated admin access for: " + auth.getUser().getUsername());
+            if (logger.isDebugEnabled()) {
+                logger.debugf("authenticated admin access for: %s", auth.getUser().getUsername());
+            }
         }
 
         Cors.builder().allowedOrigins(auth.getToken()).allowedMethods("GET", "PUT", "POST", "DELETE").exposedHeaders("Location").auth().add();
@@ -265,7 +267,7 @@ public Object getServerInfo() {
         }
 
         if (auth != null) {
-            logger.debug("authenticated admin access for: " + auth.getUser().getUsername());
+            logger.debugf("authenticated admin access for: %s", auth.getUser().getUsername());
         }
 
         Cors.builder().allowedOrigins(auth.getToken()).allowedMethods("GET", "PUT", "POST", "DELETE").auth().add();

diff --git a/...src/main/java/org/keycloak/services/resources/admin/AuthenticationManagementResource.java b/...src/main/java/org/keycloak/services/resources/admin/AuthenticationManagementResource.java
@@ -404,7 +404,7 @@ public Response copy(@Parameter(description="name of the existing authentication
 
         AuthenticationFlowModel flow = realm.getFlowByAlias(flowAlias);
         if (flow == null) {
-            logger.debug("flow not found: " + flowAlias);
+            logger.debugf("flow not found: %s", flowAlias);
             throw new NotFoundException("Flow not found");
         }
 
@@ -652,7 +652,7 @@ public List<AuthenticationExecutionInfoRepresentation> getExecutions(@Parameter(
 
         AuthenticationFlowModel flow = realm.getFlowByAlias(flowAlias);
         if (flow == null) {
-            logger.debug("flow not found: " + flowAlias);
+            logger.debugf("flow not found: %s", flowAlias);
             throw new NotFoundException("Flow not found");
         }
         List<AuthenticationExecutionInfoRepresentation> result = new LinkedList<>();
@@ -770,7 +770,7 @@ public void updateExecutions(@Parameter(description = "Flow alias") @PathParam("
 
         AuthenticationFlowModel flow = realm.getFlowByAlias(flowAlias);
         if (flow == null) {
-            logger.debug("flow not found: " + flowAlias);
+            logger.debugf("flow not found: %s", flowAlias);
             throw new NotFoundException("flow not found");
         }
 

diff --git a/services/src/main/java/org/keycloak/services/resources/admin/ClientResource.java b/services/src/main/java/org/keycloak/services/resources/admin/ClientResource.java
@@ -634,7 +634,7 @@ public void registerNode(Map<String, String> formParams) {
 
         ReservedCharValidator.validate(node);
 
-        if (logger.isDebugEnabled()) logger.debug("Register node: " + node);
+        logger.debugf("Register node: %s", node);
         client.registerNode(node, Time.currentTime());
         adminEvent.operation(OperationType.CREATE).resource(ResourceType.CLUSTER_NODE).resourcePath(session.getContext().getUri(), node).success();
     }
@@ -652,7 +652,7 @@ public void registerNode(Map<String, String> formParams) {
     public void unregisterNode(final @PathParam("node") String node) {
         auth.clients().requireConfigure(client);
 
-        if (logger.isDebugEnabled()) logger.debug("Unregister node: " + node);
+        logger.debugf("Unregister node: %s", node);
 
         Integer time = client.getRegisteredNodes().get(node);
         if (time == null) {

diff --git a/services/src/main/java/org/keycloak/services/resources/admin/IdentityProviderResource.java b/services/src/main/java/org/keycloak/services/resources/admin/IdentityProviderResource.java
@@ -184,7 +184,7 @@ public Response update(IdentityProviderRepresentation providerRep) {
     }
 
     private void updateIdpFromRep(IdentityProviderRepresentation providerRep, RealmModel realm, KeycloakSession session) {
-        
+
         if (!identityProviderModel.getInternalId().equals(providerRep.getInternalId())) {
             providerRep.setInternalId(identityProviderModel.getInternalId());
         }
@@ -204,7 +204,7 @@ private void updateIdpFromRep(IdentityProviderRepresentation providerRep, RealmM
         if (!oldProviderAlias.equals(newProviderAlias)) {
 
             // Admin changed the ID (alias) of identity provider. We must update all clients and users
-            logger.debug("Changing providerId in all clients and linked users. oldProviderId=" + oldProviderAlias + ", newProviderId=" + newProviderAlias);
+            logger.debugf("Changing providerId in all clients and linked users. oldProviderId=%s, newProviderId=%s", oldProviderAlias, newProviderAlias);
 
             updateUsersAfterProviderAliasChange(session.users().searchForUserStream(realm, Collections.singletonMap(UserModel.INCLUDE_SERVICE_ACCOUNT, Boolean.FALSE.toString())),
                     oldProviderAlias, newProviderAlias, realm, session);

diff --git a/services/src/main/java/org/keycloak/services/resources/admin/RealmAdminResource.java b/services/src/main/java/org/keycloak/services/resources/admin/RealmAdminResource.java
@@ -412,7 +412,7 @@ public RealmRepresentation getRealm() {
     public Response updateRealm(final RealmRepresentation rep) {
         auth.realm().requireManageRealm();
 
-        logger.debug("updating realm: " + realm.getName());
+        logger.debugf("updating realm: %s", realm.getName());
 
         if (Config.getAdminRealm().equals(realm.getName()) && (rep.getRealm() != null && !rep.getRealm().equals(Config.getAdminRealm()))) {
             throw ErrorResponse.error("Can't rename master realm", Status.BAD_REQUEST);
@@ -747,7 +747,7 @@ public RealmEventsConfigRepresentation getRealmEventsConfig() {
     public void updateRealmEventsConfig(final RealmEventsConfigRepresentation rep) {
         auth.realm().requireManageEvents();
 
-        logger.debug("updating realm events config: " + realm.getName());
+        logger.debugf("updating realm events config: %s", realm.getName());
         new RealmManager(session).updateRealmEventsConfig(rep, realm);
         adminEvent.operation(OperationType.UPDATE).resource(ResourceType.REALM)
                 .resourcePath(session.getContext().getUri()).representation(rep)

diff --git a/services/src/main/java/org/keycloak/services/resources/admin/RoleByIdResource.java b/services/src/main/java/org/keycloak/services/resources/admin/RoleByIdResource.java
@@ -200,7 +200,7 @@ public Stream<RoleRepresentation> getRoleComposites(final @PathParam("role-id")
                                                         final @QueryParam("max") Integer max
     ) {
 
-        if (logger.isDebugEnabled()) logger.debug("*** getRoleComposites: '" + id + "'");
+        logger.debugf("*** getRoleComposites: '%s'", id);
         RoleModel role = getRoleModel(id);
         auth.roles().requireView(role);
 

diff --git a/...ices/src/main/java/org/keycloak/services/resources/admin/permissions/RolePermissions.java b/...ices/src/main/java/org/keycloak/services/resources/admin/permissions/RolePermissions.java
@@ -287,7 +287,7 @@ private boolean checkAdminRoles(RoleModel role) {
     }
 
     private boolean adminConflictMessage(RoleModel role) {
-        logger.debug("Trying to assign admin privileges of role: " + role.getName() + " but admin doesn't have same privilege");
+        logger.debugf("Trying to assign admin privileges of role: %s but admin doesn't have same privilege", role.getName());
         return false;
     }
 

diff --git a/services/src/main/java/org/keycloak/transaction/JtaTransactionWrapper.java b/services/src/main/java/org/keycloak/transaction/JtaTransactionWrapper.java
@@ -18,7 +18,6 @@
 
 import org.jboss.logging.Logger;
 import org.keycloak.models.KeycloakSession;
-import org.keycloak.models.KeycloakSessionFactory;
 import org.keycloak.models.KeycloakTransaction;
 import org.keycloak.provider.ExceptionConverter;
 
@@ -52,11 +51,13 @@ public JtaTransactionWrapper(KeycloakSession session, TransactionManager tm) {
             tm.begin();
             ut = tm.getTransaction();
 
-            String messageToLog = "new JtaTransactionWrapper. Was existing transaction suspended: " + (suspended != null);
-            if (suspended != null) {
-                messageToLog = messageToLog + " Suspended transaction: " + suspended + ". ";
+            if (logger.isDebugEnabled()) {
+                String messageToLog = "new JtaTransactionWrapper. Was existing transaction suspended: " + (suspended != null);
+                if (suspended != null) {
+                    messageToLog = messageToLog + " Suspended transaction: " + suspended + ". ";
+                }
+                logMessage(messageToLog);
             }
-            logMessage(messageToLog);
 
             //ended = new Exception();
         } catch (Exception e) {
@@ -162,7 +163,7 @@ protected void end() {
         logMessage("JtaTransactionWrapper end.");
         if (suspended != null) {
             try {
-                logger.debug("JtaTransactionWrapper resuming suspended user transaction: " + suspended);
+                logger.debugf("JtaTransactionWrapper resuming suspended user transaction: %s", suspended);
                 tm.resume(suspended);
             } catch (Exception e) {
                 throw new RuntimeException(e);