CAS SSO login issue with cluster environment

32 views
Skip to first unread message

uvaraj s

unread,
Sep 25, 2018, 2:52:20 PM9/25/18
to CAS Community
Hi CAS Users,

We are using CAS 4.1.2 which is running on the cluster environment( One My SQL DB-> connecting Two CAS tomcat application under 1 Application LB) and we do not have any cache implemented.

intermittently when the user tries to login the user are redirected to Login page itself. Below are the logs from Tomcat server 1 and server 2

In the server 1 log, we can see that the ticket is getting removed before the validation happens from the server 2. 

Is there any way to increase the time and not to remove the ticket so that the validate from server 2 goes through without any issue?.

Logs From Server 1:

2018-09-25 16:06:58,320 INFO [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated suvara...@gmail.com with credentials [suvara...@gmail.com+password].>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - <Attribute map for suvara...@gmail.com: {}>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - <Attribute map for suvara...@gmail.com: {}>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving argument [UsernamePasswordCredential] for audit>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving argument [UsernamePasswordCredential] for audit>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.services.DefaultRegisteredServiceAccessStrategy] - <No required attributes are specified>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.services.DefaultRegisteredServiceAccessStrategy] - <No required attributes are specified>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - <Looking up service ticket id generator for [org.jasig.cas.authentication.principal.SimpleWebApplicationServiceImpl]>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - <Looking up service ticket id generator for [org.jasig.cas.authentication.principal.SimpleWebApplicationServiceImpl]>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.ticket.registry.JpaTicketRegistry] - <Updated ticket [TGT-*************************************************QgFzfra49f-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org].>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.ticket.registry.JpaTicketRegistry] - <Updated ticket [TGT-*************************************************QgFzfra49f-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org].>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.ticket.registry.JpaTicketRegistry] - <Added ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] to registry.>
2018-09-25 16:06:58,320 DEBUG [org.jasig.cas.ticket.registry.JpaTicketRegistry] - <Added ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] to registry.>
2018-09-25 16:06:58,320 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - <Granted ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] for service [https://client.mysite.org/sso] for user [suvara...@gmail.com]>
2018-09-25 16:06:58,320 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - <Granted ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] for service [https://client.mysite.org/sso] for user [suvara...@gmail.com]>
2018-09-25 16:06:58,321 DEBUG [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving argument [String] for audit>
2018-09-25 16:06:58,321 DEBUG [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving argument [String] for audit>
2018-09-25 16:07:02,813 DEBUG [org.jasig.cas.util.DefaultCipherExecutor] - <Signature successfully verified. Payload is [eyJhbGciOiJkaXIiLCJlbmMiOiJBMTI4Q0JDLUhTMjU2In0..KveWSLApp_52lPeufW-v-Q.vtzIu7ie14v4e0Mwfzapa19bva_ypdpFFiuOwHCqEu7crVODHVvPgjwkhsCUQpE620fJLn1zoOrZMJk14DL3o4vaolJRS7Ifkj1h7YGm0I9-rVjZhkH4sGSqrumG_55-28Wszh1Es6_M13MiGnZEFzGEM7CsTwpGDRyxFojKOSP0SCPJqW0bv6q073028S4I5SEnGERh-_VLhslafvYOt6QVtFAEGA2QtrDQ52Qivx4Hip1o_LXv3z_vTz0kyiS3-qlKJW6ZX1ozwYwjDDYjZkWTnvCJjW_uBWlurPpRbdzeDheifR4RZHFlZtUlhbg0.GxNWmlX6ztLNuWmwrJis2A]>
2018-09-25 16:07:02,813 DEBUG [org.jasig.cas.util.DefaultCipherExecutor] - <Signature successfully verified. Payload is [eyJhbGciOiJkaXIiLCJlbmMiOiJBMTI4Q0JDLUhTMjU2In0..KveWSLApp_52lPeufW-v-Q.vtzIu7ie14v4e0Mwfzapa19bva_ypdpFFiuOwHCqEu7crVODHVvPgjwkhsCUQpE620fJLn1zoOrZMJk14DL3o4vaolJRS7Ifkj1h7YGm0I9-rVjZhkH4sGSqrumG_55-28Wszh1Es6_M13MiGnZEFzGEM7CsTwpGDRyxFojKOSP0SCPJqW0bv6q073028S4I5SEnGERh-_VLhslafvYOt6QVtFAEGA2QtrDQ52Qivx4Hip1o_LXv3z_vTz0kyiS3-qlKJW6ZX1ozwYwjDDYjZkWTnvCJjW_uBWlurPpRbdzeDheifR4RZHFlZtUlhbg0.GxNWmlX6ztLNuWmwrJis2A]>
2018-09-25 16:07:02,813 DEBUG [org.jasig.cas.util.DefaultCipherExecutor] - <Decrypting value...>
2018-09-25 16:07:02,813 DEBUG [org.jasig.cas.util.DefaultCipherExecutor] - <Decrypting value...>
2018-09-25 16:07:02,813 DEBUG [org.jasig.cas.web.support.DefaultCasCookieValueManager] - <Decoded cookie value is [TGT-*************************************************QgFzfra49f-cas-tomcat-prod-app...@127.0.0.1@Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.22 Safari/537.36]>
2018-09-25 16:07:02,813 DEBUG [org.jasig.cas.web.support.DefaultCasCookieValueManager] - <Decoded cookie value is [TGT-*************************************************QgFzfra49f-cas-tomcat-prod-app...@127.0.0.1@Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.22 Safari/537.36]>
2018-09-25 16:07:02,814 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - <Removing ticket [TGT-*************************************************QgFzfra49f-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] from registry...>
2018-09-25 16:07:02,814 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - <Removing ticket [TGT-*************************************************QgFzfra49f-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] from registry...>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - <Ticket found. Processing logout requests and then deleting the ticket...>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - <Ticket found. Processing logout requests and then deleting the ticket...>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] - <Logout request will be sent to [https://client.mysite.org/j_spring_security_logout] for service [https://client.mysite.org/sso]>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] - <Logout request will be sent to [https://client.mysite.org/j_spring_security_logout] for service [https://client.mysite.org/sso]>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.logout.SamlCompliantLogoutMessageCreator] - <Generated logout message: [<samlp:LogoutRequest xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol" ID="LR-6751-MzdYdO05Sfn1Cl7tlPfLcWdSa4Pok2xLpcR" Version="2.0" IssueInstant="2018-09-25T16:07:02Z"><saml:NameID xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">@NOT_USED@</saml:NameID><samlp:SessionIndex>ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org</samlp:SessionIndex></samlp:LogoutRequest>]>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.logout.SamlCompliantLogoutMessageCreator] - <Generated logout message: [<samlp:LogoutRequest xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol" ID="LR-6751-MzdYdO05Sfn1Cl7tlPfLcWdSa4Pok2xLpcR" Version="2.0" IssueInstant="2018-09-25T16:07:02Z"><saml:NameID xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">@NOT_USED@</saml:NameID><samlp:SessionIndex>ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org</samlp:SessionIndex></samlp:LogoutRequest>]>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] - <Sending logout request for: [https://client.mysite.org/sso]>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] - <Sending logout request for: [https://client.mysite.org/sso]>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] - <Prepared logout message to send is [org.jasig.cas.logout.LogoutManagerImpl$LogoutHttpMessage@1eead1c7[url=https://client.mysite.org/j_spring_security_logout,message=<samlp:LogoutRequest xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol" ID="LR-6751-MzdYdO05Sfn1Cl7tlPfLcWdSa4Pok2xLpcR" Version="2.0" IssueInstant="2018-09-25T16:07:02Z"><saml:NameID xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">@NOT_USED@</saml:NameID><samlp:SessionIndex>ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org</samlp:SessionIndex></samlp:LogoutRequest>,asynchronous=true,contentType=application/x-www-form-urlencoded]]>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] - <Prepared logout message to send is [org.jasig.cas.logout.LogoutManagerImpl$LogoutHttpMessage@1eead1c7[url=https://client.mysite.org/j_spring_security_logout,message=<samlp:LogoutRequest xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol" ID="LR-6751-MzdYdO05Sfn1Cl7tlPfLcWdSa4Pok2xLpcR" Version="2.0" IssueInstant="2018-09-25T16:07:02Z"><saml:NameID xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">@NOT_USED@</saml:NameID><samlp:SessionIndex>ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org</samlp:SessionIndex></samlp:LogoutRequest>,asynchronous=true,contentType=application/x-www-form-urlencoded]]>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] - <Captured logout request [org.jasig.cas.logout.DefaultLogoutRequest@1a7feb61[ticketId=ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org,service=https://client.mysite.org/sso,status=SUCCESS]]>
2018-09-25 16:07:02,818 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] - <Captured logout request [org.jasig.cas.logout.DefaultLogoutRequest@1a7feb61[ticketId=ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org,service=https://client.mysite.org/sso,status=SUCCESS]]>



Logs From Server 2

2018-09-25 16:07:12,665 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - <ServiceTicket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] has expired.>
2018-09-25 16:07:12,665 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - <ServiceTicket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] has expired.>
2018-09-25 16:07:12,665 DEBUG [org.jasig.cas.ticket.registry.JpaTicketRegistry] - <Removing Ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] created: Tue Sep 25 16:06:58 UTC 2018>
2018-09-25 16:07:12,665 DEBUG [org.jasig.cas.ticket.registry.JpaTicketRegistry] - <Removing Ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] created: Tue Sep 25 16:06:58 UTC 2018>
2018-09-25 16:07:12,665 DEBUG [org.jasig.cas.ticket.registry.JpaTicketRegistry] - <Deleted ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] from the registry.>
2018-09-25 16:07:12,665 DEBUG [org.jasig.cas.ticket.registry.JpaTicketRegistry] - <Deleted ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] from the registry.>
2018-09-25 16:07:12,665 DEBUG [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving argument [String] for audit>
2018-09-25 16:07:12,665 DEBUG [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving argument [String] for audit>
2018-09-25 16:07:12,665 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - <Ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] by type [Ticket] cannot be found in the ticket registry.>
2018-09-25 16:07:12,665 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - <Ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] by type [Ticket] cannot be found in the ticket registry.>
2018-09-25 16:07:12,666 DEBUG [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Could not locate ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] in the registry>
2018-09-25 16:07:12,666 DEBUG [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Could not locate ticket [ST-13449-gCFWnpSdkGe2Ll1HBvFo-cas-tomcat-prod-app-i-00e883b0f45ab9503.mysite.org] in the registry>

 

Ray Bon

unread,
Sep 25, 2018, 4:10:29 PM9/25/18
to cas-...@apereo.org
Uvaraj,


The time between ticket issue (16:06:58,320) and time of check on server 2 (16:07:12,665), more than 14 seconds, is an eternity in the digital realm.
Either there is a problem with the client application, a network issue or your servers clocks are not synchronized.
The default ST life is 10s. Before changing this, check other issues above.

Ray
-- 
Ray Bon
Programmer analyst
Development Services, University Systems
2507218831 | CLE 019 | rb...@uvic.ca
Reply all
Reply to author
Forward
0 new messages