CAS 4.2.2 jpaTicketRegistry Issues

Tom O'Neill

unread,

Jun 27, 2016, 3:05:19 PM6/27/16

to cas-...@apereo.org

Hi All,

Hopefully I’m just missing something simple…I appreciate any and all insight.

I’ve worked on 3.5.x extensively and 4.0.x briefly but 4.2.2 is giving me some trouble.

I am working on a 4.2.2 CAS build using the Maven overlay method and I’d like to use LDAP and JPA support.

I added LDAP support, JPA Ticket Registry support and MySQL 5.1.39 to my pom.xml:

<groupId>org.jasig.cas</groupId>

<artifactId>cas-server-webapp</artifactId>

<version>${cas.version}</version>

<scope>runtime</scope>

</dependency>

<groupId>org.jasig.cas</groupId>

<artifactId>cas-server-support-ldap</artifactId>

<version>${cas.version}</version>

</dependency>

<groupId>org.jasig.cas</groupId>

<artifactId>cas-server-support-jpa-ticket-registry</artifactId>

<version>${cas.version}</version>

</dependency>

<groupId>mysql</groupId>

<artifactId>mysql-connector-java</artifactId>

</dependency>

</dependencies>

After getting LDAP working with the default ticket registry, I then updated src/main/webapp/WEB-INF/deployerConfigContext.xml as follows:

I also added the ticket registry database properties to my cas.properties file.

I am using a 5.7 MySQL InnoDB so I have the following dialect set:

org.hibernate.dialect.MySQL5InnoDBDialect

After authentication succeeds I see hibernate indicate that it is going to attempt an insert into the ticketgrantingticket table but the insert never seems to complete.

2016-06-27 13:34:51,614 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] - <begin>

2016-06-27 13:34:51,623 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] - <Generated identifier: TGT-1-1Pzdcw6T0gSjt4SQwa2q5CgI2x373ayd72CHMcjK2wfet0bAv2-auth1test, using strategy: org.hibernate.id.Assigned>

2016-06-27 13:34:51,715 INFO [org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN

=============================================================

WHO: audit:unknown

WHAT: TGT-**********************************************2wfet0bAv2-auth1test

ACTION: TICKET_GRANTING_TICKET_CREATED

APPLICATION: CAS

WHEN: Mon Jun 27 13:34:51 CDT 2016

CLIENT IP ADDRESS: 10.213.88.21

SERVER IP ADDRESS: 10.186.86.6

=============================================================

>

2016-06-27 13:34:51,716 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] - <committing>

2016-06-27 13:34:51,716 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] - <Processing flush-time cascades>

2016-06-27 13:34:51,717 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] - <Dirty checking collections>

2016-06-27 13:34:51,723 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] - <Flushed: 1 insertions, 0 updates, 0 deletions to 1 objects>

2016-06-27 13:34:51,723 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] - <Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections>

2016-06-27 13:34:51,723 DEBUG [org.hibernate.internal.util.EntityPrinter] - <Listing entities:>

2016-06-27 13:34:51,724 DEBUG [org.hibernate.internal.util.EntityPrinter] - <org.jasig.cas.ticket.TicketGrantingTicketImpl{lastTimeUsed=1467052491621, previousLastTimeUsed=0, proxiedBy=null, supplementalAuthentications=[], expired=false, creationTime=1467052491621, countOfUses=0, id=TGT-1-1Pzdcw6T0gSjt4SQwa2q5CgI2x373ayd72CHMcjK2wfet0bAv2-auth1test, expirationPolicy=org.jasig.cas.ticket.support.TicketGrantingTicketExpirationPolicy@42f8ab07, services={}, ticketGrantingTicket=null, authentication=org.jasig.cas.authentication.ImmutableAuthentication@c0763239}>

Hibernate: insert into TICKETGRANTINGTICKET (NUMBER_OF_TIMES_USED, CREATION_TIME, EXPIRATION_POLICY, LAST_TIME_USED, PREVIOUS_LAST_TIME_USED, ticketGrantingTicket_ID, AUTHENTICATION, EXPIRED, PROXIED_BY, SERVICES_GRANTED_ACCESS_TO, SUPPLEMENTAL_AUTHENTICATIONS, TYPE, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 'TGT', ?)

2016-06-27 13:34:51,730 DEBUG [org.hibernate.SQL] - <insert into TICKETGRANTINGTICKET (NUMBER_OF_TIMES_USED, CREATION_TIME, EXPIRATION_POLICY, LAST_TIME_USED, PREVIOUS_LAST_TIME_USED, ticketGrantingTicket_ID, AUTHENTICATION, EXPIRED, PROXIED_BY, SERVICES_GRANTED_ACCESS_TO, SUPPLEMENTAL_AUTHENTICATIONS, TYPE, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 'TGT', ?)>

