Avoid short-lived connections for ApacheDS to avoid messages around "ignoring the message MessageType UNBIND_REQUEST"

The comment in LdapRequestHandler.java in ApacheDS notes just before discarding an unbind request: "in some cases the session is becoming null though the client is sending the UnbindRequest before closing".

Also implementing a retry logic for all remaining errors regarding LDAP.

Closes #11171

model/map-ldap/src/main/java/org/keycloak/models/map/storage/ldap/LdapMapStorageProviderFactory.java

@@ -30,6 +30,7 @@ import org.keycloak.models.RoleModel;
 import org.keycloak.models.map.storage.MapKeycloakTransaction;
 import org.keycloak.models.map.storage.MapStorageProvider;
 import org.keycloak.models.map.storage.MapStorageProviderFactory;
+import org.keycloak.models.map.storage.ldap.config.LdapMapConfig;
 import org.keycloak.models.map.storage.ldap.role.LdapRoleMapKeycloakTransaction;
 import org.keycloak.provider.EnvironmentDependentProviderFactory;
 
@@ -67,6 +68,25 @@ public class LdapMapStorageProviderFactory implements
     @Override
     public void init(Config.Scope config) {
         this.config = config;
+        LdapMapConfig cfg = new LdapMapConfig(config);
+        checkSystemProperty("com.sun.jndi.ldap.connect.pool.authentication", cfg.getConnectionPoolingAuthentication(), "none simple");
+        checkSystemProperty("com.sun.jndi.ldap.connect.pool.initsize", cfg.getConnectionPoolingInitSize(), "1");
+        checkSystemProperty("com.sun.jndi.ldap.connect.pool.maxsize", cfg.getConnectionPoolingMaxSize(), "1000");
+        checkSystemProperty("com.sun.jndi.ldap.connect.pool.prefsize", cfg.getConnectionPoolingPrefSize(), "5");
+        checkSystemProperty("com.sun.jndi.ldap.connect.pool.timeout", cfg.getConnectionPoolingTimeout(), "300000");
+        checkSystemProperty("com.sun.jndi.ldap.connect.pool.protocol", cfg.getConnectionPoolingProtocol(), "plain ssl");
+        checkSystemProperty("com.sun.jndi.ldap.connect.pool.debug", cfg.getConnectionPoolingDebug(), "off");
+    }
+
+    private static void checkSystemProperty(String name, String cfgValue, String defaultValue) {
+        String value = System.getProperty(name);
+        if(cfgValue != null) {
+            value = cfgValue;
+        }
+        if(value == null) {
+            value = defaultValue;
+        }
+        System.setProperty(name, value);
     }
 
     @Override

model/map-ldap/src/main/java/org/keycloak/models/map/storage/ldap/role/LdapRoleMapKeycloakTransaction.java

@@ -392,6 +392,8 @@ public class LdapRoleMapKeycloakTransaction extends LdapMapKeycloakTransaction<L
                 identityStore.update(entity.getLdapMapObject());
             }
         });
+
+        identityStore.close();
     }
 
     @Override

model/map-ldap/src/main/java/org/keycloak/models/map/storage/ldap/store/LdapMapIdentityStore.java

@@ -64,7 +64,7 @@ import java.util.stream.Collectors;
  * @author Anil Saldhana
  * @author <a href="mailto:psilva@redhat.com">Pedro Silva</a>
  */
-public class LdapMapIdentityStore {
+public class LdapMapIdentityStore implements AutoCloseable {
 
     private static final Logger logger = Logger.getLogger(LdapMapIdentityStore.class);
     private static final Pattern rangePattern = Pattern.compile("([^;]+);range=([0-9]+)-([0-9]+|\\*)");
@@ -530,4 +530,9 @@ public class LdapMapIdentityStore {
             throw new ModelException("Could not retrieve identifier for entry [" + ldapObject.getDn().toString() + "].");
         }
     }
+
+    @Override
+    public void close() {
+        operationManager.close();
+    }
 }

model/map-ldap/src/main/java/org/keycloak/models/map/storage/ldap/store/LdapMapOperationManager.java

@@ -57,7 +57,7 @@ import java.util.Set;
  * @author Anil Saldhana
  * @author <a href="mailto:psilva@redhat.com">Pedro Silva</a>
  */
