By: matt dillenkoffer user 11 Mar 2016 at 10 a.m. CST

71 Responses
matt dillenkoffer gravatar
After I configure Cache Refresh I got to configure Manage Authentication and put in the following values Name* VITL_ldap_server Bind DN* uid=admin,ou=system Max connections* 10 Primary key* cn Local primary key* cn Server* 10.1.138.18:1024 Base DN* ou=users,dc=trio,dc=giab I uncheck SSL, Click Change Bind Password and enter my ldap's password. Click Test LDAP Connection.... get the success message Then click Update. All while watching the wrapper.log. Just normal stuff is flowing by when i made the previous clicks like.... INFO | jvm 1 | 2016/03/10 20:53:13 | Mar 10, 2016 8:53:13 PM com.sun.faces.renderkit.html_basic.HtmlBasicRenderer getForComponent INFO | jvm 1 | 2016/03/10 20:53:13 | WARNING: Unable to find component with ID j_idt259 in view. INFO | jvm 1 | 2016/03/10 20:53:13 | Mar 10, 2016 8:53:13 PM com.sun.faces.renderkit.html_basic.HtmlBasicRenderer getForComponent INFO | jvm 1 | 2016/03/10 20:53:13 | WARNING: Unable to find component with ID j_idt259 in view. INFO | jvm 1 | 2016/03/10 20:53:13 | Mar 10, 2016 8:53:13 PM com.sun.faces.renderkit.html_basic.HtmlBasicRenderer getForComponent INFO | jvm 1 | 2016/03/10 20:53:13 | WARNING: Unable to find component with ID j_idt259 in view. INFO | jvm 1 | 2016/03/10 20:53:13 | Mar 10, 2016 8:53:13 PM com.sun.faces.renderkit.html_basic.HtmlBasicRenderer getForComponent INFO | jvm 1 | 2016/03/10 20:53:13 | WARNING: Unable to find component with ID j_idt259 in view. INFO | jvm 1 | 2016/03/10 20:53:13 | Mar 10, 2016 8:53:13 PM com.sun.faces.renderkit.html_basic.MessageRenderer encodeEnd But after clicking update sometime between 5 and 30 seconds later I see this flow by in the logs and it looks to me that gluu might be creating an incorrect connection string to my legacy ldap server... maybe i'm misinterpreting what i'm seeing but note that it still says the baseDN is o=gluu and not the value I set which was ou=users,dc=trio,dc=giab Here's the stack trace.... INFO | jvm 1 | 2016/03/10 20:53:38 | 2016-03-10 20:53:38,276 ERROR [org.gluu.site.ldap.LDAPConnectionProvider] Failed to create connection pool with properties: {baseDNs=o=gluu, certsDir=/etc/certs, useSSL=false, configurationEntryDN=ou=oxauth,ou=configuration,inum=@!5E88.9AD6.F20A.4B47!0002!1C74.F7A6,ou=appliances,o=gluu, binaryAttributes=objectGUID, servers=10.1.138.18:1024, confDir=, maxconnections=10} INFO | jvm 1 | 2016/03/10 20:53:38 | LDAPException(resultCode=49 (invalid credentials), errorMessage='INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user : INFO | jvm 1 | 2016/03/10 20:53:38 | org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:669) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:442) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:216) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.lang.Thread.run(Thread.java:745) INFO | jvm 1 | 2016/03/10 20:53:38 | INFO | jvm 1 | 2016/03/10 20:53:38 | INFO | jvm 1 | 2016/03/10 20:53:38 | BindRequest = INFO | jvm 1 | 2016/03/10 20:53:38 | MessageType : BIND_REQUEST INFO | jvm 1 | 2016/03/10 20:53:38 | Message ID : 1 INFO | jvm 1 | 2016/03/10 20:53:38 | BindRequest INFO | jvm 1 | 2016/03/10 20:53:38 | Version : '3' INFO | jvm 1 | 2016/03/10 20:53:38 | Name : anonymous INFO | jvm 1 | 2016/03/10 20:53:38 | ', diagnosticMessage='INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user : INFO | jvm 1 | 2016/03/10 20:53:38 | org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:669) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:442) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:216) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.lang.Thread.run(Thread.java:745) INFO | jvm 1 | 2016/03/10 20:53:38 | INFO | jvm 1 | 2016/03/10 20:53:38 | INFO | jvm 1 | 2016/03/10 20:53:38 | BindRequest = INFO | jvm 1 | 2016/03/10 20:53:38 | MessageType : BIND_REQUEST INFO | jvm 1 | 2016/03/10 20:53:38 | Message ID : 1 INFO | jvm 1 | 2016/03/10 20:53:38 | BindRequest INFO | jvm 1 | 2016/03/10 20:53:38 | Version : '3' INFO | jvm 1 | 2016/03/10 20:53:38 | Name : anonymous INFO | jvm 1 | 2016/03/10 20:53:38 | ') INFO | jvm 1 | 2016/03/10 20:53:38 | at com.unboundid.ldap.sdk.LDAPConnection.bind(LDAPConnection.java:1837) INFO | jvm 1 | 2016/03/10 20:53:38 | at com.unboundid.ldap.sdk.LDAPConnectionPool.createConnection(LDAPConnectionPool.java:666) INFO | jvm 1 | 2016/03/10 20:53:38 | at com.unboundid.ldap.sdk.LDAPConnectionPool.<init>(LDAPConnectionPool.java:562) INFO | jvm 1 | 2016/03/10 20:53:38 | at com.unboundid.ldap.sdk.LDAPConnectionPool.<init>(LDAPConnectionPool.java:458) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.gluu.site.ldap.LDAPConnectionProvider.init(LDAPConnectionProvider.java:113) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.gluu.site.ldap.LDAPConnectionProvider.<init>(LDAPConnectionProvider.java:59) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.xdi.service.ldap.LdapConnectionService.<init>(LdapConnectionService.java:21) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.xdi.oxauth.service.AppInitializer.createConnectionProvider(AppInitializer.java:335) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.xdi.oxauth.service.AppInitializer.createBindConnectionProvider(AppInitializer.java:341) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.xdi.oxauth.service.AppInitializer.createAuthConnectionProviders(AppInitializer.java:300) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.xdi.oxauth.service.AppInitializer.createAuthConnectionProviders(AppInitializer.java:282) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.xdi.oxauth.service.AppInitializer.recreateLdapAuthEntryManagers(AppInitializer.java:248) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.xdi.oxauth.service.AppInitializer.reloadConfiguration(AppInitializer.java:179) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.xdi.oxauth.service.AppInitializer.reloadConfigurationTimerEvent(AppInitializer.java:165) INFO | jvm 1 | 2016/03/10 20:53:38 | at sun.reflect.GeneratedMethodAccessor450.invoke(Unknown Source) INFO | jvm 1 | 2016/03/10 20:53:38 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.lang.reflect.Method.invoke(Method.java:606) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.util.Reflections.invoke(Reflections.java:22) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.intercept.RootInvocationContext.proceed(RootInvocationContext.java:32) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:56) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.transaction.RollbackInterceptor.aroundInvoke(RollbackInterceptor.java:28) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.core.BijectionInterceptor.aroundInvoke(BijectionInterceptor.java:77) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.core.MethodContextInterceptor.aroundInvoke(MethodContextInterceptor.java:44) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.async.AsynchronousInterceptor.aroundInvoke(AsynchronousInterceptor.java:52) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.intercept.JavaBeanInterceptor.interceptInvocation(JavaBeanInterceptor.java:185) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.intercept.JavaBeanInterceptor.invoke(JavaBeanInterceptor.java:103) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.xdi.oxauth.service.AppInitializer_$$_javassist_seam_1.reloadConfigurationTimerEvent(AppInitializer_$$_javassist_seam_1.java) INFO | jvm 1 | 2016/03/10 20:53:38 | at sun.reflect.GeneratedMethodAccessor449.invoke(Unknown Source) INFO | jvm 1 | 2016/03/10 20:53:38 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.lang.reflect.Method.invoke(Method.java:606) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.util.Reflections.invoke(Reflections.java:22) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.util.Reflections.invokeAndWrap(Reflections.java:144) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.Component.callComponentMethod(Component.java:2275) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.core.Events.raiseEvent(Events.java:85) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.async.AsynchronousEvent$1.process(AsynchronousEvent.java:33) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.async.Asynchronous$ContextualAsynchronousRequest.run(Asynchronous.java:80) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.async.AsynchronousEvent.execute(AsynchronousEvent.java:27) INFO | jvm 1 | 2016/03/10 20:53:38 | at org.jboss.seam.async.ThreadPoolDispatcher$RunnableAsynchronous.run(ThreadPoolDispatcher.java:142) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) INFO | jvm 1 | 2016/03/10 20:53:38 | at java.lang.Thread.run(Thread.java:745)

By Aliaksandr Samuseu staff 11 Mar 2016 at 10:11 a.m. CST

Aliaksandr Samuseu gravatar
Hi, Matt. > Primary key* cn That's pretty unusual choice for primary key. We require that primary key be unique throughout namespace you are using for authentication. Usual choice is something like uid or samaccountname > Local primary key* cn That's even less usual. Best to be left as it is (`uid`), and then you should map your primary key (or another unique id) to uid in CR's mapping section. Can you provide screenshots of your CR configuration? Regards, Alex.

By Aliaksandr Samuseu staff 11 Mar 2016 at 10:14 a.m. CST

