IDP with CAS integration

Mon Jul 7 10:37:32 EDT 2014

Dear comunity,

I'm struggling with a Problem between IDP (2.3.8) and remote CAS server (3 tier configurated). Sometime (I cannot identify when and how) the SP login stucks on the following error:

Navigator:
URL: https://testidp.unifr.ch/idp/Authn/RemoteUser?ticket=ST-12-LGnqK9uu4jA7YZDBE6FR-login.unifr.ch
Display:
  SHIBBOLETH
  ERROR
  An error occurred while processing your request. Please contact your helpdesk or user ID office for assistance.
  This service requires cookies. Please ensure that they are enabled and try your going back to your desired resource and trying to login again.
  Use of your browser's back button may cause specific errors that can be resolved by going back to your desired resource and trying to login again.
  If you think you were sent here in error, please contact technical support

idp-process.log:
16:25:01.506 - DEBUG [edu.internet2.middleware.shibboleth.idp.StatusServlet:121] - Attempting to authenticate client '127.0.0.1'
16:25:01.507 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:226] - Selecting persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE persistentId = ? AND deactivationDate IS NULL
16:25:01.507 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:233] - Setting prepared statement parameter 1: 1
16:25:01.582 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:226] - Selecting persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE persistentId = ?
16:25:01.582 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:233] - Setting prepared statement parameter 1: test
16:25:20.336 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No session associated with session ID NmI1OTkxYzUyNjU3MDUzMzUxNDAzMDE5NzhjZWYwZTMzOWIzMTBlMWFlOTAxM2JkZjdmM2U3NWFlYzUyODBjZQ== - session must have timed out
16:25:20.338 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No login context in storage service
16:25:20.349 - INFO [Shibboleth-Access:74] - 20140707T142520Z|134.21.209.207|testidp.unifr.ch:443|/profile/SAML2/Redirect/SSO|
16:25:20.351 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO
16:25:20.351 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:97] - shibboleth.HandlerManager: Located profile handler of the following type for the request path: edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler
16:25:20.351 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No login context in storage service
16:25:20.351 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:186] - Incoming request does not contain a login context, processing as first leg of request
16:25:20.352 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:337] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect'
16:25:20.357 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://moodle-test.unifr.ch/shibboleth
16:25:20.357 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://moodle-test.unifr.ch/shibboleth, looking up configuration based on metadata groups.
16:25:20.357 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://moodle-test.unifr.ch/shibboleth. Using default relying party configuration.
16:25:20.363 - INFO [org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule:100] - SAML protocol message was not signed, skipping XML signature processing
16:25:20.365 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:358] - Decoded request from relying party 'https://moodle-test.unifr.ch/shibboleth'
16:25:20.365 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://moodle-test.unifr.ch/shibboleth
16:25:20.365 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://moodle-test.unifr.ch/shibboleth, looking up configuration based on metadata groups.
16:25:20.365 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://moodle-test.unifr.ch/shibboleth. Using default relying party configuration.
16:25:20.365 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:224] - Creating login context and transferring control to authentication engine
16:25:20.368 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:167] - Storing LoginContext to StorageService partition loginContexts, key 5239f4ed-651a-46db-8872-da9f30ef5125
16:25:20.368 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:237] - Redirecting user to authentication engine at https://testidp.unifr.ch:443/idp/AuthnEngine
16:25:20.372 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No session associated with session ID NmI1OTkxYzUyNjU3MDUzMzUxNDAzMDE5NzhjZWYwZTMzOWIzMTBlMWFlOTAxM2JkZjdmM2U3NWFlYzUyODBjZQ== - session must have timed out
16:25:20.372 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - Processing incoming request
16:25:20.373 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:240] - Beginning user authentication process.
16:25:20.373 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:283] - Filtering configured LoginHandlers: {urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler at 6faae28b, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler at 3bff4cf3}
16:25:20.373 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:332] - Filtering out previous session login handler because there is no existing IdP session
16:25:20.373 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:464] - Selecting appropriate login handler from filtered set {urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler at 3bff4cf3}
16:25:20.373 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:497] - Authenticating user with login handler of type edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler
16:25:20.374 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler:66] - Redirecting to https://testidp.unifr.ch:443/idp/Authn/RemoteUser
16:25:20.532 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No session associated with session ID NmI1OTkxYzUyNjU3MDUzMzUxNDAzMDE5NzhjZWYwZTMzOWIzMTBlMWFlOTAxM2JkZjdmM2U3NWFlYzUyODBjZQ== - session must have timed out

Sometime all the login chain ended correctly. Could someone help me?

By the way, does somebody know how I could handle logging CAS client on the IDP? I found that but it seems not to work:

    <logger name="fr.renater.ssocashandler">
        <level value="DEBUG" />
    </logger>

Regards,
Jacques

J.T.
University of Fribourg
Switzerland

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20140707/e55348a3/attachment-0001.html 