New to Shibboleth IdP, can't get working with testshib.org

David Gersic dgersic at niu.edu
Fri Jan 6 22:07:20 GMT 2012 

I know that I'm new to Shibboleth, and I'm hoping that this will be something simple and obvious that I'm missing. I'm trying here to include all of the relevant details, but please let me know if I missed anything. The idp-process.log is at the end, the last five lines of which look to me to be the most relevant part of the file.

I've installed the Shibboleth IdP following the instructions here: 
<https://wiki.shibboleth.net/confluence/display/SHIB2/IdPInstall>

The base OS is SuSE Linux Enterprise Server 10. I'm using Apache Tomcat 5 as the application container. The "quick test" passes, and I get the OK from <https://idp-dev.niu.edu/idp/profile/Status> like I'm supposed to.

Because this is a non-root Linux install, I've followed the directions (slightly modified) from the IdPLinuxNonRoot page here: <https://wiki.shibboleth.net/confluence/display/SHIB2/IdPLinuxNonRoot>. The modifications are because there are multiple IP addresses on this host, and I only want to have the IdP using one of them.

DNS name idp-dev.niu.edu resolves to 131.156.218.44. I have other IP addresses bound to this interface on this box. So I have tomcat5 configured via server.xml to listen on 10.0.0.1:8080 and 10.0.0.1:8443, and iptables is redirecting 131.156.218.44:80 to 10.0.0.1:8080 and 131.156.218.44:443 to 10.0.0.1:8443.

This seems to be working, because the IdP is available when I check the /idp/profile/Status page, and the /idp/status page.

I've loaded the SAML metadata from testshib.org and confirmed that it is stored in /opt/shibboleth-idp/metadata/testshib-metadata.xml like it should be.

I've configured the login handler (Username/Password) in handler.xml:

    <!--  Username/password login handler -->
    <ph:LoginHandler xsi:type="ph:UsernamePassword"
                  jaasConfigurationLocation="file:///opt/shibboleth-idp/conf/login.config">
<ph:AuthenticationMethod>urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport</ph:AuthenticationMethod>
    </ph:LoginHandler>

and have edited the login.config file to enable LDAP authentication:

   edu.vt.middleware.ldap.jaas.LdapLoginModule required
      ldapUrl="ldap://131.156.218.43"
      baseDn="ou=people,dc=niu,dc=edu"
      ssl="false"
      userFilter="uid={0}";

As this is a test system, I haven't yet worried about secure LDAP. I don't know if that matters for the problem I'm having. I'm guessing that it doesn't, because I don't think I'm getting that far.

I've joined testshib.org to use as a test SP. I followed the IdP configuration directions here: <http://www.testshib.org/testshib-two/configure.jsp>. Then added my IdP to the testshib.org site.