Aliaksandr Samuseu gravatar
Again, if that will help, here is my guide for CR (it uses AD for backend, you may need to adapt it to your solution a bit): [link](https://docs.google.com/document/d/1EvICMe5EEUlsNWE19Q_fadoKoVGQK9EKngDwNu7GOVE/edit?usp=sharing)

By matt dillenkoffer user 11 Mar 2016 at 10:14 a.m. CST

matt dillenkoffer gravatar
Regardless of whether I use uid or cn I get the same behavior. I will continue to use uid going forward. The only reason CN made sense for me was because our system enforces uniqueness at time of user creation.

By matt dillenkoffer user 11 Mar 2016 at 10:24 a.m. CST

matt dillenkoffer gravatar
You don't think it's a red flag that this error says it's trying to create a connection string to LDAP and the BaseDN is wrong? Note that the server value and the useSSL values are updated to what I set but baseDN is not. INFO | jvm 1 | 2016/03/10 20:53:38 | 2016-03-10 20:53:38,276 ERROR [org.gluu.site.ldap.LDAPConnectionProvider] Failed to create connection pool with properties: {**baseDNs=o=gluu**, certsDir=/etc/certs, useSSL=false, configurationEntryDN=ou=oxauth,ou=configuration,inum=@!5E88.9AD6.F20A.4B47!0002!1C74.F7A6,ou=appliances,o=gluu, binaryAttributes=objectGUID, servers=10.1.138.18:1024, confDir=, maxconnections=10}

By Aliaksandr Samuseu staff 11 Mar 2016 at 10:40 a.m. CST

Aliaksandr Samuseu gravatar
It may not have something to do with CR at all, especially when it's from wrapper.log. For me, it looks more like oxauth can't access its configuration entry in LDAP. Could you provide full name of the Gluu package you are using? Also, what CR's log contains?

By matt dillenkoffer user 11 Mar 2016 at 10:44 a.m. CST

matt dillenkoffer gravatar
I'm using gluu-server-2.4.2

By matt dillenkoffer user 11 Mar 2016 at 10:45 a.m. CST

matt dillenkoffer gravatar
oxtrust_cache_refresh.log looks like this.... 2016-03-10 21:21:57,967 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Attempting to load entries from source server 2016-03-10 21:21:57,977 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Found '6' entries in source server 2016-03-10 21:21:57,977 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Found '6' unique entries in source server 2016-03-10 21:21:57,979 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Found '0' changed entries 2016-03-10 21:21:57,980 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Loaded '0' problem entries from problem file 2016-03-10 21:21:58,001 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Updated '0' entries 2016-03-10 21:21:58,001 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Failed to update '0' entries 2016-03-10 21:21:58,002 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Removed '0' persons from target server 2016-03-10 21:21:58,002 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) There are '6' entries before updating inum list 2016-03-10 21:21:58,002 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) There are '6' entries after removal '0' entries 2016-03-10 21:21:58,003 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) There are '6' entries after adding '0' entries 2016-03-10 21:23:57,936 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Attempting to load entries from source server 2016-03-10 21:23:57,946 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Found '6' entries in source server 2016-03-10 21:23:57,946 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Found '6' unique entries in source server 2016-03-10 21:23:57,949 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Found '0' changed entries 2016-03-10 21:23:57,949 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Loaded '0' problem entries from problem file 2016-03-10 21:23:57,975 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Updated '0' entries 2016-03-10 21:23:57,975 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Failed to update '0' entries 2016-03-10 21:23:57,976 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Removed '0' persons from target server 2016-03-10 21:23:57,977 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) There are '6' entries before updating inum list 2016-03-10 21:23:57,977 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) There are '6' entries after removal '0' entries 2016-03-10 21:23:57,977 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) There are '6' entries after adding '0' entries 2016-03-10 21:25:57,929 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) Attempting to load entries from source server 2016-03-10 21:25:57,940 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) Found '6' entries in source server 2016-03-10 21:25:57,941 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) Found '6' unique entries in source server 2016-03-10 21:25:57,946 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) Found '0' changed entries 2016-03-10 21:25:57,946 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) Loaded '0' problem entries from problem file 2016-03-10 21:25:57,982 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) Updated '0' entries 2016-03-10 21:25:57,983 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) Failed to update '0' entries 2016-03-10 21:25:57,985 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) Removed '0' persons from target server 2016-03-10 21:25:57,985 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) There are '6' entries before updating inum list 2016-03-10 21:25:57,985 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) There are '6' entries after removal '0' entries 2016-03-10 21:25:57,985 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-10) There are '6' entries after adding '0' entries 2016-03-10 21:27:57,939 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) Attempting to load entries from source server 2016-03-10 21:27:57,947 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) Found '6' entries in source server 2016-03-10 21:27:57,948 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) Found '6' unique entries in source server 2016-03-10 21:27:57,955 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) Found '0' changed entries 2016-03-10 21:27:57,956 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) Loaded '0' problem entries from problem file 2016-03-10 21:27:57,987 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) Updated '0' entries 2016-03-10 21:27:57,987 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) Failed to update '0' entries 2016-03-10 21:27:57,988 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) Removed '0' persons from target server 2016-03-10 21:27:57,988 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) There are '6' entries before updating inum list 2016-03-10 21:27:57,989 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) There are '6' entries after removal '0' entries 2016-03-10 21:27:57,989 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-9) There are '6' entries after adding '0' entries 2016-03-10 21:29:57,964 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Attempting to load entries from source server 2016-03-10 21:29:57,975 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Found '6' entries in source server 2016-03-10 21:29:57,976 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Found '6' unique entries in source server 2016-03-10 21:29:57,978 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Found '0' changed entries 2016-03-10 21:29:57,978 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Loaded '0' problem entries from problem file 2016-03-10 21:29:57,998 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Updated '0' entries 2016-03-10 21:29:57,998 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Failed to update '0' entries 2016-03-10 21:29:57,999 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Removed '0' persons from target server 2016-03-10 21:29:57,999 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) There are '6' entries before updating inum list 2016-03-10 21:29:57,999 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) There are '6' entries after removal '0' entries 2016-03-10 21:29:58,000 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) There are '6' entries after adding '0' entries 2016-03-10 21:31:57,922 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Attempting to load entries from source server 2016-03-10 21:31:57,936 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Found '6' entries in source server 2016-03-10 21:31:57,936 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Found '6' unique entries in source server 2016-03-10 21:31:57,939 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Found '0' changed entries 2016-03-10 21:31:57,939 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Loaded '0' problem entries from problem file 2016-03-10 21:31:57,963 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Updated '0' entries 2016-03-10 21:31:57,964 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Failed to update '0' entries 2016-03-10 21:31:57,968 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) Removed '0' persons from target server 2016-03-10 21:31:57,968 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) There are '6' entries before updating inum list 2016-03-10 21:31:57,968 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) There are '6' entries after removal '0' entries 2016-03-10 21:31:57,969 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-1) There are '6' entries after adding '0' entries 2016-03-10 21:33:57,930 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Attempting to load entries from source server 2016-03-10 21:33:57,944 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Found '6' entries in source server 2016-03-10 21:33:57,944 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Found '6' unique entries in source server 2016-03-10 21:33:57,954 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Found '0' changed entries 2016-03-10 21:33:57,955 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Loaded '0' problem entries from problem file 2016-03-10 21:33:57,980 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Updated '0' entries 2016-03-10 21:33:57,980 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Failed to update '0' entries 2016-03-10 21:33:57,981 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) Removed '0' persons from target server 2016-03-10 21:33:57,981 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) There are '6' entries before updating inum list 2016-03-10 21:33:57,981 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) There are '6' entries after removal '0' entries 2016-03-10 21:33:57,981 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-4) There are '6' entries after adding '0' entries 2016-03-10 21:35:57,916 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) Attempting to load entries from source server 2016-03-10 21:35:57,928 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) Found '6' entries in source server 2016-03-10 21:35:57,928 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) Found '6' unique entries in source server 2016-03-10 21:35:57,931 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) Found '0' changed entries 2016-03-10 21:35:57,931 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) Loaded '0' problem entries from problem file 2016-03-10 21:35:57,959 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) Updated '0' entries 2016-03-10 21:35:57,959 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) Failed to update '0' entries 2016-03-10 21:35:57,960 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) Removed '0' persons from target server 2016-03-10 21:35:57,961 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) There are '6' entries before updating inum list 2016-03-10 21:35:57,961 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) There are '6' entries after removal '0' entries 2016-03-10 21:35:57,961 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-7) There are '6' entries after adding '0' entries 2016-03-10 21:37:57,950 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) Attempting to load entries from source server 2016-03-10 21:37:57,962 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) Found '6' entries in source server 2016-03-10 21:37:57,962 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) Found '6' unique entries in source server 2016-03-10 21:37:57,974 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) Found '0' changed entries 2016-03-10 21:37:57,975 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) Loaded '0' problem entries from problem file 2016-03-10 21:37:58,013 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) Updated '0' entries 2016-03-10 21:37:58,013 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) Failed to update '0' entries 2016-03-10 21:37:58,014 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) Removed '0' persons from target server 2016-03-10 21:37:58,014 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) There are '6' entries before updating inum list 2016-03-10 21:37:58,014 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) There are '6' entries after removal '0' entries 2016-03-10 21:37:58,014 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-5) There are '6' entries after adding '0' entries 2016-03-10 21:39:57,925 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) Attempting to load entries from source server 2016-03-10 21:39:57,944 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) Found '6' entries in source server 2016-03-10 21:39:57,945 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) Found '6' unique entries in source server 2016-03-10 21:39:57,947 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) Found '0' changed entries 2016-03-10 21:39:57,947 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) Loaded '0' problem entries from problem file 2016-03-10 21:39:57,982 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) Updated '0' entries 2016-03-10 21:39:57,982 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) Failed to update '0' entries 2016-03-10 21:39:57,983 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) Removed '0' persons from target server 2016-03-10 21:39:57,983 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) There are '6' entries before updating inum list 2016-03-10 21:39:57,983 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) There are '6' entries after removal '0' entries 2016-03-10 21:39:57,983 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-3) There are '6' entries after adding '0' entries 2016-03-10 21:41:57,920 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) Attempting to load entries from source server 2016-03-10 21:41:57,928 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) Found '6' entries in source server 2016-03-10 21:41:57,928 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) Found '6' unique entries in source server 2016-03-10 21:41:57,931 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) Found '0' changed entries 2016-03-10 21:41:57,931 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) Loaded '0' problem entries from problem file 2016-03-10 21:41:57,952 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) Updated '0' entries 2016-03-10 21:41:57,952 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) Failed to update '0' entries 2016-03-10 21:41:57,953 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) Removed '0' persons from target server 2016-03-10 21:41:57,953 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) There are '6' entries before updating inum list 2016-03-10 21:41:57,953 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) There are '6' entries after removal '0' entries 2016-03-10 21:41:57,959 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-8) There are '6' entries after adding '0' entries 2016-03-10 21:43:57,928 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) Attempting to load entries from source server 2016-03-10 21:43:57,937 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) Found '6' entries in source server 2016-03-10 21:43:57,938 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) Found '6' unique entries in source server 2016-03-10 21:43:57,941 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) Found '0' changed entries 2016-03-10 21:43:57,941 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) Loaded '0' problem entries from problem file 2016-03-10 21:43:57,970 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) Updated '0' entries 2016-03-10 21:43:57,971 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) Failed to update '0' entries 2016-03-10 21:43:57,972 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) Removed '0' persons from target server 2016-03-10 21:43:57,972 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) There are '6' entries before updating inum list 2016-03-10 21:43:57,972 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) There are '6' entries after removal '0' entries 2016-03-10 21:43:57,972 INFO [gluu.oxtrust.ldap.cache.service.CacheRefreshTimer] (pool-4-thread-6) There are '6' entries after adding '0' entries

