Shibboleth Developers

[Lukas Haemmerle <>]

Hello

After testing again the interaction between an IdP 2.0 (trunk) and an SP 
1.3 using a SAML1 attribute request, I noticed that there might be a 
problem with this setup. I'm pretty sure that I have tested this before 
and it worked, but it doesn't anymore for some reason right now.

The problem occurs when the SP tries to fetch the attributes from the 
IdP. The SSL connection is established and the IdP should get the SPs 
clientCert (I verified this). However, although the SPs cert is signed 
by one of the federation's accepted certs, the IdP says (also see 
attached log file):

09:20:57.065 ERROR 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler:174] 
- Message did not meet security requirements
org.opensaml.xml.security.SecurityException: Unable to select security 
policy, no communication profile criteria available.

Later on, there is then also a null pointer request. Any idea where to 
look for the problem? The SPs metadata hasn't changed for some months, 
the IdP's has and so has the IdP's container.
SAML2 to SAML2 is working with the IdP in question and the SP 1.3 also 
has no problems with other 1.3 IdPs

Lukas

--
SWITCH
Serving Swiss Universities
--------------------------
Lukas Haemmerle, Software Engineer, Security
Werdstrasse 2, P.O. Box, 8021 Zurich, Switzerland
phone +41 44 268 15 64, fax +41 44 268 15 68
,
 http://www.switch.ch
Metadata used:
http://www.switch.ch/aai/federation/aaitest/metadata.aaitest_signed.xml


IdP 2.0 trunk (26.2.2008, 09.00 CET) log:
09:20:56.391 INFO [Shibboleth-Access:72] - 
20080226T082056Z|130.59.6.143|lewotolo.switch.ch:443|/profile/Shibboleth/SSO|
09:20:56.394 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85] 
- shibboleth.HandlerManager: Looking up profile handler for request path: 
/Shibboleth/SSO
09:20:56.395 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.saml1.ShibbolethSSOProfileHandler
09:20:56.395 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler:112]
 - Processing incoming request
09:20:56.395 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler:118]
 - Incoming request does not contain a login context, processing as first leg 
of request
09:20:56.395 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler:181]
 - Decoding message with decoder binding 
urn:mace:shibboleth:1.0:profiles:AuthnRequest
09:20:56.398 DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:72] - 
Beginning to decode message from inbound transport of type: 
org.opensaml.ws.transport.http.HttpServletRequestAdapter
09:20:56.400 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://kelimutu.switch.ch/shibboleth
09:20:56.400 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity https://kelimutu.switch.ch/shibboleth
09:20:56.400 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
https://kelimutu.switch.ch/shibboleth
09:20:56.400 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:226] - 
Metadata was an EntitiesDescriptor, checking if any of its descendant 
EntityDescriptor elements is the one we're looking for.
09:20:56.401 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:234] - Located 
entity descriptor, creating an index to it for faster lookups
09:20:56.401 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:126]
 - Looking up relying party configuration for 
https://kelimutu.switch.ch/shibboleth
09:20:56.402 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:132]
 - No custom relying party configuration found for 
https://kelimutu.switch.ch/shibboleth, looking up configuration based on 
metadata groups.
09:20:56.402 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://kelimutu.switch.ch/shibboleth
09:20:56.402 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity https://kelimutu.switch.ch/shibboleth
09:20:56.403 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
https://kelimutu.switch.ch/shibboleth
09:20:56.403 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:208] - Entity 
descriptor for the ID https://kelimutu.switch.ch/shibboleth was found in 
index cache, returning
09:20:56.403 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:155]
 - No custom or group-based relying party configuration found for 
https://kelimutu.switch.ch/shibboleth. Using default relying party 
configuration.
09:20:56.404 DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:82] - 
Evaluating security policy of type 
'edu.internet2.middleware.shibboleth.common.security.ShibbolethSecurityPolicy'
 for decoded message
09:20:56.404 DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:94] - 
Successfully decoded message.
09:20:56.404 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://kelimutu.switch.ch/shibboleth
09:20:56.405 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity https://kelimutu.switch.ch/shibboleth
09:20:56.405 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
https://kelimutu.switch.ch/shibboleth
09:20:56.405 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:208] - Entity 
descriptor for the ID https://kelimutu.switch.ch/shibboleth was found in 
index cache, returning
09:20:56.406 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:126]
 - Looking up relying party configuration for 
https://kelimutu.switch.ch/shibboleth
09:20:56.406 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:132]
 - No custom relying party configuration found for 
https://kelimutu.switch.ch/shibboleth, looking up configuration based on 
metadata groups.
09:20:56.406 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://kelimutu.switch.ch/shibboleth
09:20:56.406 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity https://kelimutu.switch.ch/shibboleth
09:20:56.407 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
https://kelimutu.switch.ch/shibboleth
09:20:56.407 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:208] - Entity 
descriptor for the ID https://kelimutu.switch.ch/shibboleth was found in 
index cache, returning
09:20:56.407 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:155]
 - No custom or group-based relying party configuration found for 
https://kelimutu.switch.ch/shibboleth. Using default relying party 
configuration.
09:20:56.426 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:146] - 
Processing incoming request
09:20:56.427 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:183] - 
Beginning user authentication process
09:20:56.427 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:366] - 
Authenticating user with login handler of type 
edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler
09:20:56.432 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler:75]
 - Redirecting to https://lewotolo.switch.ch:443/idp-trunk/Authn/RemoteUser
09:20:56.470 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserAuthServlet:48]
 - Remote user identified as demouser2 returning control back to 
authentication engine
09:20:56.471 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:96] - 
Returning control to authentication engine
09:20:56.471 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:146] - 
Processing incoming request
09:20:56.472 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:390] - 
Completing user authentication process
09:20:56.472 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:419] - 
User demouser2 authenticated with method 
urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified
09:20:56.472 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:437] - 
Creating shibboleth session for principal demouser2
09:20:56.475 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:472] - 
Adding IdP session cookie to HTTP response
09:20:56.475 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:443] - 
Recording authentication and service information in Shibboleth session for 
principal: demouser2
09:20:56.477 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:116] - 
Returning control to profile handler at: /profile/Shibboleth/SSO
09:20:56.478 INFO [Shibboleth-Access:72] - 
20080226T082056Z|130.59.6.143|lewotolo.switch.ch:443|/profile/Shibboleth/SSO|
09:20:56.478 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85] 
- shibboleth.HandlerManager: Looking up profile handler for request path: 
/Shibboleth/SSO
09:20:56.479 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.saml1.ShibbolethSSOProfileHandler
09:20:56.479 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler:112]
 - Processing incoming request
