KEYCLOAK-14553 Improve logging

common/src/main/java/org/keycloak/common/util/StackUtil.java

@@ -0,0 +1,65 @@
+package org.keycloak.common.util;
+
+import java.util.regex.Pattern;
+import org.jboss.logging.Logger;
+
+/**
+ *
+ * @author hmlnarik
+ */
+public class StackUtil {
+
+    private static final Logger LOG = Logger.getLogger("org.keycloak.STACK_TRACE");
+
+    /**
+     * Returns string representation of the stack trace of the current call
+     * without the call to the {@code getShortStackTrace} itself, and ignoring
+     * usually irrelevant calls to methods in {@code sun.} and {@code java.lang.reflect}
+     * packages. The stack trace ignores calls before and including the first
+     * {@code org.jboss.resteasy} method, hence it usually finishes with the
+     * method handling respective REST endpoint.
+     *
+     * Each line of the stack trace is prepended with {@code "\n    "}.
+     *
+     * @return If the logger {@code org.keycloak.STACK_TRACE} is set to trace
+     * level, then returns stack trace, else returns empty {@link StringBuilder}
+     */
+    public static StringBuilder getShortStackTrace() {
+        return getShortStackTrace("\n    ");
+    }
+
+    private static final Pattern IGNORED = Pattern.compile("^sun\\.|java\\.lang\\.reflect\\.");
+    private static final StringBuilder EMPTY = new StringBuilder(0);
+
+    /**
+     * Returns string representation of the stack trace of the current call
+     * without the call to the {@code getShortStackTrace} itself, and ignoring
+     * usually irrelevant calls to methods in {@code sun.} and {@code java.lang.reflect}
+     * packages. The stack trace ignores calls before and including the first
+     * {@code org.jboss.resteasy} method, hence it usually finishes with the
+     * method handling respective REST endpoint.
+     *
+     * @param prefix Prefix to prepend to every stack trace line
+     * @return If the logger {@code org.keycloak.STACK_TRACE} is set to trace
+     * level, then returns stack trace, else returns empty {@link StringBuilder}
+     */
+    public static StringBuilder getShortStackTrace(String prefix) {
+        if (! LOG.isTraceEnabled()) {
+            return EMPTY;
+        }
+
+        StringBuilder sb = new StringBuilder();
+        StackTraceElement[] stackTrace = (new Throwable()).getStackTrace();
+        for (int endIndex = 2; endIndex < stackTrace.length; endIndex++) {
+            StackTraceElement st = stackTrace[endIndex];
+            if (IGNORED.matcher(st.getClassName()).find()) {
+                continue;
+            }
+            if (st.getClassName().startsWith("org.jboss.resteasy")) {
+                break;
+            }
+            sb.append(prefix).append(st);
+        }
+        return sb;
+    }
+}

model/infinispan/src/main/java/org/keycloak/models/cache/infinispan/RealmAdapter.java

@@ -1681,4 +1681,8 @@ public class RealmAdapter implements CachedRealmModel {
         return cached.getAttributes();
     }
 
+    @Override
+    public String toString() {
+        return String.format("%s@%08x", getId(), hashCode());
+    }
 }

model/jpa/src/main/java/org/keycloak/models/jpa/RealmAdapter.java

@@ -2343,4 +2343,9 @@ public class RealmAdapter implements RealmModel, JpaModel<RealmEntity> {
         if (!c.getRealm().equals(getEntity())) return null;
         return c;
     }
+
+    @Override
+    public String toString() {
+        return String.format("%s@%08x", getId(), hashCode());
+    }
 }

model/map/src/main/java/org/keycloak/models/map/client/MapClientProvider.java

@@ -1,5 +1,5 @@
 /*
- * Copyright 2016 Red Hat, Inc. and/or its affiliates
+ * Copyright 2020 Red Hat, Inc. and/or its affiliates
  * and other contributors as indicated by the @author tags.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
@@ -42,14 +42,11 @@ import java.util.function.Predicate;
 import java.util.stream.Collectors;
 import java.util.stream.Stream;
 import org.keycloak.models.map.storage.MapStorage;
+import static org.keycloak.common.util.StackUtil.getShortStackTrace;
 
-/**
- * @author <a href="mailto:bill@burkecentral.com">Bill Burke</a>
- * @version $Revision: 1 $
- */
 public class MapClientProvider implements ClientProvider {
 
-    protected static final Logger logger = Logger.getLogger(MapClientProvider.class);
+    private static final Logger LOG = Logger.getLogger(MapClientProvider.class);
     private static final Predicate<MapClientEntity> ALWAYS_FALSE = c -> { return false; };
     private final KeycloakSession session;
     final MapKeycloakTransaction<UUID, MapClientEntity> tx;
@@ -177,6 +174,8 @@ public class MapClientProvider implements ClientProvider {
             clientId = entityId.toString();
         }
 
+        LOG.tracef("addClient(%s, %s, %s)%s", realm, id, clientId, getShortStackTrace());
+
         MapClientEntity entity = new MapClientEntity(entityId, realm.getId());
         entity.setClientId(clientId);
         entity.setEnabled(true);
@@ -217,6 +216,8 @@ public class MapClientProvider implements ClientProvider {
             return false;
         }
 
+        LOG.tracef("removeClient(%s, %s)%s", realm, id, getShortStackTrace());
+
         // TODO: Sending an event (and client role removal) should be extracted to store layer
         final ClientModel client = getClientById(realm, id);
         if (client == null) return false;
@@ -256,6 +257,9 @@ public class MapClientProvider implements ClientProvider {
         if (id == null) {
             return null;
         }
+
+        LOG.tracef("getClientById(%s, %s)%s", realm, id, getShortStackTrace());
+
         MapClientEntity entity = tx.get(UUID.fromString(id), clientStore::get);
         return (entity == null || ! entityRealmFilter(realm).test(entity))
           ? null
@@ -267,6 +271,8 @@ public class MapClientProvider implements ClientProvider {
         if (clientId == null) {
             return null;
         }
+        LOG.tracef("getClientByClientId(%s, %s)%s", realm, clientId, getShortStackTrace());
+
         String clientIdLower = clientId.toLowerCase();
 
         return getNotRemovedUpdatedClientsStream()

server-spi-private/src/main/java/org/keycloak/models/utils/RepresentationToModel.java

@@ -1597,7 +1597,7 @@ public class RepresentationToModel {
     }
 
     public static ClientScopeModel createClientScope(KeycloakSession session, RealmModel realm, ClientScopeRepresentation resourceRep) {
-        logger.debug("Create client scope: {0}" + resourceRep.getName());
+        logger.debugv("Create client scope: {0}", resourceRep.getName());
 
         ClientScopeModel clientScope = resourceRep.getId() != null ? realm.addClientScope(resourceRep.getId(), resourceRep.getName()) : realm.addClientScope(resourceRep.getName());
         if (resourceRep.getName() != null) clientScope.setName(resourceRep.getName());

testsuite/integration-arquillian/tests/base/src/test/resources/log4j.properties

@@ -88,3 +88,9 @@ log4j.logger.org.keycloak.services.clientregistration.policy=debug
 
 # Enable logs the JDBC parameters passed to a query
 #log4j.logger.org.hibernate.type=trace
+
+# log4j.logger.org.keycloak.models.map=trace
+# log4j.logger.org.keycloak.models.map.transaction=debug
+
+# Enable to log short stack traces for log entries enabled with StackUtil.getShortStackTrace() calls
+# log4j.logger.org.keycloak.STACK_TRACE=trace