Chaining TrustEngine doesn't clear matching criteria between engines, so TrustEngine ordering affects the results.
Description
Environment
Tested with Centos and Solaris SPs but I believe this is independent of OS.
Failing conditions tested with 2.3.1 and 2.4.0 SP and 2.5.1 IdP.
Tested with the TrustEngines in reverse order on the 2.3.1 SP but not the 2.4.0 SP.
Activity
Scott Cantor January 21, 2011 at 7:01 PM
http://svn.middleware.georgetown.edu/view/cpp-xmltooling?view=rev&revision=831
I was able to verify the XML from the log with PKIX in second position.
Scott Cantor January 21, 2011 at 3:06 PM
I think the source of the problem is that the ExplicitKey engine saves off the certificate from the signature into the matching rules used to look up material in the metadata that should be applied to the check. That material isn't cleared out when the next engine runs. Since the keys don't match, the KeyDescriptor containing the KeyName is rejected when the matching process runs in the PKIX case. When you reverse the order, the signature content is never injected into the matching rules, so the KeyDescriptor is acceptable and the KeyName inside is seen by the engine and it works.
The project's precedent for PKIX is that we have never looked at or evaluated X509Certificate content in the metadata. I'm not sure that was the right call, and I know it's not how all the PKIX-operated federations do things or expect it to work, but I don't think we can really change that now. I know we felt that trying to combine two different semantics for the same element in metadata with two different trust engines that were both configured by default was a bad idea.
My concern is that strictly speaking, one could argue that the bug here is not that it fails in one instance but that it works in the other. If the KeyDescriptor contains Key A and you sign with Key B, should that really work? Seems kind of questionable to me.
But I think we've documented the PKIX engine as ignoring X509Certificate, period, and we have to adhere to that if we can, so the bug is probably that I need to reset the matching rules between engines.
Scott Cantor January 21, 2011 at 2:53 PM
The log trace here suggests to me that the xmltooling version may be too old. Can you please check that it's using the latest version in each case (1.3.3 and 1.4 respectively)? I think I know what it's doing, but the additional logging should help.
The SP has the following trust engine configuration in shibboleth2.xml:
<!-- Chain the two built-in trust engines together. -->
<TrustEngine type="Chaining">
<TrustEngine type="ExplicitKey"/>
<TrustEngine type="PKIX"/>
</TrustEngine>
and the IdP's metadata in the federation metadata file has a <KeyDescriptor use="signing"> in the <IDPSSODescriptor> and in the <AttributeAuthorityDescriptor> with identical contents in each one, viz. a KeyName element and an <ds:X509Data> element, with embedded certificate contents.
The embedded certificate does not match the certificate that the IdP actually is presenting, which is a CA certificate for which the appropriate certificate chain is in the federation metadata. The value of the KeyName elements does match the CN of the certificate that the IdP is presenting. "ExplicitKey" validation fails, which is correct, but "PKIX" apparently fails too, although it should succeed. At any rate, validation fails overall.
Interestingly, if the order of the trust engines within the Chaining engine is reversed, the PKIX engine succeeds and validation succeeds overall.
Link to UK federation metadata: http://metadata.ukfederation.org.uk/ukfederation-metadata.xml
IdP entity ID: https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth
SP log for failed attempt:
2011-01-21 17:04:14 DEBUG Shibboleth.Listener [3]: dispatching message (default/SAML/POST)
2011-01-21 17:04:14 DEBUG OpenSAML.MessageDecoder.SAML1POST [3]: validating input
2011-01-21 17:04:15 DEBUG OpenSAML.MessageDecoder.SAML1POST [3]: decoded SAML response:
<?xml version="1.0" encoding="UTF-8"?><saml1p:Response xmlns:saml1p="urn:oasis:names:tc:SAML:1.0:protocol" IssueInstant="2011-01-21T17:04:13.149Z" MajorVersion="1" MinorVersion="1" Recipient="https://dlib-lamlash.ucs.ed.ac.uk/Shibboleth.sso/SAML/POST" ResponseID="_2359ce0548da38b54b50334d0c3c615a"><ds:Signature xmlns:ds="http://www.w3.org/2000/09/xmldsig#">
<ds:SignedInfo>
<ds:CanonicalizationMethod Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"/>
<ds:SignatureMethod Algorithm="http://www.w3.org/2000/09/xmldsig#rsa-sha1"/>
<ds:Reference URI="#_2359ce0548da38b54b50334d0c3c615a">
<ds:Transforms>
<ds:Transform Algorithm="http://www.w3.org/2000/09/xmldsig#enveloped-signature"/>
<ds:Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"><ec:InclusiveNamespaces xmlns:ec="http://www.w3.org/2001/10/xml-exc-c14n#" PrefixList="ds saml1 saml1p"/></ds:Transform>
</ds:Transforms>
<ds:DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"/>
<ds:DigestValue>tHIIVGITNzP5Q74Dj4R8Ot1Y4Zo=</ds:DigestValue>
</ds:Reference>
</ds:SignedInfo>
<ds:SignatureValue>
LeTYHUnawA/r1j3NYnQY3H7MKfxqd7dCuTHiv1tE8dhvFAV3nUFKrp8vXSgbvuhT9dAkpqt37AKI
l/+GLo8x3QIXq823gMQENQftjv8D2CSilGpKrJZTo87RYV5FTbIXRbWuxdQ0ozZ/Yzng6c4qUq5G
B3nZ4XwE10Jn/cuaYG0znxdsuXzsN16YI3KowFJuX92prvJbVuihSfdq62J4OmMJgvnvS9uaf00Y
7CwXCzVxejyzHE9S+uR6p5Yk89kBDazTNr1rSZLBvu041dunN9O8+o2wVpRb/rd8j4duhvBWzNWE
cUHfTL3hNcXuBLW3V+lVDoktFSoxb6Zug4BpDA==
</ds:SignatureValue>
<ds:KeyInfo><ds:X509Data><ds:X509Certificate>MIIEuzCCA6OgAwIBAgIQEJLmX2HjXEpTSP6oG3681TANBgkqhkiG9w0BAQUFADA2MQswCQYDVQQG
EwJOTDEPMA0GA1UEChMGVEVSRU5BMRYwFAYDVQQDEw1URVJFTkEgU1NMIENBMB4XDTEwMDMwNTAw
MDAwMFoXDTEzMDMwNDIzNTk1OVowgY0xCzAJBgNVBAYTAkdCMREwDwYDVQQIEwhTY290bGFuZDES
MBAGA1UEBxMJRWRpbmJ1cmdoMSQwIgYDVQQKExtUaGUgVW5pdmVyc2l0eSBvZiBFZGluYnVyZ2gx
DjAMBgNVBAsTBUVESU5BMSEwHwYDVQQDExhkbGliLXNrYWlsbC51Y3MuZWQuYWMudWswggEiMA0G
CSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQCWb4zfOmHbMTONF+r6w4Ov/TWiynauU/nBK8/nsFGS
w7uaTT/9r0NEfpWV2RudjYkJIXu8k7BkgfiOKheC2r7r/1+epQ97A5WWXejMzlzEQtCyyPalMHmf
0TVTYjxboQECOP14u2DFGUoqfSwxyJ3rUrU143hYmq9R69X3rw46r5hcS+bTz/KqIRAg8yoZeZcl
osvTSPKUFFIZcjgQv8Ma5TBeA+9kncPG+U2mqURq/x8L3P3uEsS94CtPzeWdB+CO7IjewnEhzWqP
63kuD4tZR4zTgU2F/o+3IZqNRUXIOqlZRgG72g4iwqOqfMAOJa72L30b90yTCYfDOQzbM7PTAgMB
AAGjggFrMIIBZzAfBgNVHSMEGDAWgBQMvZNoDPPeq6NJays3V0fqkOO57TAdBgNVHQ4EFgQUBAl/
Rwt2hJZFIC5c1WeKMw4haHQwDgYDVR0PAQH/BAQDAgWgMAwGA1UdEwEB/wQCMAAwHQYDVR0lBBYw
FAYIKwYBBQUHAwEGCCsGAQUFBwMCMBgGA1UdIAQRMA8wDQYLKwYBBAGyMQECAh0wOgYDVR0fBDMw
MTAvoC2gK4YpaHR0cDovL2NybC50Y3MudGVyZW5hLm9yZy9URVJFTkFTU0xDQS5jcmwwbQYIKwYB
BQUHAQEEYTBfMDUGCCsGAQUFBzAChilodHRwOi8vY3J0LnRjcy50ZXJlbmEub3JnL1RFUkVOQVNT
TENBLmNydDAmBggrBgEFBQcwAYYaaHR0cDovL29jc3AudGNzLnRlcmVuYS5vcmcwIwYDVR0RBBww
GoIYZGxpYi1za2FpbGwudWNzLmVkLmFjLnVrMA0GCSqGSIb3DQEBBQUAA4IBAQCqpn/ibGdAfrYz
QOCFIgfKqDlflycaf5goStT00/bDDURCqTouYLj04AReOzf0uQxm4sSPrtm7ejseZN+v1oTkaT
aziqjqW5IcfgxK5pFFEJ5V2JGDHLQYPphHN2WZ2ShZDnA7vFhMkuWopSb0Ja2sSDOsF0dNKJKyEw
KGKIUp5cuIThJLOTYcWBUL4XZf8cYUWQYxpDTyeKEr8hV3pZcbllHWKyNP179qHJ1qCmnBSuP2Fe
G00lG39avqDw08BfKzuMMHQAOfKz4tbaQkfQSuSGK0LfkGnkrw2O9rOtLb4pRyrkThePuVmDRGfy
/gsDmi4LwmBOfBsbPYcYbPyF</ds:X509Certificate></ds:X509Data></ds:KeyInfo></ds:Signature><saml1p:Status><saml1p:StatusCode Value="saml1p:Success"/></saml1p:Status><saml1:Assertion xmlns:saml1="urn:oasis:names:tc:SAML:1.0:assertion" AssertionID="_8b9c846484469d3d7874150140273af2" IssueInstant="2011-01-21T17:04:13.149Z" Issuer="https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth" MajorVersion="1" MinorVersion="1"><saml1:Conditions NotBefore="2011-01-21T17:04:13.149Z" NotOnOrAfter="2011-01-21T17:09:13.149Z"><saml1:AudienceRestrictionCondition><saml1:Audience>https://dlib-lamlash.ucs.ed.ac.uk/sp/shibboleth</saml1:Audience></saml1:AudienceRestrictionCondition></saml1:Conditions><saml1:AuthenticationStatement AuthenticationInstant="2011-01-21T17:04:13.117Z" AuthenticationMethod="urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport"><saml1:Subject><saml1:NameIdentifier Format="urn:mace:shibboleth:1.0:nameIdentifier">_6b1bff1dd99c3c38fbfb767b988a673c</saml1:NameIdentifier><saml1:SubjectConfirmation><saml1:ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:bearer</saml1:ConfirmationMethod></saml1:SubjectConfirmation></saml1:Subject><saml1:SubjectLocality IPAddress="129.215.169.99"/></saml1:AuthenticationStatement></saml1:Assertion></saml1p:Response>
2011-01-21 17:04:15 DEBUG OpenSAML.MessageDecoder.SAML1 [3]: extracting issuer from SAML 1.x Response
2011-01-21 17:04:15 DEBUG OpenSAML.MessageDecoder.SAML1 [3]: response from (https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth)
2011-01-21 17:04:15 DEBUG OpenSAML.MessageDecoder.SAML1 [3]: searching metadata for response issuer...
2011-01-21 17:04:15 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [3]: evaluating message flow policy (replay checking on, expiration 60)
2011-01-21 17:04:15 DEBUG XMLTooling.StorageService [3]: inserted record (_2359ce0548da38b54b50334d0c3c615a) in context (MessageFlow)
2011-01-21 17:04:15 DEBUG OpenSAML.SecurityPolicyRule.XMLSigning [3]: validating signature profile
2011-01-21 17:04:15 DEBUG XMLTooling.TrustEngine.ExplicitKey [3]: unable to validate signature, no credentials available from peer
2011-01-21 17:04:15 DEBUG XMLTooling.TrustEngine.PKIX [3]: validating signature using certificate from within the signature
2011-01-21 17:04:15 DEBUG XMLTooling.TrustEngine.PKIX [3]: signature verified with key inside signature, attempting certificate validation...
2011-01-21 17:04:15 DEBUG XMLTooling.TrustEngine.PKIX [3]: checking that the certificate name is acceptable
2011-01-21 17:04:15 DEBUG XMLTooling.TrustEngine.PKIX [3]: certificate subject: CN=dlib-skaill.ucs.ed.ac.uk,OU=EDINA,O=The University of Edinburgh,L=Edinburgh,ST=Scotland,C=GB
2011-01-21 17:04:15 DEBUG XMLTooling.TrustEngine.PKIX [3]: unable to match DN, trying TLS subjectAltName match
2011-01-21 17:04:15 DEBUG XMLTooling.TrustEngine.PKIX [3]: unable to match subjectAltName, trying TLS CN match
2011-01-21 17:04:15 ERROR XMLTooling.TrustEngine.PKIX [3]: certificate name was not acceptable
2011-01-21 17:04:15 ERROR OpenSAML.SecurityPolicyRule.XMLSigning [3]: unable to verify message signature with supplied trust engine
SP log for successful attempt with TrustEngines in reverse order:
2011-01-21 17:07:06 DEBUG Shibboleth.Listener [2]: dispatching message (default/DS::run::Shib1SI)
2011-01-21 17:07:07 DEBUG Shibboleth.Listener [3]: dispatching message (default/SAML/POST)
2011-01-21 17:07:07 DEBUG OpenSAML.MessageDecoder.SAML1POST [3]: validating input
2011-01-21 17:07:07 DEBUG OpenSAML.MessageDecoder.SAML1POST [3]: decoded SAML response:
<?xml version="1.0" encoding="UTF-8"?><saml1p:Response xmlns:saml1p="urn:oasis:names:tc:SAML:1.0:protocol" IssueInstant="2011-01-21T17:07:06.405Z" MajorVersion="1" MinorVersion="1" Recipient="https://dlib-lamlash.ucs.ed.ac.uk/Shibboleth.sso/SAML/POST" ResponseID="_cfca27149d08cb9a1790608f574cbb84"><ds:Signature xmlns:ds="http://www.w3.org/2000/09/xmldsig#">
<ds:SignedInfo>
<ds:CanonicalizationMethod Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"/>
<ds:SignatureMethod Algorithm="http://www.w3.org/2000/09/xmldsig#rsa-sha1"/>
<ds:Reference URI="#_cfca27149d08cb9a1790608f574cbb84">
<ds:Transforms>
<ds:Transform Algorithm="http://www.w3.org/2000/09/xmldsig#enveloped-signature"/>
<ds:Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"><ec:InclusiveNamespaces xmlns:ec="http://www.w3.org/2001/10/xml-exc-c14n#" PrefixList="ds saml1 saml1p"/></ds:Transform>
</ds:Transforms>
<ds:DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"/>
<ds:DigestValue>hiYIy897Cutdez/E9HXBd2b0hvE=</ds:DigestValue>
</ds:Reference>
</ds:SignedInfo>
<ds:SignatureValue>
GB7Ic8fIkOel36wHGyD5OtuqlnJFc5kdw1ajGdnnytVKgyAkMVP8Um72bCs5q8QUIN74rZH7KXu9
qvA8gLWQTLKH+riNV0Rxo7dR6i8yy/HNqfrjxSZzlNQTqDj+48bvC5Q+pFbznRyptp4J45n3Dys4
tDJiSegQ9Yay+DRkidRhKPp2MkRg6kVWDgdLfTNfZQ80TvuU3bsMY7qJcvoEhN7p8BVSSCKHCha8
NcWGSX6NX2hYI/DoEtIsh0AWXQ7b0xHmG+4sf/bD/SbPn9WIa69jNN3+CnDJh7y+26KYpbkUjbzJ
9QfpXV6xBhOCgM12xjHWRuJYhoE58ib6eLylDA==
</ds:SignatureValue>
<ds:KeyInfo><ds:X509Data><ds:X509Certificate>MIIEuzCCA6OgAwIBAgIQEJLmX2HjXEpTSP6oG3681TANBgkqhkiG9w0BAQUFADA2MQswCQYDVQQG
EwJOTDEPMA0GA1UEChMGVEVSRU5BMRYwFAYDVQQDEw1URVJFTkEgU1NMIENBMB4XDTEwMDMwNTAw
MDAwMFoXDTEzMDMwNDIzNTk1OVowgY0xCzAJBgNVBAYTAkdCMREwDwYDVQQIEwhTY290bGFuZDES
MBAGA1UEBxMJRWRpbmJ1cmdoMSQwIgYDVQQKExtUaGUgVW5pdmVyc2l0eSBvZiBFZGluYnVyZ2gx
DjAMBgNVBAsTBUVESU5BMSEwHwYDVQQDExhkbGliLXNrYWlsbC51Y3MuZWQuYWMudWswggEiMA0G
CSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQCWb4zfOmHbMTONF+r6w4Ov/TWiynauU/nBK8/nsFGS
w7uaTT/9r0NEfpWV2RudjYkJIXu8k7BkgfiOKheC2r7r/1+epQ97A5WWXejMzlzEQtCyyPalMHmf
0TVTYjxboQECOP14u2DFGUoqfSwxyJ3rUrU143hYmq9R69X3rw46r5hcS+bTz/KqIRAg8yoZeZcl
osvTSPKUFFIZcjgQv8Ma5TBeA+9kncPG+U2mqURq/x8L3P3uEsS94CtPzeWdB+CO7IjewnEhzWqP
63kuD4tZR4zTgU2F/o+3IZqNRUXIOqlZRgG72g4iwqOqfMAOJa72L30b90yTCYfDOQzbM7PTAgMB
AAGjggFrMIIBZzAfBgNVHSMEGDAWgBQMvZNoDPPeq6NJays3V0fqkOO57TAdBgNVHQ4EFgQUBAl/
Rwt2hJZFIC5c1WeKMw4haHQwDgYDVR0PAQH/BAQDAgWgMAwGA1UdEwEB/wQCMAAwHQYDVR0lBBYw
FAYIKwYBBQUHAwEGCCsGAQUFBwMCMBgGA1UdIAQRMA8wDQYLKwYBBAGyMQECAh0wOgYDVR0fBDMw
MTAvoC2gK4YpaHR0cDovL2NybC50Y3MudGVyZW5hLm9yZy9URVJFTkFTU0xDQS5jcmwwbQYIKwYB
BQUHAQEEYTBfMDUGCCsGAQUFBzAChilodHRwOi8vY3J0LnRjcy50ZXJlbmEub3JnL1RFUkVOQVNT
TENBLmNydDAmBggrBgEFBQcwAYYaaHR0cDovL29jc3AudGNzLnRlcmVuYS5vcmcwIwYDVR0RBBww
GoIYZGxpYi1za2FpbGwudWNzLmVkLmFjLnVrMA0GCSqGSIb3DQEBBQUAA4IBAQCqpn/ibGdAfrYz
QOCFIgfKqDlflycaf5goStT00/bDDURCqTouYLj04AReOzf0uQxm4sSPrtm7ejseZN+v1oTkaT
aziqjqW5IcfgxK5pFFEJ5V2JGDHLQYPphHN2WZ2ShZDnA7vFhMkuWopSb0Ja2sSDOsF0dNKJKyEw
KGKIUp5cuIThJLOTYcWBUL4XZf8cYUWQYxpDTyeKEr8hV3pZcbllHWKyNP179qHJ1qCmnBSuP2Fe
G00lG39avqDw08BfKzuMMHQAOfKz4tbaQkfQSuSGK0LfkGnkrw2O9rOtLb4pRyrkThePuVmDRGfy
/gsDmi4LwmBOfBsbPYcYbPyF</ds:X509Certificate></ds:X509Data></ds:KeyInfo></ds:Signature><saml1p:Status><saml1p:StatusCode Value="saml1p:Success"/></saml1p:Status><saml1:Assertion xmlns:saml1="urn:oasis:names:tc:SAML:1.0:assertion" AssertionID="_2648947bab9b7ec15c9cbd4307140a50" IssueInstant="2011-01-21T17:07:06.405Z" Issuer="https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth" MajorVersion="1" MinorVersion="1"><saml1:Conditions NotBefore="2011-01-21T17:07:06.405Z" NotOnOrAfter="2011-01-21T17:12:06.405Z"><saml1:AudienceRestrictionCondition><saml1:Audience>https://dlib-lamlash.ucs.ed.ac.uk/sp/shibboleth</saml1:Audience></saml1:AudienceRestrictionCondition></saml1:Conditions><saml1:AuthenticationStatement AuthenticationInstant="2011-01-21T17:04:13.117Z" AuthenticationMethod="urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport"><saml1:Subject><saml1:NameIdentifier Format="urn:mace:shibboleth:1.0:nameIdentifier">_6b1bff1dd99c3c38fbfb767b988a673c</saml1:NameIdentifier><saml1:SubjectConfirmation><saml1:ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:bearer</saml1:ConfirmationMethod></saml1:SubjectConfirmation></saml1:Subject><saml1:SubjectLocality IPAddress="129.215.169.99"/></saml1:AuthenticationStatement></saml1:Assertion></saml1p:Response>
2011-01-21 17:07:07 DEBUG OpenSAML.MessageDecoder.SAML1 [3]: extracting issuer from SAML 1.x Response
2011-01-21 17:07:07 DEBUG OpenSAML.MessageDecoder.SAML1 [3]: response from (https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth)
2011-01-21 17:07:07 DEBUG OpenSAML.MessageDecoder.SAML1 [3]: searching metadata for response issuer...
2011-01-21 17:07:07 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [3]: evaluating message flow policy (replay checking on, expiration 60)
2011-01-21 17:07:07 DEBUG XMLTooling.StorageService [3]: inserted record (_cfca27149d08cb9a1790608f574cbb84) in context (MessageFlow)
2011-01-21 17:07:07 DEBUG OpenSAML.SecurityPolicyRule.XMLSigning [3]: validating signature profile
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine.PKIX [3]: validating signature using certificate from within the signature
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine.PKIX [3]: signature verified with key inside signature, attempting certificate validation...
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine.PKIX [3]: checking that the certificate name is acceptable
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine.PKIX [3]: certificate subject: CN=dlib-skaill.ucs.ed.ac.uk,OU=EDINA,O=The University of Edinburgh,L=Edinburgh,ST=Scotland,C=GB
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine.PKIX [3]: unable to match DN, trying TLS subjectAltName match
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine.PKIX [3]: matched DNS/URI subjectAltName to a key name (dlib-skaill.ucs.ed.ac.uk)
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine.PKIX [3]: performing certificate path validation...
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine [3]: supplying PKIX Validation information
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine [3]: supplied (16) CA certificate(s)
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine [3]: supplied (0) CRL(s)
2011-01-21 17:07:07 DEBUG XMLTooling.TrustEngine [3]: successfully validated certificate chain
2011-01-21 17:07:07 DEBUG OpenSAML.SecurityPolicyRule.XMLSigning [3]: signature verified against message issuer
2011-01-21 17:07:07 DEBUG Shibboleth.SSO.SAML1 [3]: processing message against SAML 1.x SSO profile
2011-01-21 17:07:07 DEBUG Shibboleth.SSO.SAML1 [3]: extracting issuer from SAML 1.x assertion
2011-01-21 17:07:07 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [3]: evaluating message flow policy (replay checking on, expiration 60)
2011-01-21 17:07:07 DEBUG XMLTooling.StorageService [3]: inserted record (_2648947bab9b7ec15c9cbd4307140a50) in context (MessageFlow)
2011-01-21 17:07:07 DEBUG Shibboleth.SSO.SAML1 [3]: checking client address
2011-01-21 17:07:07 DEBUG Shibboleth.SSO.SAML1 [3]: SSO profile processing completed successfully
2011-01-21 17:07:07 DEBUG Shibboleth.SSO.SAML1 [3]: extracting pushed attributes...
2011-01-21 17:07:07 DEBUG Shibboleth.AttributeExtractor.XML [3]: skipping unmapped NameIdentifier with format (urn:mace:shibboleth:1.0:nameIdentifier)
2011-01-21 17:07:07 DEBUG Shibboleth.SSO.SAML1 [3]: resolving attributes...
2011-01-21 17:07:07 DEBUG Shibboleth.AttributeResolver.Query [3]: attempting SAML 1.x attribute query
2011-01-21 17:07:07 DEBUG XMLTooling.SOAPTransport.CURL [3]: getting connection handle to https://dlib-skaill.ucs.ed.ac.uk:8443/idp/profile/SAML1/SOAP/AttributeQuery
2011-01-21 17:07:07 DEBUG XMLTooling.SOAPTransport.CURL [3]: nothing free in pool, returning new connection handle
2011-01-21 17:07:07 DEBUG Shibboleth.SOAPClient [3]: prepping SOAP transport for use by application (default)
2011-01-21 17:07:07 DEBUG XMLTooling.SOAPClient [3]: marshalled envelope:
<S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/"><S:Body><samlp:Request xmlns:samlp="urn:oasis:names:tc:SAML:1.0:protocol" IssueInstant="2011-01-21T17:07:07Z" MajorVersion="1" MinorVersion="1" RequestID="_166fc227f79b834730fdbb7de52d6e5c"><samlp:AttributeQuery Resource="https://dlib-lamlash.ucs.ed.ac.uk/sp/shibboleth"><saml:Subject xmlns:saml="urn:oasis:names:tc:SAML:1.0:assertion"><saml:NameIdentifier Format="urn:mace:shibboleth:1.0:nameIdentifier">_6b1bff1dd99c3c38fbfb767b988a673c</saml:NameIdentifier></saml:Subject></samlp:AttributeQuery></samlp:Request></S:Body></S:Envelope>
2011-01-21 17:07:07 DEBUG XMLTooling.SOAPTransport.CURL [3]: sending SOAP message to https://dlib-skaill.ucs.ed.ac.uk:8443/idp/profile/SAML1/SOAP/AttributeQuery
2011-01-21 17:07:08 DEBUG XMLTooling.SOAPTransport.CURL [3]: invoking custom X.509 verify callback
2011-01-21 17:07:08 DEBUG XMLTooling.TrustEngine.PKIX [3]: performing certificate path validation...
2011-01-21 17:07:08 DEBUG XMLTooling.TrustEngine [3]: supplying PKIX Validation information
2011-01-21 17:07:08 DEBUG XMLTooling.TrustEngine [3]: supplied (16) CA certificate(s)
2011-01-21 17:07:08 DEBUG XMLTooling.TrustEngine [3]: supplied (0) CRL(s)
2011-01-21 17:07:08 DEBUG XMLTooling.TrustEngine [3]: successfully validated certificate chain
2011-01-21 17:07:08 DEBUG XMLTooling.SOAPClient [3]: received XML:
<soap11:Envelope xmlns:soap11="http://schemas.xmlsoap.org/soap/envelope/"><soap11:Body><saml1p:Response xmlns:saml1p="urn:oasis:names:tc:SAML:1.0:protocol" InResponseTo="_166fc227f79b834730fdbb7de52d6e5c" IssueInstant="2011-01-21T17:07:08.187Z" MajorVersion="1" MinorVersion="1" ResponseID="_cc844be6d314d058691c4cc49fab9491"><saml1p:Status><saml1p:StatusCode Value="saml1p:Success"/></saml1p:Status><saml1:Assertion xmlns:saml1="urn:oasis:names:tc:SAML:1.0:assertion" AssertionID="_a270f4b4ddb6a60dab154e5f9bc17bb6" IssueInstant="2011-01-21T17:07:08.187Z" Issuer="https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth" MajorVersion="1" MinorVersion="1"><saml1:Conditions NotBefore="2011-01-21T17:07:08.187Z" NotOnOrAfter="2011-01-21T17:12:08.187Z"><saml1:AudienceRestrictionCondition><saml1:Audience>https://dlib-lamlash.ucs.ed.ac.uk/sp/shibboleth</saml1:Audience></saml1:AudienceRestrictionCondition></saml1:Conditions><saml1:AttributeStatement><saml1:Subject><saml1:NameIdentifier Format="urn:mace:shibboleth:1.0:nameIdentifier">_6b1bff1dd99c3c38fbfb767b988a673c</saml1:NameIdentifier><saml1:SubjectConfirmation><saml1:ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:sender-vouches</saml1:ConfirmationMethod></saml1:SubjectConfirmation></saml1:Subject><saml1:Attribute AttributeName="urn:mace:dir:attribute-def:eduPersonScopedAffiliation" AttributeNamespace="urn:mace:shibboleth:1.0:attributeNamespace:uri"><saml1:AttributeValue Scope="dlib-skaill.ucs.ed.ac.uk">member</saml1:AttributeValue><saml1:AttributeValue Scope="dlib-skaill.ucs.ed.ac.uk">student</saml1:AttributeValue></saml1:Attribute><saml1:Attribute AttributeName="urn:mace:dir:attribute-def:eduPersonTargetedID" AttributeNamespace="urn:mace:shibboleth:1.0:attributeNamespace:uri"><saml1:AttributeValue Scope="dlib-skaill.ucs.ed.ac.uk">ovv8gV2v/sj10TQBeg27f0Cw/s4=</saml1:AttributeValue></saml1:Attribute><saml1:Attribute AttributeName="urn:oid:1.3.6.1.4.1.5923.1.1.1.10" AttributeNamespace="urn:mace:shibboleth:1.0:attributeNamespace:uri"><saml1:AttributeValue><saml2:NameID xmlns:saml2="urn:oasis:names:tc:SAML:2.0:assertion" Format="urn:oasis:names:tc:SAML:2.0:nameid-format:persistent" NameQualifier="https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth" SPNameQualifier="https://dlib-lamlash.ucs.ed.ac.uk/sp/shibboleth">ovv8gV2v/sj10TQBeg27f0Cw/s4=</saml2:NameID></saml1:AttributeValue></saml1:Attribute></saml1:AttributeStatement></saml1:Assertion></saml1p:Response></soap11:Body></soap11:Envelope>
2011-01-21 17:07:08 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [3]: evaluating message flow policy (replay checking on, expiration 60)
2011-01-21 17:07:08 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [3]: evaluating message flow policy (replay checking on, expiration 60)
2011-01-21 17:07:08 DEBUG XMLTooling.StorageService [3]: inserted record (_cc844be6d314d058691c4cc49fab9491) in context (MessageFlow)
2011-01-21 17:07:08 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [3]: evaluating message flow policy (replay checking on, expiration 60)
2011-01-21 17:07:08 DEBUG XMLTooling.StorageService [3]: inserted record (_a270f4b4ddb6a60dab154e5f9bc17bb6) in context (MessageFlow)
2011-01-21 17:07:08 DEBUG Shibboleth.AttributeDecoder.Scoped [3]: decoding ScopedAttribute (affiliation) from SAML 1 Attribute (urn:mace:dir:attribute-def:eduPersonScopedAffiliation) with 2 value(s)
2011-01-21 17:07:08 DEBUG Shibboleth.AttributeDecoder.NameIDFromScoped [3]: decoding NameIDAttribute (persistent-id) from SAML 1 Attribute (urn:mace:dir:attribute-def:eduPersonTargetedID) with 1 value(s)
2011-01-21 17:07:08 DEBUG Shibboleth.AttributeDecoder.NameID [3]: decoding NameIDAttribute (persistent-id) from SAML 1 Attribute (urn:oid:1.3.6.1.4.1.5923.1.1.1.10) with 1 value(s)
2011-01-21 17:07:08 DEBUG Shibboleth.AttributeFilter [3]: filtering 3 attribute(s) from (https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth)
2011-01-21 17:07:08 DEBUG Shibboleth.AttributeFilter [3]: applying filtering rule(s) for attribute (affiliation) from (https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth)
2011-01-21 17:07:08 DEBUG Shibboleth.AttributeFilter [3]: applying filtering rule(s) for attribute (persistent-id) from (https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth)
2011-01-21 17:07:08 DEBUG Shibboleth.AttributeFilter [3]: applying filtering rule(s) for attribute (persistent-id) from (https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth)
2011-01-21 17:07:08 DEBUG Shibboleth.SessionCache [3]: creating new session
2011-01-21 17:07:08 DEBUG Shibboleth.SessionCache [3]: storing new session...
2011-01-21 17:07:08 DEBUG XMLTooling.StorageService [3]: inserted record (session) in context (_438446998eafda63bbd1751a44a0facf)
2011-01-21 17:07:08 DEBUG XMLTooling.StorageService [3]: inserted record (_6b1bff1dd99c3c38fbfb767b988a673c) in context (NameID)
2011-01-21 17:07:08 DEBUG XMLTooling.StorageService [3]: inserted record (_2648947bab9b7ec15c9cbd4307140a50) in context (_438446998eafda63bbd1751a44a0facf)
2011-01-21 17:07:08 DEBUG XMLTooling.StorageService [3]: inserted record (_a270f4b4ddb6a60dab154e5f9bc17bb6) in context (_438446998eafda63bbd1751a44a0facf)
2011-01-21 17:07:08 INFO Shibboleth.SessionCache [3]: new session created: ID (_438446998eafda63bbd1751a44a0facf) IdP (https://dlib-skaill.ucs.ed.ac.uk/idp/shibboleth) Protocol(urn:oasis:names:tc:SAML:1.1:protocol) Address (129.215.169.99)
2011-01-21 17:07:08 DEBUG Shibboleth.SSO.SAML1 [3]: ACS returning via redirect to: https://dlib-lamlash.ucs.ed.ac.uk/secure/index.html
2011-01-21 17:07:09 DEBUG Shibboleth.Listener [4]: dispatching message (default::getHeaders::Application)
2011-01-21 17:07:09 DEBUG Shibboleth.Listener [4]: dispatching message (find::StorageService::SessionCache)
2011-01-21 17:07:09 DEBUG XMLTooling.StorageService [4]: updated expiration of valid records in context (_438446998eafda63bbd1751a44a0facf)
2011-01-21 17:07:10 DEBUG Shibboleth.Listener [5]: dispatching message (default::getHeaders::Application)
2011-01-21 17:07:10 DEBUG Shibboleth.Listener [5]: dispatching message (find::StorageService::SessionCache)
2011-01-21 17:07:10 DEBUG XMLTooling.StorageService [5]: updated expiration of valid records in context (_438446998eafda63bbd1751a44a0fac