Sporadic "Simple Bind Failed" in Blitz Log

[davemason]

In an otherwise working setup previously running 5.0.2 and now 5.0.3 on Ubuntu 12.04 LTS with LDAP authentication, I occasionally get users denied login with a "Failed to log into OMERO. Please check username and/or pw".

When I link the login attempts to the Blitz log, I get the following which appears to show a problem with the LDAP bind:

Code: Select all

2014-08-11 13:43:42,035 INFO  [        ome.services.util.ServiceHandler] (.Server-18)  Excp:   org.springframework.ldap.CommunicationException: simple bind failed: livad.liv.ac.uk:636; nested exception is javax.naming.CommunicationException: simple bind failed: livad.liv.ac.uk:636 [Root exception is java.net.SocketException: Connection reset]
2014-08-11 13:43:42,036 ERROR [     o.s.blitz.fire.PermissionsVerifierI] (.Server-18) Exception thrown while checking password for:dnmason
ome.conditions.InternalException:  Wrapped Exception: (org.springframework.ldap.CommunicationException):
simple bind failed: livad.liv.ac.uk:636; nested exception is javax.naming.CommunicationException: simple bind failed: livad.liv.ac.uk:636 [Root exception is java.net.SocketException: Connection reset]
   at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:98) ~[spring-ldap.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.support.AbstractContextSource.createContext(AbstractContextSource.java:266) ~[spring-ldap.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.support.AbstractContextSource.getContext(AbstractContextSource.java:106) ~[spring-ldap.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.support.AbstractContextSource.getReadOnlyContext(AbstractContextSource.java:125) ~[spring-ldap.jar:1.3.0.RELEASE]
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.6.0_31]
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.6.0_31]
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.6.0_31]
   at java.lang.reflect.Method.invoke(Method.java:622) ~[na:1.6.0_31]
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:196) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at com.sun.proxy.$Proxy61.getReadOnlyContext(Unknown Source) ~[na:na]
   at ome.logic.LdapImpl.getBase(LdapImpl.java:603) ~[server.jar:na]
   at ome.logic.LdapImpl.getContextMapper(LdapImpl.java:562) ~[server.jar:na]
   at ome.logic.LdapImpl.findDN(LdapImpl.java:157) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.getLdapDN(LdapPasswordProvider.java:181) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.checkPassword(LdapPasswordProvider.java:135) ~[server.jar:na]
   at ome.security.auth.PasswordProviders.checkPassword(PasswordProviders.java:42) ~[server.jar:na]
   at ome.logic.AdminImpl.checkPassword(AdminImpl.java:1203) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl$9.doWork(SessionManagerImpl.java:985) ~[server.jar:na]
   at sun.reflect.GeneratedMethodAccessor272.invoke(Unknown Source) ~[na:na]
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.6.0_31]
   at java.lang.reflect.Method.invoke(Method.java:622) ~[na:1.6.0_31]
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:576) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at ome.security.basic.EventHandler.invoke(EventHandler.java:154) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111) ~[org.springframework.orm.jar:3.0.1.RELEASE-A]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108) ~[org.springframework.transaction.jar:3.0.1.RELEASE-A]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:241) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:116) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]
   at com.sun.proxy.$Proxy66.doWork(Unknown Source) ~[na:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:457) ~[server.jar:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:401) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPasswordRW(SessionManagerImpl.java:980) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:952) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:927) ~[server.jar:na]
   at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:135) ~[blitz.jar:na]
   at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:118) ~[ice.jar:na]
   at Glacier2._PermissionsVerifierDisp.__dispatch(_PermissionsVerifierDisp.java:146) ~[ice.jar:na]
   at IceInternal.Incoming.invoke(Incoming.java:159) ~[ice.jar:na]
   at Ice.ConnectionI.invokeAll(ConnectionI.java:2357) ~[ice.jar:na]
   at Ice.ConnectionI.dispatch(ConnectionI.java:1208) ~[ice.jar:na]
   at Ice.ConnectionI.message(ConnectionI.java:1163) ~[ice.jar:na]
   at IceInternal.ThreadPool.run(ThreadPool.java:302) ~[ice.jar:na]
   at IceInternal.ThreadPool.access$300(ThreadPool.java:12) ~[ice.jar:na]
   at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:643) ~[ice.jar:na]
   at java.lang.Thread.run(Thread.java:701) ~[na:1.6.0_31]


And in case it's helpful, the "omero config get" looks something like this:

Code: Select all

