12:46:55.886 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:560] - User sam@jpr.com authenticated with method urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
12:46:55.886 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:161] - Returning control to profile handler
12:46:55.886 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:335] - Looking up LoginContext with key e227c832-27e9-47a4-80ba-61157e4abfc7 from StorageService parition: loginContexts
12:46:55.886 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:341] - Retrieved LoginContext with key e227c832-27e9-47a4-80ba-61157e4abfc7 from StorageService parition: loginContexts
12:46:55.886 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:177] - Redirecting user to profile handler at https://127.0.0.1:8443/idp/profile/SAML2/Redirect/SSO
12:46:55.889 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
12:46:55.889 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:115] - Found IdP session cookie.
12:46:55.889 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:75] - Updating IdP session activity time and adding session object to the request
12:46:55.889 - INFO [Shibboleth-Access:74] - 20130626T071655Z|127.0.0.1|127.0.0.1:8443|/profile/SAML2/Redirect/SSO|
12:46:55.889 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO
12:46:55.889 - 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
12:46:55.889 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:335] - Looking up LoginContext with key e227c832-27e9-47a4-80ba-61157e4abfc7 from StorageService parition: loginContexts
12:46:55.889 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:341] - Retrieved LoginContext with key e227c832-27e9-47a4-80ba-61157e4abfc7 from StorageService parition: loginContexts
12:46:55.890 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:574] - Unbinding LoginContext
12:46:55.890 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:600] - Expiring LoginContext cookie
12:46:55.890 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:611] - Removed LoginContext, with key e227c832-27e9-47a4-80ba-61157e4abfc7, from StorageService partition loginContexts
12:46:55.890 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:170] - Incoming request contains a login context and indicates principal was authenticated, processing second leg of request
12:46:55.890 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://127.0.0.1:8443/idp/shibboleth
12:46:55.890 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://127.0.0.1:8443/idp/shibboleth
12:46:55.890 - TRACE [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:522] - Entity descriptor for the ID https://127.0.0.1:8443/idp/shibboleth was found in index cache, returning
12:46:55.890 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://127.0.0.1:8443/idp/shibboleth
12:46:55.890 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://127.0.0.1:8443/idp/shibboleth
12:46:55.890 - TRACE [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:522] - Entity descriptor for the ID https://127.0.0.1:8443/idp/shibboleth was found in index cache, returning
12:46:55.890 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://127.0.0.1:8443/idp/shibboleth
12:46:55.891 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://127.0.0.1:8443/idp/shibboleth, looking up configuration based on metadata groups.
12:46:55.891 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://127.0.0.1:8443/idp/shibboleth
12:46:55.891 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://127.0.0.1:8443/idp/shibboleth
12:46:55.891 - TRACE [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:522] - Entity descriptor for the ID https://127.0.0.1:8443/idp/shibboleth was found in index cache, returning
12:46:55.891 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://127.0.0.1:8443/idp/shibboleth. Using default relying party configuration.
12:46:55.891 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://127.0.0.1:8443/idp/shibboleth
12:46:55.891 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:518] - Searching for entity descriptor with an entity ID of https://127.0.0.1:8443/idp/shibboleth
12:46:55.891 - TRACE [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:522] - Entity descriptor for the ID https://127.0.0.1:8443/idp/shibboleth was found in index cache, returning
12:46:55.891 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:95] - Starting to unmarshall DOM element {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
12:46:55.891 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:144] - Targeted QName checking is not available for this unmarshaller, DOM Element {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest was not verified
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:185] - Building XMLObject for {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:101] - Unmarshalling attributes of DOM Element {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing attribute AssertionConsumerServiceURL
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute AssertionConsumerServiceURL is neither a schema type nor namespace, calling processAttribute()
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing attribute Destination
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute Destination is neither a schema type nor namespace, calling processAttribute()
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing attribute ID
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute ID is neither a schema type nor namespace, calling processAttribute()
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing attribute IssueInstant
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute IssueInstant is neither a schema type nor namespace, calling processAttribute()
12:46:55.892 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing attribute ProtocolBinding
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute ProtocolBinding is neither a schema type nor namespace, calling processAttribute()
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing attribute Version
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute Version is neither a schema type nor namespace, calling processAttribute()
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing attribute {http://www.w3.org/2000/xmlns/}samlp
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:251] - {http://www.w3.org/2000/xmlns/}samlp is a namespace declaration, adding it to the list of namespaces on the XMLObject
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:113] - Unmarshalling other child nodes of DOM Element {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:316] - Unmarshalling child elements of XMLObject {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:333] - Unmarshalling child element {urn:oasis:names:tc:SAML:2.0:assertion}Issuerwith unmarshaller org.opensaml.saml2.core.impl.IssuerUnmarshaller
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:95] - Starting to unmarshall DOM element {urn:oasis:names:tc:SAML:2.0:assertion}Issuer
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:144] - Targeted QName checking is not available for this unmarshaller, DOM Element {urn:oasis:names:tc:SAML:2.0:assertion}Issuer was not verified
12:46:55.893 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:185] - Building XMLObject for {urn:oasis:names:tc:SAML:2.0:assertion}Issuer
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:101] - Unmarshalling attributes of DOM Element {urn:oasis:names:tc:SAML:2.0:assertion}Issuer
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing attribute {http://www.w3.org/2000/xmlns/}saml
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:251] - {http://www.w3.org/2000/xmlns/}saml is a namespace declaration, adding it to the list of namespaces on the XMLObject
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:113] - Unmarshalling other child nodes of DOM Element {urn:oasis:names:tc:SAML:2.0:assertion}Issuer
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:316] - Unmarshalling child elements of XMLObject {urn:oasis:names:tc:SAML:2.0:protocol}AuthnRequest
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:333] - Unmarshalling child element {urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicywith unmarshaller org.opensaml.saml2.core.impl.NameIDPolicyUnmarshaller
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:95] - Starting to unmarshall DOM element {urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicy
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:144] - Targeted QName checking is not available for this unmarshaller, DOM Element {urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicy was not verified
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:185] - Building XMLObject for {urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicy
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:101] - Unmarshalling attributes of DOM Element {urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicy
12:46:55.894 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:218] - Pre-processing attribute AllowCreate
12:46:55.895 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:226] - Attribute AllowCreate is neither a schema type nor namespace, calling processAttribute()
12:46:55.895 - TRACE [org.opensaml.xml.io.AbstractXMLObjectUnmarshaller:113] - Unmarshalling other child nodes of DOM Element {urn:oasis:names:tc:SAML:2.0:protocol}NameIDPolicy
12:46:55.895 - DEBUG [org.opensaml.saml2.binding.AuthnResponseEndpointSelector:47] - Unable to select endpoint, no entity role metadata available.
12:46:55.895 - ERROR [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:429] - No return endpoint available for relying party https://127.0.0.1:8443/idp/shibboleth
12:46:55.896 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:335] - Looking up LoginContext with key e227c832-27e9-47a4-80ba-61157e4abfc7 from StorageService parition: loginContexts
12:46:55.896 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:346] - No login context in storage service
12:46:55.896 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceContactTag:177] - No relying party, nothing to display