2016-06-27 13:35:01,612 DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] - <Refurbishing idle resources - Mon Jun 27 13:35:01 CDT 2016 [com.mchange.v2.resourcepool.BasicResourcePool@156eeecf]>

2016-06-27 13:35:01,612 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@7eb9ca3c] on IDLE CHECK.>

2016-06-27 13:35:01,613 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@b2132c4] on IDLE CHECK.>

2016-06-27 13:35:01,613 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@3ee0eb3d] on IDLE CHECK.>

2016-06-27 13:35:01,616 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@b2132c4] on IDLE CHECK has SUCCEEDED.>

2016-06-27 13:35:01,616 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@cd8fa76] on IDLE CHECK.>

2016-06-27 13:35:01,616 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@3ee0eb3d] on IDLE CHECK has SUCCEEDED.>

2016-06-27 13:35:01,616 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@54b032c8] on IDLE CHECK.>

2016-06-27 13:35:01,616 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@7eb9ca3c] on IDLE CHECK has SUCCEEDED.>

2016-06-27 13:35:01,617 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@cd8fa76] on IDLE CHECK has SUCCEEDED.>

2016-06-27 13:35:01,617 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@54b032c8] on IDLE CHECK has SUCCEEDED.>

Thanks,

Tom O’Neill

Misagh Moayyed

unread,

Jun 27, 2016, 5:30:34 PM6/27/16

to cas-...@apereo.org

Point your overlay to 4.2.4-SNAPSHOT and try again please. (make sure you force an update with –U)

--
You received this message because you are subscribed to the Google Groups "CAS Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
To post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/BY1PR0201MB099948E01CE07680743753A6CB210%40BY1PR0201MB0999.namprd02.prod.outlook.com.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.

Tom O'Neill

unread,

Jun 28, 2016, 8:38:07 AM6/28/16

to Misagh Moayyed, cas-...@apereo.org

Misagh,

Thank you for the quick response!

I gave that a shot but unfortunately I am still seeing the same behavior.

I simplified the configuration by reverting to the baseline 4.2.4-SNAPSHOT deployerConfigContext.xml with a single modification:

After a successful authentication the application appears to hang and the following INSERT into the TGT table never completes.

I increased the logging level on the MySQL database and reviewed the transactions. Interestingly, I don’t see the INSERT in the MySQL logs.

2016-06-28 07:28:32,519 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] - <begin>

2016-06-28 07:28:32,576 DEBUG [org.hibernate.event.internal.AbstractSaveEventListener] - <Generated identifier: TGT-1-m3uVAIDLCrNx3kALGEi1tCoEeB0P2JwGOfFpw43oLEgfKyhb6h-cas01.example.org, using strategy: org.hibernate.id.Assigned>

2016-06-28 07:28:32,674 INFO [org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN

=============================================================

WHO: audit:unknown

WHAT: TGT-**********************************************LEgfKyhb6h-cas01.example.org

ACTION: TICKET_GRANTING_TICKET_CREATED

APPLICATION: CAS

WHEN: Tue Jun 28 07:28:32 CDT 2016

CLIENT IP ADDRESS: 10.213.88.36

SERVER IP ADDRESS: 10.186.86.6

=============================================================

>

2016-06-28 07:28:32,675 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] - <committing>

2016-06-28 07:28:32,676 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] - <Processing flush-time cascades>

2016-06-28 07:28:32,677 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] - <Dirty checking collections>

2016-06-28 07:28:32,685 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] - <Flushed: 1 insertions, 0 updates, 0 deletions to 1 objects>

2016-06-28 07:28:32,685 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] - <Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections>

2016-06-28 07:28:32,688 DEBUG [org.hibernate.internal.util.EntityPrinter] - <Listing entities:>

2016-06-28 07:28:32,689 DEBUG [org.hibernate.internal.util.EntityPrinter] - <org.jasig.cas.ticket.TicketGrantingTicketImpl{lastTimeUsed=1467116912575, previousLastTimeUsed=0, proxiedBy=null, supplementalAuthentications=[], expired=false, creationTime=1467116912575, countOfUses=0, id=TGT-1-m3uVAIDLCrNx3kALGEi1tCoEeB0P2JwGOfFpw43oLEgfKyhb6h-cas01.example.org, expirationPolicy=org.jasig.cas.ticket.support.TicketGrantingTicketExpirationPolicy@60ea79d1, services={}, ticketGrantingTicket=null, authentication=org.jasig.cas.authentication.ImmutableAuthentication@cf5621ae}>

Hibernate: insert into TICKETGRANTINGTICKET (NUMBER_OF_TIMES_USED, CREATION_TIME, EXPIRATION_POLICY, LAST_TIME_USED, PREVIOUS_LAST_TIME_USED, ticketGrantingTicket_ID, AUTHENTICATION, EXPIRED, PROXIED_BY, SERVICES_GRANTED_ACCESS_TO, SUPPLEMENTAL_AUTHENTICATIONS, TYPE, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 'TGT', ?)

