Shibboleth Developers

[Jim Fox <>]

I am running some 2.0 load tests.  These involve login to SP,
throw away cookies, repeat.  The following is seen on the idp.

The first authn request requires a loop through the local sso
to get the user's id.  It then retrieves attributes (Why does
it do this now?  It retrieves them again when the SP makes
an attribute request.)  Finally it sends the authn assertion.

On subsequent authn requests the user's id is cached and
no sso loop is used.  However, right after sending the authn
assertion I get a null pointer exception.  (See attached log)
This exception accompanies every authn assertion when a cache
entry is available.

Jim



First authn request

2007-10-22 14:38:10,373 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Looking up profile handler for request path: 
/shibboleth/SSO
2007-10-22 14:38:10,373 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Located profile handler of the following type for 
request path /shibboleth/SSO: 
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler
2007-10-22 14:38:10,373 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler]
 Processing incomming request
2007-10-22 14:38:10,373 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler]
 User session does not contain a login context, processing as first leg of 
request
2007-10-22 14:38:10,373 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Looking up relying party configuration for lost.cac.washington.edu
2007-10-22 14:38:10,373 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Relying party configuration found for lost.cac.washington.edu
2007-10-22 14:38:10,373 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Processing incoming request
2007-10-22 14:38:10,373 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] No 
active authentication method is applicable for relying party.  Authenticating 
user with to be determined method.
2007-10-22 14:38:10,373 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Selecting appropriate authentication method for request.
2007-10-22 14:38:10,374 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Looking up authentication method for relying party 
lost.cac.washington.edu
2007-10-22 14:38:10,374 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Checking for authentication handler for method 
urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified which was requested for 
relying party lost.cac.washington.edu
2007-10-22 14:38:10,374 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Authentication handler for method 
urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified for relying party 
lost.cac.washington.edu found.  Checking if it meets othe criteria.
2007-10-22 14:38:10,374 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Authentication handler for method 
urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified for relying party 
lost.cac.washington.edu meets all requirements, using it.
2007-10-22 14:38:10,374 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Authentication method urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified will 
be used to authenticate user.
2007-10-22 14:38:10,374 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Transferring control to authentication handler of type: 
edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler
2007-10-22 14:38:10,374 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler]
 Redirecting to https://urizen2.cac.washington.edu:443/idp/Authn/RemoteUser

( login via local sso )

2007-10-22 14:38:10,602 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserAuthServlet]
 Remote user identified as myuw1 returning control back to authentication 
engine
2007-10-22 14:38:10,602 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Returning control to authentication engine
2007-10-22 14:38:10,602 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Processing incoming request
2007-10-22 14:38:10,602 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] Request 
returned from authentication handler, completing authentication process.
2007-10-22 14:38:10,602 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] Creating 
shibboleth session for principal myuw1
2007-10-22 14:38:10,602 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Recording authentication and service information in Shibboleth session for 
principal: myuw1
2007-10-22 14:38:10,602 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Returning control to profile handler at: /profile/shibboleth/SSO
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Looking up profile handler for request path: 
/shibboleth/SSO
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Located profile handler of the following type for 
request path /shibboleth/SSO: 
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler]
 Processing incomming request
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler]
 User session contains a login context, processing as second leg of request
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Looking up relying party configuration for lost.cac.washington.edu
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Relying party configuration found for lost.cac.washington.edu
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOEndpointSelector]
 Relying party role contains 5 endpoints
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOEndpointSelector]
 Selecting endpoint from metadata corresponding to provided ACS URL: 
https://lost.cac.washington.edu/Shibboleth.sso/SAML/POST
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Resolving attributes for principal myuw1 of SAML request from relying party 
lost.cac.washington.edu
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attributes for principal myuw1
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 Specific attributes for principal myuw1 were not requested, resolving all 
attributes.
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute eppn for principal myuw1
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving data connector personreg for 
principal myuw1
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Begin resolve for myuw1
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.TemplateEngine]
 Populating velocity context