09:20:56.479 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler:121]
 - Incoming request contains a login context, processing as second leg of 
request
09:20:56.480 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://kelimutu.switch.ch/shibboleth
09:20:56.480 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity https://kelimutu.switch.ch/shibboleth
09:20:56.480 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
https://kelimutu.switch.ch/shibboleth
09:20:56.481 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:208] - Entity 
descriptor for the ID https://kelimutu.switch.ch/shibboleth was found in 
index cache, returning
09:20:56.481 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://kelimutu.switch.ch/shibboleth
09:20:56.482 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity https://kelimutu.switch.ch/shibboleth
09:20:56.482 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
https://kelimutu.switch.ch/shibboleth
09:20:56.483 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:208] - Entity 
descriptor for the ID https://kelimutu.switch.ch/shibboleth was found in 
index cache, returning
09:20:56.483 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:126]
 - Looking up relying party configuration for 
https://kelimutu.switch.ch/shibboleth
09:20:56.483 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:132]
 - No custom relying party configuration found for 
https://kelimutu.switch.ch/shibboleth, looking up configuration based on 
metadata groups.
09:20:56.484 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://kelimutu.switch.ch/shibboleth
09:20:56.484 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity https://kelimutu.switch.ch/shibboleth
09:20:56.484 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
https://kelimutu.switch.ch/shibboleth
09:20:56.485 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:208] - Entity 
descriptor for the ID https://kelimutu.switch.ch/shibboleth was found in 
index cache, returning
09:20:56.485 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:155]
 - No custom or group-based relying party configuration found for 
https://kelimutu.switch.ch/shibboleth. Using default relying party 
configuration.
09:20:56.486 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
urn:mace:switch.ch:aaitest:lewotolo.switch.ch
09:20:56.486 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity urn:mace:switch.ch:aaitest:lewotolo.switch.ch
09:20:56.487 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
urn:mace:switch.ch:aaitest:lewotolo.switch.ch
09:20:56.487 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:226] - 
Metadata was an EntitiesDescriptor, checking if any of its descendant 
EntityDescriptor elements is the one we're looking for.
09:20:56.487 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:234] - Located 
entity descriptor, creating an index to it for faster lookups
09:20:56.494 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOEndpointSelector:78]
 - Selecting endpoint from metadata corresponding to provided ACS URL: 
https://kelimutu.switch.ch/Shibboleth.sso/SAML/POST
09:20:56.495 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOEndpointSelector:82]
 - Relying party role contains 3 endpoints
09:20:56.495 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler:546]
 - Resolving attributes for principal demouser2 of SAML request from relying 
party https://kelimutu.switch.ch/shibboleth
09:20:56.498 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:120]
 - shibboleth.AttributeResolver resolving attributes for principal demouser2
09:20:56.498 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:258]
 - Specific attributes for principal demouser2 were not requested, resolving 
all attributes.
09:20:56.499 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute uniqueID for principal demouser2
09:20:56.501 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:334]
 - Resolving data connector myLDAP for principal demouser2
09:20:56.528 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:764]
 - Search filter: (uid=demouser2)
09:20:56.528 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:771]
 - Checking cache for search results
09:20:56.529 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:780]
 - Retrieving attributes from LDAP
09:20:56.597 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: objectClass=[eduPerson, swissEduPerson]
09:20:56.598 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: mobile=[+41 78 123 4567]
09:20:56.598 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: 
swissEduPersonHomeOrganization=[aaitest.example.ch]
09:20:56.599 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: swissEduPersonMatriculationNumber=[00345678]
09:20:56.600 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: swissEduPersonStudyBranch2=[42]
09:20:56.600 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: 
eduPersonEntitlement=[http://unil.ch/aai/resources/biblio92, 
http://switch.ch/aai/agreement-01021]
09:20:56.600 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: swissEduPersonStaffCategory=[201]
09:20:56.601 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: swissEduPersonStudyBranch3=[4800]
09:20:56.601 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: swissEduPersonGender=[1]
09:20:56.602 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: homePostalAddress=[Seestrasse 99$CH-4000 
Basel]
09:20:56.602 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: 
eduPersonPrincipalName=[]
09:20:56.603 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: givenName=[Demouser2]
09:20:56.603 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: swissEduPersonStudyBranch1=[4]
09:20:56.603 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: uid=[demouser2]
09:20:56.604 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: userPassword=[ZGVtbw==]
09:20:56.604 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: employeeNumber=[007]
09:20:56.605 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: eduPersonOrgDN=[o=SWITCH,c=CH]
09:20:56.605 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: 
mail=[]
09:20:56.606 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: homePhone=[+41 61 123 4567]
09:20:56.606 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: 
swissEduPersonUniqueID=[]
09:20:56.606 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: preferredLanguage=[en]
09:20:56.607 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: swissEduPersonStudyLevel=[4800-20]
09:20:56.607 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: 
eduPersonOrgUnitDN=[ou=aaitest,dc=example,dc=ch]
09:20:56.608 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: sn=[SWITCHaai]
09:20:56.608 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: cn=[Demouser2, SWITCHaai Demouser2]
09:20:56.609 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: postalAddress=[Département 
d'informatique$SWITCH - AAI$Limmatquai 138$CH-8001 Zurich]
09:20:56.609 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: telephoneNumber=[+4112681520]
09:20:56.609 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: eduPersonAffiliation=[student]
09:20:56.610 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: swissEduPersonHomeOrganizationType=[others]
09:20:56.610 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:882]
 - Found the following attribute: swissEduPersonDateOfBirth=[20030605]
09:20:56.611 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:791]
 - Stored results in the cache
09:20:56.611 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute uniqueID containing 1 values
09:20:56.612 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute studyBranch1 for principal demouser2
09:20:56.612 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute studyBranch1 containing 1 values
09:20:56.613 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute mobile for principal demouser2
09:20:56.613 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute mobile containing 1 values
09:20:56.613 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute homeOrganization for principal demouser2
09:20:56.618 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:334]
 - Resolving data connector myStaticAttributes for principal demouser2
