-
Bug
-
Resolution: Obsolete
-
Major
-
None
-
None
-
None
-
None
We have two RHEL 6 nodes running JBoss EAP 6.4.0.GA (AS 7.5.0.Final-redhat-21)
and jboss-as-picketlink-7.5.0-8.Final_redhat_21.1.ep6.el6.noarch in a cluster with session replication. They support GSSAPI auth and LDAP auth. They do attribute mapping via the LDAP attribute mapper.
Recently we've noticed when taking one node out of rotation, then bringing it back in and taking the next node out and bringing it back in – while doing a release that people winding back up at the IDP end up at a white screen. PL serves a 200 to them and doesn't try to redirect or auth them any further. This happens very very rarely outside of a rolling cluster restart but immediately following the rolling cluster restart it happens hundreads of times for a day or more presumably until peoples IDP session cookies expire or until they close and re-open their browser or clear cache. It doesn't happen to all users so its somewhat hard to reproduce but from what I've gathered PL seems to be asking for LDAP attributes for what look like session data instead of the users UID.
Here is what is in the JBOSS debug logs when the issue occurs. Full logs attached.
2016-01-14 09:36:00,064 INFO [org.picketlink.common] (http-/10.5.103.113:8080-19) /idp RESPONSE_TO_SP https://NOPE.com/saml/sso [Info]
2016-01-14 09:36:00,939 DEBUG [org.jboss.security.negotiation.NegotiationAuthenticator] (http-/10.5.103.113:8080-14) Header - null
2016-01-14 09:36:00,939 DEBUG [org.jboss.security.negotiation.NegotiationAuthenticator] (http-/10.5.103.113:8080-14) No Authorization Header, initiating negotiation
2016-01-14 09:36:02,587 DEBUG [org.jboss.security.negotiation.NegotiationAuthenticator] (http-/10.5.103.113:8080-12) Header - null
2016-01-14 09:36:02,587 DEBUG [org.jboss.security.negotiation.NegotiationAuthenticator] (http-/10.5.103.113:8080-12) No Authorization Header, initiating negotiation
2016-01-14 09:36:02,640 DEBUG [org.jboss.security] (http-/10.5.103.113:8080-21) PBOX000293: Exception caught: javax.naming.NamingException: PBOX000037: Search for context dc=redhat,dc=com found no results
at org.jboss.security.mapping.providers.attribute.LdapAttributeMappingProvider.performMapping(LdapAttributeMappingProvider.java:217)
at org.jboss.security.mapping.providers.attribute.LdapAttributeMappingProvider.performMapping(LdapAttributeMappingProvider.java:94)
at org.jboss.security.mapping.MappingContext.performMapping(MappingContext.java:54)
at org.picketlink.identity.federation.bindings.jboss.attribute.JBossAppServerAttributeManager.getAttributes(JBossAppServerAttributeManager.java:73)
at org.picketlink.identity.federation.core.impl.DelegatedAttributeManager.getAttributes(DelegatedAttributeManager.java:67)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.processSAMLRequestMessage(AbstractIDPValve.java:834)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.handleSAMLMessage(AbstractIDPValve.java:457)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.invoke(AbstractIDPValve.java:404)
at org.jboss.security.negotiation.NegotiationAuthenticator$WrapperValve.invoke(NegotiationAuthenticator.java:490)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:512)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:559)
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:150)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)
at org.jboss.as.web.sso.ClusteredSingleSignOn.invoke(ClusteredSingleSignOn.java:384)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:854)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:653)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926)
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_85]
2016-01-14 09:36:02,643 ERROR [org.picketlink.common] (http-/10.5.103.113:8080-21) Exception in processing authentication:: org.picketlink.common.exceptions.ConfigurationException: javax.xml.datatype.DatatypeConfigurationException: Provider _redirected._DatatypeFactory not found
at org.picketlink.common.DefaultPicketLinkLogger.configurationError(DefaultPicketLinkLogger.java:726)
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.getIssueInstant(XMLTimeUtil.java:101)
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.getIssueInstant(XMLTimeUtil.java:118)
at org.picketlink.identity.federation.api.saml.v2.response.SAML2Response.createResponseType(SAML2Response.java:236)
at org.picketlink.identity.federation.web.handlers.saml2.SAML2AuthenticationHandler$IDPAuthenticationHandler.getResponse(SAML2AuthenticationHandler.java:320)
at org.picketlink.identity.federation.web.handlers.saml2.SAML2AuthenticationHandler$IDPAuthenticationHandler.handleRequestType(SAML2AuthenticationHandler.java:241)
at org.picketlink.identity.federation.web.handlers.saml2.SAML2AuthenticationHandler.handleRequestType(SAML2AuthenticationHandler.java:128)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.processSAMLRequestMessage(AbstractIDPValve.java:861)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.handleSAMLMessage(AbstractIDPValve.java:457)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.invoke(AbstractIDPValve.java:404)
at org.jboss.security.negotiation.NegotiationAuthenticator$WrapperValve.invoke(NegotiationAuthenticator.java:490)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:512)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:559)
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:150)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)
at org.jboss.as.web.sso.ClusteredSingleSignOn.invoke(ClusteredSingleSignOn.java:384)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:854)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:653)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926)
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_85]
Caused by: javax.xml.datatype.DatatypeConfigurationException: Provider _redirected._DatatypeFactory not found
at javax.xml.datatype.DatatypeFactory.newInstance(DatatypeFactory.java:135) [rt.jar:1.7.0_85]
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.newDatatypeFactory(XMLTimeUtil.java:244)
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.getIssueInstant(XMLTimeUtil.java:99)
... 21 more
Caused by: java.lang.ClassNotFoundException: _redirected/_DatatypeFactory
at java.lang.Class.forName0(Native Method) [rt.jar:1.7.0_85]
at java.lang.Class.forName(Class.java:278) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.getProviderClass(FactoryFinder.java:126) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.newInstance(FactoryFinder.java:181) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.newInstance(FactoryFinder.java:150) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.find(FactoryFinder.java:222) [rt.jar:1.7.0_85]
at javax.xml.datatype.DatatypeFactory.newInstance(DatatypeFactory.java:129) [rt.jar:1.7.0_85]
... 23 more
2016-01-14 09:36:02,645 ERROR [org.picketlink.common] (http-/10.5.103.113:8080-21) Exception in processing request:: org.picketlink.common.exceptions.ProcessingException: PL00102: Processing Exception:
at org.picketlink.common.DefaultPicketLinkLogger.processingError(DefaultPicketLinkLogger.java:174)
at org.picketlink.identity.federation.web.handlers.saml2.SAML2AuthenticationHandler$IDPAuthenticationHandler.handleRequestType(SAML2AuthenticationHandler.java:268)
at org.picketlink.identity.federation.web.handlers.saml2.SAML2AuthenticationHandler.handleRequestType(SAML2AuthenticationHandler.java:128)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.processSAMLRequestMessage(AbstractIDPValve.java:861)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.handleSAMLMessage(AbstractIDPValve.java:457)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.invoke(AbstractIDPValve.java:404)
at org.jboss.security.negotiation.NegotiationAuthenticator$WrapperValve.invoke(NegotiationAuthenticator.java:490)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:512)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:559)
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:150)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)
at org.jboss.as.web.sso.ClusteredSingleSignOn.invoke(ClusteredSingleSignOn.java:384)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:854)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:653)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926)
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_85]
Caused by: org.picketlink.common.exceptions.ConfigurationException: javax.xml.datatype.DatatypeConfigurationException: Provider _redirected._DatatypeFactory not found
at org.picketlink.common.DefaultPicketLinkLogger.configurationError(DefaultPicketLinkLogger.java:726)
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.getIssueInstant(XMLTimeUtil.java:101)
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.getIssueInstant(XMLTimeUtil.java:118)
at org.picketlink.identity.federation.api.saml.v2.response.SAML2Response.createResponseType(SAML2Response.java:236)
at org.picketlink.identity.federation.web.handlers.saml2.SAML2AuthenticationHandler$IDPAuthenticationHandler.getResponse(SAML2AuthenticationHandler.java:320)
at org.picketlink.identity.federation.web.handlers.saml2.SAML2AuthenticationHandler$IDPAuthenticationHandler.handleRequestType(SAML2AuthenticationHandler.java:241)
... 17 more
Caused by: javax.xml.datatype.DatatypeConfigurationException: Provider _redirected._DatatypeFactory not found
at javax.xml.datatype.DatatypeFactory.newInstance(DatatypeFactory.java:135) [rt.jar:1.7.0_85]
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.newDatatypeFactory(XMLTimeUtil.java:244)
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.getIssueInstant(XMLTimeUtil.java:99)
... 21 more
Caused by: java.lang.ClassNotFoundException: _redirected/_DatatypeFactory
at java.lang.Class.forName0(Native Method) [rt.jar:1.7.0_85]
at java.lang.Class.forName(Class.java:278) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.getProviderClass(FactoryFinder.java:126) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.newInstance(FactoryFinder.java:181) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.newInstance(FactoryFinder.java:150) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.find(FactoryFinder.java:222) [rt.jar:1.7.0_85]
at javax.xml.datatype.DatatypeFactory.newInstance(DatatypeFactory.java:129) [rt.jar:1.7.0_85]
... 23 more
2016-01-14 09:36:02,648 ERROR [org.apache.catalina.connector] (http-/10.5.103.113:8080-21) JBWEB001018: An exception or error occurred in the container during the request processing: java.lang.RuntimeException: org.picketlink.common.exceptions.ConfigurationException: javax.xml.datatype.DatatypeConfigurationException: Provider _redirected._DatatypeFactory not found
at org.picketlink.identity.federation.api.saml.v2.response.SAML2Response.createResponseType(SAML2Response.java:307)
at org.picketlink.identity.federation.web.util.IDPWebRequestUtil.getErrorResponse(IDPWebRequestUtil.java:304)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.processSAMLRequestMessage(AbstractIDPValve.java:884)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.handleSAMLMessage(AbstractIDPValve.java:457)
at org.picketlink.identity.federation.bindings.tomcat.idp.AbstractIDPValve.invoke(AbstractIDPValve.java:404)
at org.jboss.security.negotiation.NegotiationAuthenticator$WrapperValve.invoke(NegotiationAuthenticator.java:490)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:512)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:559)
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:150)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)
at org.jboss.as.web.sso.ClusteredSingleSignOn.invoke(ClusteredSingleSignOn.java:384)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:854)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:653)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926)
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_85]
Caused by: org.picketlink.common.exceptions.ConfigurationException: javax.xml.datatype.DatatypeConfigurationException: Provider _redirected._DatatypeFactory not found
at org.picketlink.common.DefaultPicketLinkLogger.configurationError(DefaultPicketLinkLogger.java:726)
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.getIssueInstant(XMLTimeUtil.java:101)
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.getIssueInstant(XMLTimeUtil.java:118)
at org.picketlink.identity.federation.api.saml.v2.response.SAML2Response.createResponseType(SAML2Response.java:305)
... 17 more
Caused by: javax.xml.datatype.DatatypeConfigurationException: Provider _redirected._DatatypeFactory not found
at javax.xml.datatype.DatatypeFactory.newInstance(DatatypeFactory.java:135) [rt.jar:1.7.0_85]
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.newDatatypeFactory(XMLTimeUtil.java:244)
at org.picketlink.identity.federation.core.saml.v2.util.XMLTimeUtil.getIssueInstant(XMLTimeUtil.java:99)
... 19 more
Caused by: java.lang.ClassNotFoundException: _redirected/_DatatypeFactory
at java.lang.Class.forName0(Native Method) [rt.jar:1.7.0_85]
at java.lang.Class.forName(Class.java:278) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.getProviderClass(FactoryFinder.java:126) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.newInstance(FactoryFinder.java:181) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.newInstance(FactoryFinder.java:150) [rt.jar:1.7.0_85]
at javax.xml.datatype.FactoryFinder.find(FactoryFinder.java:222) [rt.jar:1.7.0_85]
at javax.xml.datatype.DatatypeFactory.newInstance(DatatypeFactory.java:129) [rt.jar:1.7.0_85]
... 21 more
2016-01-14 09:36:02,741 DEBUG [org.jboss.security.negotiation.NegotiationAuthenticator] (http-/10.5.103.113:8080-14) Header - null
2016-01-14 09:36:02,741 DEBUG [org.jboss.security.negotiation.NegotiationAuthenticator] (http-/10.5.103.113:8080-14) No Authorization Header, initiating negotiation
2016-01-14 09:36:04,425 DEBUG [org.picketlink.common] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) cancelToken::provider=org.picketlink.identity.federation.core.saml.v2.providers.SAML20AssertionTokenProvider@12b24323
2016-01-14 09:36:04,467 DEBUG [org.picketlink.common] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) cancelToken::provider=org.picketlink.identity.federation.core.saml.v2.providers.SAML20AssertionTokenProvider@12b24323
2016-01-14 09:36:05,969 DEBUG [org.jboss.security.negotiation.NegotiationAuthenticator] (http-/10.5.103.113:8080-3) Header - null
Here is what a good LDAP query looks like in the RHDS logs when things are working.
[08/Jan/2016:20:43:18 -0500] conn=494770 fd=67 slot=67 SSL connection from 10.5.103.113 to 10.5.110.51
[08/Jan/2016:20:43:18 -0500] conn=494770 TLS1.0 256-bit AES
[08/Jan/2016:20:43:18 -0500] conn=494770 op=0 BIND dn="uid=picketlink,ou=serviceaccounts,dc=redhat,dc=com" method=128 version=3
[08/Jan/2016:20:43:18 -0500] conn=494770 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=picketlink,ou=serviceaccounts,dc=redhat,dc=com"
[08/Jan/2016:20:43:18 -0500] conn=494770 op=1 SRCH base="dc=redhat,dc=com" scope=2 filter="(uid=dminnich)" attrs="mail cn givenName sn rhatPersonType uid manager rhatCostCenterDesc rhatJobTitle rhatGeo"
[08/Jan/2016:20:43:18 -0500] conn=494770 op=1 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jan/2016:20:43:18 -0500] conn=494770 op=2 SRCH base="uid=nhicher,ou=users,dc=redhat,dc=com" scope=2 filter="(uid=dminnich)" attrs="mail cn givenName sn rhatPersonType uid manager rhatCostCenterDesc rhatJobTitle rhatGeo"
[08/Jan/2016:20:43:18 -0500] conn=494770 op=2 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jan/2016:20:43:18 -0500] conn=494770 op=3 UNBIND
[08/Jan/2016:20:43:18 -0500] conn=494770 op=3 fd=67 closed - U1
Here is what a bad LDAP query looks like in the RHDS logs when this issue is occuring.
[13/Jan/2016:20:45:50 -0500] conn=571912 fd=70 slot=70 SSL connection from 10.5.103.112 to 10.5.110.51
[13/Jan/2016:20:45:50 -0500] conn=571912 TLS1.0 256-bit AES
[13/Jan/2016:20:45:50 -0500] conn=571912 op=0 BIND dn="uid=picketlink,ou=serviceaccounts,dc=redhat,dc=com" method=128 version=3
[13/Jan/2016:20:45:50 -0500] conn=571912 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=picketlink,ou=serviceaccounts,dc=redhat,dc=com"
[13/Jan/2016:20:45:50 -0500] conn=571912 op=1 SRCH base="dc=redhat,dc=com" scope=2 filter="(uid=NYWIhxrXaH3RmdflAt1lLSTE.s01_1452716486786)" attrs="mail cn givenName sn rhatPersonType uid manager rhatCostCenterDesc rhatJobTitle rhatGeo"
[13/Jan/2016:20:45:50 -0500] conn=571912 op=1 RESULT err=0 tag=101 nentries=0 etime=0