2007-10-22 14:38:10,603 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.TemplateEngine]
 Populating the following shibboleth.resolver.dc.personreg template
2007-10-22 14:38:10,604 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 search filter = (uwNetID=myuw1)
2007-10-22 14:38:10,605 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Retrieving attributes from LDAP
2007-10-22 14:38:10,652 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: uwNetID=[myuw1]
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: objectClass=[top, uwEntity, uwPrincipal]
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: uwRegID=[24D96540AE3511D68CBC0004AC494FFE]
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: 
serialNumber=[24D96540AE3511D68CBC0004AC494FFE]
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: displayName=[MYUW TESTER I]
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.attributeDefinition.ScopedAttributeDefinition]
 Resolving attribute: (eppn)
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute eppn.  Attribtute contains 0 
values.
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute principalName for principal 
myuw1
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute principalName.  Attribtute 
contains 1 values.
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute affiliation for principal 
myuw1
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute affiliation.  Attribtute 
contains 0 values.
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute scopedAffiliation for 
principal myuw1
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.attributeDefinition.ScopedAttributeDefinition]
 Resolving attribute: (scopedAffiliation)
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute scopedAffiliation.  
Attribtute contains 0 values.
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved 4 attributes for principal myuw1
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute eppn from resolution result 
for principal myuw1.  It contains no values.
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute affiliation from resolution 
result for principal myuw1.  It contains no values.
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute scopedAffiliation from 
resolution result for principal myuw1.  It contains no values.
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver returning 1 attributes for principal myuw1
2007-10-22 14:38:10,653 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering 1 attributes for principal myuw1
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine evaluating if filter policy 
releasePrincipalToAnyone is active for principal myuw1
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 Filter policy releasePrincipalToAnyone is active for principal myuw1
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute principalName 
for principal myuw1
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute eppn for 
principal myuw1
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute affiliation 
for principal myuw1
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute 
scopedAffiliation for principal myuw1
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute entitlement 
for principal myuw1
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtered attributes for principal myuw1.  1 
attributes remain.
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Building assertion NameIdentifier to relying party lost.cac.washington.edu 
for principal myuw1
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Supported name formats: [urn:mace:shibboleth:1.0:nameIdentifier]
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Using attribute principalName suppoting name format 
urn:mace:shibboleth:1.0:nameIdentifier to create the NameIdentifier for 
principal myuw1
2007-10-22 14:38:10,654 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Determining if SAML assertion to relying party lost.cac.washington.edu 
should be signed
2007-10-22 14:38:10,655 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Entity metadata for relying party lost.cac.washington.edu indicates to sign 
assertions: false
2007-10-22 14:38:10,655 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler] 
Encoding response to SAML request null from relying party 
lost.cac.washington.edu with outbound binding 
urn:oasis:names:tc:SAML:1.0:profiles:browser-post

Attribute query following the above authn

2007-10-22 14:38:11,095 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Looking up profile handler for request path: 
/saml1/SOAP/AttributeQuery
2007-10-22 14:38:11,095 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Located profile handler of the following type for 
request path /saml1/SOAP/AttributeQuery: 
edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler
2007-10-22 14:38:11,095 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler]
 Decoding incomming request
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler]
 Decoded request
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Looking up relying party configuration for lost.cac.washington.edu
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Relying party configuration found for lost.cac.washington.edu
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Resolving principal name for subject of SAML request from relying party 
lost.cac.washington.edu
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 Resolving principal name from name identifier of format: 
urn:mace:shibboleth:1.0:nameIdentifier
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 Using principal connector shibDirect to resolve principal name.
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Resolving attributes for principal myuw1 of SAML request from relying party 
lost.cac.washington.edu
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attributes for principal myuw1
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 Specific attributes for principal myuw1 were not requested, resolving all 
attributes.
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute eppn for principal myuw1
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving data connector personreg for 
principal myuw1
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Begin resolve for myuw1
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.TemplateEngine]
 Populating velocity context
