Facing issue with Shibboleth IDP authentication for satellite wifi user

classic Classic list List threaded Threaded
1 message Options
Reply | Threaded
Open this post in threaded view
|

Facing issue with Shibboleth IDP authentication for satellite wifi user

Krunal Saraiya
Hi,

We are struggling with a Problem between IDP (2.4.0) and CAS server (cas-server-core-3.5.2). CAS is using ActiveDirectory to authenticate users. Sometime (We cannot identify when and how) user throw back to login page after doing login. Could not get idea what is the problem with idp ?

We have figured out this happen when user is using Satellite Broadband connection on their machine. We are not sure whether this can be a problem or not .

I have captured snippet of failure log as below.

-- Failure Log

11:07:32.311 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserAuthServlet:125] - Remote user identified as TestingUser returning control back to authentication engine
11:07:32.311 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:157] - Returning control to authentication engine
11:07:32.311 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:349] - Looking up LoginContext with key 2215c4f574fa6ba99469bf3128bf2e2f77c0c5a540eb41b835527bba5ba320cf from StorageService parition: loginContexts
11:07:32.312 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:355] - Retrieved LoginContext with key 2215c4f574fa6ba99469bf3128bf2e2f77c0c5a540eb41b835527bba5ba320cf from StorageService parition: loginContexts
11:07:32.312 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:241] - Processing incoming request
11:07:32.312 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:349] - Looking up LoginContext with key 2215c4f574fa6ba99469bf3128bf2e2f77c0c5a540eb41b835527bba5ba320cf from StorageService parition: loginContexts
11:07:32.312 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:355] - Retrieved LoginContext with key 2215c4f574fa6ba99469bf3128bf2e2f77c0c5a540eb41b835527bba5ba320cf from StorageService parition: loginContexts
11:07:32.312 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:600] - Completing user authentication process
11:07:32.312 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:677] - Validating authentication was performed successfully
11:07:32.313 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:799] - Updating session information for principal TestingUser
11:07:32.313 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:804] - Creating shibboleth session for principal TestingUser
11:07:32.313 - TRACE [org.springframework.web.context.support.XmlWebApplicationContext:272] - Publishing event in context [org.springframework.web.context.support.XmlWebApplicationContext@72132192]: edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService$AddEntryEvent[source=edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService@5cc6692e]
11:07:32.313 - TRACE [edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerImpl:62] - Created session 84b928c71920c195633dcc5d8d023aa4ac204fa7ada67e4bed788cb8f2c1e82c
11:07:32.313 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:931] - Adding IdP session cookie to HTTP response
11:07:32.314 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:819] - Recording authentication and service information in Shibboleth session for principal: TestingUser
11:07:32.314 - TRACE [org.springframework.web.context.support.XmlWebApplicationContext:272] - Publishing event in context [org.springframework.web.context.support.XmlWebApplicationContext@72132192]: edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService$AddEntryEvent[source=edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService@5cc6692e]
11:07:32.314 - TRACE [edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerImpl:151] - Added index TestingUser to session 84b928c71920c195633dcc5d8d023aa4ac204fa7ada67e4bed788cb8f2c1e82c
11:07:32.314 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:650] - User TestingUser authenticated with method urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
11:07:32.314 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:180] - Returning control to profile handler
11:07:32.314 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:349] - Looking up LoginContext with key 2215c4f574fa6ba99469bf3128bf2e2f77c0c5a540eb41b835527bba5ba320cf from StorageService parition: loginContexts
11:07:32.315 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:355] - Retrieved LoginContext with key 2215c4f574fa6ba99469bf3128bf2e2f77c0c5a540eb41b835527bba5ba320cf from StorageService parition: loginContexts
11:07:32.315 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:197] - Redirecting user to profile handler at https://testdomain.com:443/idp/profile/SAML2/Redirect/SSO
11:07:33.028 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:88] - Attempting to retrieve IdP session cookie.
11:07:33.028 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:97] - Found IdP session cookie.
11:07:33.028 - INFO [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:114] -  cookieValue from additional logger MTc2LjIyNy4xNDAuMjUw|LQ==|ODRiOTI4YzcxOTIwYzE5NTYzM2RjYzVkOGQwMjNhYTRhYzIwNGZhN2FkYTY3ZTRiZWQ3ODhjYjhmMmMxZTgyYw==|xf7dZEXVgJrmQlWSIwWN/TS1k6Q=
11:07:33.028 - INFO [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:133] -  sessionIdBytes from additional logger [B@4ade47d0
11:07:33.028 - INFO [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:141] -  sessionId from additional logger 84b928c71920c195633dcc5d8d023aa4ac204fa7ada67e4bed788cb8f2c1e82c
11:07:33.030 - INFO [edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerImpl:123] -  session is expired and returning back
11:07:33.030 - TRACE [org.springframework.web.context.support.XmlWebApplicationContext:272] - Publishing event in context [org.springframework.web.context.support.XmlWebApplicationContext@72132192]: edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService$RemoveEntryEvent[source=edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService@5cc6692e]
11:07:33.030 - TRACE [org.springframework.web.context.support.XmlWebApplicationContext:272] - Publishing event in context [org.springframework.web.context.support.XmlWebApplicationContext@72132192]: edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService$RemoveEntryEvent[source=edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService@5cc6692e]
11:07:33.030 - TRACE [org.springframework.web.context.support.XmlWebApplicationContext:272] - Publishing event in context [org.springframework.web.context.support.XmlWebApplicationContext@72132192]: edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService$RemoveEntryEvent[source=edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService@5cc6692e]
11:07:33.030 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:153] - No session associated with session ID 84b928c71920c195633dcc5d8d023aa4ac204fa7ada67e4bed788cb8f2c1e82c - session must have timed out
11:07:33.030 - INFO [Shibboleth-Access:59] - 20160217T110733Z|176.227.140.250|testdomain.com:443|/profile/SAML2/Redirect/SSO|
11:07:33.031 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO
11:07:33.031 - 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
11:07:33.031 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:349] - Looking up LoginContext with key 2215c4f574fa6ba99469bf3128bf2e2f77c0c5a540eb41b835527bba5ba320cf from StorageService parition: loginContexts
11:07:33.031 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:355] - Retrieved LoginContext with key 2215c4f574fa6ba99469bf3128bf2e2f77c0c5a540eb41b835527bba5ba320cf from StorageService parition: loginContexts
11:07:33.031 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:588] - Unbinding LoginContext
11:07:33.031 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:614] - Expiring LoginContext cookie
11:07:33.032 - TRACE [org.springframework.web.context.support.XmlWebApplicationContext:272] - Publishing event in context [org.springframework.web.context.support.XmlWebApplicationContext@72132192]: edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService$RemoveEntryEvent[source=edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService@5cc6692e]
11:07:33.032 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:625] - Removed LoginContext, with key 2215c4f574fa6ba99469bf3128bf2e2f77c0c5a540eb41b835527bba5ba320cf, from StorageService partition loginContexts
11:07:33.032 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:174] - Incoming request contains a login context and indicates principal was authenticated, processing second leg of request

