[Shib-Users] Idp not posting saml response back to SP

Daniel Appleby

unread,

Nov 3, 2010, 12:28:16 AM11/3/10

to shibbole...@internet2.edu

Hi All,

I have been trying to setup a shibboleth idp and sp test bed environment. Our setup involves two hosts one hosting the idp (tomcat) and the other hosting the SP (apache) (both RHEL5). It has been success so far up until the point where we tried to get the SP to communicate with IDP. We are using SP-Initiated SSO model with Redirect/POST Bindings (SAML2SSO profile).

After doing a heap of tracing I can see the SP creating the AuthnRequest then deflating and redirecting to the IDP. The IDP opens the request and sees that no logon context exists for the user and produces the logon page. The logon works as well as the attribute filtering etc (in the logs). After all that is done I was expecting the IDP to create a SAML response to send back to the SP via POST, however, it seems to redirect back to itself (/SAML2/Redirect/SSO) and strip off the AuthnRequest so I get the decoding error shown below.

14:36:02.041 - INFO [Shibboleth-Access:73] - 20101103T033602Z|10.80.11.58|idp.mydomain:443|/profile/SAML2/Redirect/SSO|

14:36:02.041 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO

14:36:02.041 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:93] - shibboleth.HandlerManager: Located profile handler of the following type for the request path: edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler

14:36:02.042 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:326] - Looking up LoginContext with key dc78e044-5740-4c16-b3f6-b381628a0f5c from StorageService parition: loginContexts

14:36:02.042 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:337] - No login context in storage service

14:36:02.042 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:156] - Incoming request does not contain a login context, processing as first leg of request

14:36:02.042 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:304] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect'

14:36:02.042 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:72] - Beginning to decode message from inbound transport of type: org.opensaml.ws.transport.http.HttpServletRequestAdapter

14:36:02.042 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:89] - Decoded RelayState: null

14:36:02.043 - WARN [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:336] - Error decoding authentication request message

org.opensaml.ws.message.decoder.MessageDecodingException: No SAMLRequest or SAMLResponse query path parameter, invalid SAML 2 HTTP Redirect message

Is there anything in the relyingparty config that affects where the POST response is sent? (my relyparty config is below)

<rp:RelyingParty id="https://sp.mydomain/shibboleth"

provider="https://idp.mydomain/idp/shibboleth"

defaultSigningCredentialRef="IdPCredential" >

<rp:ProfileConfiguration xsi:type="saml:SAML2SSOProfile"

encryptNameIds="never"

encryptAssertions="never"

signResponses="never"

/>

</rp:RelyingParty>

I can confirm from the logs that the SP never receives the response from IDP.

Any help would be greatly appreciated

Regards,

Daniel

-------

Daniel Appleby,

Unified Communications Team Leader,

Information Technology Services Division

Deakin University Geelong, Victoria 3217 Australia.

E-Mail: dapp...@deakin.edu.au

Website: http://www.deakin.edu.au/its/

Deakin University CRICOS Provider Code 00113B

Important Notice: The contents of this email transmission, including any attachments, are intended solely for the named addressee and are confidential; any unauthorised use, reproduction or storage of the contents and any attachments is expressly prohibited. If you have received this transmission in error, please delete it and any attachments from your system immediately and advise the sender by return email or telephone. Deakin University does not warrant that this email and any attachments are error or virus free.

Scott Cantor

unread,

Nov 3, 2010, 12:58:49 AM11/3/10

to shibbole...@internet2.edu, shibbole...@internet2.edu

On Nov 3, 2010, at 12:28 AM, Daniel Appleby <daniel....@deakin.edu.au> wrote:
> After doing a heap of tracing I can see the SP creating the AuthnRequest then deflating and redirecting to the IDP. The IDP opens the request and sees that no logon context exists for the user and produces the logon page. The logon works as well as the attribute filtering etc (in the logs). After all that is done I was expecting the IDP to create a SAML response to send back to the SP via POST, however, it seems to redirect back to itself (/SAML2/Redirect/SSO) and strip off the AuthnRequest so I get the decoding error shown below.
>