When I test it, I go to the sp.testshib.org test page, I put in the URL of my IdP (https://idp-dev.niu.edu/idp/shibboleth), and that's as far as I go. The browser redirects, and dies at https://idp-dev.niu.edu/idp/AuthEngine with:

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.

[...]

When I look in the browser's cookies, I see idp-dev.niu.edu with JSESSIONID and _idp_authn_lc_key cookies. Having cleared everything else out of the browser, these are the only two cookies present.


In the idp-process.log (I've turned up the logging levels to DEBUG), here's what the IdP is doing:

15:13:09.519 - INFO [Shibboleth-Access:74] - 20120106T211309Z|131.156.12.236|idp-dev.niu.edu:443|/profile/SAML2/Redirect/SSO|
15:13:09.523 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO
15:13:09.523 - 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
15:13:09.523 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:323] - LoginContext key cookie was not present in request
15:13:09.524 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:160] - Incoming request does not contain a login context, processing as first leg of request
15:13:09.524 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:312] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect'
15:13:09.525 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:76] - Beginning to decode message from inbound transport of type: org.opensaml.ws.transport.http.HttpServletRequestAdapter
15:13:09.527 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:90] - Decoded RelayState: null
15:13:09.527 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:127] - Base64 decoding and inflating SAML message
15:13:09.528 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:183] - Parsing message stream into DOM document
15:13:09.529 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:193] - Unmarshalling message DOM
15:13:09.534 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:205] - Message succesfully unmarshalled
15:13:09.534 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:105] - Decoded SAML message
15:13:09.535 - DEBUG [org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder:112] - Extracting ID, issuer and issue instant from request
15:13:09.535 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.535 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.536 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
15:13:09.536 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.536 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.540 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
15:13:09.540 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.540 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.541 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://sp.testshib.org/shibboleth-sp
15:13:09.541 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://sp.testshib.org/shibboleth-sp, looking up configuration based on metadata groups.
15:13:09.541 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.542 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.542 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
15:13:09.542 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.542 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.544 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
15:13:09.544 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.544 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.544 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://sp.testshib.org/shibboleth-sp. Using default relying party configuration.
15:13:09.545 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:130] - Evaluating security policy of type 'edu.internet2.middleware.shibboleth.common.security.ShibbolethSecurityPolicy' for decoded message
15:13:09.545 - DEBUG [org.opensaml.util.storage.ReplayCache:92] - Attempting to acquire lock for replay cache check
15:13:09.545 - DEBUG [org.opensaml.util.storage.ReplayCache:94] - Lock acquired
15:13:09.546 - DEBUG [org.opensaml.util.storage.ReplayCache:105] - Message ID _9e3e290b6defba873491b7f6172c5af2 was not a replay
15:13:09.547 - DEBUG [org.opensaml.util.storage.ReplayCache:132] - Writing message ID https://sp.testshib.org/shibboleth-sp_9e3e290b6defba873491b7f6172c5af2 to replay cache with expiration time 2012-01-06T15:18:09.546-06:00
15:13:09.547 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:308] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.547 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.548 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:250] - Metadata document did not contain a descriptor for entity https://sp.testshib.org/shibboleth-sp
15:13:09.548 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:317] - Metadata document did not contain any role descriptors of type {urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor for entity https://sp.testshib.org/shibboleth-sp
15:13:09.548 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:286] - Metadata document does not contain a role of type {urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor supporting protocol urn:oasis:names:tc:SAML:2.0:protocol for entity https://sp.testshib.org/shibboleth-sp
15:13:09.548 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:308] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.549 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.550 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:250] - Metadata document did not contain a descriptor for entity https://sp.testshib.org/shibboleth-sp
15:13:09.550 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:317] - Metadata document did not contain any role descriptors of type {urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor for entity https://sp.testshib.org/shibboleth-sp
15:13:09.550 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:286] - Metadata document does not contain a role of type {urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor supporting protocol urn:oasis:names:tc:SAML:2.0:protocol for entity https://sp.testshib.org/shibboleth-sp
15:13:09.551 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:308] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.551 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.551 - DEBUG [org.opensaml.saml2.binding.security.SAML2AuthnRequestsSignedRule:92] - SPSSODescriptor for entity ID 'https://sp.testshib.org/shibboleth-sp' does not require AuthnRequests to be signed
15:13:09.551 - INFO [org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule:100] - SAML protocol message was not signed, skipping XML signature processing
15:13:09.552 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:64] - Evaluating simple signature rule of type: org.opensaml.saml2.binding.security.SAML2HTTPRedirectDeflateSignatureRule
15:13:09.552 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:87] - HTTP request was not signed via simple signature mechanism, skipping
15:13:09.552 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:64] - Evaluating simple signature rule of type: org.opensaml.saml2.binding.security.SAML2HTTPPostSimpleSignRule
15:13:09.553 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:81] - Rule can not handle this request, skipping processing
15:13:09.553 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:85] - Successfully decoded message.
15:13:09.553 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:191] - Checking SAML message intended destination endpoint against receiver endpoint
15:13:09.553 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:210] - Intended message destination endpoint: https://idp-dev.niu.edu/idp/profile/SAML2/Redirect/SSO
15:13:09.554 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:211] - Actual message receiver endpoint: https://idp-dev.niu.edu/idp/profile/SAML2/Redirect/SSO
15:13:09.556 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:219] - SAML message intended destination endpoint matched recipient endpoint
15:13:09.557 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:333] - Decoded request from relying party 'https://sp.testshib.org/shibboleth-sp'
15:13:09.557 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.557 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.557 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
15:13:09.557 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.558 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.559 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
15:13:09.560 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.560 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.560 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://sp.testshib.org/shibboleth-sp
15:13:09.560 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://sp.testshib.org/shibboleth-sp, looking up configuration based on metadata groups.
15:13:09.560 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.561 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.561 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
15:13:09.561 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.561 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.562 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
15:13:09.563 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
15:13:09.563 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
15:13:09.563 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://sp.testshib.org/shibboleth-sp. Using default relying party configuration.
15:13:09.563 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:203] - Creating login context and transferring control to authentication engine
15:13:09.567 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:169] - Storing LoginContext to StorageService partition loginContexts, key 938dde26-ea60-41b9-ac17-48b0ffd91ebd
15:13:09.568 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:216] - Redirecting user to authentication engine at https://idp-dev.niu.edu:443/idp/AuthnEngine
15:13:09.588 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - Processing incoming request
15:13:09.588 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:323] - LoginContext key cookie was not present in request
15:13:09.588 - WARN [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:217] - No login context available, unable to proceed with authentication
15:13:09.691 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:323] - LoginContext key cookie was not present in request
15:13:09.691 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceContactTag:177] - No relying party, nothing to display


So what am I missing here? Why am I dying in AuthnEngine?

Thanks, and sorry about the length.

More information about the users mailing list