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. From: [email protected] [mailto:[email protected]] On Behalf Of Tom O'Neill Sent: Tuesday, June 28, 2016 5:38 AM To: Misagh Moayyed <[email protected]>; [email protected] Subject: RE: [cas-user] CAS 4.2.2 jpaTicketRegistry Issues 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: <!-- <alias name="defaultTicketRegistry" alias="ticketRegistry" /> --> <alias name="jpaTicketRegistry" alias="ticketRegistry" /> 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, <mailto:expirationPolicy=org.jasig.cas.ticket.support.TicketGrantingTicketExpirationPolicy@60ea79d1> expirationPolicy=org.jasig.cas.ticket.support.TicketGrantingTicketExpirationPolicy@60ea79d1, services={}, ticketGrantingTicket=null, <mailto:authentication=org.jasig.cas.authentication.ImmutableAuthentication@cf5621ae> 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 From: [email protected] <mailto:[email protected]> [mailto:[email protected]] On Behalf Of Misagh Moayyed Sent: Monday, June 27, 2016 5:30 PM To: [email protected] <mailto:[email protected]> Subject: RE: [cas-user] CAS 4.2.2 jpaTicketRegistry Issues Point your overlay to 4.2.4-SNAPSHOT and try again please. (make sure you force an update with –U) From: [email protected] <mailto:[email protected]> [mailto:[email protected]] On Behalf Of Tom O'Neill Sent: Monday, June 27, 2016 12:05 PM To: [email protected] <mailto:[email protected]> Subject: [cas-user] CAS 4.2.2 jpaTicketRegistry Issues 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: <dependencies> <dependency> <groupId>org.jasig.cas</groupId> <artifactId>cas-server-webapp</artifactId> <version>${cas.version}</version> <type>war</type> <scope>runtime</scope> </dependency> <dependency> <groupId>org.jasig.cas</groupId> <artifactId>cas-server-support-ldap</artifactId> <version>${cas.version}</version> </dependency> <dependency> <groupId>org.jasig.cas</groupId> <artifactId>cas-server-support-jpa-ticket-registry</artifactId> <version>${cas.version}</version> </dependency> <dependency> <groupId>mysql</groupId> <artifactId>mysql-connector-java</artifactId> <version>5.1.39</version> </dependency> </dependencies> After getting LDAP working with the default ticket registry, I then updated src/main/webapp/WEB-INF/deployerConfigContext.xml as follows: <!-- TONeill/JPA Ticket registry --> <!-- <alias name="defaultTicketRegistry" alias="ticketRegistry" /> --> <alias name="jpaTicketRegistry" alias="ticketRegistry" /> 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 <mailto:expirationPolicy=org.jasig.cas.ticket.support.TicketGrantingTicketExpirationPolicy@42f8ab07> , services={}, ticketGrantingTicket=null, authentication=org.jasig.cas.authentication.ImmutableAuthentication@c0763239 <mailto: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 -- 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 [email protected] <mailto:[email protected]> . To post to this group, send email to [email protected] <mailto:[email protected]> . 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 <https://groups.google.com/a/apereo.org/d/msgid/cas-user/BY1PR0201MB099948E01CE07680743753A6CB210%40BY1PR0201MB0999.namprd02.prod.outlook.com?utm_medium=email&utm_source=footer> . For more options, visit https://groups.google.com/a/apereo.org/d/optout. -- 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 [email protected] <mailto:[email protected]> . To post to this group, send email to [email protected] <mailto:[email protected]> . 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/002901d1d0bb%241e69ffa0%245b3dfee0%24%40unicon.net <https://groups.google.com/a/apereo.org/d/msgid/cas-user/002901d1d0bb%241e69ffa0%245b3dfee0%24%40unicon.net?utm_medium=email&utm_source=footer> . For more options, visit https://groups.google.com/a/apereo.org/d/optout. -- 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 [email protected] <mailto:[email protected]> . To post to this group, send email to [email protected] <mailto:[email protected]> . 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/BY1PR0201MB099973FCFB22CE324D1AB33DCB220%40BY1PR0201MB0999.namprd02.prod.outlook.com <https://groups.google.com/a/apereo.org/d/msgid/cas-user/BY1PR0201MB099973FCFB22CE324D1AB33DCB220%40BY1PR0201MB0999.namprd02.prod.outlook.com?utm_medium=email&utm_source=footer> . For more options, visit https://groups.google.com/a/apereo.org/d/optout. -- 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 [email protected]. To post to this group, send email to [email protected]. 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/00f601d1d140%243daa5420%24b8fefc60%24%40unicon.net. For more options, visit https://groups.google.com/a/apereo.org/d/optout.