2007-10-22 14:38:11,101 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.TemplateEngine]
 Populating the following shibboleth.resolver.dc.personreg template
2007-10-22 14:38:11,102 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 search filter = (uwNetID=myuw1)
2007-10-22 14:38:11,102 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Retrieving attributes from LDAP
2007-10-22 14:38:11,152 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: uwNetID=[myuw1]
2007-10-22 14:38:11,152 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: objectClass=[top, uwEntity, uwPrincipal]
2007-10-22 14:38:11,152 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: uwRegID=[24D96540AE3511D68CBC0004AC494FFE]
2007-10-22 14:38:11,152 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: 
serialNumber=[24D96540AE3511D68CBC0004AC494FFE]
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: displayName=[MYUW TESTER I]
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.attributeDefinition.ScopedAttributeDefinition]
 Resolving attribute: (eppn)
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute eppn.  Attribtute contains 0 
values.
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute principalName for principal 
myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute principalName.  Attribtute 
contains 1 values.
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute affiliation for principal 
myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute affiliation.  Attribtute 
contains 0 values.
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute scopedAffiliation for 
principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.attributeDefinition.ScopedAttributeDefinition]
 Resolving attribute: (scopedAffiliation)
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute scopedAffiliation.  
Attribtute contains 0 values.
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved 4 attributes for principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute eppn from resolution result 
for principal myuw1.  It contains no values.
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute affiliation from resolution 
result for principal myuw1.  It contains no values.
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute scopedAffiliation from 
resolution result for principal myuw1.  It contains no values.
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver returning 1 attributes for principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering 1 attributes for principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine evaluating if filter policy 
releasePrincipalToAnyone is active for principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 Filter policy releasePrincipalToAnyone is active for principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute principalName 
for principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute eppn for 
principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute affiliation 
for principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute 
scopedAffiliation for principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute entitlement 
for principal myuw1
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtered attributes for principal myuw1.  1 
attributes remain.
2007-10-22 14:38:11,153 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Creating attribute statement in response to SAML request from relying party 
lost.cac.washington.edu
2007-10-22 14:38:11,154 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML1AttributeAuthority]
 Encoded attribute principalName with encoder of type 
edu.internet2.middleware.shibboleth.common.attribute.encoding.provider.SAML1StringAttributeEncoder
2007-10-22 14:38:11,154 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Building assertion NameIdentifier to relying party lost.cac.washington.edu 
for principal myuw1
2007-10-22 14:38:11,154 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Supported name formats: [urn:mace:shibboleth:1.0:nameIdentifier]
2007-10-22 14:38:11,154 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Using attribute principalName suppoting name format 
urn:mace:shibboleth:1.0:nameIdentifier to create the NameIdentifier for 
principal myuw1
2007-10-22 14:38:11,154 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Determining if SAML assertion to relying party lost.cac.washington.edu 
should be signed
2007-10-22 14:38:11,154 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Entity metadata for relying party lost.cac.washington.edu indicates to sign 
assertions: false
2007-10-22 14:38:11,154 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler] 
Encoding response to SAML request _77a123fc06ee73a958ce3780033e6b4d from 
relying party lost.cac.washington.edu with outbound binding 
urn:oasis:names:tc:SAML:1.0:bindings:SOAP-binding

End of first login to RP

Second authn request (note no loop through local sso)

2007-10-22 14:38:11,704 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Looking up profile handler for request path: 
/shibboleth/SSO
2007-10-22 14:38:11,704 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Located profile handler of the following type for 
request path /shibboleth/SSO: 
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler
2007-10-22 14:38:11,704 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler]
 Processing incomming request
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler]
 User session does not contain a login context, processing as first leg of 
request
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Looking up relying party configuration for lost.cac.washington.edu
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Relying party configuration found for lost.cac.washington.edu
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Processing incoming request
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] An 
active authentication method is applicable for relying party.  Using 
authentication method urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified as 
authentication method to relying party without re-authenticating user.
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Populating login context with existing session and authentication method 
information.
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Returning control to profile handler at: /profile/shibboleth/SSO
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Looking up profile handler for request path: 
/shibboleth/SSO
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Located profile handler of the following type for 
request path /shibboleth/SSO: 
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler]
 Processing incomming request