By Aliaksandr Samuseu staff 11 Mar 2016 at 10:47 a.m. CST

Aliaksandr Samuseu gravatar
> I'm using gluu-server-2.4.2 Could you please look up the exact version for it? That may help: Check gluu's version on Ubuntu: dpkg -l | grep gluu-server Check gluu's version on CentOS: yum info gluu-server rpm -qi gluu-server

By matt dillenkoffer user 11 Mar 2016 at 10:50 a.m. CST

matt dillenkoffer gravatar
ii gluu-server-2.4.2 1-1 amd64 Gluu Server Community Edition

By Aliaksandr Samuseu staff 11 Mar 2016 at 11:12 a.m. CST

Aliaksandr Samuseu gravatar
It seems CR is doing fine. Something went wrong when you configured oxAuth to use backend for authentication. Let me try to reproduce it.

By matt dillenkoffer user 11 Mar 2016 at 1:20 p.m. CST

matt dillenkoffer gravatar
Would I ever have to alter the Authentication Filters under OxAuth Configuration? I see there BaseDN is set to o=gluu.

By Aliaksandr Samuseu staff 11 Mar 2016 at 1:39 p.m. CST

Aliaksandr Samuseu gravatar
> Would I ever have to alter the Authentication Filters under OxAuth Configuration? I see there BaseDN is set to o=gluu. Under normal conditions, to complete a basic setup you shouldn't even touch anything there. This page is for fine-tuning to adapt to special conditions. To configure authentication against backend all you need is to configure CR and then point oxAuth to your backend directory on the "Manage authentication" page. I'm not sure how your instance ended up like this, I couldn't reproduce it in my test instance (though it's slightly newer than yours, I'm installing it from dev repo). I can only recommend you to reinstall from scratch and try following my guide from above as close as possible. Let's see whether or not it will show up this time.

By matt dillenkoffer user 11 Mar 2016 at 1:45 p.m. CST

matt dillenkoffer gravatar
Ok I will do that, but just an FYI after looking at your guide that is exactly what I had done.

By Aliaksandr Samuseu staff 11 Mar 2016 at 2:22 p.m. CST

Aliaksandr Samuseu gravatar
What OS you are installing it at, again? I'll try to find some time to reproduce it for this particular package.

By matt dillenkoffer user 11 Mar 2016 at 2:42 p.m. CST

matt dillenkoffer gravatar
Ubuntu 14.04.4

By matt dillenkoffer user 11 Mar 2016 at 2:51 p.m. CST

matt dillenkoffer gravatar
I'm not married to this OS so if Cent is more stable I can switch to that.

By Aliaksandr Samuseu staff 11 Mar 2016 at 3:05 p.m. CST

Aliaksandr Samuseu gravatar
I'm testing it on Ubuntu myself. There shouldn't be so much differences between packages of the same version on different OSes, as services run in a container. Still packages for different OSes may differ (by mistake, for example)

By matt dillenkoffer user 11 Mar 2016 at 3:37 p.m. CST

matt dillenkoffer gravatar
I did a fresh install of Ubuntu, followed your cache refresh and authentication configuration but once I test the ldap connection I get success but when I click update and wait a few seconds I get the same exact stack trace in the wrapper.log INFO | jvm 1 | 2016/03/11 21:35:41 | 2016-03-11 21:35:41,280 ERROR [org.gluu.site.ldap.LDAPConnectionProvider] Failed to create connection pool with properties: {baseDNs=o=gluu, certsDir=/etc/certs, useSSL=false, configurationEntryDN=ou=oxauth,ou=configuration,inum=@!8768.880E.9788.6143!0002!207D.BB3B,ou=appliances,o=gluu, binaryAttributes=objectGUID, servers=10.1.138.18:1024, confDir=, maxconnections=10} INFO | jvm 1 | 2016/03/11 21:35:41 | LDAPException(resultCode=49 (invalid credentials), errorMessage='INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user : INFO | jvm 1 | 2016/03/11 21:35:41 | org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:669) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:442) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:216) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.lang.Thread.run(Thread.java:745) INFO | jvm 1 | 2016/03/11 21:35:41 | INFO | jvm 1 | 2016/03/11 21:35:41 | INFO | jvm 1 | 2016/03/11 21:35:41 | BindRequest = INFO | jvm 1 | 2016/03/11 21:35:41 | MessageType : BIND_REQUEST INFO | jvm 1 | 2016/03/11 21:35:41 | Message ID : 1 INFO | jvm 1 | 2016/03/11 21:35:41 | BindRequest INFO | jvm 1 | 2016/03/11 21:35:41 | Version : '3' INFO | jvm 1 | 2016/03/11 21:35:41 | Name : anonymous INFO | jvm 1 | 2016/03/11 21:35:41 | ', diagnosticMessage='INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user : INFO | jvm 1 | 2016/03/11 21:35:41 | org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:669) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:442) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:216) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.lang.Thread.run(Thread.java:745) INFO | jvm 1 | 2016/03/11 21:35:41 | INFO | jvm 1 | 2016/03/11 21:35:41 | INFO | jvm 1 | 2016/03/11 21:35:41 | BindRequest = INFO | jvm 1 | 2016/03/11 21:35:41 | MessageType : BIND_REQUEST INFO | jvm 1 | 2016/03/11 21:35:41 | Message ID : 1 INFO | jvm 1 | 2016/03/11 21:35:41 | BindRequest INFO | jvm 1 | 2016/03/11 21:35:41 | Version : '3' INFO | jvm 1 | 2016/03/11 21:35:41 | Name : anonymous INFO | jvm 1 | 2016/03/11 21:35:41 | ') INFO | jvm 1 | 2016/03/11 21:35:41 | at com.unboundid.ldap.sdk.LDAPConnection.bind(LDAPConnection.java:1837) INFO | jvm 1 | 2016/03/11 21:35:41 | at com.unboundid.ldap.sdk.LDAPConnectionPool.createConnection(LDAPConnectionPool.java:666) INFO | jvm 1 | 2016/03/11 21:35:41 | at com.unboundid.ldap.sdk.LDAPConnectionPool.<init>(LDAPConnectionPool.java:562) INFO | jvm 1 | 2016/03/11 21:35:41 | at com.unboundid.ldap.sdk.LDAPConnectionPool.<init>(LDAPConnectionPool.java:458) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.gluu.site.ldap.LDAPConnectionProvider.init(LDAPConnectionProvider.java:113) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.gluu.site.ldap.LDAPConnectionProvider.<init>(LDAPConnectionProvider.java:59) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.xdi.service.ldap.LdapConnectionService.<init>(LdapConnectionService.java:21) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.xdi.oxauth.service.AppInitializer.createConnectionProvider(AppInitializer.java:335) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.xdi.oxauth.service.AppInitializer.createBindConnectionProvider(AppInitializer.java:341) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.xdi.oxauth.service.AppInitializer.createAuthConnectionProviders(AppInitializer.java:300) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.xdi.oxauth.service.AppInitializer.createAuthConnectionProviders(AppInitializer.java:282) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.xdi.oxauth.service.AppInitializer.recreateLdapAuthEntryManagers(AppInitializer.java:248) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.xdi.oxauth.service.AppInitializer.reloadConfiguration(AppInitializer.java:179) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.xdi.oxauth.service.AppInitializer.reloadConfigurationTimerEvent(AppInitializer.java:165) INFO | jvm 1 | 2016/03/11 21:35:41 | at sun.reflect.GeneratedMethodAccessor596.invoke(Unknown Source) INFO | jvm 1 | 2016/03/11 21:35:41 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.lang.reflect.Method.invoke(Method.java:606) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.util.Reflections.invoke(Reflections.java:22) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.intercept.RootInvocationContext.proceed(RootInvocationContext.java:32) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:56) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.transaction.RollbackInterceptor.aroundInvoke(RollbackInterceptor.java:28) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.core.BijectionInterceptor.aroundInvoke(BijectionInterceptor.java:77) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.core.MethodContextInterceptor.aroundInvoke(MethodContextInterceptor.java:44) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.async.AsynchronousInterceptor.aroundInvoke(AsynchronousInterceptor.java:52) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.intercept.JavaBeanInterceptor.interceptInvocation(JavaBeanInterceptor.java:185) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.intercept.JavaBeanInterceptor.invoke(JavaBeanInterceptor.java:103) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.xdi.oxauth.service.AppInitializer_$$_javassist_seam_1.reloadConfigurationTimerEvent(AppInitializer_$$_javassist_seam_1.java) INFO | jvm 1 | 2016/03/11 21:35:41 | at sun.reflect.GeneratedMethodAccessor595.invoke(Unknown Source) INFO | jvm 1 | 2016/03/11 21:35:41 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.lang.reflect.Method.invoke(Method.java:606) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.util.Reflections.invoke(Reflections.java:22) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.util.Reflections.invokeAndWrap(Reflections.java:144) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.Component.callComponentMethod(Component.java:2275) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.core.Events.raiseEvent(Events.java:85) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.async.AsynchronousEvent$1.process(AsynchronousEvent.java:33) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.async.Asynchronous$ContextualAsynchronousRequest.run(Asynchronous.java:80) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.async.AsynchronousEvent.execute(AsynchronousEvent.java:27) INFO | jvm 1 | 2016/03/11 21:35:41 | at org.jboss.seam.async.ThreadPoolDispatcher$RunnableAsynchronous.run(ThreadPoolDispatcher.java:142) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) INFO | jvm 1 | 2016/03/11 21:35:41 | at java.lang.Thread.run(Thread.java:745)

By matt dillenkoffer user 11 Mar 2016 at 3:40 p.m. CST

matt dillenkoffer gravatar
One thing to note which I'm not sure if this matters or not but the password attribute in ApacheDS is **userPassword** not pwd. Wasn't sure if that might possibly need to be mapped or not. I wasn't trying to bring it to the gluu side but if gluu is trying to query an attribute that isn't there that might be a problem.

By Aliaksandr Samuseu staff 11 Mar 2016 at 5:40 p.m. CST

Aliaksandr Samuseu gravatar
> One thing to note which I'm not sure if this matters or not but the password attribute in ApacheDS is userPassword not pwd. Wasn't sure if that might possibly need to be mapped or not. I wasn't trying to bring it to the gluu side but if gluu is trying to query an attribute that isn't there that might be a problem. That doesn't matter, CR doesn't need to pull passwords from backend, it just consolidates attributes from different sources at one place (internal LDAP directory by default) to be able to send them to remote parties after that. Actual verification of user credentials happens with LDAP Bind operation against the backend, in the end. I'll try to install that package tomorrow and reproduce the issue.

