keycloak-aplcache

KEYCLOAK-5836 More logging around LDAP performance. Added

11/14/2017 2:10:22 PM

Details

diff --git a/federation/ldap/src/main/java/org/keycloak/storage/ldap/idm/store/ldap/LDAPIdentityStore.java b/federation/ldap/src/main/java/org/keycloak/storage/ldap/idm/store/ldap/LDAPIdentityStore.java
index 3151a3b..36ff34a 100644
--- a/federation/ldap/src/main/java/org/keycloak/storage/ldap/idm/store/ldap/LDAPIdentityStore.java
+++ b/federation/ldap/src/main/java/org/keycloak/storage/ldap/idm/store/ldap/LDAPIdentityStore.java
@@ -447,9 +447,10 @@ public class LDAPIdentityStore implements IdentityStore {
             for (String objectClassValue : ldapObject.getObjectClasses()) {
                 objectClassAttribute.add(objectClassValue);
 
-                if (objectClassValue.equalsIgnoreCase(LDAPConstants.GROUP_OF_NAMES)
+                if ((objectClassValue.equalsIgnoreCase(LDAPConstants.GROUP_OF_NAMES)
                         || objectClassValue.equalsIgnoreCase(LDAPConstants.GROUP_OF_ENTRIES)
-                        || objectClassValue.equalsIgnoreCase(LDAPConstants.GROUP_OF_UNIQUE_NAMES)) {
+                        || objectClassValue.equalsIgnoreCase(LDAPConstants.GROUP_OF_UNIQUE_NAMES)) &&
+                        (entryAttributes.get(LDAPConstants.MEMBER) == null)) {
                     entryAttributes.put(LDAPConstants.MEMBER, LDAPConstants.EMPTY_MEMBER_ATTRIBUTE_VALUE);
                 }
             }
diff --git a/federation/ldap/src/main/java/org/keycloak/storage/ldap/idm/store/ldap/LDAPOperationManager.java b/federation/ldap/src/main/java/org/keycloak/storage/ldap/idm/store/ldap/LDAPOperationManager.java
index 49b8385..83f4b2d 100644
--- a/federation/ldap/src/main/java/org/keycloak/storage/ldap/idm/store/ldap/LDAPOperationManager.java
+++ b/federation/ldap/src/main/java/org/keycloak/storage/ldap/idm/store/ldap/LDAPOperationManager.java
@@ -18,6 +18,7 @@
 package org.keycloak.storage.ldap.idm.store.ldap;
 
 import org.jboss.logging.Logger;
+import org.keycloak.common.util.Time;
 import org.keycloak.models.LDAPConstants;
 import org.keycloak.models.ModelException;
 import org.keycloak.storage.ldap.LDAPConfig;
@@ -65,6 +66,8 @@ public class LDAPOperationManager {
 
     private static final Logger logger = Logger.getLogger(LDAPOperationManager.class);
 
+    private static final Logger perfLogger = Logger.getLogger(LDAPOperationManager.class, "perf");
+
     private final LDAPConfig config;
     private final Map<String, Object> connectionProperties;
 
@@ -146,6 +149,7 @@ public class LDAPOperationManager {
     public void removeEntry(final String entryDn) {
         try {
             execute(new LdapOperation<SearchResult>() {
+
                 @Override
                 public SearchResult execute(LdapContext context) throws NamingException {
                     if (logger.isTraceEnabled()) {
@@ -154,6 +158,15 @@ public class LDAPOperationManager {
                     destroySubcontext(context, entryDn);
                     return null;
                 }
+
+
+                @Override
+                public String toString() {
+                    return new StringBuilder("LdapOperation: remove\n")
+                            .append(" dn: ").append(entryDn)
+                            .toString();
+                }
+
             });
         } catch (NamingException e) {
             throw new ModelException("Could not remove entry from DN [" + entryDn + "]", e);
@@ -173,6 +186,7 @@ public class LDAPOperationManager {
     public String renameEntry(String oldDn, String newDn, boolean fallback) {
         try {
             String newNonConflictingDn = execute(new LdapOperation<String>() {
+
                 @Override
                 public String execute(LdapContext context) throws NamingException {
                     String dn = newDn;
@@ -201,6 +215,16 @@ public class LDAPOperationManager {
 
                     throw new ModelException("Could not rename entry from DN [" + oldDn + "] to new DN [" + newDn + "]. All fallbacks failed");
                 }
+
+
+                @Override
+                public String toString() {
+                    return new StringBuilder("LdapOperation: renameEntry\n")
+                            .append(" oldDn: ").append(oldDn).append("\n")
+                            .append(" newDn: ").append(newDn)
+                            .toString();
+                }
+
             });
             return newNonConflictingDn;
         } catch (NamingException e) {
@@ -236,6 +260,20 @@ public class LDAPOperationManager {
 
                     return result;
                 }
+
+
+                @Override
+                public String toString() {
+                    return new StringBuilder("LdapOperation: search\n")
+                            .append(" baseDn: ").append(baseDN).append("\n")
+                            .append(" filter: ").append(filter).append("\n")
+                            .append(" searchScope: ").append(searchScope).append("\n")
+                            .append(" returningAttrs: ").append(returningAttributes).append("\n")
+                            .append(" resultSize: ").append(result.size())
+                            .toString();
+                }
+
+
             });
         } catch (NamingException e) {
             logger.errorf(e, "Could not query server using DN [%s] and filter [%s]", baseDN, filter);
@@ -249,6 +287,7 @@ public class LDAPOperationManager {
 
         try {
             return execute(new LdapOperation<List<SearchResult>>() {
+
                 @Override
                 public List<SearchResult> execute(LdapContext context) throws NamingException {
                     try {
@@ -281,6 +320,20 @@ public class LDAPOperationManager {
                         throw new NamingException(ioe.getMessage());
                     }
                 }
+
+
+                @Override
+                public String toString() {
+                    return new StringBuilder("LdapOperation: searchPaginated\n")
+                            .append(" baseDn: ").append(baseDN).append("\n")
+                            .append(" filter: ").append(filter).append("\n")
+                            .append(" searchScope: ").append(identityQuery.getSearchScope()).append("\n")
+                            .append(" returningAttrs: ").append(identityQuery.getReturningLdapAttributes()).append("\n")
+                            .append(" limit: ").append(identityQuery.getLimit()).append("\n")
+                            .append(" resultSize: ").append(result.size())
+                            .toString();
+                }
+
             });
         } catch (NamingException e) {
             logger.errorf(e, "Could not query server using DN [%s] and filter [%s]", baseDN, filter);
@@ -308,10 +361,21 @@ public class LDAPOperationManager {
 
             try {
                 Attributes attributes = execute(new LdapOperation<Attributes>() {
+
                     @Override
                     public Attributes execute(LdapContext context) throws NamingException {
                         return context.getAttributes(strObjectGUID);
                     }
+
+
+                    @Override
+                    public String toString() {
+                        return new StringBuilder("LdapOperation: GUIDResolve\n")
+                                .append(" strObjectGUID: ").append(strObjectGUID)
+                                .toString();
+                    }
+
+
                 });
 
                 byte[] objectGUID = (byte[]) attributes.get(LDAPConstants.OBJECT_GUID).get();
@@ -340,6 +404,7 @@ public class LDAPOperationManager {
             final SearchControls cons = getSearchControls(returningAttributes, this.config.getSearchScope());
 
             return execute(new LdapOperation<SearchResult>() {
+
                 @Override
                 public SearchResult execute(LdapContext context) throws NamingException {
                     NamingEnumeration<SearchResult> search = context.search(baseDN, filter, cons);
@@ -356,6 +421,18 @@ public class LDAPOperationManager {
 
                     return null;
                 }
+
+
+                @Override
+                public String toString() {
+                    return new StringBuilder("LdapOperation: lookupById\n")
+                            .append(" baseDN: ").append(baseDN).append("\n")
+                            .append(" filter: ").append(filter).append("\n")
+                            .append(" searchScope: ").append(cons.getSearchScope()).append("\n")
+                            .append(" returningAttrs: ").append(returningAttributes)
+                            .toString();
+                }
+
             });
         } catch (NamingException e) {
             throw new ModelException("Could not query server using DN [" + baseDN + "] and filter [" + filter + "]", e);
@@ -470,11 +547,23 @@ public class LDAPOperationManager {
             }
 
             execute(new LdapOperation<Void>() {
+
                 @Override
                 public Void execute(LdapContext context) throws NamingException {
                     context.modifyAttributes(dn, mods);
                     return null;
                 }
+
+
+                @Override
+                public String toString() {
+                    return new StringBuilder("LdapOperation: modify\n")
+                            .append(" dn: ").append(dn).append("\n")
+                            .append(" modificationsSize: ").append(mods.length)
+                            .toString();
+                }
+
+
             }, decorator);
         } catch (NamingException e) {
             throw new ModelException("Could not modify attribute for DN [" + dn + "]", e);
@@ -512,6 +601,16 @@ public class LDAPOperationManager {
 
                     return null;
                 }
+
+
+                @Override
+                public String toString() {
+                    return new StringBuilder("LdapOperation: create\n")
+                            .append(" dn: ").append(name).append("\n")
+                            .append(" attributesSize: ").append(attributes.size())
+                            .toString();
+                }
+
             });
         } catch (NamingException e) {
             throw new ModelException("Error creating subcontext [" + name + "]", e);
@@ -631,8 +730,13 @@ public class LDAPOperationManager {
 
     private <R> R execute(LdapOperation<R> operation, LDAPOperationDecorator decorator) throws NamingException {
         LdapContext context = null;
+        Long start = null;
 
         try {
+            if (perfLogger.isDebugEnabled()) {
+                start = Time.currentTimeMillis();
+            }
+
             context = createLdapContext();
             if (decorator != null) {
                 decorator.beforeLDAPOperation(context, operation);
@@ -647,6 +751,16 @@ public class LDAPOperationManager {
                     logger.error("Could not close Ldap context.", ne);
                 }
             }
+
+            if (perfLogger.isDebugEnabled()) {
+                long took = Time.currentTimeMillis() - start;
+
+                if (took > 100) {
+                    perfLogger.debugf("\n%s\ntook: %d ms\n", operation.toString(), took);
+                } else if (perfLogger.isTraceEnabled()) {
+                    perfLogger.tracef("\n%s\ntook: %d ms\n", operation.toString(), took);
+                }
+            }
         }
     }
 
diff --git a/federation/ldap/src/main/java/org/keycloak/storage/ldap/LDAPUtils.java b/federation/ldap/src/main/java/org/keycloak/storage/ldap/LDAPUtils.java
index 29f561a..21f4bae 100755
--- a/federation/ldap/src/main/java/org/keycloak/storage/ldap/LDAPUtils.java
+++ b/federation/ldap/src/main/java/org/keycloak/storage/ldap/LDAPUtils.java
@@ -92,7 +92,7 @@ public class LDAPUtils {
     }
 
     // ldapUser has filled attributes, but doesn't have filled dn.
-    private static void computeAndSetDn(LDAPConfig config, LDAPObject ldapUser) {
+    public static void computeAndSetDn(LDAPConfig config, LDAPObject ldapUser) {
         String rdnLdapAttrName = config.getRdnLdapAttribute();
         String rdnLdapAttrValue = ldapUser.getAttributeAsString(rdnLdapAttrName);
         if (rdnLdapAttrValue == null) {
diff --git a/testsuite/utils/src/main/java/org/keycloak/testsuite/util/cli/LdapManyObjectsInitializerCommand.java b/testsuite/utils/src/main/java/org/keycloak/testsuite/util/cli/LdapManyObjectsInitializerCommand.java
new file mode 100644
index 0000000..e0d480b
--- /dev/null
+++ b/testsuite/utils/src/main/java/org/keycloak/testsuite/util/cli/LdapManyObjectsInitializerCommand.java
@@ -0,0 +1,203 @@
+/*
+ * Copyright 2017 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");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.keycloak.testsuite.util.cli;
+
+import java.util.ArrayList;
+import java.util.Collections;
+import java.util.HashMap;
+import java.util.HashSet;
+import java.util.List;
+import java.util.Map;
+import java.util.Optional;
+import java.util.Set;
+
+import org.keycloak.component.ComponentModel;
+import org.keycloak.models.KeycloakSession;
+import org.keycloak.models.RealmModel;
+import org.keycloak.models.UserModel;
+import org.keycloak.models.utils.UserModelDelegate;
+import org.keycloak.storage.UserStorageProvider;
+import org.keycloak.storage.ldap.LDAPStorageProvider;
+import org.keycloak.storage.ldap.LDAPUtils;
+import org.keycloak.storage.ldap.idm.model.LDAPDn;
+import org.keycloak.storage.ldap.idm.model.LDAPObject;
+import org.keycloak.storage.ldap.mappers.LDAPStorageMapper;
+import org.keycloak.storage.ldap.mappers.membership.group.GroupLDAPStorageMapper;
+
+/**
+ * The command requires that:
+ * - Realm has 1 LDAP storage provider defined
+ * - The LDAP provider has user-attribute-mapper named "streetMapper", which has both "User Model Attribute" and "LDAP Attribute" configured to "street"
+ * - The LDAP provider has group-mapper named "groupsMapper", with:
+ * -- "LDAP Groups DN" pointing to same DN, like this command <groups-dn> .
+ * -- It's supposed to use "User Roles Retrieve Strategy" - "GET_GROUPS_FROM_USER_MEMBEROF_ATTRIBUTE"
+ * -- It's supposed to use "Member-Of LDAP Attribute" - "street"
+ *
+ * @author <a href="mailto:mposolda@redhat.com">Marek Posolda</a>
+ */
+public class LdapManyObjectsInitializerCommand extends AbstractCommand {
+
+    @Override
+    public String getName() {
+        return "createLdapObjects";
+    }
+
+    @Override
+    public String printUsage() {
+        return super.printUsage() + " <realm-name> <groups-dn> <start-offset-users> <count-users> <start-offset-groups> <count-groups> .\nSee javadoc of class LdapManyObjectsInitializerCommand for additional details.";
+    }
+
+    @Override
+    protected void doRunCommand(KeycloakSession session) {
+        String realmName = getArg(0);
+        String groupsDn = getArg(1);
+        int startOffsetUsers = getIntArg(2);
+        int countUsers = getIntArg(3);
+        int batchCount = 100;
+        int startOffsetGroups = getIntArg(4);
+        int countGroups = getIntArg(5);
+
+        RealmModel realm = session.realms().getRealmByName(realmName);
+        List<ComponentModel> components = realm.getComponents(realm.getId(), UserStorageProvider.class.getName());
+        if (components.size() != 1) {
+            log.errorf("Expected 1 LDAP Provider, but found: %d providers", components.size());
+            throw new HandledException();
+        }
+        ComponentModel ldapModel = components.get(0);
+
+        // Check that street mapper exists. It's required for now, so that "street" attribute is written to the LDAP
+        getMapperModel(realm, ldapModel, "streetMapper");
+        ComponentModel groupMapperModel = getMapperModel(realm, ldapModel, "groupsMapper");
+
+        // Create users
+        Set<String> createdUserDNs = new HashSet<>();
+        BatchTaskRunner.runInBatches(startOffsetUsers, countUsers, batchCount, session.getKeycloakSessionFactory(),
+                (KeycloakSession kcSession, int firstIt, int countInIt) -> {
+
+                    LDAPStorageProvider ldapProvider = (LDAPStorageProvider)session.getProvider(UserStorageProvider.class, ldapModel);
+                    RealmModel appRealm = session.realms().getRealmByName(realmName);
+
+                    for (int i=firstIt ; i<firstIt+countInIt  ; i++) {
+                        String username = "user-" + i;
+                        String firstName = "John-" + i;
+                        String lastName = "Doe-" + i;
+                        String email = "user" + i + "@email.cz";
+                        LDAPObject createdUser = addLDAPUser(ldapProvider, appRealm, username, firstName, lastName, email, groupsDn, startOffsetGroups, countGroups);
+                        createdUserDNs.add(createdUser.getDn().toString());
+                    }
+
+                    log.infof("Created LDAP users from: %d to %d", firstIt, firstIt + countInIt -1);
+
+                });
+
+
+        // Create groups
+        BatchTaskRunner.runInBatches(startOffsetGroups, countGroups, batchCount, session.getKeycloakSessionFactory(),
+                (KeycloakSession kcSession, int firstIt, int countInIt) -> {
+
+                    LDAPStorageProvider ldapProvider = (LDAPStorageProvider)session.getProvider(UserStorageProvider.class, ldapModel);
+                    RealmModel appRealm = session.realms().getRealmByName(realmName);
+                    GroupLDAPStorageMapper groupMapper = (GroupLDAPStorageMapper) session.getProvider(LDAPStorageMapper.class, groupMapperModel);
+
+                    for (int i=firstIt ; i<firstIt+countInIt  ; i++) {
+                        String groupName = "group" + i;
+
+                        Map<String, Set<String>> groupAttrs = new HashMap<>();
+                        groupAttrs.put("member", new HashSet<>(createdUserDNs));
+
+                        groupMapper.createLDAPGroup(groupName, groupAttrs);
+                    }
+
+                    log.infof("Created LDAP groups from: %d to %d", firstIt, firstIt + countInIt -1);
+
+                });
+    }
+
+
+    private ComponentModel getMapperModel(RealmModel realm, ComponentModel ldapModel, String mapperName) {
+        List<ComponentModel> ldapMappers = realm.getComponents(ldapModel.getId(), LDAPStorageMapper.class.getName());
+        Optional<ComponentModel> optional = ldapMappers.stream().filter((ComponentModel mapper) -> {
+            return mapper.getName().equals(mapperName);
+        }).findFirst();
+
+        if (!optional.isPresent()) {
+            log.errorf("Not present LDAP mapper called '%s'", mapperName);
+            throw new HandledException();
+        }
+
+        return optional.get();
+    }
+
+
+
+    private static LDAPObject addLDAPUser(LDAPStorageProvider ldapProvider, RealmModel realm, final String username,
+                                         final String firstName, final String lastName, final String email,
+                                         String groupsDN, int startOffsetGroups, int countGroups) {
+//        LDAPObject ldapUser = new LDAPObject();
+//        LDAPConfig ldapConfig = ldapProvider.getLdapIdentityStore().getConfig();
+//        ldapUser.setRdnAttributeName(ldapConfig.getRdnLdapAttribute());
+//        ldapUser.setObjectClasses(ldapConfig.getUserObjectClasses());
+//        LDAPUtils.computeAndSetDn(ldapConfig, ldapUser);
+//
+//        ldapUser.setSingleAttribute("uid", )
+//        ldapProvider.getLdapIdentityStore().add(ldapUser);
+
+        UserModel helperUser = new UserModelDelegate(null) {
+
+            @Override
+            public String getUsername() {
+                return username;
+            }
+
+            @Override
+            public String getFirstName() {
+                return firstName;
+            }
+
+            @Override
+            public String getLastName() {
+                return lastName;
+            }
+
+            @Override
+            public String getEmail() {
+                return email;
+            }
+
+            @Override
+            public List<String> getAttribute(String name) {
+                if ("street".equals(name)) {
+
+                    List<String> groupNamesList = new ArrayList<>();
+                    for (int i=startOffsetGroups ; i<startOffsetGroups + countGroups ; i++) {
+                        String groupName = "group" + i;
+                        LDAPDn groupDn = LDAPDn.fromString(groupsDN);
+                        groupDn.addFirst("cn", groupName);
+                        groupNamesList.add(groupDn.toString());
+                    }
+                    return groupNamesList;
+
+                } else {
+                    return Collections.emptyList();
+                }
+            }
+        };
+        return LDAPUtils.addUserToLDAP(ldapProvider, realm, helperUser);
+    }
+
+}
diff --git a/testsuite/utils/src/main/java/org/keycloak/testsuite/util/cli/TestsuiteCLI.java b/testsuite/utils/src/main/java/org/keycloak/testsuite/util/cli/TestsuiteCLI.java
index baedc8a..9da8a84 100644
--- a/testsuite/utils/src/main/java/org/keycloak/testsuite/util/cli/TestsuiteCLI.java
+++ b/testsuite/utils/src/main/java/org/keycloak/testsuite/util/cli/TestsuiteCLI.java
@@ -65,7 +65,8 @@ public class TestsuiteCLI {
             CacheCommands.ListCachesCommand.class,
             CacheCommands.GetCacheCommand.class,
             CacheCommands.CacheRealmObjectsCommand.class,
-            ClusterProviderTaskCommand.class
+            ClusterProviderTaskCommand.class,
+            LdapManyObjectsInitializerCommand.class
     };
 
     private final KeycloakSessionFactory sessionFactory;
diff --git a/testsuite/utils/src/main/resources/log4j.properties b/testsuite/utils/src/main/resources/log4j.properties
index 20f1df6..0866142 100755
--- a/testsuite/utils/src/main/resources/log4j.properties
+++ b/testsuite/utils/src/main/resources/log4j.properties
@@ -71,6 +71,9 @@ log4j.logger.org.keycloak.models.sessions.infinispan=${keycloak.infinispan.loggi
 # Enable to view queries to LDAP
 # log4j.logger.org.keycloak.storage.ldap.idm.store.ldap.LDAPIdentityStore=trace
 
+# Enable to view details about LDAP performance operations
+# log4j.logger.org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.perf=trace
+
 # Enable to view kerberos/spnego logging
 # log4j.logger.org.keycloak.federation.kerberos=trace