2.3.5 IDP - Intermittently get principal as null, causing login failures
152 views
Skip to first unread message
Anand Somani
Mar 15, 2012, 4:29:43 PM3/15/12
to Shib Users
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@66de04cd, urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified=edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler@7a0d637d, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@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@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 an...@anand.com
12:41:42.793 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:178] - Successfully authenticated user an...@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 an...@anand.com
12:41:42.797 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:703] - Creating shibboleth session for principal an...@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: an...@anand.com
12:41:42.811 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:563] - User an...@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'
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@66de04cd, urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified=edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserLoginHandler@7a0d637d, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@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@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 an...@anand.com
12:41:42.793 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:178] - Successfully authenticated user an...@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 an...@anand.com
12:41:42.797 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:703] - Creating shibboleth session for principal an...@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: an...@anand.com
12:41:42.811 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:563] - User an...@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'
Anand Somani
Mar 15, 2012, 7:03:50 PM3/15/12
to Shib Users
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
Thanks
Reply all
Reply to author
Forward
0 new messages