By Aliaksandr Samuseu staff 11 Mar 2016 at 5:43 p.m. CST

Aliaksandr Samuseu gravatar
Could you provide screenshots of list of attributes your are pulling, and your mapping table?

By Aliaksandr Samuseu staff 12 Mar 2016 at 8:41 a.m. CST

Aliaksandr Samuseu gravatar
Hi, Matt. I'm sorry about missing your posts in previous ticket, we have an issue with notifications atm. Answering your question there: > I even found the oxIDPAuthentication value in Gluu's openDJ ldap which has these values which for some reason the BaseDN value is not being used and the original o=gluu is being used {"type":"auth","name":"auth_ldap_server","level":0,"priority":0,"enabled":true,"version":1,"fields":[],"config":"{\"configId\":\"auth_ldap_server\",\"bindDN\":\"uid=admin,ou=system\",\"bindPassword\":\"lc0Oex7qiYA=\",\"servers\":[\"10.1.138.18:1024\"],\"maxConnections\":1000,\"useSSL\":false,\"baseDNs\":[\"ou=users,dc=trio,dc=giab\"],\"primaryKey\":\"cn\",\"localPrimaryKey\":\"cn\",\"useAnonymousBind\":false,\"enabled\":true,\"version\":0}"} Sorry, how comes? It's your base DN there, not `o=gluu`

By Aliaksandr Samuseu staff 12 Mar 2016 at 3:12 p.m. CST

Aliaksandr Samuseu gravatar
Matt, I couldn't reproduce it for deb gluu-server-2.4.2 1-1 package using my usual test setup. So my question holds: > Could you provide screenshots of list of attributes your are pulling, and your mapping table? Also, did you change default set of attributes defined on the "Attributes" page, like activating some of them, or adding custom attributes?

By matt dillenkoffer user 14 Mar 2016 at 10 a.m. CDT

matt dillenkoffer gravatar
Did I change anything on the Attributes page? No. I have an updated link for the screenshots below.... this one should work.

By Aliaksandr Samuseu staff 14 Mar 2016 at 10:50 a.m. CDT

Aliaksandr Samuseu gravatar
Hi, Matt. Understood, thanks for pictures. I just wanted to make sure you don't pull any binary attributes (the feature was introduced recently and I thought some strange bug could be tied to it). I can't think of any way to help you at the moment, unfortunately. I can't reproduce the issue, so your best shot now will probably be to try to narrow it down to some specific configuration action that triggers that [possible] bug in your case, and report it. We don't see any other reports of such issue from other users currently, so it may be something very specific to your setup. Feel free to update us on your future findings.

By matt dillenkoffer user 14 Mar 2016 at 10:52 a.m. CDT

matt dillenkoffer gravatar
I am going to run through the install and setup process on CentOS, if I can still reproduce it I will try to detail my actions step by step in as much detail as possible and send it on to you guys, maybe you will be able to identify what I'm doing wrong if that is the case. I'll be in touch shortly. Thanks

By Aliaksandr Samuseu staff 14 Mar 2016 at 10:54 a.m. CDT

Aliaksandr Samuseu gravatar
Just one last suggestion: have you tried restarting tomcat service from inside the container? With something like `# service tomcat restart`? I.e. not with `# service gluu-server-2.4.2 restart` from outside of it, but **just** the tomcat alone.

By matt dillenkoffer user 14 Mar 2016 at 1:11 p.m. CDT

matt dillenkoffer gravatar
The tomcat restart didn't help. On CentOS I get the exact same error... INFO | jvm 1 | 2016/03/14 13:49:44 | 2016-03-14 13:49:44,036 ERROR [org.gluu.site.ldap.LDAPConnectionProvider] Failed to create connection pool with properties: {baseDNs=o=gluu, certsDir=/etc/certs, useSSL=false, configurationEntryDN=ou=oxauth,ou=configuration,inum=@!4569.ECE8.038E.4EE5!0002!45C8.BD52,ou=appliances,o=gluu, binaryAttributes=objectGUID, servers=10.1.138.18:1024, confDir=, maxconnections=10} INFO | jvm 1 | 2016/03/14 13:49:44 | LDAPException(resultCode=49 (invalid credentials), errorMessage='INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user : INFO | jvm 1 | 2016/03/14 13:49:44 | org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:669) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:442) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:216) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.lang.Thread.run(Thread.java:745) INFO | jvm 1 | 2016/03/14 13:49:44 | INFO | jvm 1 | 2016/03/14 13:49:44 | INFO | jvm 1 | 2016/03/14 13:49:44 | BindRequest = INFO | jvm 1 | 2016/03/14 13:49:44 | MessageType : BIND_REQUEST INFO | jvm 1 | 2016/03/14 13:49:44 | Message ID : 1 INFO | jvm 1 | 2016/03/14 13:49:44 | BindRequest INFO | jvm 1 | 2016/03/14 13:49:44 | Version : '3' INFO | jvm 1 | 2016/03/14 13:49:44 | Name : anonymous INFO | jvm 1 | 2016/03/14 13:49:44 | ', diagnosticMessage='INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user : INFO | jvm 1 | 2016/03/14 13:49:44 | org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:669) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:442) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:216) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.lang.Thread.run(Thread.java:745) INFO | jvm 1 | 2016/03/14 13:49:44 | INFO | jvm 1 | 2016/03/14 13:49:44 | INFO | jvm 1 | 2016/03/14 13:49:44 | BindRequest = INFO | jvm 1 | 2016/03/14 13:49:44 | MessageType : BIND_REQUEST INFO | jvm 1 | 2016/03/14 13:49:44 | Message ID : 1 INFO | jvm 1 | 2016/03/14 13:49:44 | BindRequest INFO | jvm 1 | 2016/03/14 13:49:44 | Version : '3' INFO | jvm 1 | 2016/03/14 13:49:44 | Name : anonymous INFO | jvm 1 | 2016/03/14 13:49:44 | ') INFO | jvm 1 | 2016/03/14 13:49:44 | at com.unboundid.ldap.sdk.LDAPConnection.bind(LDAPConnection.java:1837) INFO | jvm 1 | 2016/03/14 13:49:44 | at com.unboundid.ldap.sdk.LDAPConnectionPool.createConnection(LDAPConnectionPool.java:666) INFO | jvm 1 | 2016/03/14 13:49:44 | at com.unboundid.ldap.sdk.LDAPConnectionPool.<init>(LDAPConnectionPool.java:562) INFO | jvm 1 | 2016/03/14 13:49:44 | at com.unboundid.ldap.sdk.LDAPConnectionPool.<init>(LDAPConnectionPool.java:458) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.gluu.site.ldap.LDAPConnectionProvider.init(LDAPConnectionProvider.java:113) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.gluu.site.ldap.LDAPConnectionProvider.<init>(LDAPConnectionProvider.java:59) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.xdi.service.ldap.LdapConnectionService.<init>(LdapConnectionService.java:21) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.xdi.oxauth.service.AppInitializer.createConnectionProvider(AppInitializer.java:335) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.xdi.oxauth.service.AppInitializer.createBindConnectionProvider(AppInitializer.java:341) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.xdi.oxauth.service.AppInitializer.createAuthConnectionProviders(AppInitializer.java:300) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.xdi.oxauth.service.AppInitializer.createAuthConnectionProviders(AppInitializer.java:282) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.xdi.oxauth.service.AppInitializer.recreateLdapAuthEntryManagers(AppInitializer.java:248) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.xdi.oxauth.service.AppInitializer.reloadConfiguration(AppInitializer.java:179) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.xdi.oxauth.service.AppInitializer.reloadConfigurationTimerEvent(AppInitializer.java:165) INFO | jvm 1 | 2016/03/14 13:49:44 | at sun.reflect.GeneratedMethodAccessor590.invoke(Unknown Source) INFO | jvm 1 | 2016/03/14 13:49:44 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.lang.reflect.Method.invoke(Method.java:606) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.util.Reflections.invoke(Reflections.java:22) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.intercept.RootInvocationContext.proceed(RootInvocationContext.java:32) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:56) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.transaction.RollbackInterceptor.aroundInvoke(RollbackInterceptor.java:28) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.core.BijectionInterceptor.aroundInvoke(BijectionInterceptor.java:77) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.core.MethodContextInterceptor.aroundInvoke(MethodContextInterceptor.java:44) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.async.AsynchronousInterceptor.aroundInvoke(AsynchronousInterceptor.java:52) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.intercept.JavaBeanInterceptor.interceptInvocation(JavaBeanInterceptor.java:185) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.intercept.JavaBeanInterceptor.invoke(JavaBeanInterceptor.java:103) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.xdi.oxauth.service.AppInitializer_$$_javassist_seam_1.reloadConfigurationTimerEvent(AppInitializer_$$_javassist_seam_1.java) INFO | jvm 1 | 2016/03/14 13:49:44 | at sun.reflect.GeneratedMethodAccessor589.invoke(Unknown Source) INFO | jvm 1 | 2016/03/14 13:49:44 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.lang.reflect.Method.invoke(Method.java:606) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.util.Reflections.invoke(Reflections.java:22) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.util.Reflections.invokeAndWrap(Reflections.java:144) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.Component.callComponentMethod(Component.java:2275) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.core.Events.raiseEvent(Events.java:85) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.async.AsynchronousEvent$1.process(AsynchronousEvent.java:33) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.async.Asynchronous$ContextualAsynchronousRequest.run(Asynchronous.java:80) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.async.AsynchronousEvent.execute(AsynchronousEvent.java:27) INFO | jvm 1 | 2016/03/14 13:49:44 | at org.jboss.seam.async.ThreadPoolDispatcher$RunnableAsynchronous.run(ThreadPoolDispatcher.java:142) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) INFO | jvm 1 | 2016/03/14 13:49:44 | at java.lang.Thread.run(Thread.java:745)

By matt dillenkoffer user 14 Mar 2016 at 1:27 p.m. CDT

matt dillenkoffer gravatar
I'll try to outline my steps after Cache Refresh is configured and add a screen shot but there's not a lot of places I can go wrong after cache refresh but hopefully you guys will see something. Cache Refresh is working I can see my users in the Manage Users section of Gluu, now... 1) Navigate to Manage Authentication 2) Update Name, BindDn, Server, BaseDN update Bind Password 3) Test Ldap, see successful 4) Hit update, then watch the stacktrace i posted above flow through a few seconds later

