CAS 6.6.12 LDAP error messages

[Yan Zhou]

Hi there,

CAS 6.6.12 on ActiveDirectory authN, Seeing this error intermittently.

I can login successfully and authN works correctly, but seeing errors fairly often, not sure what they mean. It seems AD is closing the connection unexpectedly, but why?

thanks!

cas.authn.ldap[0].type=AUTHENTICATED
cas.authn.ldap[0].searchFilter=(&(objectCategory=Person)(sAMAccountName={user}))
cas.authn.ldap[0].baseDn=.....
cas.authn.ldap[0].bindCredential=.....
cas.authn.ldap[0].bindDn=.....
cas.authn.ldap[0].ldapUrl=ldaps://ldaps......com:636
cas.authn.ldap[0].keystore=file:///C:/...../ldapkeystore
cas.authn.ldap[0].keystorePassword=c.....t
#

I am using the default value BIND for poolPassivator. I do not think that is related. 

2024-02-15 11:09:07,213 WARN [ldaptive-ConnectionFactoryTransport-io-1-3] [org.ldaptive.transport.netty.NettyConnection] - <Inbound handler caught exception for org.ldaptive.transport.netty.NettyConnection@1781552588::ldapUrl=[org.ldaptive.LdapURL@1753603675::scheme=ldaps, hostname=ldaps.qdx.com, port=636, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null], isOpen=true, connectTime=2024-02-15T16:04:07.122332500Z, connectionConfig=[org.ldaptive.ConnectionConfig@413608697::ldapUrl=ldaps://ldaps.qdx.com:636, connectTimeout=PT5S, responseTimeout=PT5S, reconnectTimeout=PT2M, autoReconnect=true, autoReconnectCondition=org.ldaptive.ConnectionConfig$$Lambda$1462/0x0000000800a95440@2495896c, autoReplay=true, sslConfig=[org.ldaptive.ssl.SslConfig@102500509::credentialConfig=[org.ldaptive.ssl.KeyStoreCredentialConfig@-1220323769::trustStore=null, trustStoreType=null, trustStoreAliases=null, keyStore=file:///C:/apereocas66x/config/ldapkeystore, keyStoreType=null, keyStoreAliases=null], trustManagers=null, hostnameVerifier=org.ldaptive.ssl.DefaultHostnameVerifier@4d1aa28a, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null, handshakeTimeout=PT1M], useStartTLS=false, connectionInitializers=[org.ldaptive.BindConnectionInitializer@540563433::bindDn=zz_hubcas01, bindSaslConfig=null, bindControls=null], connectionStrategy=[org.ldaptive.ActivePassiveConnectionStrategy@1816897842::ldapURLSet=[org.ldaptive.LdapURLSet@1688048446::active=[[org.ldaptive.LdapURL@1753603675::scheme=ldaps, hostname=ldaps.qdx.com, port=636, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null]], inactive=[]], activateCondition=org.ldaptive.transport.TransportConnection$$Lambda$1473/0x0000000800ae0040@1ab5dbfc, retryCondition=org.ldaptive.AbstractConnectionStrategy$$Lambda$1465/0x0000000800a94040@2b86e3a1, initialized=true], connectionValidator=null, transportOptions={}], channel=[id: 0x96beeed6, L:/192.168.1.46:55245 - R:ldaps.qdx.com/100.64.1.27:636]>
java.io.IOException: An existing connection was forcibly closed by the remote host
at sun.nio.ch.SocketDispatcher.read0(Native Method) ~[?:?]
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43) ~[?:?]
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:258) ~[netty-buffer-4.1.80.Final.jar:4.1.80.Final]
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[netty-buffer-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:357) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.80.Final.jar:4.1.80.Final]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.80.Final.jar:4.1.80.Final]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.80.Final.jar:4.1.80.Final]
at java.lang.Thread.run(Thread.java:834) ~[?:?]
2024-02-15 11:09:07,930 WARN [ldaptive-ConnectionFactoryTransport-io-3-2] [org.ldaptive.transport.netty.NettyConnection] - <Inbound handler caught exception for org.ldaptive.transport.netty.NettyConnection@785795530::ldapUrl=[org.ldaptive.LdapURL@1753603675::scheme=ldaps, hostname=ldaps.qdx.com, port=636, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null], isOpen=true, connectTime=2024-02-15T16:04:07.619837500Z, connectionConfig=[org.ldaptive.ConnectionConfig@1206539402::ldapUrl=ldaps://ldaps.qdx.com:636, connectTimeout=PT5S, responseTimeout=PT5S, reconnectTimeout=PT2M, autoReconnect=true, autoReconnectCondition=org.ldaptive.ConnectionConfig$$Lambda$1462/0x0000000800a95440@2495896c, autoReplay=true, sslConfig=[org.ldaptive.ssl.SslConfig@428016524::credentialConfig=[org.ldaptive.ssl.KeyStoreCredentialConfig@-1220323769::trustStore=null, trustStoreType=null, trustStoreAliases=null, keyStore=file:///C:/apereocas66x/config/ldapkeystore, keyStoreType=null, keyStoreAliases=null], trustManagers=null, hostnameVerifier=org.ldaptive.ssl.DefaultHostnameVerifier@2e4ae838, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null, handshakeTimeout=PT1M], useStartTLS=false, connectionInitializers=[org.ldaptive.BindConnectionInitializer@34993643::bindDn=zz_hubcas01, bindSaslConfig=null, bindControls=null], connectionStrategy=[org.ldaptive.ActivePassiveConnectionStrategy@242339230::ldapURLSet=[org.ldaptive.LdapURLSet@455775966::active=[[org.ldaptive.LdapURL@1753603675::scheme=ldaps, hostname=ldaps.qdx.com, port=636, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null]], inactive=[]], activateCondition=org.ldaptive.transport.TransportConnection$$Lambda$1473/0x0000000800ae0040@1ab47954, retryCondition=org.ldaptive.AbstractConnectionStrategy$$Lambda$1465/0x0000000800a94040@2b86e3a1, initialized=true], connectionValidator=null, transportOptions={}], channel=[id: 0x5abb5006, L:/192.168.1.46:55311 - R:ldaps.qdx.com/100.64.1.27:636]>
java.io.IOException: An existing connection was forcibly closed by the remote host
at sun.nio.ch.SocketDispatcher.read0(Native Method) ~[?:?]
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43) ~[?:?]
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:258) ~[netty-buffer-4.1.80.Final.jar:4.1.80.Final]
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[netty-buffer-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:357) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) ~[netty-transport-4.1.80.Final.jar:4.1.80.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.80.Final.jar:4.1.80.Final]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.80.Final.jar:4.1.80.Final]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.80.Final.jar:4.1.80.Final]

