Successful login to IdP but no attributes returned

Discussion:

Gordon Capreol

2011-06-02 01:00:38 UTC

We are a service provider running the latest SP (2.4.2) on IIS trying to work with an IdP running 1.3. This was working in the past, but last week, we got some messages about times being out of sync and also noticed an expired cert was being used. We synchronized our time and updated the cert and we're now able to login, however, no attributes are being returned by the IdP. I've been running through our logs on the SP side, and here are some of the messages I'm seeing:

In shibd.log:
2011-06-01 19:25:11 ERROR Shibboleth.SOAPClient [1]: no CredentialResolver available for TLS

In native.log
2011-06-01 19:24:40 ERROR Shibboleth.Listener [1780] isapi_shib: socket call resulted in error (10054): Unknown error

In transaction.log:
2011-06-01 19:25:12 INFO Shibboleth-TRANSACTION [1]: Cached the following attributes with session: but no attributes are sent

Any clues on where I should start looking would be appreciated!

Kind Regards,
Gordon

Gordon Capreol | UNIVERSITYTICKETS | 115 W 30th Street | Suite 500A | New York | NY | 10001| p: 646-355-UTIX (8849) | f: 212-937-2299 | gcapreol-***@public.gmane.org

Cantor, Scott E.

2011-06-02 01:10:17 UTC

Permalink

Post by Gordon Capreol
2011-06-01 19:25:11 ERROR Shibboleth.SOAPClient [1]: no CredentialResolver available for TLS

You most likely have what should be obvious errors during startup indicating your keypair isn't loading.

-- Scott

Gordon Capreol

2011-06-02 01:22:29 UTC

Permalink

Scott - Thanks....can you give me some tips on where I should start looking, or would you recommend just creating a new cert and starting over?

~Gordon

Post by Cantor, Scott E.

Post by Gordon Capreol
2011-06-01 19:25:11 ERROR Shibboleth.SOAPClient [1]: no CredentialResolver available for TLS

You most likely have what should be obvious errors during startup indicating your keypair isn't loading.
-- Scott

Nate Klingenstein

2011-06-02 01:37:19 UTC

Permalink

Gordon,

Check the logs of your SP (shibd.log) on startup. You'll see a more
detailed message, probably ERROR level, that will detail exactly why
the credential pair failed to load. Once we know the reason for the
failure, we can give you some advice regarding remediation.

Take care,
Nate.

Post by Gordon Capreol
Scott - Thanks....can you give me some tips on where I should start
looking, or would you recommend just creating a new cert and
starting over?

Gordon Capreol

2011-06-02 11:27:49 UTC

Permalink

Ok--here's what I'm seeing at Startup:

2011-06-02 07:18:52 ERROR OpenSAML.SOAPClient [1]: SOAP client detected a SAML error: (samlp:Requester) (Invalid credentials for request.)
2011-06-02 07:18:52 ERROR Shibboleth.AttributeResolver.Query [1]: attribute authority returned a SAML error

Post by Nate Klingenstein
Gordon,
Check the logs of your SP (shibd.log) on startup. You'll see a more detailed message, probably ERROR level, that will detail exactly why the credential pair failed to load. Once we know the reason for the failure, we can give you some advice regarding remediation.
Take care,
Nate.

Post by Gordon Capreol
Scott - Thanks....can you give me some tips on where I should start looking, or would you recommend just creating a new cert and starting over?

Cantor, Scott E.

2011-06-02 14:04:18 UTC

Permalink

No, that's a runtime message, not a startup message, and it would show up
*after* the one you already posted. That's simply the logical outcome of
you not having a client key and certificate available for client TLS.

-- Scott

Gordon Capreol

2011-06-02 19:41:49 UTC

Permalink

Scott - Thanks so much for helping to troubleshoot. We're really stuck on this one...and have it things running so smoothly before this. I did do a new install of Shibboleth 2.4.2 since then and just did a restart of the service with a fresh shibd.log file. I've pasted below the contents in it's entirety (sorry for all the text):