By matt dillenkoffer user 14 Mar 2016 at 1:41 p.m. CDT

matt dillenkoffer gravatar
Does anything about my setup description raise any red flags that might point to what's causing my problem?

By matt dillenkoffer user 14 Mar 2016 at 1:48 p.m. CDT

matt dillenkoffer gravatar
And why is it that the baseDNs value in the error keeps saying INFO | jvm 1 | 2016/03/14 13:49:44 | 2016-03-14 13:49:44,034 ERROR [org.gluu.site.ldap.LDAPConnectionProvider] Failed to create connection pool with properties: {**baseDNs=o=gluu**, certsDir=/etc/certs, useSSL=false, configurationEntryDN=ou=oxauth,ou=configuration,inum=@!4569.ECE8.038E.4EE5!0002!45C8.BD52,ou=appliances,o=gluu, binaryAttributes=objectGUID, servers=10.1.138.18:1024, confDir=, maxconnections=5} This seems like the root of the problem because baseDNs should be **baseDNs=ou=users,dc=trio,dc=giab**

By matt dillenkoffer user 14 Mar 2016 at 1:55 p.m. CDT

matt dillenkoffer gravatar
Oh and BTW this is gluu 2.4.2 1-3

By Aliaksandr Samuseu staff 14 Mar 2016 at 1:56 p.m. CDT

Aliaksandr Samuseu gravatar
> Does anything about my setup description raise any red flags that might point to what's causing my problem? Not really, seems legit. Just one thing: are you sure that on port 1024 you don't have LDAPS listener? May be you need to enable SSL for that connection in Manage authentication? > And why is it that the baseDNs value in the error keeps saying That may or may not be the issue, as Gluu stores its own stuff (configuration, session states, user data etc) in LDAP and access it all the time. This could mean it can't access it's own data it needs to continue (not related directly to CR/authentication). Why? I don't know, I don't see anything like that in my test instance. Thanks for your efforts, we'll try to look into it a bit more..

By Aliaksandr Samuseu staff 14 Mar 2016 at 1:59 p.m. CDT

Aliaksandr Samuseu gravatar
Sorry if you've already mentioned it: do you have your backend LDAP and Gluu instance installed on the same, or different hosts? What are their ip addresses (I believe 10.1.138.18 is the backend)? Update: I see from CR pictures your instance is at 10.1.138.20. So they are on 2 separate physical/virtual boxes, is it correct?

By Aliaksandr Samuseu staff 14 Mar 2016 at 2:12 p.m. CDT

Aliaksandr Samuseu gravatar
> Failed to create connection pool with properties: {baseDNs=o=gluu, certsDir=/etc/certs, useSSL=false, configurationEntryDN=ou=oxauth,ou=configuration,inum=@!4569.ECE8.038E.4EE5!0002!45C8.BD52,ou=appliances,o=gluu, binaryAttributes=objectGUID, servers=10.1.138.18:1024, confDir=, maxconnections=10} INFO | jvm 1 | 2016/03/14 13:49:44 | LDAPException(resultCode=49 (invalid credentials) That record could mean just that: "Using o=gluu for looking up oxauth configuration entry ou=oxauth,ou=configuration..; connecting to 10.1.138.18:1024" etc etc. Don't know for sure, I think log entries' format has been changed recently What you really have to verify is that: >(invalid credentials) plus the possibility you try to connect to SSL-enabled listener without SSL enabled.

By matt dillenkoffer user 14 Mar 2016 at 2:16 p.m. CDT

matt dillenkoffer gravatar
How can you think there is even a possibility that this might be the problem? You realize Cache Refresh is connected to the same LDAP server on port 1024 with SSL disabled and it's is successfully importing the users. So I don't know why you think 1024 is an SSL only port. I can also connect to my LDAP server from an LDAP browser over port 1024 with SSL disabled and I can browse the whole directory just fine.

By Aliaksandr Samuseu staff 14 Mar 2016 at 2:22 p.m. CDT

Aliaksandr Samuseu gravatar
Have you tried to monitor what happens on the wire with something like Wireshark when you try to authenticate to backend? Can you provide your capture to us?

By matt dillenkoffer user 14 Mar 2016 at 2:31 p.m. CDT

matt dillenkoffer gravatar
Will do let me grab that

By matt dillenkoffer user 14 Mar 2016 at 3:02 p.m. CDT

matt dillenkoffer gravatar
Ok here's two captures. stacktraceAfterClickingUpdatePacket.pcapng is the capture of what happens after I click update on the Manage Authentication page. PacketsWhenLoggingIn.pcapng is the capture of what happens when I try to login with one of my users that were in my Legacy LDAP. Notice in this capture that LDAP is actually sending user information back to GLUU even though Gluu says authentication fails. These were both captured in wireshark

By matt dillenkoffer user 14 Mar 2016 at 3:33 p.m. CDT

matt dillenkoffer gravatar
From the stacktraceAfterClickingUpdatePacket I see this response from ldap, as if Gluu is trying to do an anonymous bind.... 1GINVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user : org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:669) at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:442) at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:216) at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) at java.lang.Thread.run(Thread.java:745) BindRequest = MessageType : BIND_REQUEST Message ID : 1 BindRequest Version : '3' Name : anonymous

By Aliaksandr Samuseu staff 14 Mar 2016 at 4:24 p.m. CDT

Aliaksandr Samuseu gravatar
Thanks, Matt. Will look at your capture tomorrow.

By Aliaksandr Samuseu staff 14 Mar 2016 at 4:37 p.m. CDT

Aliaksandr Samuseu gravatar
Btw, Matt: how do you install the package? Usual yum/apt-get way? Or do you download it manually, then install? Are you sure you are getting package from the public repo, not a dev one?

By matt dillenkoffer user 15 Mar 2016 at 8:08 a.m. CDT

matt dillenkoffer gravatar
I followed this guide for Ubuntu verbatim https://gluu.org/docs/deployment/ubuntu/ Installing Gluu Server Download and install Gluu Server by the following commands. Use the .deb installation to perform a base chroot installation with the following Gluu Server Base Ubuntu requirements. As an alternative, use our Gluu repository for Ubuntu Trusty (14.04): **# echo "deb https://repo.gluu.org/ubuntu/ trusty main" > /etc/apt/sources.list.d/gluu-repo.list # curl https://repo.gluu.org/ubuntu/gluu-apt.key | apt-key add - # apt-get update # apt-get install gluu-server-2.4.2** Configuring Gluu Server After both the retrieval, and the installation of the Gluu Server software package start the Gluu Server, and login into the local chroot environment to configure the Gluu Server. These are the single steps: **# /etc/init.d/gluu-server-2.4.2 start # /etc/init.d/gluu-server-2.4.2 login # cd /install/community-edition-setup/ #./setup.py** And I followed this guide for CentOS 7 https://gluu.org/docs/deployment/centos7/ CentOS 7 Installation Guide Installing Gluu Server Download and install Gluu Server by the following commands. Use the .rpm installation to perform a base chroot installation with the following Gluu Server Base CentOS requirements. As an alternative, use our Gluu repository for CentOS 7: **# wget https://repo.gluu.org/centos/Gluu-centos7.repo -O /etc/yum.repos.d/Gluu.repo # wget https://repo.gluu.org/centos/RPM-GPG-KEY-GLUU -O /etc/pki/rpm-gpg/RPM-GPG-KEY-GLUU # rpm --import /etc/pki/rpm-gpg/RPM-GPG-KEY-GLUU # yum clean all # yum install gluu-server-2.4.1** Configuring Gluu Server After both the retrieval, and the installation of the Gluu Server software package start the Gluu Server, and login into the local chroot environment to configure the Gluu Server. These are the single steps: **# /sbin/gluu-serverd-2.4.1 start # /sbin/gluu-serverd-2.4.1login # cd /install/community-edition-setup/ #./setup.py**

By matt dillenkoffer user 15 Mar 2016 at 9:19 a.m. CDT

matt dillenkoffer gravatar
So I went crazy this morning and installed OpenDJ and did all my testing against that LDAP server and everything works. So there is definitely a problem with Gluu Authentication and ApacheDS, but Gluu Cache Refresh and ApacheDS works just fine. Thanks for your time and efforts assisting me on this issue.

By Aliaksandr Samuseu staff 15 Mar 2016 at 9:53 a.m. CDT

Aliaksandr Samuseu gravatar
Hi, Matt. Thanks for you update. That's quite unusual to see such difference in behaviour, depending on backend. Could you please share your ApacheDS's config files with us, so we could try to repro this?

By Aliaksandr Samuseu staff 15 Mar 2016 at 10:23 a.m. CDT

