null principals since upgrade from 2.1.3 to 2.3.2

Roberto Ullfig rullfig at uic.edu
Mon Aug 22 16:30:39 BST 2011 

Since we upgraded the IDP from 2.1.3 to 2.3.2 we've been getting 
occasional null principals. At first I thought it was related to client 
cookie IP mismatch (an error that also started appearing in 2.3.2) but I 
see some null principals even without the cookie error. Here is one example:

08:04:55.638 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:686] 
- Creating shibboleth session for principal jarrio2
08:04:55.639 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:792] 
- Adding IdP session cookie to HTTP response
08:04:55.640 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:701] 
- Recording authentication and service information in Shibboleth session 
for principal: jarrio2
08:04:55.641 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:552] 
- User jarrio2 authenticated with method 
urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified
08:04:55.642 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:161] 
- Returning control to profile handler
08:04:55.643 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:170] 
- Redirecting user to profile handler at 
https://shibboleth.uic.edu:443/idp/profile/SAML2/Redirect/SSO
08:04:58.426 - ERROR 
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:182] - 
Client sent a cookie from address 74.82.64.144 but the cookie was issued 
to address 74.82.64.160
08:04:58.428 - INFO [Shibboleth-Access:74] - 
20110822T130458Z|74.82.64.144|shibboleth.uic.edu:443|/profile/SAML2/Redirect/SSO|
08:04:58.429 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] 
- shibboleth.HandlerManager: Looking up profile handler for request 
path: /SAML2/Redirect/SSO
08:04:58.429 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:97] 
- shibboleth.HandlerManager: Located profile handler of the following 
type for the request path: 
edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler
08:04:58.430 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:163] 
- Incoming request contains a login context, processing as second leg of 
request
08:04:58.430 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:572] - 
Unbinding LoginContext
08:04:58.431 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:598] - 
Expiring LoginContext cookie
08:04:58.432 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:607] - 
Removing LoginContext, with key 33887750-3871-4b8e-8dbc-10a42559e03a, 
from StorageService partition loginContexts
08:04:58.432 - DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - 
Checking child metadata provider for entity descriptor with entity ID: 
google.com
08:04:58.433 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - 
Searching for entity descriptor with an entity ID of google.com
08:04:58.434 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - 
Metadata document does not contain an EntityDescriptor with the ID 
google.com
08:04:58.435 - DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - 
Checking child metadata provider for entity descriptor with entity ID: 
google.com
08:04:58.436 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - 
Searching for entity descriptor with an entity ID of google.com
08:04:58.436 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - 
Metadata document does not contain an EntityDescriptor with the ID 
google.com
08:04:58.437 - DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - 
Checking child metadata provider for entity descriptor with entity ID: 
google.com
08:04:58.438 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - 
Searching for entity descriptor with an entity ID of google.com
08:04:58.438 - DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - 
Checking child metadata provider for entity descriptor with entity ID: 
google.com
08:04:58.439 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - 
Searching for entity descriptor with an entity ID of google.com
08:04:58.440 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - 
Metadata document does not contain an EntityDescriptor with the ID 
google.com
08:04:58.441 - DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - 
Checking child metadata provider for entity descriptor with entity ID: 
google.com
08:04:58.441 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - 
Searching for entity descriptor with an entity ID of google.com
08:04:58.442 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - 
Metadata document does not contain an EntityDescriptor with the ID 
google.com
08:04:58.443 - DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - 
Checking child metadata provider for entity descriptor with entity ID: 
google.com
08:04:58.443 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - 
Searching for entity descriptor with an entity ID of google.com
08:04:58.444 - DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:127] 
- Looking up relying party configuration for google.com
08:04:58.445 - DEBUG 
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:129] 
- Custom relying party configuration found for google.com
08:04:58.446 - DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://shibboleth.uic.edu/shibboleth
08:04:58.447 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - 
Searching for entity descriptor with an entity ID of 
https://shibboleth.uic.edu/shibboleth
08:04:58.448 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - 
Metadata document does not contain an EntityDescriptor with the ID 
https://shibboleth.uic.edu/shibboleth
08:04:58.449 - DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://shibboleth.uic.edu/shibboleth
08:04:58.449 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - 
Searching for entity descriptor with an entity ID of 
https://shibboleth.uic.edu/shibboleth
08:04:58.450 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - 
Metadata document does not contain an EntityDescriptor with the ID 
https://shibboleth.uic.edu/shibboleth
08:04:58.451 - DEBUG 
[org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - 
Checking child metadata provider for entity descriptor with entity ID: 
https://shibboleth.uic.edu/shibboleth
08:04:58.451 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:509] - 
Searching for entity descriptor with an entity ID of 
https://shibboleth.uic.edu/shibboleth
08:04:58.452 - DEBUG 
[org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:167] - 
Metadata document does not contain an EntityDescriptor with the ID 
https://shibboleth.uic.edu/shibboleth
08:04:58.454 - DEBUG 
[org.opensaml.saml2.binding.AuthnResponseEndpointSelector:101] - 
Filtering peer endpoints.  Supported peer endpoint bindings: 
[urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST-SimpleSign, 
urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST, 
urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Artifact]
08:04:58.455 - DEBUG 
[org.opensaml.saml2.binding.AuthnResponseEndpointSelector:70] - 
Selecting endpoint by ACS URL 'https://www.google.com/a/uic.edu/acs' and 
protocol binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST' for 
request 'okmgdanjpoobgjacnhhndgejplkhoenplekkheea' from entity 'google.com'
08:04:58.456 - DEBUG 
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:472] 
- Resolving attributes for principal 'null' for SAML request from 
relying party 'google.com'

Note how the Auth engine knows about jarrio2 but the Profile Handler 
doesn't. This problem only occurs from google.com but that could be just 
because that's the most popular SP we support. We've had three of these 
this morning. I just upgraded tomcat6 to the latest version as well.

-- 
Roberto Ullfig
Systems Programmer - ACCC

More information about the users mailing list