09:20:56.618 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute homeOrganization containing 1 values
09:20:56.619 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute studyLevel for principal demouser2
09:20:56.619 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute studyLevel containing 1 values
09:20:56.620 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute staffCategory for principal demouser2
09:20:56.620 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute staffCategory containing 1 values
09:20:56.620 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute homePostalAddress for principal demouser2
09:20:56.621 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute homePostalAddress containing 1 values
09:20:56.621 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute studyBranch2 for principal demouser2
09:20:56.622 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute studyBranch2 containing 1 values
09:20:56.622 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute orgDN for principal demouser2
09:20:56.622 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute orgDN containing 1 values
09:20:56.623 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute givenName for principal demouser2
09:20:56.623 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute givenName containing 1 values
09:20:56.624 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute gender for principal demouser2
09:20:56.624 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute gender containing 1 values
09:20:56.624 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute orgUnitDN for principal demouser2
09:20:56.625 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute orgUnitDN containing 1 values
09:20:56.625 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute employeeNumber for principal demouser2
09:20:56.626 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute employeeNumber containing 1 values
09:20:56.626 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute uid for principal demouser2
09:20:56.626 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute uid containing 1 values
09:20:56.627 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute mail for principal demouser2
09:20:56.627 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute mail containing 1 values
09:20:56.628 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute homePhone for principal demouser2
09:20:56.628 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute homePhone containing 1 values
09:20:56.629 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute matriculationNumber for principal demouser2
09:20:56.629 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute matriculationNumber containing 1 values
09:20:56.630 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute preferredLanguage for principal demouser2
09:20:56.630 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute preferredLanguage containing 1 values
09:20:56.630 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute studyBranch3 for principal demouser2
09:20:56.631 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute studyBranch3 containing 1 values
09:20:56.631 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute surname for principal demouser2
09:20:56.631 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute surname containing 1 values
09:20:56.632 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute dateOfBirth for principal demouser2
09:20:56.632 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute dateOfBirth containing 1 values
09:20:56.633 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute postalAddress for principal demouser2
09:20:56.633 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute postalAddress containing 1 values
09:20:56.633 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute homeOrganizationType for principal demouser2
09:20:56.634 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute homeOrganizationType containing 1 values
09:20:56.634 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute transientId for principal demouser2
09:20:56.636 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute transientId containing 1 values
09:20:56.636 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute affiliation for principal demouser2
09:20:56.636 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute affiliation containing 1 values
09:20:56.637 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute telephoneNumber for principal demouser2
09:20:56.637 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute telephoneNumber containing 1 values
09:20:56.638 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294]
 - Resolving attribute entitlement for principal demouser2
09:20:56.638 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316]
 - Resolved attribute entitlement containing 2 values
09:20:56.639 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:138]
 - shibboleth.AttributeResolver resolved, for principal demouser2, the 
attributes: [studyBranch1, uniqueID, mobile, homeOrganization, studyLevel, 
staffCategory, homePostalAddress, orgDN, studyBranch2, givenName, orgUnitDN, 
gender, employeeNumber, uid, mail, homePhone, matriculationNumber, 
preferredLanguage, studyBranch3, surname, dateOfBirth, postalAddress, 
homeOrganizationType, transientId, affiliation, telephoneNumber, entitlement]
09:20:56.639 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:70]
 - shibboleth.AttributeFilterEngine filtering 27 attributes for principal 
demouser2
09:20:56.640 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy releaseTransientIdToAnyone is active for 
principal demouser2
09:20:56.640 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:128]
 - Filter policy releaseTransientIdToAnyone is active for principal demouser2
09:20:56.640 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute transientId for principal demouser2
09:20:56.641 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.641 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.642 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.642 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:128]
 - Filter policy null is active for principal demouser2
09:20:56.642 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute dateOfBirth for principal demouser2
09:20:56.643 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute gender for principal demouser2
09:20:56.643 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute preferredLanguage for principal demouser2
09:20:56.644 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute mail for principal demouser2
09:20:56.644 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute homePostalAddress for principal demouser2
09:20:56.644 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute postalAddress for principal demouser2
09:20:56.645 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute homePhone for principal demouser2
09:20:56.645 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute telephoneNumber for principal demouser2
09:20:56.645 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute mobile for principal demouser2
09:20:56.646 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute homeOrganization for principal demouser2
09:20:56.646 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute homeOrganizationType for principal demouser2
09:20:56.647 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute affiliation for principal demouser2
09:20:56.647 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute studyBranch1 for principal demouser2
09:20:56.647 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute studyBranch2 for principal demouser2
09:20:56.648 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute studyBranch3 for principal demouser2
09:20:56.648 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute studyLevel for principal demouser2
09:20:56.648 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute staffCategory for principal demouser2
09:20:56.649 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute orgDN for principal demouser2
09:20:56.649 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute orgUnitDN for principal demouser2
09:20:56.650 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute entitlement for principal demouser2
09:20:56.650 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute uniqueID for principal demouser2
09:20:56.650 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute surname for principal demouser2
09:20:56.651 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute givenName for principal demouser2
09:20:56.651 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute uid for principal demouser2
09:20:56.651 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute employeeNumber for principal demouser2
09:20:56.652 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute principalName for principal demouser2
09:20:56.652 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:148]
 - Filtering values of attribute matriculationNumber for principal demouser2
09:20:56.653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.655 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.655 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.656 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.656 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.656 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.657 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.657 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.657 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.658 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.658 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.658 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.659 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.659 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.659 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.660 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.660 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.661 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.661 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.661 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.662 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.662 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.663 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.663 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.663 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.664 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.664 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.664 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.665 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.665 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.665 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.666 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.666 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.667 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.667 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.667 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.668 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.668 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.669 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.669 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:121]
 - Evaluating if filter policy null is active for principal demouser2
09:20:56.669 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:105]
 - Filtered attributes for principal demouser2.  The following attributes 
remain: [studyBranch1, uniqueID, mobile, homeOrganization, studyLevel, 
staffCategory, homePostalAddress, orgDN, studyBranch2, givenName, orgUnitDN, 
gender, employeeNumber, uid, mail, homePhone, matriculationNumber, 
preferredLanguage, studyBranch3, surname, dateOfBirth, postalAddress, 
homeOrganizationType, transientId, affiliation, telephoneNumber, entitlement]
09:20:56.672 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler:353]
 - Building assertion NameIdentifier to relying party 