2011-06-02 15:37:37 INFO Shibboleth.Listener : listener service shutting down
2011-06-02 15:37:37 INFO Shibboleth.Config : shibboleth 2.4.2 library shutting down
2011-06-02 15:37:37 INFO Shibboleth.Config : reload thread finished
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default::getHeaders::Application)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (run::AssertionLookup)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/Login::run::Shib1SI)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/SAML2/POST)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/SAML2/POST-SimpleSign)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/SAML2/Artifact)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/SAML2/ECP)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/SAML/POST)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/SAML/Artifact)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/Logout::run::SAML2LI)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/Logout::run::LocalLI)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/SLO/SOAP)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/SLO/Redirect)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/SLO/POST)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/SLO/Artifact)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/NIM/SOAP)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/NIM/Redirect)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/NIM/POST)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/NIM/Artifact)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/Artifact/SOAP::run::SAML2Artifact)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/Metadata)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (default/Status)
2011-06-02 15:37:37 INFO Shibboleth.AttributeFilter : reload thread finished
2011-06-02 15:37:37 INFO Shibboleth.AttributeExtractor.XML : reload thread finished
2011-06-02 15:37:37 INFO OpenSAML.MetadataProvider.XML : reload thread finished
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (find::StorageService::SessionCache)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (remove::StorageService::SessionCache)
2011-06-02 15:37:37 INFO Shibboleth.Listener : unregistered remoted message endpoint (touch::StorageService::SessionCache)
2011-06-02 15:37:37 INFO XMLTooling.StorageService : cleanup thread finished
2011-06-02 15:37:37 INFO XMLTooling.XMLToolingConfig : xmltooling 1.4.1 library shutdown complete
2011-06-02 15:37:37 INFO OpenSAML.SAMLConfig : opensaml 2.4.1 library shutdown complete
2011-06-02 15:37:37 INFO Shibboleth.Config : shibboleth 2.4.2 library shutdown complete
2011-06-02 15:37:38 INFO Shibboleth.Config : Shibboleth SP Version 2.4.2
2011-06-02 15:37:38 INFO Shibboleth.Config : Library versions: log4shib 1.0.5, Xerces-C 3.1.1, XML-Security-C 1.6.0, XMLTooling-C 1.4.1, OpenSAML-C 2.4.1, Shibboleth 1.4.2
2011-06-02 15:37:38 INFO Shibboleth.Config : building ListenerService of type TCPListener...
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (set::RelayState)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (get::RelayState)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (set::PostData)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (get::PostData)
2011-06-02 15:37:38 INFO Shibboleth.Config : building StorageService (mem) of type Memory...
2011-06-02 15:37:38 INFO Shibboleth.Config : building ReplayCache on top of StorageService (mem)...
2011-06-02 15:37:38 INFO Shibboleth.Config : no StorageService specified, using in-memory ArtifactMap
2011-06-02 15:37:38 INFO Shibboleth.Config : building SessionCache of type StorageService...
2011-06-02 15:37:38 INFO XMLTooling.StorageService : cleanup thread started...running every 900 seconds
2011-06-02 15:37:38 INFO Shibboleth.SessionCache : bound to StorageService (mem)
2011-06-02 15:37:38 INFO Shibboleth.SessionCache : StorageService for 'lite' use not set, using standard StorageService
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (find::StorageService::SessionCache)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (remove::StorageService::SessionCache)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (touch::StorageService::SessionCache)
2011-06-02 15:37:38 INFO Shibboleth.Config : building SecurityPolicyProvider of type XML...
2011-06-02 15:37:38 WARN Shibboleth.SecurityPolicyProvider.XML : detected legacy Policy configuration, please convert to new PolicyRule syntax
2011-06-02 15:37:38 INFO Shibboleth.SecurityPolicyProvider.XML : installing a default Conditions rule in policy (default) for compatibility with legacy configuration
2011-06-02 15:37:38 INFO OpenSAML.SecurityPolicyRule.Conditions : building SecurityPolicyRule of type Audience
2011-06-02 15:37:38 INFO OpenSAML.SecurityPolicyRule.Conditions : building SecurityPolicyRule of type Ignore
2011-06-02 15:37:38 INFO OpenSAML.SecurityPolicyRule.Conditions : building SecurityPolicyRule of type Ignore
2011-06-02 15:37:38 INFO OpenSAML.SecurityPolicyRule.Conditions : building SecurityPolicyRule of type Ignore
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (run::AssertionLookup)
2011-06-02 15:37:38 WARN Shibboleth.PropertySet : deprecation - remapping property (defaultACSIndex) to (acsIndex)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/Login::run::Shib1SI)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/SAML2/POST)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/SAML2/POST-SimpleSign)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/SAML2/Artifact)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/SAML2/ECP)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/SAML/POST)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/SAML/Artifact)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/Logout::run::SAML2LI)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/Logout::run::LocalLI)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/SLO/SOAP)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/SLO/Redirect)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/SLO/POST)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/SLO/Artifact)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/NIM/SOAP)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/NIM/Redirect)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/NIM/POST)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/NIM/Artifact)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/Artifact/SOAP::run::SAML2Artifact)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/Metadata)
2011-06-02 15:37:38 INFO Shibboleth.Listener : registered remoted message endpoint (default/Status)
2011-06-02 15:37:38 INFO Shibboleth.Application : building MetadataProvider of type XML...
2011-06-02 15:37:44 INFO OpenSAML.MetadataProvider.XML : loaded XML resource (http://wayf.incommonfederation.org/InCommon/InCommon-metadata.xml)
2011-06-02 15:37:45 INFO OpenSAML.MetadataProvider.XML : adjusted reload interval to 180000 seconds
2011-06-02 15:37:45 INFO Shibboleth.Application : building TrustEngine of type Chaining...
2011-06-02 15:37:45 INFO XMLTooling.TrustEngine.Chaining : building TrustEngine of type ExplicitKey
2011-06-02 15:37:45 INFO XMLTooling.TrustEngine.Chaining : building TrustEngine of type PKIX
2011-06-02 15:37:45 INFO OpenSAML.MetadataProvider.XML : reload thread started...running every 180000 seconds
2011-06-02 15:37:45 INFO Shibboleth.Application : building AttributeExtractor of type XML...
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : reload thread started...running when signaled
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : loaded XML resource (E:/opt/shibboleth-sp/etc/shibboleth/attribute-map.xml)
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:mace:dir:attribute-def:eduPersonPrincipalName
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:oid:1.3.6.1.4.1.5923.1.1.1.6
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:mace:dir:attribute-def:eduPersonScopedAffiliation
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:oid:1.3.6.1.4.1.5923.1.1.1.9
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:mace:dir:attribute-def:eduPersonAffiliation
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:oid:1.3.6.1.4.1.5923.1.1.1.1
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:mace:dir:attribute-def:eduPersonEntitlement
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:oid:1.3.6.1.4.1.5923.1.1.1.7
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:mace:dir:attribute-def:eduPersonTargetedID
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:oid:1.3.6.1.4.1.5923.1.1.1.10
2011-06-02 15:37:45 INFO Shibboleth.AttributeExtractor.XML : creating mapping for Attribute urn:oasis:names:tc:SAML:2.0:nameid-format:persistent
2011-06-02 15:37:45 INFO Shibboleth.Application : building AttributeFilter of type XML...
2011-06-02 15:37:45 INFO Shibboleth.AttributeFilter : reload thread started...running when signaled
2011-06-02 15:37:45 INFO Shibboleth.AttributeFilter : loaded XML resource (E:/opt/shibboleth-sp/etc/shibboleth/attribute-policy.xml)
2011-06-02 15:37:45 INFO Shibboleth.Application : building AttributeResolver of type Query...
2011-06-02 15:37:45 INFO Shibboleth.Application : building CredentialResolver of type File...
2011-06-02 15:37:45 INFO XMLTooling.SecurityHelper : loading private key from file (E:/opt/shibboleth-sp/etc/shibboleth/nbo.key)
2011-06-02 15:37:45 INFO XMLTooling.SecurityHelper : loading certificate(s) from file (E:/opt/shibboleth-sp/etc/shibboleth/nbo.crt)
2011-06-02 15:37:45 INFO Shibboleth.Listener : registered remoted message endpoint (default::getHeaders::Application)
2011-06-02 15:37:45 INFO Shibboleth.Listener : listener service starting

Post by Cantor, Scott E.
No, that's a runtime message, not a startup message, and it would show up
*after* the one you already posted. That's simply the logical outcome of
you not having a client key and certificate available for client TLS.
-- Scott

Cantor, Scott E.

2011-06-02 19:52:07 UTC

Permalink

Post by Gordon Capreol
Scott - Thanks so much for helping to troubleshoot. We're really stuck on
this one...and have it things running so smoothly before this. I did do a
new install of Shibboleth 2.4.2 since then and just did a restart of the
service with a fresh shibd.log file. I've pasted below the contents in

There's nothing in that log that would lead to the error you posted
orginally. If you no longer get that error and are now only getting the
SAML error back that you posted this morning, then the problem is your key
or certificate is wrong and/or not in the metadata. Originally the key
wasn't even loaded.

-- Scott

Gordon Capreol

2011-06-02 20:36:01 UTC

Permalink

You were right that the earlier message showed a problem loading the cert. That was an easy fix (just a typo in the config file). The latest situation is that the SP is loading (as per the log file I attached). We're able to go through the login process with the IdP, but not getting any attributes back.

We just recently added this cert as a new certificate with InCommon (processed today) and are waiting to have it loaded with tomorrow's Metadata refresh. In the mean time, I've given our metadata file to the IdP to load manually, but that it appears that isn't working.

Post by Cantor, Scott E.

Cantor, Scott E.

2011-06-02 20:44:27 UTC

Permalink

Post by Gordon Capreol
We just recently added this cert as a new certificate with InCommon
(processed today) and are waiting to have it loaded with tomorrow's
Metadata refresh. In the mean time, I've given our metadata file to the
IdP to load manually, but that it appears that isn't working.

Then most likely you're not using the certificate you think you are and
you'd better make sure of any changes to metadata you make.

In the future, the process for key rollover for an SP is discussed in the
wiki (and InCommon has its own material on this). There should never be a
situation with Shibboleth software where anybody has to do anything
disruptive, that's why we support multiple credentials in both metadata
and the software.

You should *never* make changes to local configuration that break the
contract the metadata represents. That's the entire purpose of using it.

-- Scott

Gordon Capreol

2011-06-02 20:48:30 UTC

Permalink

Scott - It's really helpful to have someone that know how all this works explaining it, so thank you for that!

Is it possible that right now our Shibboleth2.xml file is pointing to the right key, but since InCommon hasn't replicated the update that the IdP is expecting a different cert? If that's so, once the replication takes place, we should be back up and running again. However, they did attempt a manual load of the metadata and that's still not working.

I checked the logs and the cert is loading from the correct file on the SP side.

~Gordon

Post by Cantor, Scott E.

Then most likely you're not using the certificate you think you are and
you'd better make sure of any changes to metadata you make.
In the future, the process for key rollover for an SP is discussed in the
wiki (and InCommon has its own material on this). There should never be a
situation with Shibboleth software where anybody has to do anything
disruptive, that's why we support multiple credentials in both metadata
and the software.
You should *never* make changes to local configuration that break the
contract the metadata represents. That's the entire purpose of using it.
-- Scott

Cantor, Scott E.

2011-06-02 21:18:23 UTC

Permalink

Post by Gordon Capreol
Is it possible that right now our Shibboleth2.xml file is pointing to the
right key, but since InCommon hasn't replicated the update that the IdP
is expecting a different cert?

Yes.

Post by Gordon Capreol
If that's so, once the replication takes place, we should be back up and
running again. However, they did attempt a manual load of the metadata
and that's still not working.

Most likely that would be for the reason Chad suggested.

-- Scott

Gordon Capreol

2011-06-02 21:54:44 UTC

Permalink

Ok, great. That holds promise for a working solution soon then. Thanks so much for your assistance!

~Gordon

Post by Cantor, Scott E.

Yes.

Post by Gordon Capreol
If that's so, once the replication takes place, we should be back up and
running again. However, they did attempt a manual load of the metadata
and that's still not working.

Most likely that would be for the reason Chad suggested.
-- Scott

Chad La Joie

2011-06-02 20:48:38 UTC

Permalink

Is the metadata provider loading your temporary metadata after the one
loading the InCommon metadata? The IdP uses the first entity descriptor
for an entity that it finds and it searches providers in the order you
define them.

Post by Gordon Capreol
You were right that the earlier message showed a problem loading the cert. That was an easy fix (just a typo in the config file). The latest situation is that the SP is loading (as per the log file I attached). We're able to go through the login process with the IdP, but not getting any attributes back.
We just recently added this cert as a new certificate with InCommon (processed today) and are waiting to have it loaded with tomorrow's Metadata refresh. In the mean time, I've given our metadata file to the IdP to load manually, but that it appears that isn't working.

Post by Cantor, Scott E.

--
Chad La Joie
http://itumi.biz
trusted identities, delivered