2007-10-22 14:38:11,705 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler]
 User session contains a login context, processing as second leg of request
2007-10-22 14:38:11,706 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Looking up relying party configuration for lost.cac.washington.edu
2007-10-22 14:38:11,706 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Relying party configuration found for lost.cac.washington.edu
2007-10-22 14:38:11,706 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOEndpointSelector]
 Relying party role contains 5 endpoints
2007-10-22 14:38:11,706 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOEndpointSelector]
 Selecting endpoint from metadata corresponding to provided ACS URL: 
https://lost.cac.washington.edu/Shibboleth.sso/SAML/POST
2007-10-22 14:38:11,706 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Resolving attributes for principal myuw1 of SAML request from relying party 
lost.cac.washington.edu
2007-10-22 14:38:11,706 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attributes for principal myuw1
2007-10-22 14:38:11,710 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 Specific attributes for principal myuw1 were not requested, resolving all 
attributes.
2007-10-22 14:38:11,710 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute eppn for principal myuw1
2007-10-22 14:38:11,710 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving data connector personreg for 
principal myuw1
2007-10-22 14:38:11,710 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Begin resolve for myuw1
2007-10-22 14:38:11,710 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.TemplateEngine]
 Populating velocity context
2007-10-22 14:38:11,710 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.TemplateEngine]
 Populating the following shibboleth.resolver.dc.personreg template
2007-10-22 14:38:11,711 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 search filter = (uwNetID=myuw1)
2007-10-22 14:38:11,711 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Retrieving attributes from LDAP
2007-10-22 14:38:11,756 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: uwNetID=[myuw1]
2007-10-22 14:38:11,756 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: objectClass=[top, uwEntity, uwPrincipal]
2007-10-22 14:38:11,756 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: uwRegID=[24D96540AE3511D68CBC0004AC494FFE]
2007-10-22 14:38:11,756 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: 
serialNumber=[24D96540AE3511D68CBC0004AC494FFE]
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: displayName=[MYUW TESTER I]
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.attributeDefinition.ScopedAttributeDefinition]
 Resolving attribute: (eppn)
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute eppn.  Attribtute contains 0 
values.
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute principalName for principal 
myuw1
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute principalName.  Attribtute 
contains 1 values.
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute affiliation for principal 
myuw1
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute affiliation.  Attribtute 
contains 0 values.
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute scopedAffiliation for 
principal myuw1
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.attributeDefinition.ScopedAttributeDefinition]
 Resolving attribute: (scopedAffiliation)
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute scopedAffiliation.  
Attribtute contains 0 values.
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved 4 attributes for principal myuw1
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute eppn from resolution result 
for principal myuw1.  It contains no values.
2007-10-22 14:38:11,757 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute affiliation from resolution 
result for principal myuw1.  It contains no values.
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute scopedAffiliation from 
resolution result for principal myuw1.  It contains no values.
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver returning 1 attributes for principal myuw1
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering 1 attributes for principal myuw1
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine evaluating if filter policy 
releasePrincipalToAnyone is active for principal myuw1
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 Filter policy releasePrincipalToAnyone is active for principal myuw1
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute principalName 
for principal myuw1
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute eppn for 
principal myuw1
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute affiliation 
for principal myuw1
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute 
scopedAffiliation for principal myuw1
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute entitlement 
for principal myuw1
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtered attributes for principal myuw1.  1 
attributes remain.
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Building assertion NameIdentifier to relying party lost.cac.washington.edu 
for principal myuw1
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Supported name formats: [urn:mace:shibboleth:1.0:nameIdentifier]
2007-10-22 14:38:11,758 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Using attribute principalName suppoting name format 
urn:mace:shibboleth:1.0:nameIdentifier to create the NameIdentifier for 
principal myuw1
2007-10-22 14:38:11,759 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Determining if SAML assertion to relying party lost.cac.washington.edu 
should be signed
2007-10-22 14:38:11,759 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Entity metadata for relying party lost.cac.washington.edu indicates to sign 
assertions: false
2007-10-22 14:38:11,759 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler] 
Encoding response to SAML request null from relying party 
lost.cac.washington.edu with outbound binding 
urn:oasis:names:tc:SAML:1.0:profiles:browser-post