Aliaksandr Samuseu gravatar
It seems all its settings are stored in one file, according to [doc](https://directory.apache.org/apacheds/basic-ug/1.4.1-changing-server-port.html): > All the ApacheDS configuration is stored as a LDIF file, and can be modified either using a text editor... > .../instances/default/conf/config.ldif

By matt dillenkoffer user 15 Mar 2016 at 10:30 a.m. CDT

matt dillenkoffer gravatar
Interestingly the ApacheDS instance that comes from our build has an empty conf folder. After the test worked with openDJ I tested against an ApacheDS 2.0.0 out of the box instance and that worked too. Arg! This hasn't been my month. Here I have attached the entire ldap folder that gets generated by our build (ldap.zip). It's usable by our application and by Apache Directory Studio so I'm not sure what's missing that makes gluu not happy.

By matt dillenkoffer user 15 Mar 2016 at 12:27 p.m. CDT

matt dillenkoffer gravatar
Let me ask you this does LDAP have to support a SASL mechanism for Gluu authentication to work?

By matt dillenkoffer user 16 Mar 2016 at 11:04 a.m. CDT

matt dillenkoffer gravatar
Our ApacheDS is configured programattically, if you want to reproduce it you can run this class's main method and it should start apache ds with a gridadmin user in it which will work for Cache Refresh but fail when you try to configure Authentication with that stack trace I have posted previously. Begin Class.... package com.inventrio.idm.ldap.internal; import com.inventrio.idm.ldap.LDAPServer; import org.apache.directory.api.ldap.model.entry.Entry; import org.apache.directory.api.ldap.model.exception.LdapException; import org.apache.directory.api.ldap.model.name.Dn; import org.apache.directory.api.ldap.model.schema.SchemaManager; import org.apache.directory.api.ldap.model.schema.registries.SchemaLoader; import org.apache.directory.api.ldap.schema.extractor.SchemaLdifExtractor; import org.apache.directory.api.ldap.schema.loader.LdifSchemaLoader; import org.apache.directory.api.ldap.schema.manager.impl.DefaultSchemaManager; import org.apache.directory.api.util.exception.Exceptions; import org.apache.directory.server.constants.ServerDNConstants; import org.apache.directory.server.core.DefaultDirectoryService; import org.apache.directory.server.core.api.CacheService; import org.apache.directory.server.core.api.DirectoryService; import org.apache.directory.server.core.api.DnFactory; import org.apache.directory.server.core.api.InstanceLayout; import org.apache.directory.server.core.api.partition.Partition; import org.apache.directory.server.core.api.schema.SchemaPartition; import org.apache.directory.server.core.authn.SimpleAuthenticator; import org.apache.directory.server.core.partition.impl.btree.jdbm.JdbmIndex; import org.apache.directory.server.core.partition.impl.btree.jdbm.JdbmPartition; import org.apache.directory.server.core.partition.ldif.LdifPartition; import org.apache.directory.server.i18n.I18n; import org.apache.directory.server.ldap.LdapServer; import org.apache.directory.server.protocol.shared.transport.TcpTransport; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import java.io.File; import java.nio.charset.Charset; import java.util.HashSet; import java.util.List; import java.util.Set; /** * Created by mdillenk on 3/16/16. */ public class TestApacheDSServer { public boolean isAvailable() { return server.isStarted(); } public DirectoryService getDirectoryService() { return this.service; } public void shutdown() { server.stop(); try { service.shutdown(); } catch (Exception e) { e.printStackTrace(); } } /** * The directory service */ private DirectoryService service; /** * The LDAP server */ private LdapServer server; private Logger logger; private String port; private String partition; private String dn; private String dataDir; private String ldapadminpassword; private boolean createGridAdmin = false; private String gridadminusername; private String gridadminpassword; /** * Add a new partition to the server * * @param partitionId The partition Id * @param partitionDn The partition DN * @param dnFactory the DN factory * @return The newly added partition * @throws Exception If the partition can't be added */ private Partition addPartition(String partitionId, String partitionDn, DnFactory dnFactory) throws Exception { // Create a new partition with the given partition id JdbmPartition partition = new JdbmPartition(service.getSchemaManager(), dnFactory); partition.setId(partitionId); partition.setPartitionPath(new File(service.getInstanceLayout().getPartitionsDirectory(), partitionId).toURI()); partition.setSuffixDn(new Dn(partitionDn)); service.addPartition(partition); return partition; } /** * Add a new set of index on the given attributes * * @param partition The partition on which we want to add index * @param attrs The list of attributes to index */ private void addIndex(Partition partition, String... attrs) { // Index some attributes on the apache partition Set indexedAttributes = new HashSet(); for (String attribute : attrs) { indexedAttributes.add(new JdbmIndex(attribute, false)); } ((JdbmPartition) partition).setIndexedAttributes(indexedAttributes); } /** * initialize the schema manager and add the schema partition to diectory service * * @throws Exception if the schema LDIF files are not found on the classpath */ private void initSchemaPartition() throws Exception { InstanceLayout instanceLayout = service.getInstanceLayout(); File schemaPartitionDirectory = new File(instanceLayout.getPartitionsDirectory(), "schema"); // Extract the schema on disk (a brand new one) and load the registries if (schemaPartitionDirectory.exists()) { System.out.println("schema partition already exists, skipping schema extraction"); } else { SchemaLdifExtractor extractor = new DefaultSchemaLdifExtractor(instanceLayout.getPartitionsDirectory()); extractor.extractOrCopy(); } SchemaLoader loader = new LdifSchemaLoader(schemaPartitionDirectory); SchemaManager schemaManager = new DefaultSchemaManager(loader); // We have to load the schema now, otherwise we won't be able // to initialize the Partitions, as we won't be able to parse // and normalize their suffix Dn schemaManager.loadAllEnabled(); List<Throwable> errors = schemaManager.getErrors(); if (errors.size() != 0) { throw new Exception(I18n.err(I18n.ERR_317, Exceptions.printErrors(errors))); } service.setSchemaManager(schemaManager); // Init the LdifPartition with schema LdifPartition schemaLdifPartition = new LdifPartition(schemaManager, service.getDnFactory()); schemaLdifPartition.setPartitionPath(schemaPartitionDirectory.toURI()); // The schema partition SchemaPartition schemaPartition = new SchemaPartition(schemaManager); schemaPartition.setWrappedPartition(schemaLdifPartition); service.setSchemaPartition(schemaPartition); } /** * Initialize the server. It creates the partition, adds the index, and * injects the context entries for the created partitions. * * @param workDir the directory to be used for storing the data * @throws Exception if there were some problems while initializing the system */ private void initDirectoryService(File workDir) throws Exception { // Initialize the LDAP service service = new DefaultDirectoryService(); service.setInstanceLayout(new InstanceLayout(workDir)); CacheService cacheService = new CacheService(); cacheService.initialize(service.getInstanceLayout()); service.setCacheService(cacheService); // first load the schema initSchemaPartition(); // then the system partition // this is a MANDATORY partition // DO NOT add this via addPartition() method, trunk code complains about duplicate partition // while initializing JdbmPartition systemPartition = new JdbmPartition(service.getSchemaManager(), service.getDnFactory()); systemPartition.setId("system"); systemPartition.setPartitionPath(new File(service.getInstanceLayout().getPartitionsDirectory(), systemPartition.getId()).toURI()); systemPartition.setSuffixDn(new Dn(ServerDNConstants.SYSTEM_DN)); systemPartition.setSchemaManager(service.getSchemaManager()); // mandatory to call this method to set the system partition // Note: this system partition might be removed from trunk service.setSystemPartition(systemPartition); // Disable the ChangeLog system service.getChangeLog().setEnabled(false); service.setDenormalizeOpAttrsEnabled(true); // Now we can create as many partitions as we need // Create some new partitions named 'foo', 'bar' and 'apache'. Partition inventrioPartition = addPartition(partition, dn, service.getDnFactory()); // Index some attributes on the apache partition addIndex(inventrioPartition, "objectClass", "ou", "uid"); // And start the service service.startup(); // Inject the context entry for partition if it does not already exist try { service.getAdminSession().lookup(inventrioPartition.getSuffixDn()); } catch (LdapException lnnfe) { Dn inventrioDN = new Dn(dn); Entry entryInventrio = service.newEntry(inventrioDN); entryInventrio.add("objectClass", "top", "domain", "extensibleObject"); entryInventrio.add("dc", "department"); service.getAdminSession().add(entryInventrio); } class SimpleAuthenticatorFacade extends SimpleAuthenticator { @Override public String createDigestedPassword(final String algorithm, final byte[] password) throws IllegalArgumentException { return super.createDigestedPassword(algorithm, password); } } SimpleAuthenticatorFacade auth = new SimpleAuthenticatorFacade(); String encPass = auth.createDigestedPassword("SHA", ldapadminpassword.getBytes(Charset.forName("UTF-8"))); Dn dnAdmin = new Dn("cn=admin," + dn); try { service.getAdminSession().lookup(dnAdmin); } catch (LdapException lnnfe) { Entry entryAdmin = service.newEntry(dnAdmin); entryAdmin.add("objectClass", "simpleSecurityObject", "organizationalRole"); entryAdmin.add("cn", "admin"); entryAdmin.add("userPassword", encPass.getBytes(Charset.forName("UTF-8"))); entryAdmin.add("description", "LDAP administrator"); service.getAdminSession().add(entryAdmin); } Dn dnGroup = new Dn("ou=users," + dn); try { service.getAdminSession().lookup(dnGroup); } catch (LdapException lnnfe) { Entry entryGroup = service.newEntry(dnGroup); entryGroup.add("objectClass", "organizationalUnit"); entryGroup.add("ou", "users"); entryGroup.add("description", "The users at " + partition); service.getAdminSession().add(entryGroup); } String gridadminencPass = auth.createDigestedPassword("SHA", gridadminpassword.getBytes(Charset.forName("UTF-8"))); if (createGridAdmin) { Dn dnGridAdmin = new Dn("cn=" + gridadminusername + ",ou=users," + dn); try { service.getAdminSession().lookup(dnGridAdmin); } catch (LdapException lnnfe) { Entry entryGridAdmin = service.newEntry(dnGridAdmin); entryGridAdmin.add("objectClass", "organizationalPerson", "person", "inetOrgPerson", "top"); entryGridAdmin.add("cn", gridadminusername); entryGridAdmin.add("sn", gridadminusername); entryGridAdmin.add("givenName", gridadminusername); entryGridAdmin.add("mail", gridadminusername + "@giab.dev"); entryGridAdmin.add("uid", gridadminusername); entryGridAdmin.add("userPassword", gridadminencPass.getBytes(Charset.forName("UTF-8"))); service.getAdminSession().add(entryGridAdmin); } } // We are all done ! } public TestApacheDSServer(String port, String partition, String dn, String dataDir, String ldapadminpassword) throws Exception { this(port, partition, dn, dataDir, ldapadminpassword, "false", "", ""); } public TestApacheDSServer(String port, String partition, String dn, String dataDir, String ldapadminpassword, String createGridAdminString, String gridadminusername, String gridadminpassword) throws Exception { logger = LoggerFactory.getLogger(getClass()); this.port = port; this.partition = partition; this.dn = dn; this.dataDir = dataDir; this.ldapadminpassword = ldapadminpassword; if (Boolean.parseBoolean(createGridAdminString)) { this.createGridAdmin = true; } else this.createGridAdmin = false; this.gridadminpassword = gridadminpassword; this.gridadminusername = gridadminusername; logger.debug("Successfully Initialized the Identity Management Service LDAP."); initDirectoryService(new File(dataDir)); startServer(); } /** * starts the LdapServer * * @throws Exception */ public void startServer() throws Exception { server = new LdapServer(); int serverPort = Integer.valueOf(port); server.setTransports(new TcpTransport(serverPort)); server.setDirectoryService(service); server.start(); } /** * Main class. * * @param args Not used. */ public static void main(String[] args) { try { File workDir = new File(System.getProperty("java.io.tmpdir") + "/server-work"); workDir.mkdirs(); // Create the server TestApacheDSServer ads = new TestApacheDSServer("1024", "inventrio", "dc=trio,dc=giab", workDir.getAbsolutePath(), "secret", "true", "gridadmin", "inventrio"); // Read an entry Entry result = ads.service.getAdminSession().lookup(new Dn("dc=trio,dc=giab")); // And print it if available System.out.println("Found entry : " + result); // optionally we can start a server too ads.startServer(); } catch (Exception e) { // Ok, we have something wrong going on ... e.printStackTrace(); } } } END Class... Here is a list of my dependencies defined... you probably only need the apacheDS ones.... <dependencies> <dependency> <groupId>org.apache.directory.server</groupId> <artifactId>apacheds-core</artifactId> <version>2.0.0-M21</version> <exclusions> <exclusion> <artifactId>slf4j-api</artifactId> <groupId>org.slf4j</groupId> </exclusion> <exclusion> <artifactId>bcprov-jdk15</artifactId> <groupId>bouncycastle</groupId> </exclusion> </exclusions> </dependency> <dependency> <artifactId>bcprov-jdk15</artifactId> <groupId>org.bouncycastle</groupId> <version>1.46</version> </dependency> <dependency> <groupId>org.apache.directory.server</groupId> <artifactId>apacheds-protocol-ldap</artifactId> <version>2.0.0-M21</version> </dependency> <dependency> <groupId>org.apache.directory.server</groupId> <artifactId>apacheds-ldif-partition</artifactId> <version>2.0.0-M21</version> </dependency> <dependency> <groupId>org.apache.directory.server</groupId> <artifactId>apacheds-jdbm-partition</artifactId> <version>2.0.0-M21</version> </dependency> <dependency> <groupId>org.apache.directory.server</groupId> <artifactId>apacheds-service</artifactId> <version>2.0.0-M21</version> </dependency> <dependency> <groupId>org.osgi</groupId> <artifactId>org.osgi.core</artifactId> <version>4.2.0</version> <scope>compile</scope> </dependency> <dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-api</artifactId> </dependency> <!-- concrete Log4J Implementation for SLF4J API --> <dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-log4j12</artifactId> </dependency> <dependency> <groupId>com.inventrio.tpl</groupId> <artifactId>inventrio-tpl-spring</artifactId> <type>pom</type> </dependency> </dependencies>

By matt dillenkoffer user 16 Mar 2016 at 11:10 a.m. CDT

matt dillenkoffer gravatar
I think the problem is that there is some feature missing that Gluu requires to validate authentication against LDAP. That feature must be there in the out of the box configuration but not there by default when starting this Embedded instance. If I knew what feature needed to be there I could probably added it programmattically in the class I posted above. That's why I was asking about the SASL stuff earlier.

By matt dillenkoffer user 16 Mar 2016 at 11:54 a.m. CDT

matt dillenkoffer gravatar
Does Gluu use the LDAP Simple Authentication mechanism or does something else have to be enabled for authentication to work?

By Aliaksandr Samuseu staff 16 Mar 2016 at 11:58 a.m. CDT

Aliaksandr Samuseu gravatar
I've passed your question to dev team. While we are waiting for the answer, could we get back to your captures again? I gave it another look, and now I see `PacketsWhenLoggingIn.pcapng` is incomplete for some reason. It successfully looks up the user entry you were trying to log in with (`cn=vitality_admin,..`), but what had to follow next is a bind attempt to it using password you put into login form. This final step is totally missed. Are you sure you provided the full capture?

By matt dillenkoffer user 16 Mar 2016 at noon CDT

matt dillenkoffer gravatar
Let me try again and see...

By matt dillenkoffer user 16 Mar 2016 at 2:14 p.m. CDT

matt dillenkoffer gravatar
That capture looked to be complete I ran several tests to capture a new one and it always came back Identical. BUT I may have stumbled onto something. When clicking update after configuring authentication I always see this stack trace... INFO | jvm 1 | 2016/03/14 14:11:14 | 2016-03-14 14:11:14,015 ERROR [org.gluu.site.ldap.LDAPConnectionProvider] Failed to create connection pool with properties: {baseDNs=o=gluu, certsDir=/etc/certs, useSSL=false, configurationEntryDN=ou=oxauth,ou=configuration,inum=@!4569.ECE8.038E.4EE5!0002!45C8.BD52,ou=appliances,o=gluu, binaryAttributes=objectGUID, servers=10.1.138.18:1024, confDir=, maxconnections=10} INFO | jvm 1 | 2016/03/14 14:11:14 | LDAPException(resultCode=49 (invalid credentials), errorMessage='INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user : INFO | jvm 1 | 2016/03/14 14:11:14 | org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:671) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:439) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.lang.Thread.run(Thread.java:745) INFO | jvm 1 | 2016/03/14 14:11:14 | INFO | jvm 1 | 2016/03/14 14:11:14 | INFO | jvm 1 | 2016/03/14 14:11:14 | BindRequest = INFO | jvm 1 | 2016/03/14 14:11:14 | MessageType : BIND_REQUEST INFO | jvm 1 | 2016/03/14 14:11:14 | Message ID : 1 INFO | jvm 1 | 2016/03/14 14:11:14 | BindRequest INFO | jvm 1 | 2016/03/14 14:11:14 | Version : '3' INFO | jvm 1 | 2016/03/14 14:11:14 | Name : anonymous INFO | jvm 1 | 2016/03/14 14:11:14 | ', diagnosticMessage='INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user : INFO | jvm 1 | 2016/03/14 14:11:14 | org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:671) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:439) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.lang.Thread.run(Thread.java:745) INFO | jvm 1 | 2016/03/14 14:11:14 | INFO | jvm 1 | 2016/03/14 14:11:14 | INFO | jvm 1 | 2016/03/14 14:11:14 | BindRequest = INFO | jvm 1 | 2016/03/14 14:11:14 | MessageType : BIND_REQUEST INFO | jvm 1 | 2016/03/14 14:11:14 | Message ID : 1 INFO | jvm 1 | 2016/03/14 14:11:14 | BindRequest INFO | jvm 1 | 2016/03/14 14:11:14 | Version : '3' INFO | jvm 1 | 2016/03/14 14:11:14 | Name : anonymous INFO | jvm 1 | 2016/03/14 14:11:14 | ') INFO | jvm 1 | 2016/03/14 14:11:14 | at com.unboundid.ldap.sdk.LDAPConnection.bind(LDAPConnection.java:1837) INFO | jvm 1 | 2016/03/14 14:11:14 | at com.unboundid.ldap.sdk.LDAPConnectionPool.createConnection(LDAPConnectionPool.java:666) INFO | jvm 1 | 2016/03/14 14:11:14 | at com.unboundid.ldap.sdk.LDAPConnectionPool.<init>(LDAPConnectionPool.java:562) INFO | jvm 1 | 2016/03/14 14:11:14 | at com.unboundid.ldap.sdk.LDAPConnectionPool.<init>(LDAPConnectionPool.java:458) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.gluu.site.ldap.LDAPConnectionProvider.init(LDAPConnectionProvider.java:113) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.gluu.site.ldap.LDAPConnectionProvider.<init>(LDAPConnectionProvider.java:59) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.xdi.service.ldap.LdapConnectionService.<init>(LdapConnectionService.java:21) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.xdi.oxauth.service.AppInitializer.createConnectionProvider(AppInitializer.java:335) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.xdi.oxauth.service.AppInitializer.createBindConnectionProvider(AppInitializer.java:341) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.xdi.oxauth.service.AppInitializer.createAuthConnectionProviders(AppInitializer.java:300) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.xdi.oxauth.service.AppInitializer.createAuthConnectionProviders(AppInitializer.java:282) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.xdi.oxauth.service.AppInitializer.recreateLdapAuthEntryManagers(AppInitializer.java:248) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.xdi.oxauth.service.AppInitializer.reloadConfiguration(AppInitializer.java:179) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.xdi.oxauth.service.AppInitializer.reloadConfigurationTimerEvent(AppInitializer.java:165) INFO | jvm 1 | 2016/03/14 14:11:14 | at sun.reflect.GeneratedMethodAccessor545.invoke(Unknown Source) INFO | jvm 1 | 2016/03/14 14:11:14 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.lang.reflect.Method.invoke(Method.java:606) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.util.Reflections.invoke(Reflections.java:22) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.intercept.RootInvocationContext.proceed(RootInvocationContext.java:32) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:56) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.transaction.RollbackInterceptor.aroundInvoke(RollbackInterceptor.java:28) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.core.BijectionInterceptor.aroundInvoke(BijectionInterceptor.java:77) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.core.MethodContextInterceptor.aroundInvoke(MethodContextInterceptor.java:44) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.async.AsynchronousInterceptor.aroundInvoke(AsynchronousInterceptor.java:52) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.intercept.JavaBeanInterceptor.interceptInvocation(JavaBeanInterceptor.java:185) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.intercept.JavaBeanInterceptor.invoke(JavaBeanInterceptor.java:103) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.xdi.oxauth.service.AppInitializer_$$_javassist_seam_1.reloadConfigurationTimerEvent(AppInitializer_$$_javassist_seam_1.java) INFO | jvm 1 | 2016/03/14 14:11:14 | at sun.reflect.GeneratedMethodAccessor544.invoke(Unknown Source) INFO | jvm 1 | 2016/03/14 14:11:14 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.lang.reflect.Method.invoke(Method.java:606) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.util.Reflections.invoke(Reflections.java:22) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.util.Reflections.invokeAndWrap(Reflections.java:144) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.Component.callComponentMethod(Component.java:2275) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.core.Events.raiseEvent(Events.java:85) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.async.AsynchronousEvent$1.process(AsynchronousEvent.java:33) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.async.Asynchronous$ContextualAsynchronousRequest.run(Asynchronous.java:80) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.async.AsynchronousEvent.execute(AsynchronousEvent.java:27) INFO | jvm 1 | 2016/03/14 14:11:14 | at org.jboss.seam.async.ThreadPoolDispatcher$RunnableAsynchronous.run(ThreadPoolDispatcher.java:142) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) INFO | jvm 1 | 2016/03/14 14:11:14 | at java.lang.Thread.run(Thread.java:745) Notice **Name : anonymous** is being used to attempt to bind. My embedded apacheDS doesn't allow for anonymous binds, then I looked at the out of the box instance of ApacheDS and it does allow for anonymous binds. SO it seems that Gluu isn't using the BindDN value that I set on the Manage Authentication section and only tries to bind Anonymously. The reason I came to this conclusion is that I tried to connect to ApacheDS with the studio with an incorrect value and got the same exact stack trace but not for anonymous but the actual users it was trying to login as.... as you see here... From ApacheDirectory Studio The authentication failed - [LDAP: error code 49 - INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user cn=gridadmin,ou=users,dc=trio,dc=giab java.lang.Exception: [LDAP: error code 49 - INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user cn=gridadmin,ou=users,dc=trio,dc=giab: org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user cn=gridadmin,ou=users,dc=trio,dc=giab at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:671) at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:439) at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217) at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) at java.lang.Thread.run(Thread.java:745) BindRequest = MessageType : BIND_REQUEST Message ID : 1 BindRequest Version : '3' Name : 'cn=gridadmin,ou=users,dc=trio,dc=giab' Simple authentication : '(omitted-for-safety)' ] at org.apache.directory.studio.connection.core.io.api.DirectoryApiConnectionWrapper.checkResponse(DirectoryApiConnectionWrapper.java:1278) at org.apache.directory.studio.connection.core.io.api.DirectoryApiConnectionWrapper.access$9(DirectoryApiConnectionWrapper.java:1246) at org.apache.directory.studio.connection.core.io.api.DirectoryApiConnectionWrapper$2.run(DirectoryApiConnectionWrapper.java:448) at org.apache.directory.studio.connection.core.io.api.DirectoryApiConnectionWrapper.runAndMonitor(DirectoryApiConnectionWrapper.java:1173) at org.apache.directory.studio.connection.core.io.api.DirectoryApiConnectionWrapper.doBind(DirectoryApiConnectionWrapper.java:457) at org.apache.directory.studio.connection.core.io.api.DirectoryApiConnectionWrapper.bind(DirectoryApiConnectionWrapper.java:303) at org.apache.directory.studio.connection.core.jobs.CheckBindRunnable.run(CheckBindRunnable.java:79) at org.apache.directory.studio.connection.ui.RunnableContextRunner$1.run(RunnableContextRunner.java:122) at org.eclipse.jface.operation.ModalContext$ModalContextThread.run(ModalContext.java:122) [LDAP: error code 49 - INVALID_CREDENTIALS: Bind failed: ERR_229 Cannot authenticate user cn=gridadmin,ou=users,dc=trio,dc=giab: org.apache.directory.api.ldap.model.exception.LdapAuthenticationException: ERR_229 Cannot authenticate user cn=gridadmin,ou=users,dc=trio,dc=giab at org.apache.directory.server.core.authn.AuthenticationInterceptor.bind(AuthenticationInterceptor.java:671) at org.apache.directory.server.core.DefaultOperationManager.bind(DefaultOperationManager.java:439) at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handleSimpleAuth(BindRequestHandler.java:184) at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:636) at org.apache.directory.server.ldap.handlers.request.BindRequestHandler.handle(BindRequestHandler.java:66) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:193) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217) at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:854) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:542) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1300(DefaultIoFilterChain.java:48) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:943) at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:475) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:429) at java.lang.Thread.run(Thread.java:745) BindRequest = MessageType : BIND_REQUEST Message ID : 1 BindRequest Version : '3' Name : 'cn=gridadmin,ou=users,dc=trio,dc=giab' Simple authentication : '(omitted-for-safety)' ] Since this is a dev instance I don't care if anonymous access is allowed but I would hope that you can assure us that when we are using active directory that the BindDN will work when anonymous access definitely won't be enabled.

