Confirmation of issue with invalid TGT

[Pablo Vidaurri]

We are running into a strange issue where login sometimes does not work. The TGT is created, and 40ms later the ticket is determined to be invalid so the TGT gets destroyed. 

We are using JPA against a postgres db. Is this just not fast enough to persist the ticket?

Bumping up log level for org.apereo.cas.web.flow package reveals the following:

08:13:25,645 INFO  [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] (default task-3363) Audit trail record BEGIN
=============================================================
WHO: xx...@xxxxx.com
WHAT: TGT-8132-5BH4unLipbzoIApkH8R27D6atlA6-6uoT-TKG3wFbuvXrx9Poc6jyh5RkxKBqt2lHck
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Wed Sep 14 08:13:25 MST 2022
CLIENT IP ADDRESS: xx.xx.xx.xx
SERVER IP ADDRESS: www.xxxxxx.com
=============================================================


08:13:25,683 DEBUG [org.apereo.cas.web.flow.GenerateServiceTicketAction] (default task-3363) Ticket-granting ticket found in the context is [TGT-8132-5BH4unLipbzoIApkH8R27D6atlA6-6uoT-TKG3wFbuvXrx9Poc6jyh5RkxKBqt2lHck]
08:13:25,685 DEBUG [org.apereo.cas.web.flow.GenerateServiceTicketAction] (default task-3363) CAS has determined ticket-granting ticket [TGT-8132-5BH4unLipbzoIApkH8R27D6atlA6-6uoT-TKG3wFbuvXrx9Poc6jyh5RkxKBqt2lHck] is invalid and must be destroyed
08:13:25,686 INFO  [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] (default task-3363) Audit trail record BEGIN
=============================================================
WHO: xx...@xxxxx.com
WHAT: TGT-8132-5BH4unLipbzoIApkH8R27D6atlA6-6uoT-TKG3wFbuvXrx9Poc6jyh5RkxKBqt2lHck
ACTION: TICKET_DESTROYED
APPLICATION: CAS
WHEN: Wed Sep 14 08:13:25 MST 2022
CLIENT IP ADDRESS: xx.xx.xx.xx
SERVER IP ADDRESS: www.xxxxxx.com
=============================================================

[Ray Bon]

Pablo,

If it works with the default in memory store, try turning up the logging JPA/hibernate related classes.

Can you view the ticket in postgres or see postgres logs?

Ray

On Wed, 2022-09-14 at 08:29 -0700, Pablo Vidaurri wrote:

Notice: This message was sent from outside the University of Victoria email system. Please be cautious with links and sensitive information.

[Pablo Vidaurri]

I enabled JPA logging.

I do see a message that it is creating the ticket.

   [org.apereo.cas.ticket.registry.JpaTicketRegistry] Added ticket [xxx] to registry.

30ms later I see a message that the ticket is being destroyed:

   [org.apereo.cas.web.flow.login.SendTicketGrantingTicketAction] (default task-6) Setting ticket-granting cookie for current session linked to [xxx].

   [org.apereo.cas.web.flow.GenerateServiceTicketAction] (default task-6) Ticket-granting ticket found in the context is [xxx]

   [org.apereo.cas.ticket.registry.JpaTicketRegistry] (default task-6) No record could be found for ticket

   [org.apereo.cas.web.flow.GenerateServiceTicketAction] (default task-6) CAS has determined ticket-granting ticket [xxx] is invalid and must be destroyed

   [org.apereo.cas.ticket.registry.JpaTicketRegistry] (default task-6) No record could be found for ticket [xxx]
   [org.apereo.cas.ticket.registry.AbstractTicketRegistry] (default task-6) Ticket [xxx] could not be fetched from the registry; it may have been expired and deleted.

Even though it logs "must be destroyed", it does not appear that this is actually removing from db because I still see the TGT in the table.

Looks like 30ms is too fast to query for a ticket after it has been added. Is there a retry or delay config that can be added? Doesn't happen often but often enough to cause a bad user experience.

-psv