( note it now can't find an authentication method )

2007-10-22 14:38:11,778 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] No 
active authentication method is applicable for relying party.  Authenticating 
user with to be determined method.
2007-10-22 14:38:11,778 DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine] 
Selecting appropriate authentication method for request.
2007-10-22 14:38:11,778 ERROR 
[org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/idp].[AuthenticationEngine]]
 Servlet.service() for servlet AuthenticationEngine threw exception
java.lang.NullPointerException
        at 
edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager.getAuthenticationHandler(IdPProfileHandlerManager.java:146)
        at 
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.authenticateUserWithoutActiveMethod1(AuthenticationEngine.java:226)
        at 
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.service(AuthenticationEngine.java:169)
        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 
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:672)
        at 
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:463)
        at 
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:398)
        at 
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler.performAuthentication(ShibbolethSSOProfileHandler.java:159)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler.processRequest(ShibbolethSSOProfileHandler.java:117)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler.processRequest(ShibbolethSSOProfileHandler.java:64)
        at 
edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:74)
        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 
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.valves.FastCommonAccessLogValve.invoke(FastCommonAccessLogValve.java:495)
        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:754)
        at 
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:684)
        at 
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:876)
        at 
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)
2007-10-22 14:38:11,779 ERROR 
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet]
 Encountered error processing request to /shibboleth/SSO, invoking error 
handler
java.lang.NullPointerException
        at 
edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager.getAuthenticationHandler(IdPProfileHandlerManager.java:146)
        at 
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.authenticateUserWithoutActiveMethod1(AuthenticationEngine.java:226)
        at 
edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.service(AuthenticationEngine.java:169)
        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 
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:672)
        at 
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:463)
        at 
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:398)
        at 
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler.performAuthentication(ShibbolethSSOProfileHandler.java:159)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler.processRequest(ShibbolethSSOProfileHandler.java:117)
        at 
edu.internet2.middleware.shibboleth.idp.profile.saml1.ShibbolethSSOProfileHandler.processRequest(ShibbolethSSOProfileHandler.java:64)
        at 
edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:74)
        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 
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.valves.FastCommonAccessLogValve.invoke(FastCommonAccessLogValve.java:495)
        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:754)
        at 
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:684)
        at 
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:876)
        at 
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)
2007-10-22 14:38:11,780 ERROR 
[edu.internet2.middleware.shibboleth.common.profile.provider.JSPErrorHandler] 
Could not dispatch to error JSP page: /error.jsp
java.lang.IllegalStateException: Cannot forward after response has been 
committed
        at 
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:313)
        at 
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:301)
        at 
edu.internet2.middleware.shibboleth.common.profile.provider.JSPErrorHandler.processRequest(JSPErrorHandler.java:81)
        at 
edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:87)
        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 
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.valves.FastCommonAccessLogValve.invoke(FastCommonAccessLogValve.java:495)
        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:754)
        at 
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:684)
        at 
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:876)
        at 
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)


2007-10-22 14:38:11,952 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Looking up profile handler for request path: 
/saml1/SOAP/AttributeQuery
2007-10-22 14:38:11,952 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager] 
shibboleth.HandlerManager: Located profile handler of the following type for 
request path /saml1/SOAP/AttributeQuery: 
edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler
2007-10-22 14:38:11,952 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler]
 Decoding incomming request
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler]
 Decoded request
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Looking up relying party configuration for lost.cac.washington.edu
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager]
 Relying party configuration found for lost.cac.washington.edu
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Resolving principal name for subject of SAML request from relying party 
lost.cac.washington.edu
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 Resolving principal name from name identifier of format: 
urn:mace:shibboleth:1.0:nameIdentifier
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 Using principal connector shibDirect to resolve principal name.
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Resolving attributes for principal myuw1 of SAML request from relying party 
lost.cac.washington.edu
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attributes for principal myuw1
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 Specific attributes for principal myuw1 were not requested, resolving all 
attributes.
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute eppn for principal myuw1
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving data connector personreg for 
principal myuw1
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Begin resolve for myuw1
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.TemplateEngine]
 Populating velocity context