By matt dillenkoffer user 17 Mar 2016 at 2:24 p.m. CDT

matt dillenkoffer gravatar
So, no comment on Gluu using anonymous binding vs the BindDN that I entered in the form?

By Aliaksandr Samuseu staff 17 Mar 2016 at 2:54 p.m. CDT

Aliaksandr Samuseu gravatar
Hi, Matt. I'm working on customer's ticket atm, this is a higher priority. Still, no new installations manifest the issue you are facing. Active Directory I was using when tried to reproduce it in my test instance doesn't allow anonymous access by default, so if that was true, I would probably seen the same issue as you. Though I remember some anonymous bind in your captures, the one related to the moment when you click "Update" button. AFAICR, it fails in that capture, though I can't say what purpose it's used for. Regarding the actual capture of the login attempt - it misses a lot of parts the actual bind capture should have. There is even no attempts of the final bind step in that capture, like no SYN TCP packets to the port, nothing. You also said that > Notice in this capture that LDAP is actually sending user information back to GLUU even though Gluu says authentication fails. that's not quite true. Please check attachment "bind-correct.jpg" which shows LDAP capture generated by my instance. You can see there are no anonymous binds happen, and there are a lot of other things happen at the same time. The second picture is your login capture. Not a single Bind operation in it. That doesn't look as a complete capture at all. To speed up things a bit, could you make 2 another captures: 1. Auth attempt against non-working ApacheDS backend 2. Auth attempt against the default setup of ApacheDS which, as you said, is working. Please make sure it's as complete as possible so we could compare them and find any differences. Unless these are provided, I can't guarantee any help any soon, as no other reports exist, and we have other issues too.