https://kelimutu.switch.ch/shibboleth for principal demouser2
09:20:56.673 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler:372]
 - Supported name formats: [urn:mace:shibboleth:1.0:nameIdentifier]
09:20:56.673 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler:381]
 - Using attribute transientId suppoting name format 
urn:mace:shibboleth:1.0:nameIdentifier to create the NameIdentifier for 
principal
09:20:56.681 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler:640]
 - Determining if SAML assertion to relying party 
https://kelimutu.switch.ch/shibboleth should be signed
09:20:56.682 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler:666]
 - Entity metadata for relying party https://kelimutu.switch.ch/shibboleth 
indicates to sign assertions: false
09:20:56.684 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:461]
 - Encoding response to SAML request null from relying party 
https://kelimutu.switch.ch/shibboleth
09:20:56.684 DEBUG [org.opensaml.ws.message.encoder.BaseMessageEncoder:47] - 
Beginning encode message to outbound transport of type: 
org.opensaml.ws.transport.http.HttpServletResponseAdapter
09:20:56.684 DEBUG 
[org.opensaml.saml1.binding.encoding.BaseSAML1MessageEncoder:89] - Signing 
outbound SAML message.
09:20:56.693 DEBUG [org.opensaml.xml.signature.impl.SignatureMarshaller:99] - 
Starting to marshall {http://www.w3.org/2000/09/xmldsig#}Signature
09:20:56.693 DEBUG [org.opensaml.xml.signature.impl.SignatureMarshaller:102] 
- Creating XMLSignature object
09:20:56.694 DEBUG [org.opensaml.xml.signature.impl.SignatureMarshaller:112] 
- Adding content to XMLSignature.
09:20:56.695 DEBUG [org.opensaml.common.impl.SAMLObjectContentReference:172] 
- Adding list of inclusive namespaces for signature exclusive 
canonicalization transform
09:20:56.696 DEBUG [org.opensaml.xml.signature.impl.SignatureMarshaller:117] 
- Creating Signature DOM element
09:20:56.699 DEBUG [org.opensaml.xml.signature.Signer:77] - Computing 
signature over XMLSignature object
09:20:56.779 DEBUG [org.opensaml.saml1.binding.encoding.HTTPPostEncoder:120] 
- Invoking velocity template to create POST body
09:20:56.779 DEBUG [org.opensaml.saml1.binding.encoding.HTTPPostEncoder:125] 
- Encoding action url of: https://kelimutu.switch.ch/Shibboleth.sso/SAML/POST
09:20:56.780 DEBUG [org.opensaml.saml1.binding.encoding.HTTPPostEncoder:128] 
- Marshalling and Base64 encoding SAML message
09:20:56.780 DEBUG [org.opensaml.ws.message.encoder.BaseMessageEncoder:77] - 
Marshalling message
09:20:56.787 DEBUG [org.opensaml.saml1.binding.encoding.HTTPPostEncoder:134] 
- Setting TARGET parameter to: cookie
09:20:56.794 DEBUG [org.opensaml.ws.message.encoder.BaseMessageEncoder:52] - 
Successfully encoded message.
09:20:56.796 INFO [Shibboleth-Audit:492] - 
20080226T082056Z|urn:mace:shibboleth:1.0:profiles:AuthnRequest||https://kelimutu.switch.ch/shibboleth|urn:mace:shibboleth:2.0:profiles:saml1:sso|urn:mace:switch.ch:aaitest:lewotolo.switch.ch|urn:oasis:names:tc:SAML:1.0:profiles:browser-post|_e5f93b524413c45f07b876ee66d3f4b8|demouser2|urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified||
09:20:57.025 INFO [Shibboleth-Access:72] - 
20080226T082057Z|2001:620:0:14:20c:29ff:fe6e:c211|lewotolo.switch.ch:8443|/profile/SAML1/SOAP/AttributeQuery|
09:20:57.026 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85] 
- shibboleth.HandlerManager: Looking up profile handler for request path: 
/SAML1/SOAP/AttributeQuery
09:20:57.026 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.saml1.AttributeQueryProfileHandler
09:20:57.026 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler:136]
 - Decoding message with decoder binding 
urn:oasis:names:tc:SAML:1.0:bindings:SOAP-binding
09:20:57.029 DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:72] - 
Beginning to decode message from inbound transport of type: 
org.opensaml.ws.transport.http.HttpServletRequestAdapter
09:20:57.029 DEBUG 
[org.opensaml.saml1.binding.decoding.HTTPSOAP11Decoder:122] - Unmarshalling 
SOAP message
09:20:57.030 DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:140] - 
Parsing message stream into DOM document
09:20:57.032 DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:150] - 
Unmarshalling message DOM
09:20:57.049 DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:162] - 
Message succesfully unmarshalled
09:20:57.050 DEBUG 
[org.opensaml.saml1.binding.decoding.HTTPSOAP11Decoder:148] - Decoded SOAP 
messaged which included SAML message of type 
{urn:oasis:names:tc:SAML:1.0:protocol}Request
09:20:57.053 DEBUG 
[org.opensaml.saml1.binding.decoding.BaseSAML1MessageDecoder:143] - 
Extracting ID, issuer and issue instant from request
09:20:57.053 DEBUG 
[org.opensaml.saml1.binding.decoding.BaseSAML1MessageDecoder:188] - 
Attempting to extract issuer from SAML 1 AttributeQuery Resource attribute
09:20:57.053 DEBUG 
[org.opensaml.saml1.binding.decoding.BaseSAML1MessageDecoder:193] - Extracted 
issuer from SAML 1.x AttributeQuery: https://kelimutu.switch.ch/shibboleth
09:20:57.054 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://kelimutu.switch.ch/shibboleth
09:20:57.054 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity https://kelimutu.switch.ch/shibboleth
09:20:57.054 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
https://kelimutu.switch.ch/shibboleth
09:20:57.054 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:208] - Entity 
descriptor for the ID https://kelimutu.switch.ch/shibboleth was found in 
index cache, returning
09:20:57.055 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:126]
 - Looking up relying party configuration for 
https://kelimutu.switch.ch/shibboleth
09:20:57.055 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:132]
 - No custom relying party configuration found for 
