[jboss-jira] [JBoss JIRA] (ELY-1703) Intermittent failure of PrincipalMappingSuiteChild#testDnToDnVerify

Intermittent failure of PrincipalMappingSuiteChild#testDnToDnVerify ------------------------------------------------------------------- Key: ELY-1703 URL: https://issues.jboss.org/browse/ELY-1703 Project: WildFly Elytron Issue Type: Bug Components: Testsuite Affects Versions: 1.7.0.CR3 Reporter: Martin Choma Assignee: Justin Cook Priority: Optional Fix For: 1.8.0.CR3 Test PrincipalMappingSuiteChild#testDnToDnVerify failed (1:1000) on read timeout, which is 60 s. So probably prolonging timeout is not an option. Maybe solution is implement some kind of retry? Error Message ELY01108: Ldap-backed realm identity search failed Stacktrace {noformat} org.wildfly.security.auth.server.RealmUnavailableException: ELY01108: Ldap-backed realm identity search failed at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm$LdapSearch.search(LdapSecurityRealm.java:1141) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm$LdapRealmIdentity.getIdentity(LdapSecurityRealm.java:688) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm$LdapRealmIdentity.getIdentity(LdapSecurityRealm.java:669) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm$LdapRealmIdentity.exists(LdapSecurityRealm.java:624) at org.wildfly.security.ldap.PrincipalMappingSuiteChild.testDnToDnVerify(PrincipalMappingSuiteChild.java:132) at org.wildfly.security.ldap.DirContextFactoryRule$1.evaluate(DirContextFactoryRule.java:218) Caused by: javax.naming.NamingException: LDAP response read timed out, timeout used:60000ms.; remaining name 'uid=nobody,dc=elytron,dc=wildfly,dc=org' at java.naming/com.sun.jndi.ldap.Connection.readReply(Connection.java:443) at java.naming/com.sun.jndi.ldap.LdapClient.processReply(LdapClient.java:888) at java.naming/com.sun.jndi.ldap.LdapClient.compare(LdapClient.java:1168) at java.naming/com.sun.jndi.ldap.LdapCtx.compare(LdapCtx.java:2117) at java.naming/com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1840) at java.naming/com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1770) at java.naming/com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1787) at java.naming/com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:418) at java.naming/com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:396) at java.naming/javax.naming.directory.InitialDirContext.search(InitialDirContext.java:297) at org.wildfly.security.auth.realm.ldap.DelegatingLdapContext.search(DelegatingLdapContext.java:336) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm$LdapSearch.searchWithPagination(LdapSecurityRealm.java:1161) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm$LdapSearch.search(LdapSecurityRealm.java:1038) ... 5 more {noformat} {noformat} 21:11:54,245 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:695> Identity for principal [uid=nobody,dc=elytron,dc=wildfly,dc=org] not found. 21:11:54,245 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:628> Principal [uid=nobody,dc=elytron,dc=wildfly,dc=org] does not exists. 21:11:54,248 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:463> Context [javax.naming.ldap.InitialLdapContext@2dba05b1] was closed. Connection closed or just returned to the pool. 21:11:54,249 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:189> Obtaining lock for identity [uid=PlainUser,dc=elytron,dc=wildfly,dc=org]... 21:11:54,249 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:197> Obtained lock for identity [uid=PlainUser,dc=elytron,dc=wildfly,dc=org]. 21:11:54,249 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:427> Creating [class javax.naming.directory.InitialDirContext] with environment: 21:11:54,249 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.security.credentials] with value [******] 21:11:54,249 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.ldap.factory.socket] with value [org.wildfly.security.auth.realm.ldap.ThreadLocalSSLSocketFactory] 21:11:54,249 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.security.authentication] with value [simple] 21:11:54,249 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.provider.url] with value [ldap://localhost:11390/] 21:11:54,249 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [com.sun.jndi.ldap.read.timeout] with value [60000] 21:11:54,250 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [com.sun.jndi.ldap.connect.timeout] with value [5000] 21:11:54,250 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.security.principal] with value [uid=server,dc=elytron,dc=wildfly,dc=org] 21:11:54,250 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.referral] with value [ignore] 21:11:54,250 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.factory.initial] with value [com.sun.jndi.ldap.LdapCtxFactory] 21:11:54,300 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:444> [javax.naming.ldap.InitialLdapContext@31b0f02] successfully created. Connection established to LDAP server. 21:11:54,300 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:673> Trying to create identity for principal [uid=PlainUser,dc=elytron,dc=wildfly,dc=org]. 21:11:54,300 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:1027> Executing search [(uid={0})] in context [uid=PlainUser,dc=elytron,dc=wildfly,dc=org] with arguments [PlainUser]. Returning attributes are [null]. Binary attributes are [null]. 21:11:54,302 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:1096> Found entry [uid=PlainUser,dc=elytron,dc=wildfly,dc=org]. 21:11:54,302 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:692> Identity for principal [uid=PlainUser,dc=elytron,dc=wildfly,dc=org] found at [uid=PlainUser,dc=elytron,dc=wildfly,dc=org]. 21:11:54,303 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:463> Context [javax.naming.ldap.InitialLdapContext@31b0f02] was closed. Connection closed or just returned to the pool. 21:11:54,303 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:189> Obtaining lock for identity [uid=nobody,dc=elytron,dc=wildfly,dc=org]... 21:11:54,303 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:197> Obtained lock for identity [uid=nobody,dc=elytron,dc=wildfly,dc=org]. 21:11:54,303 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:427> Creating [class javax.naming.directory.InitialDirContext] with environment: 21:11:54,304 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.security.credentials] with value [******] 21:11:54,304 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.ldap.factory.socket] with value [org.wildfly.security.auth.realm.ldap.ThreadLocalSSLSocketFactory] 21:11:54,304 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.security.authentication] with value [simple] 21:11:54,304 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.provider.url] with value [ldap://localhost:11390/] 21:11:54,304 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [com.sun.jndi.ldap.read.timeout] with value [60000] 21:11:54,304 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [com.sun.jndi.ldap.connect.timeout] with value [5000] 21:11:54,304 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.security.principal] with value [uid=server,dc=elytron,dc=wildfly,dc=org] 21:11:54,304 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.referral] with value [ignore] 21:11:54,304 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.factory.initial] with value [com.sun.jndi.ldap.LdapCtxFactory] 21:11:54,354 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:444> [javax.naming.ldap.InitialLdapContext@19ae2ee5] successfully created. Connection established to LDAP server. 21:11:54,354 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:673> Trying to create identity for principal [uid=nobody,dc=elytron,dc=wildfly,dc=org]. 21:11:54,354 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:1027> Executing search [(uid={0})] in context [uid=nobody,dc=elytron,dc=wildfly,dc=org] with arguments [nobody]. Returning attributes are [null]. Binary attributes are [null]. 21:12:54,358 WARN (pool-3-thread-2) [org.apache.directory.server.ldap.LdapSession] <LdapSession.java:254> AbandonableRequest with messageId 2 not found in outstandingRequests. 21:12:54,364 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:463> Context [javax.naming.ldap.InitialLdapContext@19ae2ee5] was closed. Connection closed or just returned to the pool. 21:12:54,368 INFO (pool-3-thread-2) [org.apache.directory.server.ldap.handlers.LdapRequestHandler] <LdapRequestHandler.java:131> ignoring the message MessageType : UNBIND_REQUEST Message ID : 4 UnBind Requestorg.apache.directory.api.ldap.model.message.UnbindRequestImpl@949b7f8 ManageDsaITImpl Control Type OID : '2.16.840.1.113730.3.4.2' Criticality : 'false' ' received from null session {noformat}