2.3.5 IDP - Intermittently get principal as null, causing login failures
Anand Somani
meatforums at gmail.com
Thu Mar 15 23:03:50 GMT 2012
ok, here what I figured I had reduced the session timeout to very low (in
internal.xml file). So the second leg would succeed when it was within that
timeout, else fail.
Thanks
On Thu, Mar 15, 2012 at 1:29 PM, Anand Somani <meatforums at gmail.com> wrote:
> 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/19507c35/attachment-0001.html
More information about the users
mailing list