[Shib-Users] Strange Attribute retrieval problem in IDP after upgrading from 2.1.2 to 2.1.5
Jeffrey Crawford
We are experiencing a strange failure after we upgraded from Shibboleth
IDP 2.1.2 to 2.1.5. Right after the upgrade we see the users
authenticating to the SP via our IDP, and at first they are all
successful. Shortly thereafter we see successful authentication however
the SP intermittently fails to get the associated attributes. The only
clue we have as to what is going on, is that we see that the IDP is
complaining that the attribute search to our LDAP server closed with the
message "socket closed". We don't have any errors or strange behavior on
the LDAP servers themselves. We can't be entirely sure but the problem
seems to be isolated to SP that use inCommon, we have yet to have a
failure with SP's were we have local copies of SAML 2 metadata on the IDP.
Below is a snippet of the log entries we see (We replaced some server
names to protect the innocent):
=====
12:12:34.533 - INFO [Shibboleth-Access:73] -
20091214T201234Z|128.114.204.180|login.ucsc.edu:443|/profile/Shibboleth/SSO|
12:12:41.758 - INFO
[edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:802]
- PKIX validation info cache cleared
12:12:41.760 - INFO
[edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:802]
- PKIX validation info cache cleared
12:12:49.739 - INFO [edu.vt.middleware.ldap.Authenticator:296] -
Authentication succeeded for user: uid=jeffreyc,ou=orgUnit,dc=ucsc,dc=edu
12:12:49.848 - INFO [Shibboleth-Access:73] -
20091214T201249Z|128.114.204.180|login.ucsc.edu:443|/profile/Shibboleth/SSO|
12:13:04.883 - ERROR
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:838]
- An error occured when attempting to search the LDAP:
{java.naming.provider.url=ldap://ldap-server.ucsc.edu:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.security.protocol=ssl}
javax.naming.ServiceUnavailableException: ldap-server.ucsc.edu:636;
socket closed
at com.sun.jndi.ldap.Connection.readReply(Connection.java:410)
[na:1.5.0_12]
at
com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:611)
[na:1.5.0_12]
at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:534)
[na:1.5.0_12]
at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1944)
[na:1.5.0_12]
at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1806)
[na:1.5.0_12]
at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1731)
[na:1.5.0_12]
at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1748)
[na:1.5.0_12]
at
com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:394)
[na:1.5.0_12]
at
com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:376)
[na:1.5.0_12]
at
com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:358)
[na:1.5.0_12]
at edu.vt.middleware.ldap.Ldap.search(Ldap.java:592)
[vt-ldap-2.8.4.jar:na]
at edu.vt.middleware.ldap.Ldap.search(Ldap.java:466)
[vt-ldap-2.8.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector.searchLdap(LdapDataConnector.java:836)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector.resolve(LdapDataConnector.java:782)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector.resolve(LdapDataConnector.java:1)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.ContextualDataConnector.resolve(ContextualDataConnector.java:76)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.ContextualDataConnector.resolve(ContextualDataConnector.java:1)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.resolveDataConnector(ShibbolethAttributeResolver.java:345)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.resolveDependencies(ShibbolethAttributeResolver.java:377)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.resolveAttribute(ShibbolethAttributeResolver.java:303)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.resolveAttributes(ShibbolethAttributeResolver.java:257)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.resolveAttributes(ShibbolethAttributeResolver.java:130)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML1AttributeAuthority.getAttributes(ShibbolethSAML1AttributeAuthority.java:166)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML1AttributeAuthority.getAttributes(ShibbolethSAML1AttributeAuthority.java:1)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler.resolveAttributes(AbstractSAML1ProfileHandler.java:503)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler.completeAuthenticationRequest(ShibbolethSSOProfileHandler.java:252)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler.processRequest(ShibbolethSSOProfileHandler.java:122)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler.processRequest(ShibbolethSSOProfileHandler.java:1)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:83)
[shibboleth-common-1.1.4.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
[servlet-api.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:630)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:436)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:374)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:302)
[catalina.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.forwardRequest(AuthenticationEngine.java:185)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.returnToProfileHandler(AuthenticationEngine.java:171)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.completeAuthentication(AuthenticationEngine.java:520)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.service(AuthenticationEngine.java:213)
[shibboleth-identityprovider-2.1.5.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
[servlet-api.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:630)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:436)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:374)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:302)
[catalina.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.forwardRequest(AuthenticationEngine.java:185)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.returnToAuthenticationEngine(AuthenticationEngine.java:149)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.service(UsernamePasswordLoginServlet.java:107)
[shibboleth-identityprovider-2.1.5.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
[servlet-api.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:na]
at
edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:77)
[shibboleth-identityprovider-2.1.5.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:na]
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
[catalina.jar:na]
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
[catalina.jar:na]
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
[catalina.jar:na]
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
[catalina.jar:na]
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
[catalina.jar:na]
at
org.terracotta.modules.tomcat.tomcat_5_5.SessionValve55.invoke(SessionValve55.java:52)
[na:na]
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
[catalina.jar:na]
at
org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190)
[tomcat-coyote.jar:na]
at
org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:283)
[tomcat-coyote.jar:na]
at
org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:767)
[tomcat-coyote.jar:na]
at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:697)
[tomcat-coyote.jar:na]
at
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:889)
[tomcat-coyote.jar:na]
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690)
[tomcat-coyote.jar:na]
at java.lang.Thread.run(Thread.java:595) [na:1.5.0_12]
12:13:04.893 - WARN
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler:507]
- Error resolving attributes for principal 'jeffreyc'. No name
identifier or attribute statement will be included in response
12:13:04.934 - INFO [Shibboleth-Audit:714] -
20091214T201304Z|urn:mace:shibboleth:1.0:profiles:AuthnRequest||https://ucready.berkeley.edu/shibboleth-sp|urn:mace:shibboleth:2.0:profiles:saml1:sso|urn:mace:incommon:ucsc.edu|urn:oasis:names:tc:SAML:1.0:profiles:browser-post|_2eee238b28e74b4a8c845bdc57ee4cf9|jeffreyc|urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified|||_04de8bc8059aff9bc0e303b603cf4fae,|
====
Thanks
Jeffrey
Daniel Fisher
> Hello Everyone,
>
> We are experiencing a strange failure after we upgraded from
> Shibboleth IDP 2.1.2 to 2.1.5. Right after the upgrade we see the
> users authenticating to the SP via our IDP, and at first they are all
> successful. Shortly thereafter we see successful authentication
> however the SP intermittently fails to get the associated attributes.
> The only clue we have as to what is going on, is that we see that the
> IDP is complaining that the attribute search to our LDAP server closed
> with the message "socket closed". We don't have any errors or strange
> behavior on the LDAP servers themselves. We can't be entirely sure but
> the problem seems to be isolated to SP that use inCommon, we have yet
> to have a failure with SP's were we have local copies of SAML 2
> metadata on the IDP.
https://bugs.internet2.edu/jira/browse/SC-87
I'm not sure how an IDP upgrade could have revealed this problem.
I would expect this to occur in 2.1.2 as well.
--Daniel Fisher
Jeffrey Crawford
We are positive we didn't get the error in 2.1.2, we still have the logs
for that time but failed to find any instances of the error before we
deployed 2.1.5.
the vt-ldap.jar file did fix the the error on the first email but now we
are getting a new one. I'm wondering if this is being caused by some
sort of dropped connection as well, sort of like an xml request is being
cut short:
====
16:02:13.553 - ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:88]
- Error occured while processing request
org.w3c.dom.ls.LSException: null
at
org.apache.xml.serializer.dom3.LSSerializerImpl.write(LSSerializerImpl.java:1087)
[na:na]
at
org.opensaml.xml.util.XMLHelper.writeNode(XMLHelper.java:899)
[xmltooling-1.2.1.jar:na]
at
org.opensaml.saml1.binding.encoding.HTTPSOAP11Encoder.doEncode(HTTPSOAP11Encoder.java:100)
[opensaml-2.3.1.jar:na]
at
org.opensaml.ws.message.encoder.BaseMessageEncoder.encode(BaseMessageEncoder.java:50)
[openws-1.3.0.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler.encodeResponse(AbstractSAMLProfileHandler.java:528)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler.processRequest(AttributeQueryProfileHandler.java:120)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler.processRequest(AttributeQueryProfileHandler.java:1)
[shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:83)
[shibboleth-common-1.1.4.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
[servlet-api.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:na]
at
org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:880)
[tomcat-coyote.jar:na]
at
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:719)
[tomcat-coyote.jar:na]
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2081)
[tomcat-coyote.jar:na]
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
[na:1.5.0_12]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
[na:1.5.0_12]
at java.lang.Thread.run(Thread.java:595) [na:1.5.0_12]
Caused by: org.apache.xml.serializer.utils.WrappedRuntimeException: null
at
org.apache.xml.serializer.dom3.DOM3SerializerImpl.serializeDOM3(DOM3SerializerImpl.java:113)
[na:na]
at
org.apache.xml.serializer.dom3.LSSerializerImpl.write(LSSerializerImpl.java:1069)
[na:na]
... 26 common frames omitted
16:02:13.562 - ERROR
[edu.internet2.middleware.shibboleth.common.profile.provider.JSPErrorHandler:85]
- Could not dispatch to error
JSP page: /error.jsp
java.lang.IllegalStateException: Cannot forward after response has been
committed
at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:312)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:302)
[catalina.jar:na]
at
edu.internet2.middleware.shibboleth.common.profile.provider.JSPErrorHandler.processRequest(JSPErrorHandler.java:82)
[shibboleth-common-1.1.4.jar:na]
at
edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:97)
[shibboleth-common-1.1.4.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
[servlet-api.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
[catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:na]
at
org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:880)
[tomcat-coyote.jar:na]
at
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:719)
[tomcat-coyote.jar:na]
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2081)
[tomcat-coyote.jar:na]
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
[na:1.5.0_12]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
[na:1.5.0_12]
at java.lang.Thread.run(Thread.java:595) [na:1.5.0_12]
====
Thanks
Jeffrey
Daniel Fisher
You should see a debug message that looks like:
AttributeResolver resolved, for principal XXXXX, the attributes: [LIST
OF ATTRS]
--Daniel Fisher
Fabio Spelta
> Hello Everyone,
>
> We are experiencing a strange failure after we upgraded from Shibboleth
> IDP 2.1.2 to 2.1.5. Right after the upgrade we see the users
> authenticating to the SP via our IDP, and at first they are all
> successful. Shortly thereafter we see successful authentication however
> the SP intermittently fails to get the associated attributes. The only
> clue we have as to what is going on, is that we see that the IDP is
> complaining that the attribute search to our LDAP server closed with the
> message "socket closed".
We are experiencing the same issue on our environment, and it all begun
only after the upgrade. The logs are idenctical. The only difference we
experience is that the IdP is unable to get the attributes all the time,
not only intermittently.
--
Fabio Spelta <fabio....@unimib.it>
Universita` degli Studi di Milano-Bicocca
Daniel Fisher
environment.
JDK Version:
Container Version:
Output of jar -tf idp.war:
LDAP Server:
LDAP Data Connector Config:
Description of behavior and exceptions received:
Relevant output of vt-ldap debug:
Relevant output of idp-process.log:
Thanks.
--Daniel Fisher
Jeffrey Crawford
Just to make sure you are aware we have had to revert back to the
previous version as this was causing service outages we could not
tolerate in our production enviroment. We will have to set up a load
balancer in our test environment to try and reproduce this, however this
won't happen until after new year. However reverting to 2.1.2 has fixed
both the Ldap error and the error described below. We still don't see
this error in test which is not load balanced (It is using round robin DNS)
So now thats out of the way, no, we would not see that the resolver
returned attributes, at least not until a new attempt was started, we
either got a failure or we got success. To further the example below
here is an example of the three lines proceeding the error:
====
16:01:50.622 - INFO [Shibboleth-Access:73] -
20091216T000150Z|169.229.219.16|login.ucsc.edu:8443|/profile/SAML1/SOAP/AttributeQuery|
16:01:58.177 - INFO
[edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:802]
- PKIX validation info cache cleared
16:01:58.179 - INFO
[edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:802]
- PKIX validation info cache cleared
====
After thoes lines we would see the error block as seen below
Scott Cantor
If you mean this...
>
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcher
> Servlet:88]
> >> - Error occured while processing request
> >> org.w3c.dom.ls.LSException: null
Etc.
That looks more like a timeout from the SP side causing the socket to close
and the SOAP logic to fail to write out the XML.
Does the SP end log a timeout on a query?
You have to have both ends to draw any conclusions, really.
-- Scott
Jeffrey Crawford
I'll have to try and coordinate with them to find out if they were
receiving timeouts. However to add to that the behavior was
indiscriminate about who our customers were trying to connect to,
meaning all of the service providers were having the same *timeout*
issue and reverting back to 2.1.2 eliminated that.
We don't have any local SP that are connected to our production system
(Well we have one but it is so seldom used that it never saw the issue)
and the most frustrating part is that we can't reproduce in test.
I'll work on getting a snip of the SP log on one of the systems.
Jeffrey
Fabio Spelta
> If you are experiencing this problem,
Unfortunately we are and up to date the only "workaround" we found is to
revert our setup to 2.1.2 too.
In the last hour, _sometimes_ the connection to fetch the attribute
worked fine, so I can now say that the behaviour is just precisely
identical to the one described by Jeffrey.
> please post some data about your
> environment.
Right. Here it is.
> JDK Version:
"1.6.0_12"
> Container Version:
5.5
> Output of jar -tf idp.war:
META-INF/
META-INF/MANIFEST.MF
WEB-INF/
WEB-INF/web.xml
WEB-INF/lib/
WEB-INF/lib/activation-1.1.jar
WEB-INF/lib/avalon-framework-4.1.3.jar
WEB-INF/lib/bcprov-jdk15-1.43.jar
WEB-INF/lib/beanshell-engine-20080611.jar
WEB-INF/lib/c3p0-0.9.1.2.jar
WEB-INF/lib/commons-codec-1.3.jar
WEB-INF/lib/commons-collections-3.1.jar
WEB-INF/lib/commons-httpclient-3.1.jar
WEB-INF/lib/commons-lang-2.1.jar
WEB-INF/lib/commons-logging-1.1.jar
WEB-INF/lib/commons-pool-1.3.jar
WEB-INF/lib/groovy-engine-20080611.jar
WEB-INF/lib/janino-2.5.10.jar
WEB-INF/lib/jargs-1.0.jar
WEB-INF/lib/jcip-annotations-1.0.jar
WEB-INF/lib/jcl-over-slf4j-1.5.8.jar
WEB-INF/lib/jgrapht-jdk1.5-0.7.3.jar
WEB-INF/lib/joda-time-1.6.jar
WEB-INF/lib/jruby-engine-20080611.jar
WEB-INF/lib/js-engine-20080611.jar
WEB-INF/lib/jul-to-slf4j-1.5.8.jar
WEB-INF/lib/jython-engine-20080611.jar
WEB-INF/lib/log4j-1.2.12.jar
WEB-INF/lib/log4j-over-slf4j-1.5.8.jar
WEB-INF/lib/logback-classic-0.9.17.jar
WEB-INF/lib/logback-core-0.9.17.jar
WEB-INF/lib/logkit-1.0.1.jar
WEB-INF/lib/mail-1.4.1.jar
WEB-INF/lib/not-yet-commons-ssl-0.3.9.jar
WEB-INF/lib/opensaml-2.3.1.jar
WEB-INF/lib/openws-1.3.0.jar
WEB-INF/lib/rhino-1.7R1.jar
WEB-INF/lib/scripting-api-1.0.jar
WEB-INF/lib/shibboleth-common-1.1.4.jar
WEB-INF/lib/shibboleth-identityprovider-2.1.5.jar
WEB-INF/lib/shibboleth-jce-1.1.0.jar
WEB-INF/lib/slf4j-api-1.5.8.jar
WEB-INF/lib/spring-beans-2.5.6.jar
WEB-INF/lib/spring-context-2.5.6.jar
WEB-INF/lib/spring-context-support-2.5.6.jar
WEB-INF/lib/spring-core-2.5.6.jar
WEB-INF/lib/spring-web-2.5.6.jar
WEB-INF/lib/ssh2-213.jar
WEB-INF/lib/svnkit-1.3.0.jar
WEB-INF/lib/velocity-1.5.jar
WEB-INF/lib/vt-ldap-2.8.4.jar
WEB-INF/lib/xmlsec-1.4.3.jar
WEB-INF/lib/xmltooling-1.2.1.jar
images/
error-404.jsp
error.jsp
images/internet2.gif
images/logo.jpg
images/logopersonal.png
login-error.jsp
login.jsp
shibboleth.jsp
> LDAP Server:
OpenLDAP 2.3.43
> LDAP Data Connector Config:
<resolver:DataConnector id="myLDAP" xsi:type="LDAPDirectory"
xmlns="urn:mace:shibboleth:2.0:resolver:dc"
ldapURL="ldaps://ldapserveraddr" baseDN="dc=base,dc=it"
principal="cn=user,dc=base,dc=it"
principalCredential="whatever">
<FilterTemplate>
<![CDATA[
(uid=$requestContext.principalName)
]]>
</FilterTemplate>
</resolver:DataConnector>
> Description of behavior and exceptions received:
After the upgrade of the IDP to Shibboleth 2.1.5 we often experiment
this behaviour. The authentication (which now happens over LDAP) works
fine. Then when the IDP connects to the LDAP server to fetch the data,
it logs what I pasted below. At the same time, on the LDAP server we
log:
conn=5552625 fd=24 ACCEPT from IP=X.Y.Z.Q:6384 (IP=0.0.0.0:636)
conn=5552625 fd=24 TLS established tls_ssf=128 ssf=128
conn=5552625 op=0 BIND dn="cn=user,dc=base,dc=it" method=128
conn=5552625 op=0 BIND dn="cn=user,dc=base,dc=it" mech=SIMPLE ssf=0
conn=5552625 op=0 RESULT tag=97 err=0 text=
conn=5552625 fd=24 closed (connection lost)
When things go well, we log on the LDAP server:
conn=5553771 fd=24 ACCEPT from IP=149.132.2.23:6562 (IP=0.0.0.0:636)
conn=5553771 fd=24 TLS established tls_ssf=128 ssf=128
conn=5553771 op=0 BIND dn="cn=user,dc=base,dc=it" method=128
conn=5553771 op=0 BIND dn="cn=user,dc=base,dc=it" mech=SIMPLE ssf=0
conn=5553771 op=0 RESULT tag=97 err=0 text=
conn=5553771 op=1 SRCH base="dc=base,dc=it" scope=2 deref=3
filter="(uid=end...@base.it)"
conn=5553771 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text=
conn=5553771 op=2 SRCH base="dc=base,dc=it" scope=2 deref=3
filter="(uid=end...@base.it)"
conn=5553771 op=2 SEARCH RESULT tag=101 err=0 nentries=1 text=
> Relevant output of vt-ldap debug:
> Relevant output of idp-process.log:
18:54:12.352 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:249] - Specific attributes for principal end...@base.it were not requested, resolving all attributes.
18:54:12.352 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:285] - Resolving attribute uid for principal end...@base.it
18:54:12.352 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:325] - Resolving data connector myLDAP for principal end...@base.it
18:54:12.353 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:765] - Search filter: (uid=end...@base.it)
18:54:12.354 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:781] - Retrieving attributes from LDAP
18:54:27.364 - ERROR
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:838] - An error occured when attempting to search the LDAP: {java.naming.provider.url=ldap://ourserver:636, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}
javax.naming.ServiceUnavailableException: ourserver:636; socket closed
at com.sun.jndi.ldap.Connection.readReply(Connection.java:416)
[na:1.6.0_12]
at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:611)
[na:1.6.0_12]
at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:534)
[na:1.6.0_12]
at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1948) [na:1.6.0_12]
at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1810) [na:1.6.0_12]
at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1735) [na:1.6.0_12]
at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1752) [na:1.6.0_12]
at
com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:394) [na:1.6.0_12]
at
com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:376) [na:1.6.0_12]
at
com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:358) [na:1.6.0_12]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
[servlet-api-2.4.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:679) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:461) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:399) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301) [catalina.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.forwardRequest(AuthenticationEngine.java:185) [shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.returnToProfileHandler(AuthenticationEngine.java:171) [shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.completeAuthentication(AuthenticationEngine.java:520) [shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.service(AuthenticationEngine.java:213) [shibboleth-identityprovider-2.1.5.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
[servlet-api-2.4.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:679) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:461) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:399) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301) [catalina.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.forwardRequest(AuthenticationEngine.java:185) [shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.returnToAuthenticationEngine(AuthenticationEngine.java:149) [shibboleth-identityprovider-2.1.5.jar:na]
at
edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.service(UsernamePasswordLoginServlet.java:107) [shibboleth-identityprovider-2.1.5.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
[servlet-api-2.4.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) [catalina.jar:na]
at
edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:77) [shibboleth-identityprovider-2.1.5.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188) [catalina.jar:na]
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:204) [catalina.jar:na]
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172) [catalina.jar:na]
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [catalina.jar:na]
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117) [catalina.jar:na]
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108) [catalina.jar:na]
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174) [catalina.jar:na]
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
[tomcat-ajp.jar:na]
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:283)
[tomcat-ajp.jar:na]
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:773)
[tomcat-ajp.jar:na]
at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:703) [tomcat-ajp.jar:na]
at org.apache.jk.common.ChannelSocket
$SocketConnection.runIt(ChannelSocket.java:895) [tomcat-ajp.jar:na]
at org.apache.tomcat.util.threads.ThreadPool
$ControlRunnable.run(ThreadPool.java:689) [tomcat-util.jar:5.1]
at java.lang.Thread.run(Thread.java:619) [na:1.6.0_12]
18:54:27.365 - WARN
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler:507] - Error resolving attributes for principal 'end...@base.it'. No name identifier or attribute statement will be included in response
Thank you very much for taking care of this.
Scott Cantor
> Unfortunately all of the SP systems belong to different companies so
> I'll have to try and coordinate with them to find out if they were
> receiving timeouts. However to add to that the behavior was
> indiscriminate about who our customers were trying to connect to,
> meaning all of the service providers were having the same *timeout*
> issue and reverting back to 2.1.2 eliminated that.
It should be fairly obvious when you connect to one if it's pausing for an
apparently longish period.
If it's not a timeout, then it's not obvious to me how LDAP has anything to
do with it. And if there's a regression that isn't LDAP related, people
should be seeing it...
-- Scott
Jeffrey Crawford
in so I imagine there is a timeout. Please note that the ldap issue was
corrected by using the updated vt-ldap library as mentioned by Daniel in
the second thread, a second problem with the
"org.w3c.dom.ls.LSException: null" error message.
Furthermore I imaging this has something to do with load balancers
silently dropping connections so this may be specific to installations
with that kind of arch. Our test env. doesn't have LB's so that is
probably why we are not seeing problems there.
Jeffrey
Scott Cantor
> Yes when the error occurs there is an unusually long lag trying to log
> in so I imagine there is a timeout.
Ok. I just wanted to rule out something message/SOAP/whatever related.
> Please note that the ldap issue was
> corrected by using the updated vt-ldap library as mentioned by Daniel in
> the second thread, a second problem with the
> "org.w3c.dom.ls.LSException: null" error message.
Right, but I think that message is a red herring. I suspect that any time
the SP times out, that might show up in the IdP log if the IdP eventually
completes its transaction and tries to send back an answer. I don't know
that for sure, but somebody should be able to verify that.
> Furthermore I imaging this has something to do with load balancers
> silently dropping connections so this may be specific to installations
> with that kind of arch. Our test env. doesn't have LB's so that is
> probably why we are not seeing problems there.
If the whole issue was with LDAP, I would assume that the fix would not
require rolling back the IdP, only the LDAP jar.
-- Scott
Jeffrey Crawford
Scott Cantor wrote:
> Jeffrey Crawford wrote on 2009-12-17:
>> Yes when the error occurs there is an unusually long lag trying to log
>> in so I imagine there is a timeout.
>
> Ok. I just wanted to rule out something message/SOAP/whatever related.
>
>> Please note that the ldap issue was
>> corrected by using the updated vt-ldap library as mentioned by Daniel in
>> the second thread, a second problem with the
>> "org.w3c.dom.ls.LSException: null" error message.
>
> Right, but I think that message is a red herring. I suspect that any time
> the SP times out, that might show up in the IdP log if the IdP eventually
> completes its transaction and tries to send back an answer. I don't know
> that for sure, but somebody should be able to verify that.
Ok that may be the case but the SP's are no longer timing out when using
version 2.1.2. If that's not what you meant I'm probably
misunderstanding the statement.
I may be able to verify after we get a similar LB in place in our test
environment, however this will have to be done by a different dept. and
they will not have any time to do so until Jan.
>
>> Furthermore I imaging this has something to do with load balancers
>> silently dropping connections so this may be specific to installations
>> with that kind of arch. Our test env. doesn't have LB's so that is
>> probably why we are not seeing problems there.
>
> If the whole issue was with LDAP, I would assume that the fix would not
> require rolling back the IdP, only the LDAP jar.
Ok the 2.1.2 version is using ldap-2.8.2.jar and the 2.1.5 version is
using vt-ldap-2.8.4 which we upgraded to vt-ldap-2.8.5.
Is it possible that the 2.1.5 version is relying more on persistent
connections than the older versions did?
>
> -- Scott
>
>
Jeffrey
Jeffrey Crawford
Are you guys using load balancers in your environment? We only see this
in prod where we have the infrastructure in place but test never seems
to have the problem. but the cluster is DNS round robin, not load balancers.
Do you agree with that?
Jeffrey
Scott Cantor
> Ok that may be the case but the SP's are no longer timing out when using
> version 2.1.2. If that's not what you meant I'm probably
> misunderstanding the statement.
Maybe I misunderstood, but I thought the error message was showing up with
the newer LDAP library + 2.1.5, but not with 2.1.2. So my point was just
that if the thing seems to hang a bit and then you get those DOM/SOAP
errors, that would just mean that the timeout causes the socket to close and
then the IdP tries to write back to the closed socket.
> Is it possible that the 2.1.5 version is relying more on persistent
> connections than the older versions did?
I don't know why it would have, but either the connector plugin changed, or
it didn't, I would assume. svn would know.
-- Scott
Fabio Spelta
> Fabio,
>
> Are you guys using load balancers in your environment? We only see this
> in prod where we have the infrastructure in place but test never seems
> to have the problem. but the cluster is DNS round robin, not load balancers.
>
> Do you agree with that?
We do indeed have a load balancer in front of the LDAP servers.
Fabio Spelta
> > Container Version:
>
> 5.5
I upgraded tomcat to version 6.0.20 and I tested the new environment
(with shib 2.1.5) with a pretty big amount of connections from various
browsers: so far there's no issue.
I'll update the thread if some will arise.
Thank you so much.
Fabio Spelta
> > > Container Version:
> >
> > 5.5
>
> I upgraded tomcat to version 6.0.20 and I tested the new environment
> (with shib 2.1.5) with a pretty big amount of connections from various
> browsers: so far there's no issue.
>
> I'll update the thread if some will arise.
I am sorry to inform you that after some hours of tests it happened
again.
The container used now is tomcat 6.0.20. The behaviour is idenctical.
Thank you so much,
Daniel Fisher
>> Description of behavior and exceptions received:
>>
> After the upgrade of the IDP to Shibboleth 2.1.5 we often experiment
> this behaviour. The authentication (which now happens over LDAP) works
> fine. Then when the IDP connects to the LDAP server to fetch the data,
> it logs what I pasted below. At the same time, on the LDAP server we
> log:
>
> conn=5552625 fd=24 ACCEPT from IP=X.Y.Z.Q:6384 (IP=0.0.0.0:636)
> conn=5552625 fd=24 TLS established tls_ssf=128 ssf=128
> conn=5552625 op=0 BIND dn="cn=user,dc=base,dc=it" method=128
> conn=5552625 op=0 BIND dn="cn=user,dc=base,dc=it" mech=SIMPLE ssf=0
> conn=5552625 op=0 RESULT tag=97 err=0 text=
> conn=5552625 fd=24 closed (connection lost)
>
> When things go well, we log on the LDAP server:
>
> conn=5553771 fd=24 ACCEPT from IP=149.132.2.23:6562 (IP=0.0.0.0:636)
> conn=5553771 fd=24 TLS established tls_ssf=128 ssf=128
> conn=5553771 op=0 BIND dn="cn=user,dc=base,dc=it" method=128
> conn=5553771 op=0 BIND dn="cn=user,dc=base,dc=it" mech=SIMPLE ssf=0
> conn=5553771 op=0 RESULT tag=97 err=0 text=
> conn=5553771 op=1 SRCH base="dc=base,dc=it" scope=2 deref=3
> filter="(uid=end...@base.it)"
> conn=5553771 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text=
> conn=5553771 op=2 SRCH base="dc=base,dc=it" scope=2 deref=3
> filter="(uid=end...@base.it)"
> conn=5553771 op=2 SEARCH RESULT tag=101 err=0 nentries=1 text=
>
>
>
Do you have any timestamps to go along with these ldap logs?
--Daniel Fisher
Jeffrey Crawford
Fabio Spelta
Yes I do, here's the full logs, sorry. It all happens in a matter of
seconds:
------------------
failed attempt
------------------
Dec 17 18:16:39 ldapsrv slapd[5964]: conn=5552625 fd=24 ACCEPT from
IP=149.132.2.23:6384 (IP=0.0.0.0:636)
Dec 17 18:16:39 ldapsrv slapd[5964]: conn=5552625 fd=24 TLS established
tls_ssf=128 ssf=128
Dec 17 18:16:39 ldapsrv slapd[5964]: conn=5552625 op=0 BIND
dn="cn=user,dc=base,dc=it" method=128
Dec 17 18:16:39 ldapsrv slapd[5964]: conn=5552625 op=0 BIND
dn="cn=user,dc=base,dc=it" mech=SIMPLE ssf=0
Dec 17 18:16:39 ldapsrv slapd[5964]: conn=5552625 op=0 RESULT tag=97
err=0 text=
Dec 17 18:16:43 ldapsrv slapd[5964]: conn=5552625 fd=24 closed
(connection lost)
------------------
successful attempt
------------------
Dec 17 18:24:22 ldapsrv slapd[5964]: conn=5553771 fd=24 ACCEPT from
IP=149.132.2.23:6562 (IP=0.0.0.0:636)
Dec 17 18:24:22 ldapsrv slapd[5964]: conn=5553771 fd=24 TLS established
tls_ssf=128 ssf=128
Dec 17 18:24:22 ldapsrv slapd[5964]: conn=5553771 op=0 BIND
dn="cn=user,dc=base,dc=it" method=128
Dec 17 18:24:22 ldapsrv slapd[5964]: conn=5553771 op=0 BIND
dn="cn=user,dc=base,dc=it" mech=SIMPLE ssf=0
Dec 17 18:24:22 ldapsrv slapd[5964]: conn=5553771 op=0 RESULT tag=97
err=0 text=
Dec 17 18:24:45 ldapsrv slapd[5964]: conn=5553771 op=1 SRCH
base="dc=base,dc=it" scope=2 deref=3 filter="(uid=end...@base.it)"
Dec 17 18:24:45 ldapsrv slapd[5964]: conn=5553771 op=1 SEARCH RESULT
tag=101 err=0 nentries=1 text=
Dec 17 18:24:45 ldapsrv slapd[5964]: conn=5553771 op=2 SRCH
base="dc=base,dc=it" scope=2 deref=3 filter="(uid=end...@base.it)"
Dec 17 18:24:45 ldapsrv slapd[5964]: conn=5553771 op=2 SEARCH RESULT
tag=101 err=0 nentries=1 text=
Thank you very much for your interest.
Mark Southam
09:09:32.799 - ERROR [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:811] - Could not retrieve Ldap object from pool
java.lang.NullPointerException: null
at java.util.Hashtable.__tc_put(Unknown Source) [na:na]
at java.util.Hashtable.put(Unknown Source) [na:na]
at edu.vt.middleware.ldap.Ldap.bind(Ldap.java:1739) [vt-ldap-2.8.5.jar:na]
at edu.vt.middleware.ldap.Ldap.connect(Ldap.java:1535) [vt-ldap-2.8.5.jar:na]
at edu.vt.middleware.ldap.PoolableLdapFactory.activateObject(PoolableLdapFactory.java:91) [vt-ldap-2.8.5.jar:na]
at org.apache.commons.pool.impl.StackObjectPool.borrowObject(StackObjectPool.java:136) [commons-pool-1.3.jar:1.3]
at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector.validate(LdapDataConnector.java:803) [shibboleth-common-1.1.4.jar:na]
at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.validate(ShibbolethAttributeResolver.java:145) [shibboleth-common-1.1.4.jar:na]
at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.onNewContextCreated(ShibbolethAttributeResolver.java:500) [shibboleth-common-1.1.4.jar:na]
at edu.internet2.middleware.shibboleth.common.config.BaseService.loadContext(BaseService.java:173) [shibboleth-common-1.1.4.jar:na]
at edu.internet2.middleware.shibboleth.common.config.BaseReloadableService.initialize(BaseReloadableService.java:147) [shibboleth-common-1.1.4.jar:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [na:1.6.0_12]
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) [na:1.6.0_12]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) [na:1.6.0_12]
at java.lang.reflect.Method.invoke(Unknown Source) [na:1.6.0_12]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1414) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1375) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1335) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:473) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:409) [spring-beans-2.5.6.jar:2.5.6]
at java.security.AccessController.doPrivileged(Native Method) [na:1.6.0_12]
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:380) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:264) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:261) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:185) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:429) [spring-beans-2.5.6.jar:2.5.6]
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:728) [spring-context-2.5.6.jar:2.5.6]
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:380) [spring-context-2.5.6.jar:2.5.6]
at org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:255) [spring-web-2.5.6.jar:2.5.6]
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:199) [spring-web-2.5.6.jar:2.5.6]
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:45) [spring-web-2.5.6.jar:2.5.6]
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3843) [catalina.jar:na]
at org.apache.catalina.core.StandardContext.start(StandardContext.java:4342) [catalina.jar:na]
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:791) [catalina.jar:na]
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:771) [catalina.jar:na]
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:525) [catalina.jar:na]
at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:627) [catalina.jar:na]
at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:553) [catalina.jar:na]
at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:488) [catalina.jar:na]
at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1149) [catalina.jar:na]
at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:311) [catalina.jar:na]
at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117) [catalina.jar:na]
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1053) [catalina.jar:na]
at org.apache.catalina.core.StandardHost.start(StandardHost.java:719) [catalina.jar:na]
at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1045) [catalina.jar:na]
at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:443) [catalina.jar:na]
at org.apache.catalina.core.StandardService.start(StandardService.java:516) [catalina.jar:na]
at org.apache.catalina.core.StandardServer.start(StandardServer.java:710) [catalina.jar:na]
at org.apache.catalina.startup.Catalina.start(Catalina.java:578) [catalina.jar:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [na:1.6.0_12]
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) [na:1.6.0_12]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) [na:1.6.0_12]
at java.lang.reflect.Method.invoke(Unknown Source) [na:1.6.0_12]
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) [bootstrap.jar:na]
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) [bootstrap.jar:na]
09:09:32.799 - ERROR [edu.internet2.middleware.shibboleth.common.config.BaseService:187] - Configuration was not loaded for shibboleth.AttributeResolver service, error creating components. The root cause of this error was: edu.internet2.middleware.shibboleth.common.attribute.resolver.AttributeResolutionException: An error occurred when attempting to retrieve a LDAP connection from the pool
Mark Southam
Snr Systems Engineer
Integration Services
RM Education Plc
Email: msou...@rm.com
Tel: 01235 823366
Fax: 01235 823358
www.rm.com
------------------
failed attempt
------------------
------------------
successful attempt
------------------
____________________________________________________________________
Don’t miss out on our New Year Offers. There are so many ICT bargains to be had!
http://www.rm.com/offers2010
Offers end 28th February 2010!
____________________________________________________________________
P.S. Think Green - don't print this email unless you really need to.
This message is confidential, so please treat it appropriately and for its intended purpose only. In particular, if it refers to any technical data, terms or prices not generally available or known, such items are "commercially sensitive information" within the terms of the Freedom of Information Act 2000 and related laws. As it would be prejudicial to RM's commercial interests if these were disclosed, please refrain from doing so.
As Internet communications are not secure, please be aware that RM cannot accept responsibility for its contents. Any views or opinions presented are those of the author only and not of RM. If you are not the intended recipient of this e-mail, please accept our apologies and arrange for copies of it to be deleted. For your information, RM may intercept incoming and outgoing email communications.
RM Education plc
Registered Office: New Mill House, 183 Milton Park, Abingdon, Oxfordshire, OX14 4SE, England
Registered Number: 1148594
Daniel Fisher
please post your ldap data connector config.
Jeffrey Crawford
ldap jar seems to help the ldap part but the second error that seem to
be releated to:
"edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:88"
The compleate stack dump is in the third thread from the initial request.
We don't have a load balancer in our test environment so I can't
reproduce any of these issues in our test instance. We didn't see any of
this until it went to prod and through a load balancer.
Jeffrey
Chad La Joie
On 2/3/10 12:39 PM, Jeffrey Crawford wrote:
> Has there been any new information regarding this issue, changing the
> ldap jar seems to help the ldap part but the second error that seem to
> be releated to:
>
> "edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:88"
It has nothing to do with the dispatcher, that's just where all uncaught
exception get caught and a generic error message is given.
> We don't have a load balancer in our test environment so I can't
> reproduce any of these issues in our test instance. We didn't see any of
> this until it went to prod and through a load balancer.
Well, assuming everything else is the same it seems pretty clear that it
is something to do with the load balancer and how they are handling
connections. Have you tried asking your load balancer vendor about
this? Maybe this is an issue they've seen before.
--
Chad La Joie
www.itumi.biz
trusted identities, delivered
Jeffrey Crawford
After talking to our Network admin responsible for the LB, he says that
the connection persistence is about 5 minutes currently. Therefore his
question was should he set up the connections to be sticky? or should he
just increase the persistence but we would have to tell him by how much
ie. He won't make it indefinite.
He also mentioned that if the client is able to perform a "keepalive"
operation less than 5 minutes then that would work too. I'm however not
sure where to set that.
Does any of this help?
Jeffrey
Mark Southam
<resolver:DataConnector id="directory" xsi:type="LDAPDirectory" xmlns="urn:mace:shibboleth:2.0:resolver:dc" baseDN="%baseDN%">
<resolver:Dependency ref="principalRegexSplit" />
<FilterTemplate>
<![CDATA[
(sAMAccountName=${principalRegexSplit.get(0)})
]]>
</FilterTemplate>
<ReturnAttributes>samaccountname</ReturnAttributes>
<LDAPProperty name="poolInitialSize" value="5"/>
<LDAPProperty name="poolMaxIdleSize" value="5"/>
<LDAPProperty name="java.naming.security.authentication" value="GSSAPI"/>
<LDAPProperty name="java.naming.referral" value="follow"/>
<LDAPProperty name="cacheResults" value="true"/>
</resolver:DataConnector>
Mark Southam
<resolver:DataConnector id="directory" xsi:type="LDAPDirectory" xmlns="urn:mace:shibboleth:2.0:resolver:dc" ldapURL="LDAP://%ldapserver%" baseDN="%baseDN%">
<resolver:Dependency ref="principalRegexSplit" />
<FilterTemplate>
<![CDATA[
(sAMAccountName=${principalRegexSplit.get(0)})
]]>
</FilterTemplate>
<ReturnAttributes>samaccountname</ReturnAttributes>
<LDAPProperty name="poolInitialSize" value="5"/>
<LDAPProperty name="poolMaxIdleSize" value="5"/>
<LDAPProperty name="java.naming.security.authentication" value="GSSAPI"/>
<LDAPProperty name="java.naming.referral" value="follow"/>
<LDAPProperty name="cacheResults" value="true"/>
</resolver:DataConnector>
Snr Systems Engineer
Integration Services
RM Education Plc
Email: msou...@rm.com
Tel: 01235 823366
Fax: 01235 823358
www.rm.com
-----Original Message-----
From: Daniel Fisher [mailto:dfi...@vt.edu]
Sent: 19 January 2010 14:54