https://kelimutu.switch.ch/shibboleth, looking up configuration based on 
metadata groups.
09:20:57.055 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://kelimutu.switch.ch/shibboleth
09:20:57.055 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity https://kelimutu.switch.ch/shibboleth
09:20:57.058 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
https://kelimutu.switch.ch/shibboleth
09:20:57.058 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:208] - Entity 
descriptor for the ID https://kelimutu.switch.ch/shibboleth was found in 
index cache, returning
09:20:57.058 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:155]
 - No custom or group-based relying party configuration found for 
https://kelimutu.switch.ch/shibboleth. Using default relying party 
configuration.
09:20:57.065 ERROR 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler:174]
 - Message did not meet security requirements
org.opensaml.xml.security.SecurityException: Unable to select security 
policy, no communication profile criteria available.
        at 
edu.internet2.middleware.shibboleth.common.relyingparty.RelyingPartySecurityPolicyResolver.resolveSingle(RelyingPartySecurityPolicyResolver.java:72)
        at 
edu.internet2.middleware.shibboleth.common.relyingparty.RelyingPartySecurityPolicyResolver.resolve(RelyingPartySecurityPolicyResolver.java:53)
        at 
edu.internet2.middleware.shibboleth.common.relyingparty.RelyingPartySecurityPolicyResolver.resolve(RelyingPartySecurityPolicyResolver.java:31)
        at 
org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:78)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler.decodeRequest(AttributeQueryProfileHandler.java:157)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler.processRequest(AttributeQueryProfileHandler.java:80)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler.processRequest(AttributeQueryProfileHandler.java:54)
        at 
edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:82)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at 
edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:72)
        at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
        at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at 
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at 
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at 
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at 
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at 
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at 
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at 
org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:199)
        at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:282)
        at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:767)
        at 
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:697)
        at 
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:889)
        at 
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)
09:20:57.069 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: null
09:20:57.069 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity null
09:20:57.072 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of null
09:20:57.073 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:226] - 
Metadata was an EntitiesDescriptor, checking if any of its descendant 
EntityDescriptor elements is the one we're looking for.
09:20:57.073 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata 
document does not contain an entity descriptor with the ID null
09:20:57.076 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: null
09:20:57.076 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity null
09:20:57.077 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of null
09:20:57.077 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:226] - 
Metadata was an EntitiesDescriptor, checking if any of its descendant 
EntityDescriptor elements is the one we're looking for.
09:20:57.077 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata 
document does not contain an entity descriptor with the ID null
09:20:57.078 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: null
09:20:57.080 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity null
09:20:57.081 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of null
09:20:57.081 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:226] - 
Metadata was an EntitiesDescriptor, checking if any of its descendant 
EntityDescriptor elements is the one we're looking for.
09:20:57.082 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata 
document does not contain an entity descriptor with the ID null
09:20:57.082 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: null
09:20:57.082 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity null
09:20:57.083 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of null
09:20:57.083 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:226] - 
Metadata was an EntitiesDescriptor, checking if any of its descendant 
EntityDescriptor elements is the one we're looking for.
09:20:57.083 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata 
document does not contain an entity descriptor with the ID null
09:20:57.084 WARN 
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:247]
 - No metadata for relying party null, treating party as anonymous
09:20:57.084 DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:216] - 
Checking child metadata provider for entity descriptor with entity ID: 
urn:mace:switch.ch:aaitest:lewotolo.switch.ch
09:20:57.084 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:73] - Getting 
descriptor for entity urn:mace:switch.ch:aaitest:lewotolo.switch.ch
09:20:57.084 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - 
Searching for entity descriptor with an entity ID of 
urn:mace:switch.ch:aaitest:lewotolo.switch.ch
09:20:57.085 DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:208] - Entity 
descriptor for the ID urn:mace:switch.ch:aaitest:lewotolo.switch.ch was found 
in index cache, returning
09:20:57.086 ERROR 
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
 - Error processing profile request
java.lang.NullPointerException
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler.populateStatusResponse(AbstractSAML1ProfileHandler.java:496)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler.buildErrorResponse(AbstractSAML1ProfileHandler.java:479)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler.processRequest(AttributeQueryProfileHandler.java:114)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler.processRequest(AttributeQueryProfileHandler.java:54)
        at 
edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:82)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at 
edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:72)
        at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
        at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at 
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at 
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at 
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at 
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at 
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at 
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at 
org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:199)
        at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:282)
        at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:767)
        at 
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:697)
        at 
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:889)
        at 
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)




