IdP 3: error on SAML 1 AttributeQuery

Sara Hopkins sara.hopkins at ed.ac.uk
Tue Mar 17 11:39:03 EDT 2015 

I'm trying to support a UK federation member setting up a v3 IdP. I can't reproduce his problem with my own V3.0 install. He has been getting the error with V3.0 and is still seeing it after upgrading to V3.1. I've searched the list archives and issues.shibboleth.net and can't see anything relevant. If anyone could give me any pointers I'd be very grateful.

The error affects SAML 1 attribute query; the IdP receives the samlp:AttributeQuery from the UK federation test SP, apparently attempts to invoke a message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl', logs an exception message at WARN level saying "Message context was not authenticated", and sends back the error message "An error occurred." in the StatusMessage in the soap11:Envelope to the SP.

I include below an example IdP DEBUG log from the AttributeQuery onwards. I've elided the IdP entity ID (changing it to IdPEntityID) but everything else is there.

Many thanks,

Sara

<?xml version="1.0" encoding="UTF-8"?>
<S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/">
    <S:Body>
        <samlp:Request IssueInstant="2015-03-17T09:09:14Z"
            MajorVersion="1" MinorVersion="1"
            RequestID="_4f50ac5bd84dad473979cf220c920923" xmlns:samlp="urn:oasis:names:tc:SAML:1.0:protocol">
            <samlp:AttributeQuery Resource="https://test.ukfederation.org.uk/entity">
                <saml:Subject xmlns:saml="urn:oasis:names:tc:SAML:1.0:assertion">
                    <saml:NameIdentifier
                        Format="urn:mace:shibboleth:1.0:nameIdentifier" NameQualifier="IdPEntityID">AAdzZWNyZXQxVSXqqSxwIyl/0TWP/UctHBfr6Rx7njlY60x8EWnDuKisaNEUxo6//cmR7yIWme6GoVCeQoWQJof2zABoPINUFNr9mS827zyq3it04VseoI11yan2ovu3tDTLInQhX81QI41LEQh9f5lmZWg=</saml:NameIdentifier>
                </saml:Subject>
            </samlp:AttributeQuery>
        </samlp:Request>
    </S:Body>
</S:Envelope>

