CAS5 intermittent login loop

[Baron Fujimoto]

We're trying to troubleshoot an intermittent problem some of our users
have been reporting with CAS5 (RC4). The behavior being reported is that
that after providing their credentials at the login page, they are simply
returned to the login page again with no error. Unfortunately we have not
yet been able to reliably reproduce the problem.

It appears from the logs that the user may be attempting to access the app
with an invalid TGT. It's not clear to me how or where the TGT is being
"mishandled" though. I've pulled a couple of incidents from out logs:

#################
##### user1 #####
#################

User1 logs in and is issued a TGT

2016-11-29 09:25:27,647 INFO [org.apereo.cas.adaptors.duo.authn.web.DuoAuthenticationHandler] - <Successful Duo authentication for [user1]>
2016-11-29 09:25:27,647 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <DuoAuthenticationHandler successfully authenticated org.apereo.cas.adaptors.duo.authn.web.DuoCredential@10xxxxx8[username=user1,signedDuoResponse=AUTH|dGxx...xx]>
2016-11-29 09:25:27,663 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [TGT-***************************************************PwWjCaS35u-cas01] to registry.>

User1 logs in again later is issued a new TGT

2016-11-29 15:17:41,553 INFO [org.apereo.cas.adaptors.duo.authn.web.DuoAuthenticationHandler] - <Successful Duo authentication for [user1]>
2016-11-29 15:17:41,554 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <DuoAuthenticationHandler successfully authenticated org.apereo.cas.adaptors.duo.authn.web.DuoCredential@1cxxxxx9[username=user1,signedDuoResponse=AUTH|dGxx...xx]>
2016-11-29 15:17:41,570 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [TGT-***************************************************DbtsqgSBiQ-cas01] to registry.>

A ST is successfully granted and validated using that TGT