SP 1.3 log:
2008-02-26 09:17:34 DEBUG shibtarget.Listener [466] sessionNew: creating 
session for 130.59.6.143
2008-02-26 09:17:34 DEBUG shibtarget.Listener [466] sessionNew: recipient: 
https://kelimutu.switch.ch/Shibboleth.sso/SAML/POST
2008-02-26 09:17:34 DEBUG shibtarget.Listener [466] sessionNew: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.Listener [466] sessionNew: executing 
browser profile...
2008-02-26 09:17:34 DEBUG SAML.BrowserProfile [466] sessionNew: decoded SAML 
response:
<?xml version="1.0" encoding="UTF-8"?><samlp:Response 
xmlns:samlp="urn:oasis:names:tc:SAML:1.0:protocol" 
IssueInstant="2008-02-26T08:17:34.117Z" MajorVersion="1" MinorVersion="1" 
Recipient="https://kelimutu.switch.ch/Shibboleth.sso/SAML/POST"; 
ResponseID="_876f394b86044457aef2f3541a928d47"><ds:Signature 
xmlns:ds="http://www.w3.org/2000/09/xmldsig#";>
<ds:SignedInfo xmlns:ds="http://www.w3.org/2000/09/xmldsig#";>
<ds:CanonicalizationMethod 
Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"; 
xmlns:ds="http://www.w3.org/2000/09/xmldsig#"/>
<ds:SignatureMethod Algorithm="http://www.w3.org/2000/09/xmldsig#rsa-sha1"; 
xmlns:ds="http://www.w3.org/2000/09/xmldsig#"/>
<ds:Reference URI="#_876f394b86044457aef2f3541a928d47" 
xmlns:ds="http://www.w3.org/2000/09/xmldsig#";>
<ds:Transforms xmlns:ds="http://www.w3.org/2000/09/xmldsig#";>
<ds:Transform 
Algorithm="http://www.w3.org/2000/09/xmldsig#enveloped-signature"; 
xmlns:ds="http://www.w3.org/2000/09/xmldsig#"/>
<ds:Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"; 
xmlns:ds="http://www.w3.org/2000/09/xmldsig#";><ec:InclusiveNamespaces 
xmlns:ec="http://www.w3.org/2001/10/xml-exc-c14n#"; PrefixList="ds saml 
samlp"/></ds:Transform>
</ds:Transforms>
<ds:DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"; 
xmlns:ds="http://www.w3.org/2000/09/xmldsig#"/>
<ds:DigestValue 
xmlns:ds="http://www.w3.org/2000/09/xmldsig#";>utfz8nKew3D+Q75saVZ5QRjmHzU=</ds:DigestValue>
</ds:Reference>
</ds:SignedInfo>
<ds:SignatureValue xmlns:ds="http://www.w3.org/2000/09/xmldsig#";>
B59dDOqZANIEcr0smu8VBMPN+IvBTPc4G7QSGlu/C5E7Q4aAcmx1LsZ60uqE2g2zSw7U5AwPjQ1F
TCk1x0KuSSXPRQvPC6GOtsDJ1RJseQOwLSdKJ57SbBlvIJ5DyAr4P9woczuGp0gjDp5gxVWLgTTo
UWG1+gXLSGu7w6y69vXATBLSp537LotxRa6jlA17l7eH0yHQYtBOmxDY7V9Nie7PydveuXP937mj
6fygnKs9zzwW/NF1gMapxnB/PQ6EqUYGrEXm+oXvqWbVoZJ+AEUmc8vnehhzTonO5mLMQhRY4qaw
Q2AGmZ1Kg7uNMvFfh4w4+2kkegAHsx2S81rkpw==
</ds:SignatureValue>
<ds:KeyInfo><ds:X509Data><ds:X509Certificate>MIIEWzCCA0OgAwIBAgICAJ8wDQYJKoZIhvcNAQEFBQAwdTELMAkGA1UEBhMCQ0gxDzANBgNVBAcT
Blp1cmljaDETMBEGA1UEChMKU1dJVENIIEFBSTEMMAoGA1UECxMDQUFJMRQwEgYDVQQDEwtBQUkg
VGVzdCBDQTEcMBoGCSqGSIb3DQEJARYNYWFpQHN3aXRjaC5jaDAeFw0wNzA3MjQxMjM4MDBaFw0w
ODA3MjMxMjM4MDBaMGwxCzAJBgNVBAYTAkNIMUAwPgYDVQQKEzdTd2l0Y2ggLSBUZWxlaW5mb3Jt
YXRpa2RpZW5zdGUgZnVlciBMZWhyZSB1bmQgRm9yc2NodW5nMRswGQYDVQQDExJsZXdvdG9sby5z
d2l0Y2guY2gwggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQCeg3ABc5jTWbF3ZyoWNxLR
mv2p+iPYn4+ZH8p3kCr/KSzThpqoQMawbQwFrA0vZTB6mYWfPAByCgj19GXcIiK2IZXUxH2IH7gA
YSl2o+1QZ4Q6t+cEbBfkDWjz07cWvDvwTFzo8SVd4VMXqFeASFsGIq/6vTPbCWDydbyrG5gE29UN
nLuhBbuq3TyWrVANQgzv4YN9pKN/Izbn4jeylZUGxgdjlVuL7IDg9i9KjwFx5/yY0JjYLBvRG+sx
opm1jteRPZGQOUOuEc1AZU6PMYFZ/NjCqPTDv40OGbB28w6CyyJGNXJ9nAAGcNsZ5N7m5GY8ravg
may5pGr4R+k6g/b1AgMBAAGjgf0wgfowCQYDVR0TBAIwADAsBglghkgBhvhCAQ0EHxYdT3BlblNT
TCBHZW5lcmF0ZWQgQ2VydGlmaWNhdGUwHQYDVR0OBBYEFJc+tQ/baIeSIdFKYJIm4fOVK2WkMIGf
BgNVHSMEgZcwgZSAFAVHxIaHU/oPMNBSpaHwSyZreVJDoXmkdzB1MQswCQYDVQQGEwJDSDEPMA0G
A1UEBxMGWnVyaWNoMRMwEQYDVQQKEwpTV0lUQ0ggQUFJMQwwCgYDVQQLEwNBQUkxFDASBgNVBAMT
C0FBSSBUZXN0IENBMRwwGgYJKoZIhvcNAQkBFg1hYWlAc3dpdGNoLmNoggEAMA0GCSqGSIb3DQEB
BQUAA4IBAQAFiG8OORo+UsdkIwSyPudhGMiJN43rcfMlmi6jAtRrN5slzQRYWduMWbIAIJ/pyCWG
xA6xK52IEZ75z+ppzFEXk3/4FOVoRBUxFW8oIZxEsfus7tO13MHXH5hwDw8NAKmlDadEsdX1IW93
eqDPIKN8P8S45g0IHUK5I2jX0lTLQbyVh+owaO01k03y9gpz7uMFLgjhyU8VYZLBfJ/CLvC2t+01
6ZaMg/NlS/57+vkOGI+t4DhtlJIsQs9i7tTYfI81ofQpaKhhOsg3SK9Um2YF7+gd//Z0bkdyMdSq
yFXXVGx9zHDq/lDPvHg9WEWjUjX8gyH6EZcug8nZ0x0gtr+Y</ds:X509Certificate></ds:X509Data></ds:KeyInfo></ds:Signature><samlp:Status><samlp:StatusCode
 Value="samlp:Success"/></samlp:Status><saml:Assertion 
xmlns:saml="urn:oasis:names:tc:SAML:1.0:assertion" 
AssertionID="_bfb77e410ffe75f2a58cfecdf6265656" 
IssueInstant="2008-02-26T08:17:34.117Z" 
Issuer="urn:mace:switch.ch:aaitest:lewotolo.switch.ch" MajorVersion="1" 
MinorVersion="1"><saml:Conditions NotBefore="2008-02-26T08:17:34.117Z" 
NotOnOrAfter="2008-02-26T08:22:34.117Z"/><saml:AuthenticationStatement 
AuthenticationInstant="2008-02-26T08:17:34.036Z" 
AuthenticationMethod="urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified"><saml:Subject><saml:NameIdentifier
 
Format="urn:mace:shibboleth:1.0:nameIdentifier">_3260d38871153d32010a91d604c87014</saml:NameIdentifier><saml:SubjectConfirmation><saml:ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:bearer</saml:ConfirmationMethod></saml:SubjectConfirmation></saml:Subject><saml:SubjectLocality
 