By matt dillenkoffer user 17 Mar 2016 at 3:13 p.m. CDT

matt dillenkoffer gravatar
Understood, I will try to get you those captures as soon as I can but now that dev is working I've been re-tasked to work on other tickets. I'll try and get it to you tomorrow if I can. Thanks for the additional info and things to try.

By Aliaksandr Samuseu staff 17 Mar 2016 at 3:26 p.m. CDT

Aliaksandr Samuseu gravatar
I've given another look at your first capture, and now I got it. That anonymous bind access happens in a single place - to access rootDSE (which contain directory's properties that should be accessible by all clients). As I said, your second capture doesn't look complete, but as you can see from mine login capture, during this stage oxAuth accesses rootDSE too (AD allows anonymous access to this object by default). So I can only guess this is your problem - for some reason your custom ApacheDS instance doesn't allow free access to it for requesters.

By Aliaksandr Samuseu staff 17 Mar 2016 at 3:46 p.m. CDT

Aliaksandr Samuseu gravatar
Here is an ApacheDS bug report on [possibly] similar issue back from 2005: [link](https://issues.apache.org/jira/browse/DIRSERVER-360) From [RFC 4513](https://docs.ldap.com/specs/rfc4513.txt): > LDAP servers SHOULD allow all clients -- even those with an anonymous authorization -- to retrieve the 'supportedSASLMechanisms' attribute of the root DSE both before and after the SASL authentication exchange.

By Aliaksandr Samuseu staff 17 Mar 2016 at 3:53 p.m. CDT

Aliaksandr Samuseu gravatar
Not sure is it an issue or not, will ask the dev team about it. As spec doesn't make such access mandatory requirement, it may be one. Still, it would be great if you provided at least this one capture of failed login attempt that shows full inter-exchange, to be sure.

By matt dillenkoffer user 18 Mar 2016 at 10:08 a.m. CDT

matt dillenkoffer gravatar
Ok I've uploaded 4 captures. These 2 are both successful. fridayApacheDSAnonyousDisabledTestLdapPlusClickedUpdate.pcapng capture is when I click Test LDAP then click update on the Manage Authentication form. The fridayApacheDSAnonyousDisabledSuccessfulLogin.pcapng capture is when I login with a test new admin user coming from my ldap. The ApacheDS_EMBEDDED captures with similar names are against my embedded instance with anonymous authentication disabled following the same steps as the first 2 captures and they both should indicate some form of communication failure. I see now that there is definitely a difference between ApacheDS out of the box and embedded because the out of the box instance works with Gluu even with Anonymous Auth turned off.

By Yuriy Movchan staff 18 Mar 2016 at 11:16 a.m. CDT

Yuriy Movchan gravatar
As far as I understand from this discussion and from logs there is one problem with user authentication. For user authentication in our LDAP layer we create anonymous connection pool. Then we uses bind to valide user DN/password. For your case we can need to create authentication pool using admin DN/password and rebind to user DN/password to validate user credentials. After that we need to release this connection. Am I understand problem correctly? Can you test specific oxauth.war/oxtrust.war once I will prepare fix for this?

By matt dillenkoffer user 18 Mar 2016 at 11:28 a.m. CDT

matt dillenkoffer gravatar
That sounds like an accurate description of the problem and I would be happy to test if for you. Additionally on 16 Mar 2016 I posted a TestApacheDSServer class that should allow you to reproduce the EmbeddedApacheDS server where authentication won't work. Then if you find the code // And start the service service.startup(); and change it to // And start the service service.setAllowAnonymousAccess(true); service.startup(); Then authentication with Gluu will work. I'm just saying that to show you an easy way to reproduce the error on your side, but I'll still be happy to verify it on my end as well. Thank you for your help

By Yuriy Movchan staff 18 Mar 2016 at 12:19 p.m. CDT

Yuriy Movchan gravatar
Thank you for your help. I will prepare updated oxauth.war for testing.. And if this will work fine we will make it as part of CE 2.4.3.

By Yuriy Movchan staff 21 Mar 2016 at 4:58 a.m. CDT

Yuriy Movchan gravatar
Hi, Can you try to use http://ox.gluu.org/maven/org/xdi/oxauth-server/2.4.2.1-SNAPSHOT/oxauth-server-2.4.2.1-SNAPSHOT.war this build?

By matt dillenkoffer user 21 Mar 2016 at 2:08 p.m. CDT

matt dillenkoffer gravatar
Yes, np. I will try and test today. I have my environment ripped apart working another ticket but I'm almost done and will then be able to give this new war a test and I'll let you know what happens.

By matt dillenkoffer user 21 Mar 2016 at 4:45 p.m. CDT

matt dillenkoffer gravatar
What's the correct way to swap out the war because swapping it after Gluu's already been started before doesn't seem to be working.

By Aliaksandr Samuseu staff 21 Mar 2016 at 5:11 p.m. CDT

Aliaksandr Samuseu gravatar
Matt, 1. Move into the container 2. `service tomcat stop` 3. Remove **both** oxauth.war and oxauth/ subdirectory in the directory `/opt/tomcat/webapps/` 4. Put new snapshot .war into `/opt/tomcat/webapps/` while renaming it to `oxauth.war` 5. `service tomcat start`

By matt dillenkoffer user 22 Mar 2016 at 8:10 a.m. CDT

matt dillenkoffer gravatar
That's pretty much what I did but I didn't rename it. Lemme try again.

By matt dillenkoffer user 22 Mar 2016 at 8:28 a.m. CDT

matt dillenkoffer gravatar
Your previous steps worked great. I got the server to come back up. AND I was able to setup cache refresh and authentication between gluu and my embedded apacheDS server with anonymous access disabled. To be sure that my apacheDS was configured correctly to reproduce the problem I went through the setup one last time with the original war prior to swapping it out just to make sure I could still reproduce the problem. Once I was sure my apacheDS server was configured correctly to be able to reproduce the problem I swapped out the war as you described and went back through cache refresh and authentication setup and everything worked beautifully. Thank you all for your help and support on this issue! Matt

By Yuriy Movchan staff 22 Mar 2016 at 9 a.m. CDT

Yuriy Movchan gravatar
Thank you for feedback!