I have captured snippet of success log as below.

11:04:34.392 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.RemoteUserAuthServlet:125] - Remote user identified as TestingUser1 returning control back to authentication engine
11:04:34.392 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:157] - Returning control to authentication engine
11:04:34.393 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:349] - Looking up LoginContext with key 1a988e4ce92e9c8b3d58c1a05322fb005f350915957c86e46f94c3adc46fa592 from StorageService parition: loginContexts
11:04:34.393 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:355] - Retrieved LoginContext with key 1a988e4ce92e9c8b3d58c1a05322fb005f350915957c86e46f94c3adc46fa592 from StorageService parition: loginContexts
11:04:34.393 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:241] - Processing incoming request
11:04:34.393 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:349] - Looking up LoginContext with key 1a988e4ce92e9c8b3d58c1a05322fb005f350915957c86e46f94c3adc46fa592 from StorageService parition: loginContexts
11:04:34.393 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:355] - Retrieved LoginContext with key 1a988e4ce92e9c8b3d58c1a05322fb005f350915957c86e46f94c3adc46fa592 from StorageService parition: loginContexts
11:04:34.393 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:600] - Completing user authentication process
11:04:34.394 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:677] - Validating authentication was performed successfully
11:04:34.394 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:799] - Updating session information for principal TestingUser1
11:04:34.394 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:804] - Creating shibboleth session for principal TestingUser1
11:04:34.394 - TRACE [org.springframework.web.context.support.XmlWebApplicationContext:272] - Publishing event in context [org.springframework.web.context.support.XmlWebApplicationContext@72132192]: edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService$AddEntryEvent[source=edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService@5cc6692e]
11:04:34.394 - TRACE [edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerImpl:62] - Created session 2c129aaaee0c7302670125f189d37c02eb2407a2a0e63a4cf91463b4366d821a
11:04:34.395 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:931] - Adding IdP session cookie to HTTP response
11:04:34.395 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:819] - Recording authentication and service information in Shibboleth session for principal: TestingUser1
11:04:34.395 - TRACE [org.springframework.web.context.support.XmlWebApplicationContext:272] - Publishing event in context [org.springframework.web.context.support.XmlWebApplicationContext@72132192]: edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService$AddEntryEvent[source=edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService@5cc6692e]
11:04:34.395 - TRACE [edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerImpl:151] - Added index TestingUser1 to session 2c129aaaee0c7302670125f189d37c02eb2407a2a0e63a4cf91463b4366d821a
11:04:34.395 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:650] - User TestingUser1 authenticated with method urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
11:04:34.395 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:180] - Returning control to profile handler
11:04:34.396 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:349] - Looking up LoginContext with key 1a988e4ce92e9c8b3d58c1a05322fb005f350915957c86e46f94c3adc46fa592 from StorageService parition: loginContexts
11:04:34.396 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:355] - Retrieved LoginContext with key 1a988e4ce92e9c8b3d58c1a05322fb005f350915957c86e46f94c3adc46fa592 from StorageService parition: loginContexts
11:04:34.396 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:197] - Redirecting user to profile handler at https://testdomain.com:443/idp/profile/SAML2/Redirect/SSO
11:04:34.444 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:88] - Attempting to retrieve IdP session cookie.
11:04:34.444 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:97] - Found IdP session cookie.
11:04:34.445 - INFO [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:114] -  cookieValue from additional logger ODEuMTQ5LjEyMC4zOA==|LQ==|MmMxMjlhYWFlZTBjNzMwMjY3MDEyNWYxODlkMzdjMDJlYjI0MDdhMmEwZTYzYTRjZjkxNDYzYjQzNjZkODIxYQ==|nwzVsL1FgukFsOXRVAYLf1CYw8U=
11:04:34.445 - INFO [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:133] -  sessionIdBytes from additional logger [B@53485c4f
11:04:34.445 - INFO [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:141] -  sessionId from additional logger 2c129aaaee0c7302670125f189d37c02eb2407a2a0e63a4cf91463b4366d821a
11:04:34.445 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:53] - Updating IdP session activity time and adding session object to the request
11:04:34.445 - INFO [Shibboleth-Access:59] - 20160217T110434Z|81.149.120.38|testdomain.com:443|/profile/SAML2/Redirect/SSO|
11:04:34.446 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO
11:04:34.446 - 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
11:04:34.446 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:349] - Looking up LoginContext with key 1a988e4ce92e9c8b3d58c1a05322fb005f350915957c86e46f94c3adc46fa592 from StorageService parition: loginContexts
11:04:34.446 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:355] - Retrieved LoginContext with key 1a988e4ce92e9c8b3d58c1a05322fb005f350915957c86e46f94c3adc46fa592 from StorageService parition: loginContexts
11:04:34.447 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:588] - Unbinding LoginContext
11:04:34.447 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:614] - Expiring LoginContext cookie
11:04:34.448 - TRACE [org.springframework.web.context.support.XmlWebApplicationContext:272] - Publishing event in context [org.springframework.web.context.support.XmlWebApplicationContext@72132192]: edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService$RemoveEntryEvent[source=edu.internet2.middleware.shibboleth.common.util.EventingMapBasedStorageService@5cc6692e]
11:04:34.448 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:625] - Removed LoginContext, with key 1a988e4ce92e9c8b3d58c1a05322fb005f350915957c86e46f94c3adc46fa592, from StorageService partition loginContexts
11:04:34.448 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:174] - Incoming request contains a login context and indicates principal was authenticated, processing second leg of request
11:04:34.448 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:253] - Checking child metadata provider for entity descriptor with entity ID: https://testdomain.portal.com/shibboleth
11:04:34.448 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:520] - Searching for entity descriptor with an entity ID of https://testdomain.portal.com/shibboleth
11:04:34.448 - TRACE [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:533] - Metadata root is an entity descriptor, checking if it's the one we're looking for.


I would be really grateful for any thoughts.

Thanks in advance,