IPAddress="130.59.6.143"/></saml:AuthenticationStatement></saml:Assertion></samlp:Response>
2008-02-26 09:17:34 DEBUG Shibboleth.ShibBrowserProfile [466] sessionNew: 
searching metadata for assertion issuer...
2008-02-26 09:17:34 DEBUG Shibboleth.ShibBrowserProfile [466] sessionNew: 
matched assertion issuer against metadata
2008-02-26 09:17:34 DEBUG Shibboleth.ShibBrowserProfile [466] sessionNew: 
passing signed response to trust layer
2008-02-26 09:17:34 DEBUG Shibboleth.Trust.Basic [466] sessionNew: validating 
signature with KeyDescriptors
2008-02-26 09:17:34 DEBUG Shibboleth.Trust.Basic [466] sessionNew: 
KeyDescriptor resolved into a key, trying it...
2008-02-26 09:17:34 INFO Shibboleth.Trust.Basic [466] sessionNew: signature 
verified with KeyDescriptor
2008-02-26 09:17:34 INFO shibtarget.Listener [466] sessionNew: creating new 
session
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [466] sessionNew: caching 
new entry for application default: "_582e6aab6acbdfbc5d9931ddaa1e364f"
2008-02-26 09:17:34 INFO shibtarget.SessionCache [466] sessionNew: new 
session created with session ID (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [466] sessionNew: NameID 
(_3260d38871153d32010a91d604c87014), IdP 
(urn:mace:switch.ch:aaitest:lewotolo.switch.ch), Address (130.59.6.143)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [466] sessionNew: new session 
id: _582e6aab6acbdfbc5d9931ddaa1e364f
2008-02-26 09:17:34 DEBUG shibtarget.Listener [467] sessionGet: checking for 
session: 

2008-02-26 09:17:34 DEBUG shibtarget.Listener [467] sessionGet: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [467] sessionGet: searching 
memory cache for key (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [467] sessionGet: Match 
found
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [467] sessionGet: testing 
session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f) (lifetime=7200, timeout=3600)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [467] sessionGet: session ok
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [467] sessionGet: 
populating attributes for session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 INFO shibtarget.SessionCache [467] sessionGet: trying to 
get new attributes for session (ID=_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [467] sessionGet: trying to 
query an AA...
2008-02-26 09:17:34 WARN shibtarget.SessionCache [467] sessionGet: skipping 
binding on unsupported protocol (urn:oasis:names:tc:SAML:2.0:bindings:SOAP)
2008-02-26 09:17:34 DEBUG SAML.SAMLSOAPHTTPBinding.CURLPool [467] sessionGet: 
getting connection handle to 
https://lewotolo.switch.ch:8443/idp-trunk/profile/SAML1/SOAP/AttributeQuery
2008-02-26 09:17:34 DEBUG SAML.SAMLSOAPHTTPBinding.CURLPool [467] sessionGet: 
nothing free in pool, returning new connection handle
2008-02-26 09:17:34 INFO SAML.SAMLSOAPHTTPBinding [467] sessionGet: sending 
SOAP message to 
https://lewotolo.switch.ch:8443/idp-trunk/profile/SAML1/SOAP/AttributeQuery
2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: About to connect() 
to lewotolo.switch.ch port 8443

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet:   Trying 
2001:620:0:14:20c:29ff:fe5e:9f04... 
2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: connected

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: Connected to 
lewotolo.switch.ch (2001:620:0:14:20c:29ff:fe5e:9f04) port 8443

2008-02-26 09:17:34 DEBUG shibtarget.ShibHTTPHook [467] sessionGet: OpenSAML 
invoked SSL context callback
2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, Client hello (1):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, Server hello (2):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, CERT (11):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: 

2008-02-26 09:17:34 DEBUG OpenSSL [467] sessionGet: invoking default X509 
verify callback
2008-02-26 09:17:34 DEBUG Shibboleth.Trust.Basic [467] sessionGet: comparing 
certificate to KeyDescriptors
2008-02-26 09:17:34 DEBUG Shibboleth.Trust.Basic [467] sessionGet: 
KeyDescriptor resolved into a certificate, comparing it...
2008-02-26 09:17:34 INFO Shibboleth.Trust.Basic [467] sessionGet: certificate 
match found in KeyDescriptor
2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, Server key exchange (12):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: 

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, Request CERT (13):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: 
2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, Server finished (14):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, CERT (11):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: 

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, Client key exchange (16):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, CERT verify (15):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS change 
cipher, Client hello (1):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, Finished (20):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS change 
cipher, Client hello (1):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS 
handshake, Finished (20):

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSL connection using 
DHE-RSA-AES256-SHA

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: Server certificate:

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet:         subject: 
/C=CH/O=Switch - Teleinformatikdienste fuer Lehre und 
Forschung/CN=lewotolo.switch.ch

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet:         start date: 
2007-07-24 12:38:00 GMT

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet:         expire date: 
2008-07-23 12:38:00 GMT

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet:         common name: 
lewotolo.switch.ch (matched)

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet:         issuer: 
/C=CH/L=Zurich/O=SWITCH AAI/OU=AAI/CN=AAI Test 


2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSL certificate 
verify ok.

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: POST 
/idp-trunk/profile/SAML1/SOAP/AttributeQuery HTTP/1.1
Host: lewotolo.switch.ch:8443
Accept: */*
Content-Type: text/xml
SOAPAction: http://www.oasis-open.org/committees/security
Shibboleth: 1.3
Xerces-C: 2.6.1
XML-Security-C: 1.3.0
OpenSAML-C: 1.1.0
Content-Length: 726

<Envelope xmlns="http://schemas.xmlsoap.org/soap/envelope/";><Body><Request 
xmlns="urn:oasis:names:tc:SAML:1.0:protocol" 
IssueInstant="2008-02-26T08:17:34Z" MajorVersion="1" MinorVersion="1" 
RequestID="_2bd815b71e6491732561988947f90602" 
xmlns:saml="urn:oasis:names:tc:SAML:1.0:assertion" 
xmlns:samlp="urn:oasis:names:tc:SAML:1.0:protocol" 
xmlns:xsd="http://www.w3.org/2001/XMLSchema"; 
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance";><AttributeQuery 
Resource="https://kelimutu.switch.ch/shibboleth";><Subject 
xmlns="urn:oasis:names:tc:SAML:1.0:assertion"><NameIdentifier 
Format="urn:mace:shibboleth:1.0:nameIdentifier">_3260d38871153d32010a91d604c87014</NameIdentifier></Subject></AttributeQuery></Request></Body></Envelope>
2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: HTTP/1.1 200 OK

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: Date: Tue, 26 Feb 
2008 08:17:34 GMT

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: Server: Apache/2.2.3 
(Debian) mod_jk/1.2.18 PHP/5.2.0-8+etch10 mod_ssl/2.2.3 OpenSSL/0.9.8c

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: Set-Cookie: 
JSESSIONID=22420ABD5F41D3C3A96E429BAC6E99FB; Path=/idp-trunk; Secure

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: Content-Length: 314

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: Content-Type: 
text/html;charset=ISO-8859-1

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: 

<html>

<body>
        <img src="/idp-trunk/images/logo.jpg" />
        <h3>ERROR</h3>
        <p>
            An error occurred while processing your request.  Please contact 
your helpdesk or
            user ID office for assistance.
        </p>
        
        <strong>Error Message: Message did not meet security policy 
requirements</strong>
        
        
</body>

</html>
2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: Connection #0 to 
host lewotolo.switch.ch left intact

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: Closing connection #0

2008-02-26 09:17:34 DEBUG SAML.libcurl [467] sessionGet: SSLv3, TLS alert, 
Client hello (1):

2008-02-26 09:17:34 ERROR shibtarget.SessionCache [467] sessionGet: caught 
SAML exception during SAML attribute query: 
Cgo8aHRtbD4KCjxib2R5PgoJPGltZyBzcmM9Ii9pZHAtdHJ1bmsvaW1hZ2Vz
L2xvZ28uanBnIiAvPgoJPGgzPkVSUk9SPC9oMz4KCTxwPgoJICAgIEFuIGVy
cm9yIG9jY3VycmVkIHdoaWxlIHByb2Nlc3NpbmcgeW91ciByZXF1ZXN0LiAg
UGxlYXNlIGNvbnRhY3QgeW91ciBoZWxwZGVzayBvcgoJICAgIHVzZXIgSUQg
b2ZmaWNlIGZvciBhc3Npc3RhbmNlLgoJPC9wPgoJCgk8c3Ryb25nPkVycm9y
IE1lc3NhZ2U6IE1lc3NhZ2UgZGlkIG5vdCBtZWV0IHNlY3VyaXR5IHBvbGlj
eSByZXF1aXJlbWVudHM8L3N0cm9uZz4KCQoJCjwvYm9keT4KCjwvaHRtbD4=

2008-02-26 09:17:34 ERROR shibtarget.SessionCache [467] sessionGet: no 
response obtained
2008-02-26 09:17:34 DEBUG shibtarget.Listener [468] sessionGet: checking for 
session: 

2008-02-26 09:17:34 DEBUG shibtarget.Listener [468] sessionGet: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [468] sessionGet: searching 
memory cache for key (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [468] sessionGet: Match 
found
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [468] sessionGet: testing 
session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f) (lifetime=7200, timeout=3600)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [468] sessionGet: session ok
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [468] sessionGet: 
populating attributes for session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [469] sessionGet: checking for 
session: 

2008-02-26 09:17:34 DEBUG shibtarget.Listener [469] sessionGet: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [469] sessionGet: searching 
memory cache for key (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [469] sessionGet: Match 
found
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [469] sessionGet: testing 
session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f) (lifetime=7200, timeout=3600)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [469] sessionGet: session ok
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [469] sessionGet: 
populating attributes for session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [470] sessionGet: checking for 
session: 

2008-02-26 09:17:34 DEBUG shibtarget.Listener [470] sessionGet: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [470] sessionGet: searching 
memory cache for key (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [470] sessionGet: Match 
found
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [470] sessionGet: testing 
session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f) (lifetime=7200, timeout=3600)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [470] sessionGet: session ok
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [470] sessionGet: 
populating attributes for session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [471] sessionGet: checking for 
session: 

2008-02-26 09:17:34 DEBUG shibtarget.Listener [471] sessionGet: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [471] sessionGet: searching 
memory cache for key (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [471] sessionGet: Match 
found
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [471] sessionGet: testing 
session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f) (lifetime=7200, timeout=3600)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [471] sessionGet: session ok
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [471] sessionGet: 
populating attributes for session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [472] sessionGet: checking for 
session: 

2008-02-26 09:17:34 DEBUG shibtarget.Listener [472] sessionGet: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [472] sessionGet: searching 
memory cache for key (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [472] sessionGet: Match 
found
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [472] sessionGet: testing 
session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f) (lifetime=7200, timeout=3600)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [472] sessionGet: session ok
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [472] sessionGet: 
populating attributes for session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [473] sessionGet: checking for 
session: 

2008-02-26 09:17:34 DEBUG shibtarget.Listener [473] sessionGet: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [473] sessionGet: searching 
memory cache for key (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [473] sessionGet: Match 
found
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [473] sessionGet: testing 
session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f) (lifetime=7200, timeout=3600)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [473] sessionGet: session ok
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [473] sessionGet: 
populating attributes for session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [474] sessionGet: checking for 
session: 

2008-02-26 09:17:34 DEBUG shibtarget.Listener [474] sessionGet: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [474] sessionGet: searching 
memory cache for key (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [474] sessionGet: Match 
found
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [474] sessionGet: testing 
session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f) (lifetime=7200, timeout=3600)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [474] sessionGet: session ok
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [474] sessionGet: 
populating attributes for session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [475] sessionGet: checking for 
session: 

2008-02-26 09:17:34 DEBUG shibtarget.Listener [475] sessionGet: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [475] sessionGet: searching 
memory cache for key (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [475] sessionGet: Match 
found
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [475] sessionGet: testing 
session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f) (lifetime=7200, timeout=3600)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [475] sessionGet: session ok
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [475] sessionGet: 
populating attributes for session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [476] sessionGet: checking for 
session: 

2008-02-26 09:17:34 DEBUG shibtarget.Listener [476] sessionGet: application: 
default
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [476] sessionGet: searching 
memory cache for key (_582e6aab6acbdfbc5d9931ddaa1e364f)
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [476] sessionGet: Match 
found
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [476] sessionGet: testing 
session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f) (lifetime=7200, timeout=3600)
2008-02-26 09:17:34 DEBUG shibtarget.Listener [476] sessionGet: session ok
2008-02-26 09:17:34 DEBUG shibtarget.SessionCache [476] sessionGet: 
populating attributes for session (ID: _582e6aab6acbdfbc5d9931ddaa1e364f)