-public class LdapMapOperationManager {
+public class LdapMapOperationManager implements AutoCloseable {
 
     private static final Logger logger = Logger.getLogger(LdapMapOperationManager.class);
 
@@ -65,6 +65,7 @@ public class LdapMapOperationManager {
 
     private final KeycloakSession session;
     private final LdapMapConfig config;
+    private LdapMapContextManager ldapMapContextManager;
 
     public LdapMapOperationManager(KeycloakSession session, LdapMapConfig config) {
         this.session = session;
@@ -191,7 +192,6 @@ public class LdapMapOperationManager {
                             }
                         }
                     }
-
                     throw new ModelException("Could not rename entry from DN [" + oldDn + "] to new DN [" + newDn + "]. All fallbacks failed");
                 }
 
@@ -580,9 +580,14 @@ public class LdapMapOperationManager {
     }
 
     private <R> R execute(LdapOperation<R> operation, LdapMapOperationDecorator decorator) throws NamingException {
-        try (LdapMapContextManager ldapMapContextManager = LdapMapContextManager.create(session, config)) {
+        return execute(operation, getLdapContextManager().getLdapContext(), decorator);
-            return execute(operation, ldapMapContextManager.getLdapContext(), decorator);
+    }
+
+    private LdapMapContextManager getLdapContextManager() {
+        if (ldapMapContextManager == null) {
+            ldapMapContextManager = LdapMapContextManager.create(session, config);
         }
+        return ldapMapContextManager;
     }
 
     private <R> R execute(LdapOperation<R> operation, LdapContext context, LdapMapOperationDecorator decorator) throws NamingException {
@@ -615,6 +620,11 @@ public class LdapMapOperationManager {
         }
     }
 
+    @Override
+    public void close() {
+        ldapMapContextManager.close();
+    }
+
     public interface LdapOperation<R> {
         R execute(LdapContext context) throws NamingException;
     }

testsuite/integration-arquillian/servers/auth-server/services/testsuite-providers/src/main/java/org/keycloak/testsuite/rest/resource/TestLDAPResource.java

@@ -74,7 +74,13 @@ public class TestLDAPResource {
         MultivaluedHashMap<String, String> ldapConfig = toComponentConfig(ldapCfg);
         ldapConfig.putSingle(LDAPConstants.SYNC_REGISTRATIONS, "true");
         ldapConfig.putSingle(LDAPConstants.EDIT_MODE, UserStorageProvider.EditMode.WRITABLE.toString());
-
+        // ApacheDS has a problem when processing an unbind request just before closing the connection, it will print
+        // "ignoring the message ... received from null session" and drop the message. To work around this:
+        // (1) enable connection pooling, to avoid short-lived connections
+        ldapConfig.putSingle(LDAPConstants.CONNECTION_POOLING, "true");
+        // (2) set pref size to max size so that there are no connections that are opened and then closed immediately again
+        ldapConfig.putSingle(LDAPConstants.CONNECTION_POOLING_PREFSIZE, "100");
+        ldapConfig.putSingle(LDAPConstants.CONNECTION_POOLING_MAXSIZE, "100");
         UserStorageProviderModel model = new UserStorageProviderModel();
         model.setLastSync(0);
         model.setChangedSyncPeriod(-1);

testsuite/integration-arquillian/tests/base/src/main/java/org/keycloak/testsuite/util/LDAPRule.java

@@ -75,7 +75,7 @@ public class LDAPRule extends ExternalResource {
     }
 
     @Override
-    protected void before() throws Throwable {
+    public void before() throws Throwable {
         String connectionPropsLocation = getConnectionPropertiesLocation();
         ldapTestConfiguration = LDAPTestConfiguration.readConfiguration(connectionPropsLocation);
 
@@ -92,6 +92,13 @@ public class LDAPRule extends ExternalResource {
     public Statement apply(Statement base, Description description) {
         // Default bind credential value
         defaultProperties.setProperty(LDAPConstants.BIND_CREDENTIAL, "secret");
+        // ApacheDS has a problem when processing an unbind request just before closing the connection, it will print
+        // "ignoring the message ... received from null session" and drop the message. To work around this:
+        // (1) enable connection pooling, to avoid short-lived connections
+        defaultProperties.setProperty(LDAPConstants.CONNECTION_POOLING, "true");
+        // (2) set pref size to max size so that there are no connections that are opened and then closed immediately again
+        defaultProperties.setProperty(LDAPConstants.CONNECTION_POOLING_MAXSIZE, "100");
+        defaultProperties.setProperty(LDAPConstants.CONNECTION_POOLING_PREFSIZE, "100");
         // Default values of the authentication / access control method and connection encryption to use on the embedded
         // LDAP server upon start if not (re)set later via the LDAPConnectionParameters annotation directly on the test
         defaultProperties.setProperty(LDAPEmbeddedServer.PROPERTY_ENABLE_ACCESS_CONTROL, "true");
@@ -163,7 +170,7 @@ public class LDAPRule extends ExternalResource {
     }
 
     @Override
-    protected void after() {
+    public void after() {
         try {
             if (ldapEmbeddedServer != null) {
                 ldapEmbeddedServer.stop();

testsuite/integration-arquillian/tests/base/src/main/java/org/keycloak/testsuite/util/LDAPTestConfiguration.java

@@ -81,6 +81,11 @@ public class LDAPTestConfiguration {
         DEFAULT_VALUES.put(LDAPConstants.BIND_CREDENTIAL, "secret");
         DEFAULT_VALUES.put(LDAPConstants.VENDOR, LDAPConstants.VENDOR_OTHER);
         DEFAULT_VALUES.put(LDAPConstants.CONNECTION_POOLING, "true");
+        // ApacheDS has a problem when processing an unbind request just before closing the connection, it will print
+        // "ignoring the message ... received from null session" and drop the message. To work around this:
+        // set pref size to max size so that there are no connections that are opened and then closed immediately again
+        DEFAULT_VALUES.put(LDAPConstants.CONNECTION_POOLING_MAXSIZE, "100");
+        DEFAULT_VALUES.put(LDAPConstants.CONNECTION_POOLING_PREFSIZE, "100");
         DEFAULT_VALUES.put(LDAPConstants.PAGINATION, "true");
         DEFAULT_VALUES.put(LDAPConstants.BATCH_SIZE_FOR_SYNC, String.valueOf(LDAPConstants.DEFAULT_BATCH_SIZE_FOR_SYNC));
         DEFAULT_VALUES.put(LDAPConstants.USERNAME_LDAP_ATTRIBUTE, null);

testsuite/model/src/test/java/org/keycloak/testsuite/model/UserModelTest.java

@@ -216,16 +216,7 @@ public class UserModelTest extends KeycloakModelTest {
             log.debugf("Removing selected users from backend");
             IntStream.range(FIRST_DELETED_USER_INDEX, LAST_DELETED_USER_INDEX).forEach(j -> {
                 final UserModel user = session.users().getUserByUsername(realm, "user-" + j);
-                try {
+                ((UserRegistrationProvider) instance).removeUser(realm, user);
-                    ((UserRegistrationProvider) instance).removeUser(realm, user);
-                } catch (ModelException ex) {
-                    // removing user might have failed for an LDAP reason
-                    // as this is not the main subject under test, retry once more to delete the entry
-                    if (ex.getMessage().contains("Could not unbind DN") && ex.getCause() instanceof NamingException) {
-                        log.warn("removing failed, retrying", ex);
-                        ((UserRegistrationProvider) instance).removeUser(realm, user);
-                    }
-                }
             });
             return null;
         });

testsuite/model/src/test/java/org/keycloak/testsuite/model/parameters/LdapMapStorage.java

@@ -17,10 +17,14 @@
 package org.keycloak.testsuite.model.parameters;
 
 import com.google.common.collect.ImmutableSet;
+import org.jboss.logging.Logger;
 import org.junit.runner.Description;
 import org.junit.runners.model.Statement;
 import org.keycloak.authorization.store.StoreFactorySpi;
 import org.keycloak.models.DeploymentStateSpi;
+import org.keycloak.models.LDAPConstants;
+import org.keycloak.models.ModelDuplicateException;
+import org.keycloak.models.ModelException;
 import org.keycloak.models.UserLoginFailureSpi;
 import org.keycloak.models.UserSessionSpi;
 import org.keycloak.models.map.storage.MapStorageSpi;
@@ -33,6 +37,7 @@ import org.keycloak.testsuite.model.KeycloakModelParameters;
 import org.keycloak.testsuite.util.LDAPRule;
 import org.keycloak.util.ldap.LDAPEmbeddedServer;
 
+import javax.naming.NamingException;
 import java.util.Set;
 
 /**
@@ -40,6 +45,8 @@ import java.util.Set;
  */
 public class LdapMapStorage extends KeycloakModelParameters {
 
+    private static final Logger LOG = Logger.getLogger(LdapMapStorage.class.getName());
+
     static final Set<Class<? extends Spi>> ALLOWED_SPIS = ImmutableSet.<Class<? extends Spi>>builder()
             .build();
 
@@ -79,7 +86,14 @@ public class LdapMapStorage extends KeycloakModelParameters {
                 .config("role.object.classes", "groupOfNames")
                 .config("role.attributes", "ou")
                 .config("mode", "LDAP_ONLY")
-                .config("use.realm.roles.mapping", "true");
+                .config("use.realm.roles.mapping", "true")
+                // ApacheDS has a problem when processing an unbind request just before closing the connection, it will print
+                // "ignoring the message ... received from null session" and drop the message. To work around this:
+                // (1) enable connection pooling, to avoid short-lived connections
+                .config(LDAPConstants.CONNECTION_POOLING, "true")
+                // (2) set pref size to max size so that there are no connections that are opened and then closed immediately again
+                .config(LDAPConstants.CONNECTION_POOLING_PREFSIZE, "1000")
+                .config(LDAPConstants.CONNECTION_POOLING_MAXSIZE, "1000");
 
         cf.spi("client").config("map.storage.provider", ConcurrentHashMapStorageProviderFactory.PROVIDER_ID)
                 .spi("clientScope").config("map.storage.provider", ConcurrentHashMapStorageProviderFactory.PROVIDER_ID)
@@ -106,4 +120,45 @@ public class LdapMapStorage extends KeycloakModelParameters {
         return ldapRule.apply(base, description);
     }
 
+    @Override
+    public Statement instanceRule(Statement base, Description description) {
+
+        /* test execution might fail due to random errors rooted in ApacheDS, sometimes entites can't be removed,
+           also a follow-up test might fail when an entity already exists from a previous test. Therefore, retry in case of LDAP errors
+           or suspected LDAP errors. Rate of failures is about 1 in 150 attempts.
+         */
+        return new Statement() {
+            @Override
+            public void evaluate() throws Throwable {
+                int currentAttempt = 0;
+                int maxAttempts = 10;
+                while (true) {
+                    try {
+                        base.evaluate();
+                        return;
+                    } catch (Throwable t) {
+                        boolean shouldRetry = false;
+                        Throwable t2 = t;
+                        while(t2 != null) {
+                            if ((t2 instanceof ModelException && t2.getMessage() != null && t2.getMessage().startsWith("Could not unbind DN")
+                                    && t.getCause() instanceof NamingException) ||
+                                t2 instanceof ModelDuplicateException) {
+                                shouldRetry = true;
+                                break;
+                            }
+                            t2 = t2.getCause();
+                        }
+                        if (!shouldRetry || currentAttempt > maxAttempts) {
+                            throw t;
+                        }
+                        LOG.warn("retrying after exception", t);
+                        // reset LDAP so that is is really cleaned up and no previous elements remain
+                        ldapRule.after();
+                        ldapRule.before();
+                        ++ currentAttempt;
+                    }
+                }
+            }
+        };
+    }
 }

testsuite/model/src/test/java/org/keycloak/testsuite/model/parameters/LdapUserStorage.java

@@ -73,6 +73,13 @@ public class LdapUserStorage extends KeycloakModelParameters {
             }
             config.putSingle(LDAPConstants.SYNC_REGISTRATIONS, "true");
             config.putSingle(LDAPConstants.EDIT_MODE, UserStorageProvider.EditMode.WRITABLE.toString());
+            // ApacheDS has a problem when processing an unbind request just before closing the connection, it will print
+            // "ignoring the message ... received from null session" and drop the message. To work around this:
+            // (1) enable connection pooling, to avoid short-lived connections
+            config.putSingle(LDAPConstants.CONNECTION_POOLING, "true");
+            // (2) set pref size to max size so that there are no connections that are opened and then closed immediately again
+            config.putSingle(LDAPConstants.CONNECTION_POOLING_PREFSIZE, "1000");
+            config.putSingle(LDAPConstants.CONNECTION_POOLING_MAXSIZE, "1000");
 
             UserStorageProviderModel federatedStorage = new UserStorageProviderModel();
             federatedStorage.setName(LDAPStorageProviderFactory.PROVIDER_NAME + ":" + counter.getAndIncrement());

testsuite/model/src/test/java/org/keycloak/testsuite/model/role/RoleModelTest.java

@@ -1,7 +1,9 @@
 package org.keycloak.testsuite.model.role;
 
 import org.hamcrest.Matcher;
+import org.junit.Rule;
 import org.junit.Test;
+import org.junit.rules.TestRule;
 import org.keycloak.models.ClientModel;
 import org.keycloak.models.ClientProvider;
 import org.keycloak.models.Constants;

testsuite/utils/src/main/resources/META-INF/keycloak-server.json

@@ -136,7 +136,13 @@
             "role.object.classes": "groupOfNames",
             "role.attributes": "ou",
             "mode": "LDAP_ONLY",
-            "use.realm.roles.mapping": "true"
+            "use.realm.roles.mapping": "true",
+            "//connectionPooling": "ApacheDS has a problem when processing an unbind request just before closing the connection, therefore enable connection pooling to avoid short-lived connections",
+            "connectionPooling": "true",
+            "//connectionPoolingPrefSize": "ApacheDS has a problem when processing an unbind request just before closing the connection, therefore set max=preferred to avoid short-lived connections",
+            "connectionPoolingPrefSize": "1000",
+            "//connectionPoolingMaxSize": "ApacheDS has a problem when processing an unbind request just before closing the connection, therefore set max=preferred to avoid short-lived connections",
+            "connectionPoolingMaxSize": "1000"
         }
     },