2.3.5 IDP - Intermittently get principal as null, causing login failures

Anand Somani meatforums at gmail.com
Thu Mar 15 20:29:43 GMT 2012


Hi,

Using version 2.3.5 under jetty.

Login fails intermittently and when comparing the logs I see that principal
is null sometimes. Not sure if this a configuration gotcha or a bug.
Help!!.

Thanks
Anand

Logs from a failed login, please let me know if there is anything else in
terms of configs and such that I should be attaching.
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

12:41:14.911 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No
session associated with session ID
ODhhNjgyNmRiOGM0NTFjY2Y3MmRkZWRhMTEzM2I5YjVlNzY2ZTliOThjMzczMDAzMjc2YzQxYzRkOTFjZmRjNw==
- session must have timed out
12:41:14.914 - INFO [Shibboleth-Access:74] -
20120315T194114Z|0:0:0:0:0:0:0:1|localhost:8443|/profile/SAML2/Redirect/SSO|
12:41:14.921 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86]
- shibboleth.HandlerManager: Looking up profile handler for request path:
/SAML2/Redirect/SSO
12:41:14.922 - 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
12:41:14.922 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:344] - No
login context in storage service
12:41:14.922 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:160]
- Incoming request does not contain a login context, processing as first
leg of request
12:41:14.923 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:312]
- Decoding message with decoder binding
'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect'
12:41:14.947 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128]
- Looking up relying party configuration for sample-sample-client
12:41:14.948 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134]
- No custom relying party configuration found for sample-sample-client,
looking up configuration based on metadata groups.
12:41:14.948 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157]
- No custom or group-based relying party configuration found for
sample-sample-client. Using default relying party configuration.
12:41:14.950 - WARN
[org.opensaml.saml2.binding.security.SAML2AuthnRequestsSignedRule:81] -
SPSSODescriptor role metadata for entityID 'sample-sample-client' could not
be resolved
12:41:14.950 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:333]
- Decoded request from relying party 'sample-sample-client'
12:41:14.950 - WARN
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:287]
- No metadata for relying party sample-sample-client, treating party as
anonymous
12:41:14.951 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:203]
- Creating login context and transferring control to authentication engine
12:41:14.955 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:169] -
Storing LoginContext to StorageService partition loginContexts, key
57eaabee-4c16-47d5-9ce1-83fd75af2d85
12:41:14.956 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:216]
- Redirecting user to authentication engine at
https://localhost:8443/idp/AuthnEngine
12:41:14.962 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No
session associated with session ID
ODhhNjgyNmRiOGM0NTFjY2Y3MmRkZWRhMTEzM2I5YjVlNzY2ZTliOThjMzczMDAzMjc2YzQxYzRkOTFjZmRjNw==
- session must have timed out
12:41:14.963 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] -
Processing incoming request
12:41:14.963 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:240] -
Beginning user authentication process.
12:41:14.964 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:286] -
Filtering configured LoginHandlers:
{urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler at 66de04cd,
urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified=edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler at 7a0d637d,
urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 4fee225
}
12:41:14.964 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:291] -
Filtering possible login handlers by requested authentication methods:
[urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport]
12:41:14.964 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:299] -
Filtering out login handler for authentication
urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified, it does not provide a
requested authentication method
12:41:14.964 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:335] -
Filtering out previous session login handler because there is no existing
IdP session
12:41:14.965 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:467] -
Selecting appropriate login handler from filtered set
{urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 4fee225
}
12:41:14.965 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:500] -
Authenticating user with login handler of type
edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler
12:41:14.965 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:169] -
Storing LoginContext to StorageService partition loginContexts, key
8ab6eb5b-7b30-4451-aff4-1ff45df0d879
12:41:14.966 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler:66]
- Redirecting to https://localhost:8443/idp/Authn/UserPassword
12:41:14.969 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No
session associated with session ID
ODhhNjgyNmRiOGM0NTFjY2Y3MmRkZWRhMTEzM2I5YjVlNzY2ZTliOThjMzczMDAzMjc2YzQxYzRkOTFjZmRjNw==
- session must have timed out
12:41:17.583 - DEBUG
[edu.internet2.middleware.shibboleth.idp.ui.ServiceTagSupport:348] - No
relying party, nothing to display
12:41:17.605 - DEBUG
[edu.internet2.middleware.shibboleth.idp.ui.ServiceTagSupport:348] - No
relying party, nothing to display
12:41:17.607 - DEBUG
[edu.internet2.middleware.shibboleth.idp.ui.ServiceDescriptionTag:93] - No
relying party, nothing to display
12:41:17.607 - DEBUG
[edu.internet2.middleware.shibboleth.idp.ui.ServiceDescriptionTag:93] - No
relying party, nothing to display
12:41:17.612 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:150]
- Redirecting to login page /login.jsp
12:41:17.619 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No
session associated with session ID
ODhhNjgyNmRiOGM0NTFjY2Y3MmRkZWRhMTEzM2I5YjVlNzY2ZTliOThjMzczMDAzMjc2YzQxYzRkOTFjZmRjNw==
- session must have timed out
12:41:17.639 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No
session associated with session ID
ODhhNjgyNmRiOGM0NTFjY2Y3MmRkZWRhMTEzM2I5YjVlNzY2ZTliOThjMzczMDAzMjc2YzQxYzRkOTFjZmRjNw==
- session must have timed out
12:41:42.617 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No
session associated with session ID
ODhhNjgyNmRiOGM0NTFjY2Y3MmRkZWRhMTEzM2I5YjVlNzY2ZTliOThjMzczMDAzMjc2YzQxYzRkOTFjZmRjNw==
- session must have timed out
12:41:42.618 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:170]
- Attempting to authenticate user anand at anand.com
12:41:42.793 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:178]
- Successfully authenticated user anand at anand.com
12:41:42.795 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:144] -
Returning control to authentication engine
12:41:42.795 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] -
Processing incoming request
12:41:42.796 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:517] -
Completing user authentication process
12:41:42.796 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:588] -
Validating authentication was performed successfully
12:41:42.796 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:699] -
Updating session information for principal anand at anand.com
12:41:42.797 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:703] -
Creating shibboleth session for principal anand at anand.com
12:41:42.807 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:809] -
Adding IdP session cookie to HTTP response
12:41:42.808 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:718] -
Recording authentication and service information in Shibboleth session for
principal: anand at anand.com
12:41:42.811 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:563] -
User anand at anand.com authenticated with method
urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
12:41:42.811 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:161] -
Returning control to profile handler
12:41:42.811 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:177] -
Redirecting user to profile handler at
https://localhost:8443/idp/profile/SAML2/Redirect/SSO
12:41:42.818 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:160] - No
session associated with session ID
NTAzNjI1NDZhZTgxOGNjM2MwZjc3YzU1NTI0MTAyOWI3NWQ2Y2MxOTQyNjEzYTdiMWVjMWJjZjBmMjNkZmI1Yg==
- session must have timed out
12:41:42.818 - INFO [Shibboleth-Access:74] -
20120315T194142Z|0:0:0:0:0:0:0:1|localhost:8443|/profile/SAML2/Redirect/SSO|
12:41:42.819 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86]
- shibboleth.HandlerManager: Looking up profile handler for request path:
/SAML2/Redirect/SSO
12:41:42.819 - 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
12:41:42.820 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:163]
- Incoming request contains a login context, processing as second leg of
request
12:41:42.820 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:572] -
Unbinding LoginContext
12:41:42.820 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:598] -
Expiring LoginContext cookie
12:41:42.821 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:607] -
Removing LoginContext, with key 8ab6eb5b-7b30-4451-aff4-1ff45df0d879, from
StorageService partition loginContexts
12:41:42.821 - WARN
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:287]
- No metadata for relying party sample-sample-client, treating party as
anonymous
12:41:42.824 - WARN
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:666]
- Generating endpoint for anonymous relying party self-identified as
'sample-sample-client', ACS url 'http://10.23.8.163:3000/sample/authorize'
and binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST'*
12:41:42.825 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:472]
- Resolving attributes for principal 'null' for SAML request from relying
party 'sample-sample-client'*
12:41:42.827 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:119]
- shibboleth.AttributeResolver resolving attributes for principal null
12:41:42.827 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:275]
- Specific attributes for principal null were not requested, resolving all
attributes.
12:41:42.828 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:314]
- Resolving attribute principal_uid for principal null
12:41:42.829 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:336]
- Resolved attribute principal_uid containing 0 values
12:41:42.830 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:450]
- Removing attribute principal_uid from resolution result for principal
null.  It contains no values.
12:41:42.830 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:137]
- shibboleth.AttributeResolver resolved, for principal null, the
attributes: []
12:41:42.831 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:71]
- shibboleth.AttributeFilterEngine filtering 0 attributes for principal null
12:41:42.833 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:499]
- Creating attribute statement in response to SAML request
'_bfec8a31-5104-012f-e909-5fffd6b1c939' from relying party
'sample-sample-client'
12:41:42.834 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML2AttributeAuthority:128]
- No attributes remained after encoding and filtering by value, no
attribute statement built
12:41:42.844 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:465]
- Attempting to select name identifier attribute for relying party
'sample-sample-client' that requires format
'urn:oasis:names:tc:SAML:1.1:nameid-format:emailAddress'
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20120315/16863b12/attachment-0001.html 


More information about the users mailing list