SP metadata expired?

Thu Mar 14 09:27:17 EDT 2013

Hi all,
I'm running IDP version 2.3.8 and I'm seeing a lot of strange messages in my DEBUG process.log file relating to one individual SP we have. It's an ezproxy server running version 5.6.1 but I'm not sure what Shibboleth SP version that relates to.

The obfuscated messages are:
13:17:10.024 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler:217] - Decoded Shibboleth SSO request from relying party 'https://sp.ezproxy.domain.ac.uk'
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:199] - Checking child metadata provider for entity descriptor with entity ID: https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - Searching for entity descriptor with an entity ID of https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:166] - Metadata document does not contain an EntityDescriptor with the ID https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:170] - Metadata document contained an EntityDescriptor with the ID https://sp.ezproxy.domain.ac.uk, but it was no longer valid
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:199] - Checking child metadata provider for entity descriptor with entity ID: https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - Searching for entity descriptor with an entity ID of https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:126] - Looking up relying party configuration for https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:132] - No custom relying party configuration found for https://sp.ezproxy.domain.ac.uk, looking up configuration based on metadata groups.
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:199] - Checking child metadata provider for entity descriptor with entity ID: https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - Searching for entity descriptor with an entity ID of https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:166] - Metadata document does not contain an EntityDescriptor with the ID https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:170] - Metadata document contained an EntityDescriptor with the ID https://sp.ezproxy.domain.ac.uk, but it was no longer valid
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:199] - Checking child metadata provider for entity descriptor with entity ID: https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - Searching for entity descriptor with an entity ID of https://sp.ezproxy.domain.ac.uk
13:17:10.024 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:155] - No custom or group-based relying party configuration found for https://sp.ezproxy.domain.ac.uk. Using default relying party configuration.
13:17:10.024 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:166] - Storing LoginContext to StorageService partition loginContexts, key 125fae1b-9ec9-43bc-b937-a805749257eb
13:17:10.024 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler:173] - Redirecting user to authentication engine at https://idp.domain.ac.uk:443/idp/AuthnEngine
13:17:10.039 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:201] - Processing incoming request
13:17:10.039 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:326] - Looking up LoginContext with key 125fae1b-9ec9-43bc-b937-a805749257eb from StorageService parition: loginContexts
13:17:10.039 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:332] - Retrieved LoginContext with key 125fae1b-9ec9-43bc-b937-a805749257eb from StorageService parition: loginContexts
13:17:10.039 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:231] - Beginning user authentication process.
13:17:10.039 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:277] - Filtering configured LoginHandlers: {urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler at 19bdb65, urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified=edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler at 160e796}
13:17:10.039 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:326] - Filtering out previous session login handler because there is no existing IdP session
13:17:10.039 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:458] - Selecting appropriate login handler from filtered set {urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified=edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler at 160e796}
13:17:10.039 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:491] - Authenticating user with login handler of type edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler
13:17:10.039 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:166] - Storing LoginContext to StorageService partition loginContexts, key f919d387-4e52-4459-886b-4dfa6f528cb6
13:17:10.039 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler:65] - Redirecting to https://idp.domain.ac.uk:443/idp/Authn/RemoteUser

Requests going through ezproxy seem to be working on the whole, we have an issue with one remote user accessing resources at the moment which is why I turned debug on and saw these messages.
I've double checked the relying-party.xml for any valid until reference in the ezproxy declaration, and checked the the correct metadata is loaded.
When I restart the Tomcat service I see the IDP successfully load all the metadata files I have declared.

Can anybody help with this please? I'd like to get rid of these messages from the debug if possible so I can troubleshoot the other individual access issue we're getting.

Cheers,
Andi
________________________________

>From 1st November 2011 UWIC changed its title to Cardiff Metropolitan University. From the 6th December 2011, as part of this change, all email addresses which included @uwic.ac.uk have changed to @cardiffmet.ac.uk. All emails sent from Cardiff Metropolitan University will now be sent from the new @cardiffmet.ac.uk address. Please could you ensure that all of your contact records and databases are updated to reflect this change. Further information can be found on the website here.<http://www3.uwic.ac.uk/English/News/Pages/UWIC-Name-Change.aspx>

Ar Dachwedd y 1af 2011 newidiodd UWIC ei henw i Brifysgol Fetropolitan Caerdydd. O Ragfyr 6ed, fel rhan o'r newid yma, bydd pob cyfeiriad e-bost sy'n cynnwys @uwic.ac.uk yn newid i @cardiffmet.ac.uk. Bydd yr holl ebyst a ddanfonir o Brifysgol Fetropolitan Caerdydd yn cael eu danfon o'r cyfeiriad @cardiffmet.ac.uk newydd. Gwnewch yn siwr eich bod yn diweddaru eich cofnodion cyswllt a'ch cronfeydd data i adlewyrchu hyn. Gellir cael rhagor o wybodaeth ar y wefan yma.<http://www3.uwic.ac.uk/English/News/Pages/UWIC-Name-Change.aspx>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20130314/ef59fa71/attachment-0001.html 