[ome-devel] LDAP error logging
McCaughey, Michael J
michael.j.mccaughey at Vanderbilt.Edu
Thu Jan 20 20:30:37 GMT 2011
Josh-
Following up with this, I'm including the relevant portion of the Blitz log for what's happening. The reported LDAP error 32 is fairly generic but implies something is up with DN of either the authenticating user or the user attempting to logon. Is there a way to tell which?
Mike
2011-01-20 14:05:27,946 DEBUG [amework.aop.framework.JdkDynamicAopProxy] (l.Server-9) Creating JDK dynamic proxy: target source is SingletonTargetSource for target object [ome.services.sessions.SessionManagerImpl$7 at 55571f07]
2011-01-20 14:05:27,947 INFO [ ome.services.util.ServiceHandler] (l.Server-9) Executor.doWork -- ome.services.sessions.SessionManagerImpl.executeCheckPasswordRO(mytestuser)
2011-01-20 14:05:27,947 INFO [ ome.services.util.ServiceHandler] (l.Server-9) Args: [null, ome.tools.spring.InternalServiceFactory at 7f1f846b]
2011-01-20 14:05:27,947 DEBUG [.datasource.DataSourceTransactionManager] (l.Server-9) Creating new transaction with name [ome.services.util.Executor$Work.doWork]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly; ''
2011-01-20 14:05:27,954 DEBUG [.datasource.DataSourceTransactionManager] (l.Server-9) Acquired Connection [a JdbcConnectionHandle of a JdbcPooledConnection fromdatasource af64c398-9b42-4ec1-a3bd-b26711c6bc79 in state ACCESSIBLE wrapping aLrcXAConnectionon a LrcConnectionHandle of a LrcXAResource in state NO_TX] for JDBC transaction
2011-01-20 14:05:27,954 DEBUG [ramework.jdbc.datasource.DataSourceUtils] (l.Server-9) Setting JDBC Connection [a JdbcConnectionHandle of a JdbcPooledConnection from datasource af64c398-9b42-4ec1-a3bd-b26711c6bc79 in state ACCESSIBLE wrapping a LrcXAConnection on a LrcConnectionHandle of a LrcXAResource in state NO_TX] read-only
2011-01-20 14:05:27,955 DEBUG [.datasource.DataSourceTransactionManager] (l.Server-9) Switching JDBC Connection [a JdbcConnectionHandle of a JdbcPooledConnection from datasource af64c398-9b42-4ec1-a3bd-b26711c6bc79 in state ACCESSIBLE wrapping a LrcXAConnection on a LrcConnectionHandle of a LrcXAResource in state NO_TX] to manual commit
2011-01-20 14:05:27,955 DEBUG [ework.orm.hibernate3.SessionFactoryUtils] (l.Server-9) Opening Hibernate Session
2011-01-20 14:05:27,955 DEBUG [ework.orm.hibernate3.SessionFactoryUtils] (l.Server-9) Registering Spring transaction synchronization for new Hibernate Session
2011-01-20 14:05:27,955 DEBUG [work.orm.hibernate3.HibernateInterceptor] (l.Server-9) Found thread-bound Session for HibernateInterceptor
2011-01-20 14:05:27,956 INFO [ ome.security.basic.EventHandler] (l.Server-9) Auth: user=0,group=0,event=null(Sessions),sess=af64c398-9b42-4ec1-a3bd-b26711c6bc79
2011-01-20 14:05:27,956 DEBUG [g.springframework.jdbc.core.JdbcTemplate] (l.Server-9) Executing prepared SQL query
2011-01-20 14:05:27,956 DEBUG [g.springframework.jdbc.core.JdbcTemplate] (l.Server-9) Executing prepared SQL statement [select id from experimenter where omeName = ?]
2011-01-20 14:05:27,956 DEBUG [ramework.jdbc.datasource.DataSourceUtils] (l.Server-9) Fetching JDBC Connection from DataSource
2011-01-20 14:05:27,956 DEBUG [ramework.jdbc.datasource.DataSourceUtils] (l.Server-9) Registering transaction synchronization for JDBC Connection
2011-01-20 14:05:28,091 DEBUG [work.orm.hibernate3.HibernateInterceptor] (l.Server-9) Not closing pre-bound Hibernate Session after HibernateInterceptor
2011-01-20 14:05:28,091 DEBUG [ramework.jdbc.datasource.DataSourceUtils] (l.Server-9) Returning JDBC Connection to DataSource
2011-01-20 14:05:28,091 DEBUG [.datasource.DataSourceTransactionManager] (l.Server-9) Initiating transaction rollback
2011-01-20 14:05:28,091 DEBUG [.datasource.DataSourceTransactionManager] (l.Server-9) Rolling back JDBC transaction on Connection [a JdbcConnectionHandle of a JdbcPooledConnection from datasource af64c398-9b42-4ec1-a3bd-b26711c6bc79 in state ACCESSIBLE wrapping a LrcXAConnection on a LrcConnectionHandle of a LrcXAResource in state NO_TX]
2011-01-20 14:05:28,092 DEBUG [ework.orm.hibernate3.SessionFactoryUtils] (l.Server-9) Closing Hibernate Session
2011-01-20 14:05:28,092 DEBUG [ramework.jdbc.datasource.DataSourceUtils] (l.Server-9) Resetting read-only flag of JDBC Connection [a JdbcConnectionHandle of a JdbcPooledConnection from datasource af64c398-9b42-4ec1-a3bd-b26711c6bc79 in state ACCESSIBLE wrapping a LrcXAConnection on a LrcConnectionHandle of a LrcXAResource in state NO_TX]
2011-01-20 14:05:28,092 DEBUG [.datasource.DataSourceTransactionManager] (l.Server-9) Releasing JDBC Connection [a JdbcConnectionHandle of a JdbcPooledConnection from datasource af64c398-9b42-4ec1-a3bd-b26711c6bc79 in state ACCESSIBLE wrapping a LrcXAConnection on a LrcConnectionHandle of a LrcXAResource in state NO_TX] after transaction
2011-01-20 14:05:28,092 DEBUG [ramework.jdbc.datasource.DataSourceUtils] (l.Server-9) Returning JDBC Connection to DataSource
2011-01-20 14:05:28,092 INFO [ org.perf4j.TimingLogger] (l.Server-9) start[1295553927947] time[145] tag[omero.call.exception]
2011-01-20 14:05:28,093 WARN [ ome.services.util.ServiceHandler] (l.Server-9) Unknown exception thrown.
org.springframework.ldap.AuthenticationException: [LDAP: error code 32 - No SuchObject]; nested exception is javax.naming.AuthenticationException: [LDAP: errorcode 32 - No Such Object]
at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:180)
at org.springframework.ldap.core.support.AbstractContextSource.createContext(AbstractContextSource.java:266)
at org.springframework.ldap.core.support.AbstractContextSource.getContext(AbstractContextSource.java:106)
at org.springframework.ldap.core.support.AbstractContextSource.getReadOnlyContext(AbstractContextSource.java:125)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:196)
at $Proxy51.getReadOnlyContext(Unknown Source)
at ome.logic.LdapImpl.getBase(LdapImpl.java:454)
at ome.logic.LdapImpl.getContextMapper(LdapImpl.java:414)
at ome.logic.LdapImpl.findExperimenter(LdapImpl.java:174)
at ome.logic.LdapImpl.createUserFromLdap(LdapImpl.java:270)
at ome.security.auth.LdapPasswordProvider.checkPassword(LdapPasswordProvider.java:85)
at ome.security.auth.PasswordProviders.checkPassword(PasswordProviders.java:42)
at ome.logic.AdminImpl.checkPassword(AdminImpl.java:1131)
at ome.services.sessions.SessionManagerImpl$7.doWork(SessionManagerImpl.java:939)
at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:409)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at ome.security.basic.EventHandler.invoke(EventHandler.java:157)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:231)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:111)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy56.doWork(Unknown Source)
at ome.services.util.Executor$Impl.execute(Executor.java:339)
at ome.services.sessions.SessionManagerImpl.executeCheckPasswordRO(SessionManagerImpl.java:933)
at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:920)
at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:894)
at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:72)
at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:90)
at Glacier2._PermissionsVerifierDisp.__dispatch(_PermissionsVerifierDisp.java:118)
at IceInternal.Incoming.invoke(Incoming.java:159)
at Ice.ConnectionI.invokeAll(ConnectionI.java:2037)
at Ice.ConnectionI.message(ConnectionI.java:972)
at IceInternal.ThreadPool.run(ThreadPool.java:577)
at IceInternal.ThreadPool.access$100(ThreadPool.java:12)
at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:971)
Caused by: javax.naming.AuthenticationException: [LDAP: error code 32 - No SuchObject]
at com.sun.jndi.ldap.LdapClient.authenticate(LdapClient.java:290)
at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2685)
at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:306)
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:193)
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:211)
at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:154)
at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:84)
at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:684)
at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:305)
at javax.naming.InitialContext.init(InitialContext.java:240)
at javax.naming.ldap.InitialLdapContext.<init>(InitialLdapContext.java:151)
at org.springframework.ldap.core.support.LdapContextSource.getDirContextInstance(LdapContextSource.java:43)
at org.springframework.ldap.core.support.AbstractContextSource.createContext(AbstractContextSource.java:254)
... 50 more
2011-01-20 14:05:28,094 INFO [ ome.services.util.ServiceHandler] (l.Server-9) Excp: org.springframework.ldap.AuthenticationException: [LDAP: error code 32 - No Such Object]; nested exception is javax.naming.AuthenticationException: [LDAP: error code 32 - No Such Object]
2011-01-20 14:05:28,094 ERROR [services.blitz.fire.PermissionsVerifierI] (l.Server-9) Exception thrown while checking password for:mytestuser ome.conditions.InternalException: Wrapped Exception: (org.springframework.ldap.
AuthenticationException):[LDAP: error code 32 - No Such Object]; nested exception is javax.naming.AuthenticationException: [LDAP: error code 32 - No Such Object]
at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:180)
at org.springframework.ldap.core.support.AbstractContextSource.createContext(AbstractContextSource.java:266)
at org.springframework.ldap.core.support.AbstractContextSource.getContext(AbstractContextSource.java:106)
at org.springframework.ldap.core.support.AbstractContextSource.getReadOnlyContext(AbstractContextSource.java:125)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:196)
at $Proxy51.getReadOnlyContext(Unknown Source)
at ome.logic.LdapImpl.getBase(LdapImpl.java:454)
at ome.logic.LdapImpl.getContextMapper(LdapImpl.java:414)
at ome.logic.LdapImpl.findExperimenter(LdapImpl.java:174)
at ome.logic.LdapImpl.createUserFromLdap(LdapImpl.java:270)
at ome.security.auth.LdapPasswordProvider.checkPassword(LdapPasswordProvider.java:85)
at ome.security.auth.PasswordProviders.checkPassword(PasswordProviders.java:42)
at ome.logic.AdminImpl.checkPassword(AdminImpl.java:1131)
at ome.services.sessions.SessionManagerImpl$7.doWork(SessionManagerImpl.java:939)
at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:409)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at ome.security.basic.EventHandler.invoke(EventHandler.java:157)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:231)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:111)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy56.doWork(Unknown Source)
at ome.services.util.Executor$Impl.execute(Executor.java:339)
at ome.services.sessions.SessionManagerImpl.executeCheckPasswordRO(SessionManagerImpl.java:933)
at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:920)
at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:894)
at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:72)
at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:90)
at Glacier2._PermissionsVerifierDisp.__dispatch(_PermissionsVerifierDisp.java:118)
at IceInternal.Incoming.invoke(Incoming.java:159)
at Ice.ConnectionI.invokeAll(ConnectionI.java:2037)
at Ice.ConnectionI.message(ConnectionI.java:972)
at IceInternal.ThreadPool.run(ThreadPool.java:577)
at IceInternal.ThreadPool.access$100(ThreadPool.java:12)
at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:971)
________________________________________
From: ome-devel-bounces at lists.openmicroscopy.org.uk [ome-devel-bounces at lists.openmicroscopy.org.uk] On Behalf Of Josh Moore [josh at glencoesoftware.com]
Sent: Tuesday, January 18, 2011 1:29 AM
To: McCaughey, Michael J
Cc: ome-devel at lists.openmicroscopy.org.uk
Subject: Re: [ome-devel] LDAP error logging
Hi Mike,
I agree that the logging is not nearly as useful as it needs to be. I've added a ticket to improve ldap logging support:
http://trac.openmicroscopy.org.uk/omero/ticket/3892
However, could it be the missing "o" from your "omero.ldap.username" causing the problem? Or is that just a cut-n-paste artifact? If that doesn't clear things up, I'll create a test with a space in the username and see if I can reproduce your problems.
Cheers,
~Josh
On Jan 17, 2011, at 9:56 PM, McCaughey, Michael J wrote:
> Josh-
> bin/omero config get (less password) returns:
> omero.ldap.base=ou=people,dc=vanderbilt,dc=edu
> omero.ldap.config=true
> omero.ldap.urls=ldaps://ldap.vanderbilt.edu:636
> mero.ldap.username=uid=myuser,ou=special users,dc=vanderbilt,dc=edu
> omero.ldap.user_mapping=omeName=uid,firstName=givenName,lastName=sn,email=mail
>
> Setting log level to DEBUG adds only the following to a failed logon attempt:
>
> 2011-01-17 14:48:54,452 INFO [.ldap.DefaultSpringSecurityContextSource] ( main) URL 'ldaps://ldap.vanderbilt.edu:636', root DN is ''
> 2011-01-17 14:48:54,486 DEBUG [.ldap.core.support.AbstractContextSource] ( main) AuthenticationSource not set - using default implementation
> 2011-01-17 14:48:54,486 DEBUG [.ldap.core.support.AbstractContextSource] ( main) Using LDAP pooling.
> 2011-01-17 14:48:54,487 DEBUG [.ldap.core.support.AbstractContextSource] ( main) Trying provider Urls: ldaps://ldap.vanderbilt.edu:636/ou=people,dc=vanderbilt,dc=edu
> 2011-01-17 14:48:54,501 DEBUG [amework.aop.framework.JdkDynamicAopProxy] ( main) Creating JDK dynamic proxy: target source is HotSwappableTargetSource for target: org.springframework.security.ldap.DefaultSpringSecurityContextSource at 70a0afab
>
>
> One of the ou= has a space in the value, will that break anything?
>
> Mike
> ________________________________________
> From: Josh Moore [josh at glencoesoftware.com]
> Sent: Monday, January 17, 2011 1:30 PM
> To: McCaughey, Michael J
> Cc: ome-devel at lists.openmicroscopy.org.uk
> Subject: Re: [ome-devel] LDAP error logging
>
> On Jan 17, 2011, at 7:44 PM, McCaughey, Michael J wrote:
>
>> Hello-
>
> Hi Mike,
>
>> I'm trying to configure ldap support on 4.2.2 (platform is fedora 12). Our local ldap service is functional, and my test server can at least ping it. I can execute ldapsearch from a command line using the same credentials I provide in omero.properties, so I think that's correct. Using ldapsearch with known good username and the exisitng filter as specified in omero.properties (i.e. (&(objectClass=person)(uid=cisr1))) returns a single result.
>> Java truststore has the CA of the provider (all that is required to reach our ldap box) plus local; keystore is set up as well.
>>
>> When I try to logon with users known to ldap from the insight client, I either get an logon failure or the client hangs forever. I the case of the logon error, I can see from the log file that it's trying to vet the password:
>>
>> 2011-01-14 11:57:40,917 INFO [ ome.services.util.ServiceHandler] (l.Server-8) Executor.doWork -- ome.services.sessions.SessionManagerImpl.executeCheckPasswordRO(cisr1)
>> 2011-01-14 11:57:40,917 INFO [ ome.services.util.ServiceHandler] (l.Server-8) Args: [null, ome.tools.spring.InternalServiceFactory at 3486a602]
>> 2011-01-14 11:57:40,924 INFO [ ome.security.basic.EventHandler] (l.Server-8) Auth: user=0,group=0,event=null(Sessions),sess=32696c27-5b72-4a39-b86c-8b6fcb71440d
>> 2011-01-14 11:57:40,928 INFO [ org.perf4j.TimingLogger] (l.Server-8) start[1295027860917] time[11] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$7.doWork]
>> 2011-01-14 11:57:40,928 INFO [ ome.services.util.ServiceHandler] (l.Server-8) Rslt: false
>>
>> However, this doesn't really tell me *where* it's trying to check the credentials. The hung login logs nothing at all.
>> Pre-creating the experimenter account does not help.
>>
>> Is there a way to turn on more extensive logging so I can determine what's gone off in the process?
>
> There is some minimal logging that will be added by modifying the line:
>
> <category name="org.springframework"> <priority value="WARN"/> </category>
>
> in etc/log4j.xml to say "DEBUG" rather than "WARN". (This doesn't require a restart).
>
> You can then grep your logs for "ldap". This will only make sure that you are using the right URL and similar, though I expected there to be much more logging from the Spring libraries. I'll keep looking for a better method. At the same time, could you possibly show us your configuration, i.e. the output of bin/omero config get? E.g.
>
> ~/code/git/dist $ bin/omero config get | grep ldap | grep -v pass
> omero.ldap.base=ou=lifesci,o=dundee
> omero.ldap.config=true
> omero.ldap.urls=ldap://localhost:1389
>
> Be sure, of course, to change any sensitive information.
>
> Cheers,
> ~Josh
>
>> Thanks,
>> Mike
>
_______________________________________________
ome-devel mailing list
ome-devel at lists.openmicroscopy.org.uk
http://lists.openmicroscopy.org.uk/mailman/listinfo/ome-devel
More information about the ome-devel
mailing list