null principals since upgrade from 2.1.3 to 2.3.2

Tue Aug 23 14:57:48 BST 2011

All these null principals are being generated from blackberry.net 
connections. Does anyone have an idea of where to start looking at this. 
I'd also like to know what the user sees on his end when this happens. 
Does he get into google or does he get an error message?

On 08/22/2011 10:30 AM, Roberto Ullfig wrote:
> 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
UIC Research Programmer