I don't know which login handler you're using, but this looks like a bug I found and patched around that occurs when the handler returns to the engine with a failure instead of a principal identified. The code loops back to the incoming message phase and tries to process it as a new request. So I would look for that behavior in your login handler.

I filed it in Jira along with a patch, which was simple.
>

-- Scott

Daniel Appleby

unread,

Nov 3, 2010, 1:23:59 AM11/3/10

to shibbole...@internet2.edu

I am using ldap 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>

The logs indicate that the ldap lookup and validation were successful.

Regards,
Daniel

Scott Cantor

unread,

Nov 3, 2010, 9:05:31 AM11/3/10

to shibbole...@internet2.edu

> The logs indicate that the ldap lookup and validation were successful.

Ok, probably not the bug I saw then. Just a thought.

-- Scott

Chad La Joie

unread,

Nov 3, 2010, 9:09:03 AM11/3/10

to shibbole...@internet2.edu

The log says the IdP received an invalid message. You'll really need
to address that before you can go on.

On Wed, Nov 3, 2010 at 00:28, Daniel Appleby
<daniel....@deakin.edu.au> wrote:
> 14:36:02.043 - WARN
> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:336]
> - Error decoding authentication request message
>
> org.opensaml.ws.message.decoder.MessageDecodingException: No SAMLRequest or
> SAMLResponse query path parameter, invalid SAML 2 HTTP Redirect message

--
Chad La Joie
www.itumi.biz
trusted identities, delivered

Brent Putman

unread,

Nov 3, 2010, 1:11:07 PM11/3/10

to shibbole...@internet2.edu

On 11/3/10 12:28 AM, Daniel Appleby wrote:

14:36:02.043 - WARN [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:336] - Error decoding authentication request message

org.opensaml.ws.message.decoder.MessageDecodingException: No SAMLRequest or SAMLResponse query path parameter, invalid SAML 2 HTTP Redirect message

Well the actual error is pretty self-explanatory: the inbound redirect to the Idp doesn't have the SAMLRequest query param. Are you sure you're not mistakenly doing a SAML 1 Shibboleth SSO request on the SP side, and then mistakenly sending it to a SAML 2 endpoint due to incorrect metadata? Other than the bug Scott mentioned, I can't off-hand think of anything else that would cause the data to not be there in the binding.

Is there anything in the relyingparty config that affects where the POST response is sent? (my relyparty config is below)

It's failing in the decoding phase, which is long before any of that config is really relevant. The request essentially just doesn't have the data params that are expected for that binding. Might be useful to trace the whole flow with Live Headers or something, to see exactly what's going on vis-a-vis the browser.

Daniel Appleby

unread,

Nov 3, 2010, 10:46:22 PM11/3/10

to shibbole...@internet2.edu

The decoding error is due to the fact the IDP is redirecting to itself (which I am not sure why this occurring). The first redirect from the SP to IDP works perfectly the SAML request is picked up however it’s after all the processing the IDP should send the SAML response but it doesn’t. It redirects back to itself causing the error.

14:35:56.020 - INFO [Shibboleth-Access:73] - 20101103T033556Z|10.80.11.58|idp.example.org:443|/profile/SAML2/Redirect/SSO|

14:35:56.022 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO

14:35:56.022 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:93] - shibboleth.HandlerManager: Located profile handler of the following type for the request path: edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler

14:35:56.023 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:316] - LoginContext key cookie was not present in request

14:35:56.023 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:156] - Incoming request does not contain a login context, processing as first leg of request

14:35:56.024 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:304] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect'

14:35:56.025 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:72] - Beginning to decode message from inbound transport of type: org.opensaml.ws.transport.http.HttpServletRequestAdapter

14:35:56.025 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:89] - Decoded RelayState: cookie:87424bfb

14:35:56.026 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:126] - Base64 decoding and inflating SAML message

14:35:56.026 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:161] - Parsing message stream into DOM document

14:35:56.027 - TRACE [org.opensaml.ws.message.decoder.BaseMessageDecoder:168] - Resultant DOM message was:

<?xml version="1.0" encoding="UTF-8"?><samlp:AuthnRequest xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol" AssertionConsumerServiceURL="https://sp.example.org/Shibboleth.sso/SAML2/POST" Destination="https://idp.example.org/idp/profile/SAML2/Redirect/SSO" ID="_036874ef61c1ae673a07ffc88e1d63bc" IssueInstant="2010-11-03T03:35:55Z" ProtocolBinding="urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST" Version="2.0"><saml:Issuer xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">https://sp.example.org/shibboleth</saml:Issuer><samlp:NameIDPolicy AllowCreate="1"/></samlp:AuthnRequest>

14:35:56.027 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:171] - Unmarshalling message DOM

14:35:56.036 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:183] - Message succesfully unmarshalled

14:35:56.036 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:104] - Decoded SAML message

14:35:56.036 - DEBUG [org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder:111] - Extracting ID, issuer and issue instant from request

14:35:56.036 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:199] - Checking child metadata provider for entity descriptor with entity ID: https://sp.example.org/shibboleth

14:35:56.036 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - Searching for entity descriptor with an entity ID of https://sp.example.org/shibboleth

14:35:56.036 - TRACE [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:522] - Metadata root is an entity descriptor, checking if it's the one we're looking for.

14:35:56.036 - TRACE [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:529] - Found entity descriptor for entity with ID

14:35:56.038 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - Searching for entity descriptor with an entity ID of https://sp.example.org/shibboleth

14:35:56.038 - TRACE [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:522] - Metadata root is an entity descriptor, checking if it's the one we're looking for.

14:35:56.038 - TRACE [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:543] - Located entity descriptor, creating an index to it for faster lookups

14:35:56.039 - DEBUG [PROTOCOL_MESSAGE:91] -

<?xml version="1.0" encoding="UTF-8"?><samlp:AuthnRequest xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol" AssertionConsumerServiceURL="https://sp.example.org/Shibboleth.sso/SAML2/POST" Destination="https://idp.example.org/idp/profile/SAML2/Redirect/SSO" ID="_036874ef61c1ae673a07ffc88e1d63bc" IssueInstant="2010-11-03T03:35:55Z" ProtocolBinding="urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST" Version="2.0">

<saml:Issuer xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">https://sp.example.org/shibboleth</saml:Issuer>

<samlp:NameIDPolicy AllowCreate="1"/>

</samlp:AuthnRequest>

#### NORMAL IDP PROCESSING SNIP ####

14:35:56.355 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:203] - Processing incoming request

14:35:56.355 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:326] - Looking up LoginContext with key 83887e6d-96e5-4e09-a9e2-cad4281aa019 from StorageService parition: loginContexts

14:35:56.355 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:332] - Retrieved LoginContext with key 83887e6d-96e5-4e09-a9e2-cad4281aa019 from StorageService parition: loginContexts

14:35:56.356 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:233] - Beginning user authentication process.

14:35:56.356 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:279] - Filtering configured LoginHandlers: {urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler@654d8a08, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@45a1472d}

14:35:56.356 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:329] - Filtering out previous session login handler because there is no existing IdP session

14:35:56.356 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:463] - Selecting appropriate login handler from filtered set {urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@45a1472d}

###### SUCCESSFUL AUTHENTICATION SNIP ######

14:36:01.966 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:106] - Filtered attributes for principal dappleby. The following attributes remain: [homeOrganizationType, uid, sn, transientId, o, givenName, homeOrganization, eduPersonTargetedID, cn, eduPersonEntitlement, displayName]

14:36:02.040 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:565] - Unbinding LoginContext

14:36:02.041 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:591] - Expiring LoginContext cookie

14:36:02.041 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:600] - Removing LoginContext, with key dc78e044-5740-4c16-b3f6-b381628a0f5c, from StorageService partition loginContexts

####### The idp should send a post response back here but instead redirects to itself (/profile/SAML2/Redirect/SSO) without the SAML Request that was sent above…hence the decode error…

14:36:02.041 - INFO [Shibboleth-Access:73] - 20101103T033602Z|10.80.11.58|idp.example.org:443|/profile/SAML2/Redirect/SSO|