2007-10-22 14:38:11,958 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.TemplateEngine]
 Populating the following shibboleth.resolver.dc.personreg template
2007-10-22 14:38:11,959 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 search filter = (uwNetID=myuw1)
2007-10-22 14:38:11,959 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Retrieving attributes from LDAP
2007-10-22 14:38:12,002 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: uwNetID=[myuw1]
2007-10-22 14:38:12,002 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: objectClass=[top, uwEntity, uwPrincipal]
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: uwRegID=[24D96540AE3511D68CBC0004AC494FFE]
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: 
serialNumber=[24D96540AE3511D68CBC0004AC494FFE]
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector]
 Found the following attribute: displayName=[MYUW TESTER I]
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.attributeDefinition.ScopedAttributeDefinition]
 Resolving attribute: (eppn)
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute eppn.  Attribtute contains 0 
values.
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute principalName for principal 
myuw1
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute principalName.  Attribtute 
contains 1 values.
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute affiliation for principal 
myuw1
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute affiliation.  Attribtute 
contains 0 values.
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolving attribute scopedAffiliation for 
principal myuw1
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.attributeDefinition.ScopedAttributeDefinition]
 Resolving attribute: (scopedAffiliation)
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved attribute scopedAffiliation.  
Attribtute contains 0 values.
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver resolved 4 attributes for principal myuw1
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute eppn from resolution result 
for principal myuw1.  It contains no values.
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute affiliation from resolution 
result for principal myuw1.  It contains no values.
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver removing attribute scopedAffiliation from 
resolution result for principal myuw1.  It contains no values.
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver]
 shibboleth.AttributeResolver returning 1 attributes for principal myuw1
2007-10-22 14:38:12,003 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering 1 attributes for principal myuw1
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine evaluating if filter policy 
releasePrincipalToAnyone is active for principal myuw1
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 Filter policy releasePrincipalToAnyone is active for principal myuw1
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute principalName 
for principal myuw1
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute eppn for 
principal myuw1
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute affiliation 
for principal myuw1
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute 
scopedAffiliation for principal myuw1
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtering values of attribute entitlement 
for principal myuw1
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine]
 shibboleth.AttributeFilterEngine filtered attributes for principal myuw1.  1 
attributes remain.
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Creating attribute statement in response to SAML request from relying party 
lost.cac.washington.edu
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML1AttributeAuthority]
 Encoded attribute principalName with encoder of type 
edu.internet2.middleware.shibboleth.common.attribute.encoding.provider.SAML1StringAttributeEncoder
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Building assertion NameIdentifier to relying party lost.cac.washington.edu 
for principal myuw1
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Supported name formats: [urn:mace:shibboleth:1.0:nameIdentifier]
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Using attribute principalName suppoting name format 
urn:mace:shibboleth:1.0:nameIdentifier to create the NameIdentifier for 
principal myuw1
2007-10-22 14:38:12,004 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Determining if SAML assertion to relying party lost.cac.washington.edu 
should be signed
2007-10-22 14:38:12,005 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml1.AbstractSAML1ProfileHandler]
 Entity metadata for relying party lost.cac.washington.edu indicates to sign 
assertions: false
2007-10-22 14:38:12,005 DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler] 
Encoding response to SAML request _e5ada7c9fd380070e2cd92c63f33eab1 from 
relying party lost.cac.washington.edu with outbound binding 
urn:oasis:names:tc:SAML:1.0:bindings:SOAP-binding