2015-03-17 09:09:15,043 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:198] - Profile Action PopulateAuditContext: Skipping field 'p' not included in audit format
2015-03-17 09:09:15,043 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:198] - Profile Action PopulateAuditContext: Skipping field 'pasv' not included in audit format
2015-03-17 09:09:15,043 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:220] - Profile Action PopulateAuditContext: Adding 1 value for field 'I'
2015-03-17 09:09:15,043 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:220] - Profile Action PopulateAuditContext: Adding 1 value for field 'b'
2015-03-17 09:09:15,043 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:198] - Profile Action PopulateAuditContext: Skipping field 'D' not included in audit format
2015-03-17 09:09:15,043 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:198] - Profile Action PopulateAuditContext: Skipping field 'fauth' not included in audit format
2015-03-17 09:09:15,059 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.CheckMessageVersionHandler' on INBOUND message context
2015-03-17 09:09:15,059 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,059 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.saml1.binding.impl.SAML1ArtifactRequestIssuerHandler' on INBOUND message context
2015-03-17 09:09:15,059 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,074 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLProtocolAndRoleHandler' on INBOUND message context
2015-03-17 09:09:15,074 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,074 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLMetadataLookupHandler' on INBOUND message context
2015-03-17 09:09:15,074 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,074 - DEBUG [org.opensaml.saml.common.messaging.context.SAMLPeerEntityContext:237] - Attempting to extract entity ID from SAML 1 AttributeQuery Resource attribute
2015-03-17 09:09:15,074 - DEBUG [org.opensaml.saml.common.messaging.context.SAMLPeerEntityContext:241] - Extracted entity ID from SAML 1.x AttributeQuery: https://test.ukfederation.org.uk/entity
2015-03-17 09:09:15,074 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLMetadataLookupHandler:124] - Message Handler:  org.opensaml.saml.common.messaging.context.SAMLMetadataContext added to MessageContext
2015-03-17 09:09:15,090 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler' on INBOUND message context
2015-03-17 09:09:15,090 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,090 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler:129] - Message Handler:  Selecting default AttributeConsumingService, if any
2015-03-17 09:09:15,090 - DEBUG [org.opensaml.saml.metadata.support.AttributeConsumingServiceSelector:186] - Resolving AttributeConsumingService candidates from SPSSODescriptor
2015-03-17 09:09:15,090 - DEBUG [org.opensaml.saml.metadata.support.AttributeConsumingServiceSelector:145] - AttributeConsumingService index was specified: false
2015-03-17 09:09:15,090 - DEBUG [org.opensaml.saml.metadata.support.AttributeConsumingServiceSelector:227] - Selecting default AttributeConsumingService
2015-03-17 09:09:15,090 - DEBUG [org.opensaml.saml.metadata.support.AttributeConsumingServiceSelector:242] - Selected first AttributeConsumingService with no explicit isDefault
2015-03-17 09:09:15,090 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLAddAttributeConsumingServiceHandler:133] - Message Handler:  Selected AttributeConsumingService with index 1
2015-03-17 09:09:15,090 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeRelyingPartyContextFromSAMLPeer:132] - Profile Action InitializeRelyingPartyContextFromSAMLPeer: Attaching RelyingPartyContext based on SAML peer https://test.ukfederation.org.uk/entity
2015-03-17 09:09:15,106 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:286] - Resolving relying party configuration
2015-03-17 09:09:15,106 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:307] - No relying party configurations are applicable, returning the default configuration shibboleth.DefaultRelyingParty
2015-03-17 09:09:15,106 - DEBUG [net.shibboleth.idp.profile.impl.SelectRelyingPartyConfiguration:136] - Profile Action SelectRelyingPartyConfiguration: Found relying party configuration shibboleth.DefaultRelyingParty for request
2015-03-17 09:09:15,106 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:220] - Profile Action PopulateAuditContext: Adding 1 value for field 'IDP'
2015-03-17 09:09:15,106 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:220] - Profile Action PopulateAuditContext: Adding 1 value for field 'SP'
2015-03-17 09:09:15,121 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.PopulateProfileInterceptorContext:126] - Profile Action PopulateProfileInterceptorContext: Installing flow intercept/security-policy/saml-soap into interceptor context
2015-03-17 09:09:15,137 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.FilterFlowsByNonBrowserSupport:70] - Profile Action FilterFlowsByNonBrowserSupport: Retaining flow 'intercept/security-policy/saml-soap', it supports non-browser authentication
2015-03-17 09:09:15,137 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.FilterFlowsByNonBrowserSupport:82] - Profile Action FilterFlowsByNonBrowserSupport: Available interceptor flows after filtering: '{intercept/security-policy/saml-soap=ProfileInterceptorFlowDescriptor{flowId=intercept/security-policy/saml-soap, nonBrowserSupported=true}}'
2015-03-17 09:09:15,137 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:101] - Profile Action SelectProfileInterceptorFlow: Checking flow intercept/security-policy/saml-soap for applicability...
2015-03-17 09:09:15,137 - DEBUG [net.shibboleth.idp.profile.interceptor.impl.SelectProfileInterceptorFlow:84] - Profile Action SelectProfileInterceptorFlow: Selecting flow intercept/security-policy/saml-soap
2015-03-17 09:09:15,309 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler' on INBOUND message context
2015-03-17 09:09:15,309 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,309 - DEBUG [org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler:156] - Message Handler:  Checking SAML message intended destination endpoint against receiver endpoint
2015-03-17 09:09:15,309 - DEBUG [org.opensaml.saml.common.binding.security.impl.ReceivedEndpointSecurityHandler:175] - Message Handler:  SAML message intended destination endpoint was empty, not required by binding, skipping
2015-03-17 09:09:15,324 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.MessageReplaySecurityHandler' on INBOUND message context
2015-03-17 09:09:15,324 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,324 - DEBUG [org.opensaml.saml.common.binding.security.impl.MessageReplaySecurityHandler:151] - Message Handler:  Evaluating message replay for message ID '_4f50ac5bd84dad473979cf220c920923', issue instant '2015-03-17T09:09:14.000Z', entityID 'https://test.ukfederation.org.uk/entity'
2015-03-17 09:09:15,324 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.MessageLifetimeSecurityHandler' on INBOUND message context
2015-03-17 09:09:15,324 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,387 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.SAMLMDClientCertAuthSecurityHandler' on INBOUND message context
2015-03-17 09:09:15,387 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,403 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.saml.common.binding.security.impl.SAMLProtocolMessageXMLSignatureSecurityHandler' on INBOUND message context
2015-03-17 09:09:15,403 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,418 - DEBUG [org.opensaml.saml.common.binding.security.impl.SAMLProtocolMessageXMLSignatureSecurityHandler:102] - Message Handler:  SAML protocol message was not signed, skipping XML signature processing
2015-03-17 09:09:15,418 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.messaging.handler.impl.CheckMandatoryIssuer' on INBOUND message context
2015-03-17 09:09:15,418 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,449 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:154] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.messaging.handler.impl.CheckMandatoryAuthentication' on INBOUND message context
2015-03-17 09:09:15,449 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.RequestImpl'
2015-03-17 09:09:15,449 - WARN [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:182] - Profile Action WebFlowMessageHandlerAdaptor: Exception handling message
org.opensaml.messaging.handler.MessageHandlerException: Message context was not authenticated
	at org.opensaml.messaging.handler.impl.CheckMandatoryAuthentication.doInvoke(CheckMandatoryAuthentication.java:70)