2016-06-28 07:28:32,726 DEBUG [org.hibernate.SQL] - <insert into TICKETGRANTINGTICKET (NUMBER_OF_TIMES_USED, CREATION_TIME, EXPIRATION_POLICY, LAST_TIME_USED, PREVIOUS_LAST_TIME_USED, ticketGrantingTicket_ID, AUTHENTICATION, EXPIRED, PROXIED_BY, SERVICES_GRANTED_ACCESS_TO, SUPPLEMENTAL_AUTHENTICATIONS, TYPE, ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 'TGT', ?)>

2016-06-28 07:28:45,129 DEBUG [org.quartz.core.QuartzSchedulerThread] - <batch acquisition of 1 triggers>

2016-06-28 07:28:50,464 DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] - <Refurbishing idle resources - Tue Jun 28 07:28:50 CDT 2016 [com.mchange.v2.resourcepool.BasicResourcePool@4673a74]>

2016-06-28 07:28:50,465 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@8dcec67] on IDLE CHECK.>

2016-06-28 07:28:50,465 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@378e94cf] on IDLE CHECK.>

2016-06-28 07:28:50,465 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@100f9122] on IDLE CHECK.>

2016-06-28 07:28:50,467 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@100f9122] on IDLE CHECK has SUCCEEDED.>

2016-06-28 07:28:50,467 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@20182d8a] on IDLE CHECK.>

2016-06-28 07:28:50,468 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@8dcec67] on IDLE CHECK has SUCCEEDED.>

2016-06-28 07:28:50,468 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@30391200] on IDLE CHECK.>

2016-06-28 07:28:50,469 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@20182d8a] on IDLE CHECK has SUCCEEDED.>

2016-06-28 07:28:50,469 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@30391200] on IDLE CHECK has SUCCEEDED.>

2016-06-28 07:28:50,471 DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] - <Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@378e94cf] on IDLE CHECK has SUCCEEDED.>

2016-06-28 07:29:09,730 DEBUG [org.quartz.core.QuartzSchedulerThread] - <batch acquisition of 0 triggers>

2016-06-28 07:29:09,730 DEBUG [org.quartz.core.JobRunShell] - <Calling execute on job DEFAULT.DefaultServicesManagerImpl361f5f80-a0ee-4777-bbc6-070165fd23d7>

2016-06-28 07:29:09,730 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - <Reloading registered services.>

2016-06-28 07:29:09,735 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from JsonServiceRegistryDao.>

I’m starting to wonder if the issue could be the MySQL release. We are running 5.7 but using the MySQL 5.7 InnoDB dialect for hibernate resulted in an exception during table creation.

The database initializes correctly using the MySQL 5 InnoDB dialect and the health check seems to work but obviously the INSERT isn’t working.

Thanks,

Tom O’Neill

To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/002901d1d0bb%241e69ffa0%245b3dfee0%24%40unicon.net.

Misagh Moayyed

unread,

Jun 28, 2016, 9:23:30 AM6/28/16

to cas-...@apereo.org

Well, unless you can produce logs to explain what’s going on I am inclined to blame MYSQL too. Turn up DEBUG logs for org.springframework.orm.jpa and org.springframework.transaction. See if you can spot anomalies.

If you want to post your overlay to the issues project so we can duplicate it, that’s fine too.

To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/BY1PR0201MB099973FCFB22CE324D1AB33DCB220%40BY1PR0201MB0999.namprd02.prod.outlook.com.

Tom O'Neill

unread,

Jun 28, 2016, 9:40:47 AM6/28/16

to cas-...@apereo.org

Misagh,

I think that sounds like a reasonable approach and I will try increasing logging for those packages specifically.

I had hibernate set to DEBUG but the current output isn’t providing any clues at this point.

If I don’t find anything solid I will swap out the MySQL versions to see if that makes a difference.

I appreciate the insight and feedback.

Thanks!

Tom O’Neill

Senior Consultant

Strata Information Group

one...@sigcorp.com

Mobile : (401) 644-4847

Corporate : (619) 296-0170

To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/00f601d1d140%243daa5420%24b8fefc60%24%40unicon.net.

Tom O'Neill

unread,

Jul 7, 2016, 9:55:33 AM7/7/16

to cas-...@apereo.org

Hi All,

After swapping out the backend MySQL database we reproduced the same ‘INSERT issue’ with PostgreSQL.

A system admin reviewed the VM and ended up building a new one citing some strange issues with the networking stack.

I started from scratch on the new system and got the JPA ticket registry working on the first try with MySQL.

Thanks,

Tom O’Neill

To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/BY1PR0201MB099961E225F41BA17656B6ACCB220%40BY1PR0201MB0999.namprd02.prod.outlook.com.

Reply all

Reply to author

Forward