SAML2 attribute query fails with InvalidMessageContext
GOSWAMI, Shivanggiri (Contractor)
Shivanggiri.Goswami.contractor at oup.com
Sat Dec 16 04:35:23 EST 2017
Hello all,
I am working on implementing ECP client on idp 3.3.1 for mobile sso. I am not able to get the attribute query working. In idp-process.log i see "A non-proceed event occurred while processing the request: InvalidMessageContext" not sure what i am missing. I get the following statusMessage in the response.
<saml2p:Status>
<saml2p:StatusCode Value="urn:oasis:names:tc:SAML:2.0:status:Responder"/>
<saml2p:StatusMessage>unexpected</saml2p:StatusMessage>
</saml2p:Status>
I have enabled detailed error logging in idp.properties and in logback.xml, but i cannot get the exception trace in the logs. Following are the AttributeQuery request and the idp-process.log. Please help to get this working .
1). AttributeQuery request.
<SOAP-ENV:Envelope
xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion"
xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol"
xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"
xmlns:ecp="urn:oasis:names:tc:SAML:2.0:profiles:SSO:ecp">
<SOAP-ENV:Header>
</SOAP-ENV:Header>
<SOAP-ENV:Body>
<samlp:AttributeQuery
xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion"
xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol"
ID="aaf23196-1773-2113-474a-fe114412ab72"
Version="2.0"
IssueInstant="2017-12-15T17:03:09.061Z">
<saml:Issuer>
CES
</saml:Issuer>
<saml:Subject>
<saml:NameID Format="urn:oasis:names:tc:SAML:2.0:nameid-format:transient" NameQualifier="https://ip-c0a882f9/idp/shibboleth" SPNameQualifier="CES">AAdzZWNyZXQxsKD7pGse7dEzbWyvmvaMGmOVlxCGOkdqWkRdowXjXRwr2ArK3Y/UzwCvqZJzp5Ejv+fJixz/aBywXzjX5uKEqzkt37uQCdZNdsffsa956Q==</saml:NameID>
<saml:SubjectConfirmation Method="urn:oasis:names:tc:SAML:2.0:cm:bearer">
<saml:SubjectConfirmationData Address="127.0.0.1" InResponseTo="123456789abcde" NotOnOrAfter="2017-12-15T17:08:52.881Z" Recipient="http://localhost:8080/idp/profile/saml/SOAP/ECP"/>
</saml:SubjectConfirmation>
</saml:Subject>
<saml:Attribute
NameFormat="urn:oasis:names:tc:SAML:2.0:attrname-format:uri"
Name="urn:oid:2.5.4.42"
FriendlyName="userName">
</saml:Attribute>
<saml:Attribute
NameFormat="urn:oasis:names:tc:SAML:2.0:attrname-format:uri"
Name="urn:oid:1.3.6.1.4.1.1466.115.121.1.26"
FriendlyName="sessionKey">
</saml:Attribute>
<saml:Attribute
NameFormat="urn:oasis:names:tc:SAML:2.0:attrname-format:uri"
Name="urn:oid:1.3.6.1.4.1.1466.115.121.1.26"
FriendlyName="Role">
</saml:Attribute>
<saml:Conditions NotBefore="2017-12-15T17:03:52.374Z" NotOnOrAfter="2017-12-15T17:08:52.374Z">
<saml:AudienceRestriction>
<saml:Audience>CES</saml:Audience>
</saml:AudienceRestriction>
</saml:Conditions>
</samlp:AttributeQuery>
</SOAP-ENV:Body>
</SOAP-ENV:Envelope>
=============================================
2). idp-process.log
2017-12-16 14:22:37,677 - DEBUG [net.shibboleth.idp.saml.profile.impl.PopulateBindingAndEndpointContexts:418] - Profile Action PopulateBindingAndEndpointContexts: Resolved endpoint at location http://localhost:8080/idp/profile/SAML2/SOAP/ECP using binding urn:oasis:names:tc:SAML:2.0:bindings:PAOS
2017-12-16 14:22:37,678 - DEBUG [net.shibboleth.idp.saml.saml2.profile.delegation.impl.PopulateDelegationContext:319] - Request is not a SAML 2 AuthnRequest
2017-12-16 14:22:37,678 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:184] - Profile Action PopulateSignatureSigningParameters: Signing enabled
2017-12-16 14:22:37,679 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:197] - Profile Action PopulateSignatureSigningParameters: Resolving SignatureSigningParameters for request
2017-12-16 14:22:37,679 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:229] - Profile Action PopulateSignatureSigningParameters: Adding metadata to resolution criteria for signing/digest algorithms
2017-12-16 14:22:37,679 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:237] - Profile Action PopulateSignatureSigningParameters: Resolved SignatureSigningParameters
2017-12-16 14:22:37,681 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:184] - Profile Action PopulateSignatureSigningParameters: Signing enabled
2017-12-16 14:22:37,682 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:197] - Profile Action PopulateSignatureSigningParameters: Resolving SignatureSigningParameters for request
2017-12-16 14:22:37,682 - DEBUG [org.opensaml.saml.common.profile.impl.PopulateSignatureSigningParameters:211] - Profile Action PopulateSignatureSigningParameters: Found existing SecurityParametersContext to copy from
2017-12-16 14:22:37,683 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.PopulateEncryptionParameters:299] - Profile Action PopulateEncryptionParameters: No encryption requested, nothing to do
2017-12-16 14:22:37,749 - DEBUG [org.opensaml.saml.common.profile.logic.AbstractNameIDPolicyPredicate:193] - Applying policy to NameID with Format urn:oasis:names:tc:SAML:2.0:nameid-format:transient
2017-12-16 14:22:37,749 - DEBUG [net.shibboleth.idp.saml.profile.impl.ExtractSubjectFromRequest:170] - Profile Action ExtractSubjectFromRequest: Creating Subject for canonicalization around NameID AAdzZWNyZXQxTr/cgJ4EjwshlD+lfUBqNpnK1hLYRG1Z61OBN9pMGiiim/Pct3TVwhx+u3FbdFFDUpqPSJuHHe6wpQ1tJ2AKbJ3crV9kqws8cfH8i8xlBQ==
2017-12-16 14:22:37,750 - DEBUG [net.shibboleth.idp.saml.profile.impl.ExtractSubjectFromRequest:197] - Profile Action ExtractSubjectFromRequest: Created subject canonicalization context
2017-12-16 14:22:37,751 - DEBUG [net.shibboleth.idp.authn.impl.PopulateSubjectCanonicalizationContext:79] - Profile Action PopulateSubjectCanonicalizationContext: Installing 7 canonicalization flows into SubjectCanonicalizationContext
2017-12-16 14:22:37,752 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/LegacyPrincipalConnector for applicability...
2017-12-16 14:22:37,752 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:106] - Profile Action SelectSubjectCanonicalizationFlow: Canonicalization flow c14n/LegacyPrincipalConnector was not applicable to this request
2017-12-16 14:22:37,753 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/SAML2Transient for applicability...
2017-12-16 14:22:37,753 - DEBUG [net.shibboleth.idp.saml.nameid.impl.NameIDCanonicalization$ActivationCondition:168] - Attempting to match format 'urn:oasis:names:tc:SAML:2.0:nameid-format:transient'
2017-12-16 14:22:37,753 - DEBUG [net.shibboleth.idp.saml.nameid.impl.NameIDCanonicalization$ActivationCondition:186] - NameIDCanonicalizationFlowDescriptor c14n/SAML2Transient: format matches urn:oasis:names:tc:SAML:2.0:nameid-format:transient
2017-12-16 14:22:37,753 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:83] - Profile Action SelectSubjectCanonicalizationFlow: Selecting canonicalization flow c14n/SAML2Transient
2017-12-16 14:22:37,756 - DEBUG [net.shibboleth.idp.saml.nameid.impl.BaseTransientDecoder:122] - Transient Decoder 'net.shibboleth.idp.saml.nameid.impl.TransientNameIDDecoder#a50afd5': using the store 'shibboleth.StorageService'
2017-12-16 14:22:37,757 - DEBUG [net.shibboleth.idp.saml.nameid.impl.NameIDCanonicalization$ActivationCondition:168] - Attempting to match format 'urn:oasis:names:tc:SAML:2.0:nameid-format:transient'
2017-12-16 14:22:37,758 - DEBUG [net.shibboleth.idp.saml.nameid.impl.NameIDCanonicalization$ActivationCondition:186] - NameIDCanonicalizationFlowDescriptor c14n/SAML2Transient: format matches urn:oasis:names:tc:SAML:2.0:nameid-format:transient
2017-12-16 14:22:37,758 - INFO [net.shibboleth.idp.saml.nameid.impl.BaseTransientDecoder:96] - Transient Decoder 'net.shibboleth.idp.saml.nameid.impl.TransientNameIDDecoder#a50afd5': Could not find transient identifier
2017-12-16 14:22:37,759 - INFO [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:62] - Profile Action SelectSubjectCanonicalizationFlow: Moving incomplete flow c14n/SAML2Transient to intermediate set, reselecting a different one
2017-12-16 14:22:37,759 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/LegacyPrincipalConnector for applicability...
2017-12-16 14:22:37,759 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:106] - Profile Action SelectSubjectCanonicalizationFlow: Canonicalization flow c14n/LegacyPrincipalConnector was not applicable to this request
2017-12-16 14:22:37,760 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:100] - Profile Action SelectSubjectCanonicalizationFlow: Checking canonicalization flow c14n/SAML2CryptoTransient for applicability...
2017-12-16 14:22:37,760 - DEBUG [net.shibboleth.idp.saml.nameid.impl.NameIDCanonicalization$ActivationCondition:168] - Attempting to match format 'urn:oasis:names:tc:SAML:2.0:nameid-format:transient'
2017-12-16 14:22:37,760 - DEBUG [net.shibboleth.idp.saml.nameid.impl.NameIDCanonicalization$ActivationCondition:186] - NameIDCanonicalizationFlowDescriptor c14n/SAML2CryptoTransient: format matches urn:oasis:names:tc:SAML:2.0:nameid-format:transient
2017-12-16 14:22:37,761 - DEBUG [net.shibboleth.idp.authn.impl.SelectSubjectCanonicalizationFlow:83] - Profile Action SelectSubjectCanonicalizationFlow: Selecting canonicalization flow c14n/SAML2CryptoTransient
2017-12-16 14:22:37,763 - DEBUG [net.shibboleth.idp.saml.nameid.impl.NameIDCanonicalization$ActivationCondition:168] - Attempting to match format 'urn:oasis:names:tc:SAML:2.0:nameid-format:transient'
2017-12-16 14:22:37,763 - DEBUG [net.shibboleth.idp.saml.nameid.impl.NameIDCanonicalization$ActivationCondition:186] - NameIDCanonicalizationFlowDescriptor c14n/SAML2CryptoTransient: format matches urn:oasis:names:tc:SAML:2.0:nameid-format:transient
2017-12-16 14:22:37,765 - DEBUG [org.opensaml.saml.common.profile.impl.VerifyChannelBindings:154] - Profile Action VerifyChannelBindings: No channel bindings found to verify, nothing to do
2017-12-16 14:22:37,767 - DEBUG [org.opensaml.saml.saml2.profile.impl.PopulateECPContext:149] - Profile Action PopulateECPContext: RequestAuthenticated: false
2017-12-16 14:22:37,767 - DEBUG [org.opensaml.saml.saml2.profile.impl.PopulateECPContext:167] - Profile Action PopulateECPContext: Assertion encryption is not enabled, skipping session key generation
2017-12-16 14:22:37,768 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeAuthenticationContext:90] - Profile Action InitializeAuthenticationContext: No inbound AuthnRequest, passive and forced flags will be off
2017-12-16 14:22:37,769 - DEBUG [net.shibboleth.idp.saml.profile.impl.InitializeAuthenticationContext:115] - Profile Action InitializeAuthenticationContext: Created authentication context: AuthenticationContext{initiationInstant=2017-12-16T14:22:37.769+05:30, isPassive=false, forceAuthn=false, hintedName=null, potentialFlows=[], activeResults=[], attemptedFlow=null, signaledFlowId=null, authenticationStateMap={}, resultCacheable=true, initialAuthenticationResult=null, authenticationResult=null, completionInstant=1970-01-01T05:30:00.000+05:30}
2017-12-16 14:22:37,770 - DEBUG [net.shibboleth.idp.saml.saml2.profile.impl.ProcessRequestedAuthnContext:159] - Profile Action ProcessRequestedAuthnContext: AuthnRequest message was not returned by lookup strategy
2017-12-16 14:22:37,772 - WARN [org.opensaml.profile.action.impl.LogEvent:105] - A non-proceed event occurred while processing the request: InvalidMessageContext
2017-12-16 14:22:37,772 - DEBUG [org.opensaml.saml.common.profile.logic.DefaultLocalErrorPredicate:184] - Error event InvalidMessageContext will be handled with response
2017-12-16 14:22:37,774 - DEBUG [org.opensaml.saml.saml2.profile.impl.AbstractResponseShellAction:217] - Profile Action AddStatusResponseShell: Setting Issuer to https://ip-c0a882f9/idp/shibboleth
2017-12-16 14:22:37,776 - DEBUG [org.opensaml.saml.common.profile.impl.AddInResponseToToResponse:110] - Profile Action AddInResponseToToResponse: Attempting to add InResponseTo to outgoing Response
2017-12-16 14:22:37,783 - DEBUG [org.opensaml.saml.saml2.profile.impl.AddStatusToResponse:195] - Profile Action AddStatusToResponse: Detailed errors are enabled
2017-12-16 14:22:37,783 - DEBUG [org.opensaml.saml.saml2.profile.impl.AddStatusToResponse:230] - Profile Action AddStatusToResponse: Current state of request was mappable, setting StatusMessage to mapped value
2017-12-16 14:22:37,789 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:179] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.messaging.handler.impl.BasicMessageHandlerChain' on OUTBOUND message context
2017-12-16 14:22:37,789 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml2.core.impl.ResponseImpl'
2017-12-16 14:22:37,790 - DEBUG [org.opensaml.saml.common.binding.impl.SAMLOutboundDestinationHandler:62] - Adding destination to outbound SAML 2 protocol message: http://localhost:8080/idp/profile/SAML2/SOAP/ECP
2017-12-16 14:22:37,791 - DEBUG [org.opensaml.saml.common.binding.security.impl.EndpointURLSchemeSecurityHandler:52] - Message Handler: Checking outbound endpoint for allowed URL scheme: http://localhost:8080/idp/profile/SAML2/SOAP/ECP
2017-12-16 14:22:37,792 - DEBUG [org.opensaml.saml.common.SAMLObjectSupport:56] - Examining signed object for content references with exclusive canonicalization transform
2017-12-16 14:22:37,793 - DEBUG [org.opensaml.saml.common.SAMLObjectSupport:70] - Saw exclusive transform, declaring non-visible namespaces on signed object
2017-12-16 14:22:37,794 - DEBUG [org.opensaml.saml.common.SAMLObjectContentReference:165] - Adding list of inclusive namespaces for signature exclusive canonicalization transform
2017-12-16 14:22:37,812 - DEBUG [net.shibboleth.idp.saml.profile.impl.SpringAwareMessageEncoderFactory:100] - Looking up message encoder based on binding URI: urn:oasis:names:tc:SAML:2.0:bindings:PAOS
2017-12-16 14:22:37,813 - DEBUG [org.opensaml.saml.common.binding.impl.AddChannelBindingsHeaderHandler:85] - Message Handler: No ChannelBindings to add, nothing to do
Thank you for your time..!!
Thanks & Best Regards,
Shivang Goswami
Oxford University Press (UK) Disclaimer
This message is confidential. You should not copy it or disclose its contents to anyone. You may use and apply the information for the intended purpose only. OUP does not accept legal responsibility for the contents of this message. Any views or opinions presented are those of the author only and not of OUP. If this email has come to you in error, please delete it, along with any attachments. Please note that OUP may intercept incoming and outgoing email communications.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20171216/fb6a4fc6/attachment-0001.html>
More information about the users
mailing list