omero@cci02:$ omero config get

omero.data.dir=/data/OMERO.data
omero.db.name=********
omero.db.pass=********
omero.db.user=********
omero.fs.repo.path=%groupId%/%group%/%user%_%userId%//%year%-%month%%day%/%time%
omero.ldap.base=ou=uol,dc=livad,dc=liv,dc=ac,dc=uk
omero.ldap.config=true
omero.ldap.new_user_group=NewUsers
omero.ldap.password=********
omero.ldap.urls=ldaps://livad.liv.ac.uk:636
omero.ldap.user_filter=(objectClass=User)
omero.ldap.user_mapping=omeName=sAMAccountName,firstName=givenName,lastName=sn,email=mail
omero.ldap.username=********
omero.security.keyStore=/home/omero/.keystore
omero.security.keyStorePassword=********
omero.security.trustStore=/home/omero/.keystore
omero.security.trustStorePassword=********


Time always seems to fix this. My question is whether this is the result of an overloaded OMERO server or if it's a problem on the LDAP server. The system works fine 99% of the time, I'm just curious where the problem is.

Thanks,

Dave

[bpindelski]

Hi Dave,

The root cause of the exception is java.net.SocketException: Connection reset. This exception comes from one of the core Java classes responsible for network connection management.
This means that there might be connection issues between the node running OMERO and the LDAP server. There are many causes for such issues, starting from faulty network cabling finishing with resource exhaustion.

I'd first try checking /var/log/dmesg and /var/log/syslog for any log messages that could have occured at the same time as the LDAP error. This will allow for localizing the issue.

Another option is trying to increase the timeout for Spring LDAP (test code can be found here http://stackoverflow.com/questions/1246 ... et-by-peer).

Regards,
Blazej

[davemason]

Hi Blazej,

Thanks for the reply. Unfortunately, I found nothing corresponding to LDAP problems in either of the logs you recommended.

I had a look at the link you posted, but fiddling with java is a bit outside of my comfort zone for a minor (occasional) inconvenience.

Thanks!

Dave

[bpindelski]

Hi Dave,

The lack of any relevant messages in your node's log files might indicate that the issue is one the other end or somewhere in the connection path. Another option would be to ask your facility's IT department if they have noticed any anomalies.

With kind regards,
Blazej

[davemason]

Just to follow up on this issue in case anyone else comes across it. It is a problem on the side of our authentication servers. I don't know the exact cause, but the solution that seems to have fixed the problems is to give a specific server in the OMERO config.

For example, instead of:

Code: Select all

omero.ldap.urls=ldap://ldap.host.ac.uk

(which can redirect to a handful of authentication servers) to use

Code: Select all

omero.ldap.urls=ldap://server01.host.ac.uk

Which reduces redundancy but seems to solve the problem.

Big thanks to the team as usual!

Dave

[bpindelski]

Hi Dave,

Thanks for coming back to the forum with some testing results.

It might be that OMERO can still work with LDAP server redirection (referrals). In the OMERO server configuration, we expose a setting called omero.ldap.referral. This setting can take 3 values ("ignore" - default, "follow" or "throw"). It'd be very interesting to see if setting omero.ldap.referral to follow (using bin/omero config set) fixes your issue. In such a case, we will look at updating the documentation and making this setting more prominent.

With kind regards,
Blazej

[davemason]

Hi Blazej,

Thanks for the pointers, I wasn't even aware of an ldap referrals option so that's good to know.

I did a bit of testing on one of my virtual builds (5.0.3 release build). After confirming that I get the "simple bind failed" error with default setting (omero.ldap.referral=ignore), I changed the setting (omero.ldap.referral=follow), restarted the omero server and still get the error when logging in.

It seems odd to me that it works some of the time but throws errors others? Still, I'm happy with my workaround for the time being.

Best,

Dave

[bpindelski]

Hi Dave,

I've created a ticket on our bug-tracking system (http://trac.openmicroscopy.org.uk/ome/ticket/12533). We shall try and investigate why in such a setup you see exceptions. Please let me know if you'd like to be CC'd on the ticket.

Regards,
Blazej

[davemason]

Blazej;

I'll try and get more information on the authentication server side and report back if I come up with anything.

Thanks for your help,

Dave

[bpindelski]

Hi Dave

One useful resource I could also point you to is http://www.openmicroscopy.org/site/supp ... -directory. This is a setup used by another OMERO deployment site which works with Active Directory.

With kind regards,
Blazej