2016-11-29 15:17:41,585 INFO [org.apereo.cas.CentralAuthenticationServiceImpl] - <Granted ticket [ST-302853-XDJDK6Jgwx5MnntO5cPU-cas01] for service [https://www.hawaii.edu/casl2/login?service=https%3A%2F%2Ffoo.hawaii.edu%2Fkfs-prd%2Fportal.do&renew=true] and principal [user1]>
2016-11-29 15:17:41,585 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasServiceTicketGrantedEvent@30a6f889[ticketGrantingTicket=TGT-***************************************************DbtsqgSBiQ-cas01,serviceTicket=ST-302853-XDJxxxxxwx5MnntO5cPU-PwWjCaS35ucas01]>
2016-11-29 15:17:41,611 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasServiceTicketValidatedEvent@157c27ed[assertion=org.apereo.cas.authentication.DefaultAuthentication@99a0bcfc:https://www.hawaii.edu/casl2/login?service=https%3A%2F%2Ffoo.hawaii.edu%2Fkfs-prd%2Fportal.do&renew=true,serviceTicket=ST-302853-XDJDK6Jgwx5MnntO5cPU-cas01]>

A short while later, there's a different AuthN for the same app (LDAP vs
Duo?), but CAS fails to issue a ST

2016-11-29 15:33:24,106 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://www.hawaii.edu/casl2/login?service=https%3A%2F%2Ffoo.hawaii.edu%2Fkfs-prd%2Fportal.do%3FchannelTitle%3DAction%2520List%26channelUrl%3Dhttps%3A%2F%2Ffoo.hawaii.edu%2Fkfs-prd%2Fkew%2FActionList.do&renew=true based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@324cde8c>
2016-11-29 15:33:24,122 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler successfully authenticated user1>
2016-11-29 15:33:24,126 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@1d736a2 and service https://www.hawaii.edu/casl2/login?service=https%3A%2F%2Ffoo.hawaii.edu%2Fkfs-prd%2Fportal.do%3FchannelTitle%3DAction%2520List%26channelUrl%3Dhttps%3A%2F%2Ffoo.hawaii.edu%2Fkfs-prd%2Fkew%2FActionList.do&renew=true>
2016-11-29 15:33:24,126 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Ticket [TGT-***************************************************PwWjCaS35u-cas01] by type [TicketGrantingTicket] cannot be found in the ticket registry.>

Note that it is attempting to use the old TGT. I can't find evidence in
the logs that the old PwWjCaS35u-cas01 ticket was removed. I think it is
at this point that the user is returned to the login screen again. I find
this general sequence of events repeated in the logs. Service tickets are
not issued, and always correlated with the DEBUG that the
"TGT-***PwWjCaS35u-cas01] by type [TicketGrantingTicket] cannot be found".

#################
##### user2 #####
#################

User2 logs in and is issues a TGT

2016-11-29 14:50:49,891 INFO [org.apereo.cas.adaptors.duo.authn.web.DuoAuthenticationHandler] - <Successful Duo authentication for [user2]>
2016-11-29 14:50:49,891 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <DuoAuthenticationHandler successfully authenticated org.apereo.cas.adaptors.duo.authn.web.DuoCredential@7b0b2d05[username=user2,signedDuoResponse=AUTH|dGxx...xx]>
2016-11-29 14:50:49,909 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [TGT-***************************************************10Ro5btR3h-cas01] to registry.>

Later, user2's TGT expires

2016-11-29 16:50:57,777 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Cleaning up expired ticket-granting ticket [TGT-***************************************************10Ro5btR3h-cas01]>
2016-11-29 16:50:57,777 INFO [org.apereo.cas.logout.LogoutManagerImpl] - <Performing logout operations for [TGT-***************************************************10Ro5btR3h-cas01]>
2016-11-29 16:50:57,779 INFO [org.apereo.cas.logout.LogoutManagerImpl] - <There are no proxy-granting tickets associated with [TGT-***************************************************10Ro5btR3h-cas01] to process for single logout>
2016-11-29 16:50:57,779 INFO [org.apereo.cas.logout.LogoutManagerImpl] - <1 logout requests were processed>
2016-11-29 16:50:57,779 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Removing children of ticket [TGT-***************************************************10Ro5btR3h-cas01] from the registry.>
2016-11-29 16:50:57,779 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Removing ticket [TGT-***************************************************10Ro5btR3h-cas01] from the registry.>

The following day, user2 attempt to access a different app, again this
time via LDAP and not Duo?

2016-11-30 06:19:09,954 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://bar.hawaii.edu/support/login/verify.php based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@324cde8c>
2016-11-30 06:19:09,978 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler successfully authenticated user2>

I can't find evidence in the logs that a new TGT is issued to user2. CAS
fails to issue a ST

2016-11-30 06:19:09,982 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@e8xxxxxe and service https://bar.hawaii.edu/support/login/verify.php>
2016-11-30 06:19:09,982 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Ticket [TGT-***************************************************10Ro5btR3h-cas01] by type [TicketGrantingTicket] cannot be found in the ticket registry.>

Again I note that it's trying to use the expired TGT. At this point user2
is returned to the the login screen and the cycle repeats.

Are we even on the the right track focusing on the TGTs?

The only thing we do know for sure is that if the users open a new
icognito/private browser window, the login process works reliably as
expected.

User1 reports that clearing her cache does not help, and that switching
tabs can prevent the loop. However, user2 reports that the problem seems
more prevalent when using different tabs. I'm not sure we have enough of
a sample size to make any definitive judgements about this. FWIW, I think
user1 is using Firefox on Windows for her browser, and user2 is using
Safari on MacOS.

Any suggestions or insight into these problems would be greatly
appreciated.

Aloha,
-baron
--
Baron Fujimoto <ba...@hawaii.edu> :: UH Information Technology Services
minutas cantorum, minutas balorum, minutas carboratum desendus pantorum

[Baron Fujimoto]

In case anyone else encounters this or for future reference, we were
able to isolate and replicate the problem, and it's now being tracked
here: <https://github.com/apereo/cas/issues/2209>