Intermittently failing AttributeMappingSuiteChild ------------------------------------------------- Key: ELY-1700 URL: https://issues.redhat.com/browse/ELY-1700 Project: WildFly Elytron Issue Type: Bug Components: Testsuite Affects Versions: 1.7.0.CR2 Reporter: Martin Choma Priority: Minor Fix For: 1.11.0.CR6 With ration 1:1000 we see ELY01125: Ldap-backed realm failed to obtain context. {noformat} org.wildfly.security.auth.server.RealmUnavailableException: ELY01125: Ldap-backed realm failed to obtain context at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm.obtainContext(LdapSecurityRealm.java:215) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm.access$600(LdapSecurityRealm.java:102) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm$LdapRealmIdentity.exists(LdapSecurityRealm.java:622) at org.wildfly.security.auth.server.ServerAuthenticationContext.exists(ServerAuthenticationContext.java:447) at org.wildfly.security.ldap.AbstractAttributeMappingSuiteChild.assertAttributes(AbstractAttributeMappingSuiteChild.java:85) at org.wildfly.security.ldap.AbstractAttributeMappingSuiteChild.assertAttributes(AbstractAttributeMappingSuiteChild.java:77) at org.wildfly.security.ldap.AttributeMappingSuiteChild.testSingleAttributeToSpecifiedName(AttributeMappingSuiteChild.java:33) at org.wildfly.security.ldap.DirContextFactoryRule$1.evaluate(DirContextFactoryRule.java:218) Caused by: javax.naming.NamingException: LDAP response read timed out, timeout used:5000ms. at com.sun.jndi.ldap.Connection.readReply(Connection.java:507) at com.sun.jndi.ldap.LdapClient.ldapBind(LdapClient.java:365) at com.sun.jndi.ldap.LdapClient.authenticate(LdapClient.java:214) at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2791) at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:319) at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:192) at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:210) at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:153) at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:83) at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:684) at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:313) at javax.naming.InitialContext.init(InitialContext.java:244) at javax.naming.ldap.InitialLdapContext.<init>(InitialLdapContext.java:154) at org.wildfly.security.auth.realm.ldap.SimpleDirContextFactoryBuilder$SimpleDirContextFactory.createDirContext(SimpleDirContextFactoryBuilder.java:436) at org.wildfly.security.auth.realm.ldap.SimpleDirContextFactoryBuilder$SimpleDirContextFactory.obtainDirContext(SimpleDirContextFactoryBuilder.java:355) at org.wildfly.security.ldap.DirContextFactoryRule.lambda$create$0(DirContextFactoryRule.java:258) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm.obtainContext(LdapSecurityRealm.java:203) ... 7 more {noformat} {noformat} 00:29:39,451 TRACE (main) [org.wildfly.security] <SecurityDomain.java:1036> Building security domain with defaultRealmName default. 00:29:39,452 TRACE (main) [org.wildfly.security] <SecurityDomain.java:708> Role mapping: principal [anonymous] -> decoded roles [] -> realm mapped roles [] -> domain mapped roles [] 00:29:39,452 TRACE (main) [org.wildfly.security] <ServerAuthenticationContext.java:1163> Principal assigning: [userWithAttributes], pre-realm rewritten: [userWithAttributes], realm name: [default], post-realm rewritten: [userWithAttributes], realm rewritten: [userWithAttributes] 00:29:39,453 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:189> Obtaining lock for identity [userWithAttributes]... 00:29:39,454 DEBUG (main) [org.wildfly.security] <LdapSecurityRealm.java:197> Obtained lock for identity [userWithAttributes]. 00:29:39,454 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:427> Creating [class javax.naming.directory.InitialDirContext] with environment: 00:29:39,454 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.security.credentials] with value [******] 00:29:39,455 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.ldap.factory.socket] with value [org.wildfly.security.auth.realm.ldap.ThreadLocalSSLSocketFactory] 00:29:39,455 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.security.authentication] with value [simple] 00:29:39,456 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.provider.url] with value [ldap://localhost:11390/] 00:29:39,456 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [com.sun.jndi.ldap.read.timeout] with value [60000] 00:29:39,456 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [com.sun.jndi.ldap.connect.timeout] with value [5000] 00:29:39,456 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.security.principal] with value [uid=server,dc=elytron,dc=wildfly,dc=org] 00:29:39,457 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.referral] with value [ignore] 00:29:39,457 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:428> Property [java.naming.factory.initial] with value [com.sun.jndi.ldap.LdapCtxFactory] 00:29:44,528 DEBUG (main) [org.wildfly.security] <SimpleDirContextFactoryBuilder.java:438> Could not create [class javax.naming.ldap.InitialLdapContext]. Failed to connect to LDAP server.: javax.naming.NamingException: LDAP response read timed out, timeout used:5000ms. at com.sun.jndi.ldap.Connection.readReply(Connection.java:507) at com.sun.jndi.ldap.LdapClient.ldapBind(LdapClient.java:365) at com.sun.jndi.ldap.LdapClient.authenticate(LdapClient.java:214) at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2791) at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:319) at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:192) at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:210) at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:153) at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:83) at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:684) at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:313) at javax.naming.InitialContext.init(InitialContext.java:244) at javax.naming.ldap.InitialLdapContext.<init>(InitialLdapContext.java:154) at org.wildfly.security.auth.realm.ldap.SimpleDirContextFactoryBuilder$SimpleDirContextFactory.createDirContext(SimpleDirContextFactoryBuilder.java:436) at org.wildfly.security.auth.realm.ldap.SimpleDirContextFactoryBuilder$SimpleDirContextFactory.obtainDirContext(SimpleDirContextFactoryBuilder.java:355) at org.wildfly.security.ldap.DirContextFactoryRule.lambda$create$0(DirContextFactoryRule.java:258) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm.obtainContext(LdapSecurityRealm.java:203) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm.access$600(LdapSecurityRealm.java:102) at org.wildfly.security.auth.realm.ldap.LdapSecurityRealm$LdapRealmIdentity.exists(LdapSecurityRealm.java:622) at org.wildfly.security.auth.server.ServerAuthenticationContext.exists(ServerAuthenticationContext.java:447) at org.wildfly.security.ldap.AbstractAttributeMappingSuiteChild.assertAttributes(AbstractAttributeMappingSuiteChild.java:85) at org.wildfly.security.ldap.AbstractAttributeMappingSuiteChild.assertAttributes(AbstractAttributeMappingSuiteChild.java:77) at org.wildfly.security.ldap.AttributeMappingSuiteChild.testSingleAttributeToSpecifiedName(AttributeMappingSuiteChild.java:33) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) at mockit.integration.junit4.internal.JUnit4TestRunnerDecorator.executeTestMethod(JUnit4TestRunnerDecorator.java:162) at mockit.integration.junit4.internal.JUnit4TestRunnerDecorator.invokeExplosively(JUnit4TestRunnerDecorator.java:71) at mockit.integration.junit4.internal.MockFrameworkMethod.invokeExplosively(MockFrameworkMethod.java:37) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.junit.runners.Suite.runChild(Suite.java:128) at org.junit.runners.Suite.runChild(Suite.java:27) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.wildfly.security.ldap.DirContextFactoryRule$1.evaluate(DirContextFactoryRule.java:218) at org.junit.rules.RunRules.evaluate(RunRules.java:20) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:367) at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:274) at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238) at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:161) at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121) 00:29:44,529 INFO (pool-3-thread-2) [org.apache.directory.server.ldap.handlers.LdapRequestHandler] <LdapRequestHandler.java:131> ignoring the message Abandon Request : Message Id : 1org.apache.directory.api.ldap.model.message.AbandonRequestImpl@8444b052 received from null session {noformat} Maybe just to try prolong SimpleDirContextFactoryBuilder#DEFAULT_CONNECT_TIMEOUT [1] This issue occurs also with ELY-1699. It is very probable machine was slow. But it would be fine if testsuite could cope with this situation as well. [1] https://github.com/wildfly-security/wildfly-elytron/blob/38e1e01972414ad7...