at java.lang.Thread.run(Thread.java:834) ~[?:?]    

I actually do not understand what this CAS comment referring to, is it saying the default value BIND is designed to resolve this error?  it passivates a connection by doing a BIND on it?

/**
     * You may receive unexpected LDAP failures, when CAS is configured to authenticate
     * using {@code DIRECT} or {@code AUTHENTICATED} types and LDAP is locked down to not allow anonymous binds/searches.
     * Every second attempt with a given LDAP connection from the pool would fail if it was on
     * the same connection as a failed login attempt, and the regular connection validator would
     * similarly fail. When a connection is returned back to a pool,
     * it still may contain the principal and credentials from the previous attempt.
     * Before the next bind attempt using that connection, the validator tries to
     * validate the connection again but fails because it’s no longer trying with the
     * configured bind credentials but with whatever user DN was used in the previous step.
     * Given the validation failure, the connection is closed and CAS would deny
     * access by default. Passivators attempt to reconnect
     * to LDAP with the configured bind credentials, effectively resetting the connection
     * to what it should be after each bind request.
     * Furthermore if you are seeing errors in the logs that resemble
     * a 'Operation exception encountered, reopening connection' type of message, this
     * usually is an indication that the connection pool’s validation timeout
     * established and created by CAS is greater than the timeout configured
     * in the LDAP server, or more likely, in the load balancer in front of
     * the LDAP servers. You can adjust the LDAP server session’s timeout
     * for connections, or you can teach CAS to use a validity period that
     * is equal or less than the LDAP server session’s timeout.
     * Accepted values are:
     * <ul>
     * <li>{@code NONE}: No passivation takes place.</li>
     * <li>{@code BIND}: The default behavior which passivates a connection by performing a
     * bind operation on it. This option requires the availability of bind credentials when establishing connections to LDAP.</li>
     * </ul>
     */
    private String poolPassivator = "BIND";

[Daniel Fisher]

On Thu, Feb 15, 2024 at 12:26 PM Yan Zhou <yana...@gmail.com> wrote:

I can login successfully and authN works correctly, but seeing errors fairly often, not sure what they mean. It seems AD is closing the connection unexpectedly, but why?

You should ask your AD administrator, there is likely an idle connection timeout you need to be aware of. These log messages are warnings, they may or may not represent a problem.

I actually do not understand what this CAS comment referring to, is it saying the default value BIND is designed to resolve this error?  it passivates a connection by doing a BIND on it?

The passivator is not designed to solve the issue you're having. It is meant to solve the problem where connections cannot be validated because the entry they are bound as is not authorized to perform the validation operation.

--Daniel Fisher