Hi,
I am recognizing frequent errors while connecting to LDAP. The connection fails
and delivers a HTTP 401 or 500 to the client using Knox (see log below).
To resolve the issue, I activated ehcache and set it to 6h.
Now it seems that every 6 hours, nearly 50% of the first uncached connections
fail.
Active Directory informed that idle sessions are closed after 15 mins.
As Knox uses Shiro connection pooling, could it relate to some old connections
in the pool which are used but which have timed out already?
Do you have another idea, how to work around this issue?
Thanks for your input,
Benjamin
Log extract (I replaced users and hostnames):
2016-12-07 14:37:36,268 DEBUG authc.BasicHttpAuthenticationFilter
(BasicHttpAuthenticationFilter.java:sendChallenge(274)) - Authentication
required: sending 401 Authentication challenge response.
2016-12-07 14:37:36,275 DEBUG authc.BasicHttpAuthenticationFilter
(BasicHttpAuthenticationFilter.java:createToken(308)) - Attempting to execute
login with headers [Basic REtedSfMzNDI4Masodß2HcyNmZRNTBrUHNB]
2016-12-07 14:37:36,276 DEBUG ldap.JndiLdapRealm
(JndiLdapRealm.java:queryForAuthenticationInfo(369)) - Authenticating user
'USERNAME' through LDAP
2016-12-07 14:37:36,277 DEBUG ldap.JndiLdapContextFactory
(JndiLdapContextFactory.java:getLdapContext(488)) - Initializing LDAP context
using URL [ldaps://LDAPSERVER:636] and principal
[CN=BINDUSER,OU=someOU,DC=someDC] with pooling enabled
2016-12-07 14:37:36,402 INFO hadoop.gateway
(KnoxLdapRealm.java:getUserDn(679)) - Computed userDn:
CN=USERNAME,OU=someOU,DC=someDC using ldapSearch for principal: USERNAME
2016-12-07 14:37:36,404 DEBUG ldap.JndiLdapContextFactory
(JndiLdapContextFactory.java:getLdapContext(488)) - Initializing LDAP context
using URL [ldaps://LDAPSERVER:636] and principal
[CN=USERNAME,OU=someOU,DC=someDC] with pooling disabled
2016-12-07 14:37:36,479 DEBUG realm.AuthenticatingRealm
(AuthenticatingRealm.java:getAuthenticationInfo(569)) - Looked up
AuthenticationInfo [USERNAME] from doGetAuthenticationInfo
2016-12-07 14:37:36,480 DEBUG disk.Segment (Segment.java:put(420)) - put added
0 on heap
2016-12-07 14:37:36,483 DEBUG credential.SimpleCredentialsMatcher
(SimpleCredentialsMatcher.java:equals(95)) - Performing credentials equality
check for tokenCredentials of type [org.apache.shiro.crypto.hash.SimpleHash and
accountCredentials of type [org.apache.shiro.crypto.hash.SimpleHash]
2016-12-07 14:37:36,483 DEBUG credential.SimpleCredentialsMatcher
(SimpleCredentialsMatcher.java:equals(101)) - Both credentials arguments can be
easily converted to byte arrays. Performing array equals comparison
2016-12-07 14:37:36,483 DEBUG authc.AbstractAuthenticator
(AbstractAuthenticator.java:authenticate(231)) - Authentication successful for
token [org.apache.shiro.authc.UsernamePasswordToken - USERNAME,
rememberMe=false (10.41.64.180)]. Returned account [USERNAME]
2016-12-07 14:37:36,483 DEBUG support.DefaultSubjectContext
(DefaultSubjectContext.java:resolveSecurityManager(102)) - No SecurityManager
available in subject context map. Falling back to
SecurityUtils.getSecurityManager() lookup.
2016-12-07 14:37:36,484 DEBUG support.DefaultSubjectContext
(DefaultSubjectContext.java:resolveSecurityManager(102)) - No SecurityManager
available in subject context map. Falling back to
SecurityUtils.getSecurityManager() lookup.
2016-12-07 14:37:36,490 DEBUG disk.Segment (Segment.java:fault(774)) - fault
removed 0 from heap
2016-12-07 14:37:36,490 DEBUG disk.Segment (Segment.java:fault(787)) - fault
added 0 on disk
2016-12-07 14:37:36,494 DEBUG servlet.SimpleCookie
(SimpleCookie.java:addCookieHeader(226)) - Added HttpServletResponse Cookie
[rememberMe=deleteMe; Path=/gateway/test; Max-Age=0; Expires=Tue, 06-Dec-2016
13:37:36 GMT]
2016-12-07 14:37:36,494 DEBUG mgt.AbstractRememberMeManager
(AbstractRememberMeManager.java:onSuccessfulLogin(300)) - AuthenticationToken
did not indicate RememberMe is requested. RememberMe functionality will not be
executed for corresponding account.
2016-12-07 14:37:36,495 DEBUG ldap.JndiLdapContextFactory
(JndiLdapContextFactory.java:getLdapContext(488)) - Initializing LDAP context
using URL [ldaps://LDAPSERVER:636] and principal
[CN=BINDUSER,OU=someOU,DC=someDC] with pooling enabled
2016-12-07 14:37:36,564 DEBUG servlet.AdviceFilter
(AdviceFilter.java:cleanup(194)) - Filter execution resulted in an unexpected
Exception (not IOException or ServletException as the Filter API recommends).
Wrapping in ServletException and propagating.
2016-12-07 14:37:36,566 ERROR hadoop.gateway
(AbstractGatewayFilter.java:doFilter(66)) - Failed to execute filter:
javax.servlet.ServletException: org.apache.shiro.authz.AuthorizationException:
LDAP naming error while attempting to retrieve authorization for user
[USERNAME].
2016-12-07 14:37:36,567 ERROR hadoop.gateway
(AbstractGatewayFilter.java:doFilter(66)) - Failed to execute filter:
javax.servlet.ServletException: org.apache.shiro.authz.AuthorizationException:
LDAP naming error while attempting to retrieve authorization for user
[USERNAME].
2016-12-07 14:37:36,567 ERROR hadoop.gateway (GatewayFilter.java:doFilter(145))
- Gateway processing failed: javax.servlet.ServletException:
org.apache.shiro.authz.AuthorizationException: LDAP naming error while
attempting to retrieve authorization for user [USERNAME].
javax.servlet.ServletException: org.apache.shiro.authz.AuthorizationException:
LDAP naming error while attempting to retrieve authorization for user
[USERNAME].
at
org.apache.shiro.web.servlet.AdviceFilter.cleanup(AdviceFilter.java:196)
at
org.apache.shiro.web.filter.authc.AuthenticatingFilter.cleanup(AuthenticatingFilter.java:155)
at
org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:148)
at
org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
at
org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66)
at
org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449)
at
org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)
at
org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)
at
org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)
at
org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383)
at
org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)
at
org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
at
org.apache.hadoop.gateway.GatewayFilter$Holder.doFilter(GatewayFilter.java:332)
at
org.apache.hadoop.gateway.GatewayFilter$Chain.doFilter(GatewayFilter.java:232)
at
org.apache.hadoop.gateway.filter.ResponseCookieFilter.doFilter(ResponseCookieFilter.java:50)
at
org.apache.hadoop.gateway.filter.AbstractGatewayFilter.doFilter(AbstractGatewayFilter.java:61)
at
org.apache.hadoop.gateway.GatewayFilter$Holder.doFilter(GatewayFilter.java:332)
at
org.apache.hadoop.gateway.GatewayFilter$Chain.doFilter(GatewayFilter.java:232)
at
org.apache.hadoop.gateway.filter.XForwardedHeaderFilter.doFilter(XForwardedHeaderFilter.java:30)
at
org.apache.hadoop.gateway.filter.AbstractGatewayFilter.doFilter(AbstractGatewayFilter.java:61)
at
org.apache.hadoop.gateway.GatewayFilter$Holder.doFilter(GatewayFilter.java:332)
at
org.apache.hadoop.gateway.GatewayFilter$Chain.doFilter(GatewayFilter.java:232)
at
org.apache.hadoop.gateway.GatewayFilter.doFilter(GatewayFilter.java:139)
at
org.apache.hadoop.gateway.GatewayFilter.doFilter(GatewayFilter.java:91)
at
org.apache.hadoop.gateway.GatewayServlet.service(GatewayServlet.java:138)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at
org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)
at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)
at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
at
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at
org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
at
org.apache.hadoop.gateway.trace.TraceHandler.handle(TraceHandler.java:51)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
at
org.apache.hadoop.gateway.filter.CorrelationHandler.handle(CorrelationHandler.java:39)
at
org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
at org.eclipse.jetty.server.Server.handle(Server.java:499)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
at
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
at
org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
at
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
at
org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.apache.shiro.authz.AuthorizationException: LDAP naming error
while attempting to retrieve authorization for user [USERNAME].
at
org.apache.shiro.realm.ldap.JndiLdapRealm.doGetAuthorizationInfo(JndiLdapRealm.java:316)
at
org.apache.shiro.realm.AuthorizingRealm.getAuthorizationInfo(AuthorizingRealm.java:341)
at
org.apache.shiro.realm.AuthorizingRealm.hasRole(AuthorizingRealm.java:571)
at
org.apache.shiro.authz.ModularRealmAuthorizer.hasRole(ModularRealmAuthorizer.java:374)
at
org.apache.shiro.mgt.AuthorizingSecurityManager.hasRole(AuthorizingSecurityManager.java:153)
at
org.apache.shiro.subject.support.DelegatingSubject.hasRole(DelegatingSubject.java:224)
at
org.apache.hadoop.gateway.filter.ShiroSubjectIdentityAdapter.doFilter(ShiroSubjectIdentityAdapter.java:69)
at
org.apache.hadoop.gateway.GatewayFilter$Holder.doFilter(GatewayFilter.java:332)
at
org.apache.hadoop.gateway.GatewayFilter$Chain.doFilter(GatewayFilter.java:232)
at
org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61)
at
org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)
at
org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)
... 46 more
Caused by: javax.naming.CommunicationException: simple bind failed:
LDAP-SERVER-NAME:636 [Root exception is java.net.SocketException: Connection
reset]
at com.sun.jndi.ldap.LdapClient.authenticate(LdapClient.java:219)
at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2788)
at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:319)
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:192)
at
com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:210)
at
com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:153)
at
com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:83)
at
javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:684)
at
javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:313)
at javax.naming.InitialContext.init(InitialContext.java:244)
at
javax.naming.ldap.InitialLdapContext.<init>(InitialLdapContext.java:154)
at
org.apache.shiro.realm.ldap.JndiLdapContextFactory.createLdapContext(JndiLdapContextFactory.java:508)
at
org.apache.hadoop.gateway.shirorealm.KnoxLdapContextFactory.createLdapContext(KnoxLdapContextFactory.java:63)
at
org.apache.shiro.realm.ldap.JndiLdapContextFactory.getLdapContext(JndiLdapContextFactory.java:495)
at
org.apache.shiro.realm.ldap.JndiLdapContextFactory.getSystemLdapContext(JndiLdapContextFactory.java:402)
at
org.apache.hadoop.gateway.shirorealm.KnoxLdapRealm.getRoles(KnoxLdapRealm.java:236)
at
org.apache.hadoop.gateway.shirorealm.KnoxLdapRealm.queryForAuthorizationInfo(KnoxLdapRealm.java:223)
at
org.apache.shiro.realm.ldap.JndiLdapRealm.doGetAuthorizationInfo(JndiLdapRealm.java:313)
... 57 more
Caused by: java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:209)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
at sun.security.ssl.InputRecord.read(InputRecord.java:503)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
at
sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1375)
at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:747)
at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:123)
at
java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
at com.sun.jndi.ldap.Connection.writeRequest(Connection.java:426)
at com.sun.jndi.ldap.Connection.writeRequest(Connection.java:399)
at com.sun.jndi.ldap.LdapClient.ldapBind(LdapClient.java:359)
at com.sun.jndi.ldap.LdapClient.authenticate(LdapClient.java:214)
... 74 more
