2.3.5 IDP - Intermittently get principal as null, causing login failures
Daniele Russo
ruda76 at gmail.com
Thu Apr 19 08:16:18 BST 2012
Hi Anand,I have the same problem.
Which value have you setted for session timeout?
Thanks a lot.
Daniele
2012/3/16 Anand Somani <meatforums at gmail.com>
> 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'
>>
>>
>
> --
> To unsubscribe from this list send an email to
> users-unsubscribe at shibboleth.net
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20120419/02769908/attachment-0001.html
More information about the users
mailing list