2015-03-17 09:09:15,481 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeOutboundMessageContextForError:191] - Profile Action InitializeOutboundMessageContextForError: Initialized outbound message context for error delivery
2015-03-17 09:09:15,481 - DEBUG [org.opensaml.saml.common.profile.impl.AddInResponseToToResponse:110] - Profile Action AddInResponseToToResponse: Attempting to add InResponseTo to outgoing Response
2015-03-17 09:09:15,559 - DEBUG [org.opensaml.saml.saml1.profile.impl.AddStatusToResponse:195] - Profile Action AddStatusToResponse: Detailed errors are disabled
2015-03-17 09:09:15,574 - DEBUG [org.opensaml.saml.saml1.profile.impl.AddStatusToResponse:224] - Profile Action AddStatusToResponse: Setting StatusMessage to defaulted value
2015-03-17 09:09:15,606 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:220] - Profile Action PopulateAuditContext: Adding 1 value for field 'bb'
2015-03-17 09:09:15,606 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:198] - Profile Action PopulateAuditContext: Skipping field 'DD' not included in audit format
2015-03-17 09:09:15,606 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:198] - Profile Action PopulateAuditContext: Skipping field 'II' not included in audit format
2015-03-17 09:09:15,606 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:198] - Profile Action PopulateAuditContext: Skipping field 'SS' not included in audit format
2015-03-17 09:09:15,606 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:198] - Profile Action PopulateAuditContext: Skipping field 's' not included in audit format
2015-03-17 09:09:15,606 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:198] - Profile Action PopulateAuditContext: Skipping field 'S' not included in audit format
2015-03-17 09:09:15,606 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:220] - Profile Action PopulateAuditContext: Adding 1 value for field 'III'
2015-03-17 09:09:15,606 - DEBUG [net.shibboleth.idp.profile.audit.impl.PopulateAuditContext:198] - Profile Action PopulateAuditContext: Skipping field 'SM' not included in audit format
2015-03-17 09:09:15,621 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:159] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.messaging.handler.impl.BasicMessageHandlerChain' on OUTBOUND message context
2015-03-17 09:09:15,621 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:175] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.ResponseImpl'
2015-03-17 09:09:15,621 - DEBUG [org.opensaml.saml.common.binding.security.impl.SAMLOutboundProtocolMessageSigningHandler:84] - Message Handler:  Message context did not contain signing parameters, outbound message will not be signed
2015-03-17 09:09:15,621 - DEBUG [net.shibboleth.idp.saml.profile.impl.SpringAwareMessageEncoderFactory:100] - Looking up message encoder based on binding URI: urn:oasis:names:tc:SAML:1.0:bindings:SOAP-binding
2015-03-17 09:09:15,637 - DEBUG [PROTOCOL_MESSAGE:70] - 
<?xml version="1.0" encoding="UTF-8"?>
<soap11:Envelope xmlns:soap11="http://schemas.xmlsoap.org/soap/envelope/">
    <soap11:Body>
        <saml1p:Response
            InResponseTo="_4f50ac5bd84dad473979cf220c920923"
            IssueInstant="2015-03-17T09:09:15.481Z" MajorVersion="1"
            MinorVersion="1"
            ResponseID="_488ca9a4e8795a4c2f3beb2b60fd45af" xmlns:saml1p="urn:oasis:names:tc:SAML:1.0:protocol">
            <saml1p:Status>
                <saml1p:StatusCode Value="saml1p:Requester"/>
                <saml1p:StatusMessage>An error occurred.</saml1p:StatusMessage>
            </saml1p:Status>
        </saml1p:Response>
    </soap11:Body>
</soap11:Envelope>

2015-03-17 09:09:15,653 - DEBUG [net.shibboleth.idp.profile.impl.RecordResponseComplete:89] - Profile Action RecordResponseComplete: Record response complete
2015-03-17 09:09:15,668 - INFO [Shibboleth-Audit.AttributeQuery:241] - 20150317T090915Z|urn:oasis:names:tc:SAML:1.0:bindings:SOAP-binding|_4f50ac5bd84dad473979cf220c920923|https://test.ukfederation.org.uk/entity|http://shibboleth.net/ns/profiles/saml1/query/attribute|IdPEntityID|urn:oasis:names:tc:SAML:1.0:bindings:SOAP-binding|_488ca9a4e8795a4c2f3beb2b60fd45af|||||



-- 
Sara Hopkins
Support Team
UK Access Management Federation for Education and Research
web:    http://www.ukfederation.org.uk/

The University of Edinburgh is a charitable body, registered in
Scotland, with registration number SC005336.

More information about the users mailing list