[cas-user] Deadlocks and Uncommited Transaction

[Trevor Fong]

Hi There, 

We've trying out CAS 5.2.4 in a clustered environment with the ticket registry in an Oracle 12c database.  We've been seeing tons of persistent deadlock errors after a load test - you kill one locker and another deadlock springs up.

Our DBA tells us that deadlocks were seen against the tables LOCKS, SERVICETICKET, TICKETGRANTINGTICKET

Checking the catalina.out log, tons of messages like this:

2018-10-04 22:45:06,347 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] - <SQL Error: 60, SQLState: 61000>

2018-10-04 22:45:06,347 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] - <ORA-00060: deadlock detected while waiting for resource

>

2018-10-04 22:45:06,347 ERROR [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <org.hibernate.exception.LockAcquisitionException: could not execute statement>

javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement

        at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:149) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:157) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1514) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.apereo.cas.ticket.registry.JpaTicketRegistry.deleteTicketGrantingTickets(JpaTicketRegistry.java:177) ~[cas-server-support-jpa-ticket-registry-5.2.4.jar:5.2.4]

        at org.apereo.cas.ticket.registry.JpaTicketRegistry.deleteSingleTicket(JpaTicketRegistry.java:145) ~[cas-server-support-jpa-ticket-registry-5.2.4.jar:5.2.4]

        at org.apereo.cas.ticket.registry.AbstractTicketRegistry.deleteTicket(AbstractTicketRegistry.java:126) ~[cas-server-core-tickets-5.2.4.jar:5.2.4]

        at org.apereo.cas.ticket.registry.AbstractTicketRegistry$$FastClassBySpringCGLIB$$d3c67a11.invoke(<generated>) ~[cas-server-core-tickets-5.2.4.jar:5.2.4]

        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:669) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.apereo.cas.ticket.registry.JpaTicketRegistry$$EnhancerBySpringCGLIB$$45967896.deleteTicket(<generated>) ~[cas-server-support-jpa-ticket-registry-5.2.4.jar:5.2.4]

        at sun.reflect.GeneratedMethodAccessor351.invoke(Unknown Source) ~[?:?]

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_172]

        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_172]

        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at com.sun.proxy.$Proxy104.deleteTicket(Unknown Source) ~[?:?]

        at org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner.cleanTicket(DefaultTicketRegistryCleaner.java:78) ~[cas-server-core-tickets-5.2.4.jar:5.2.4]

        at java.util.stream.ReferencePipeline$4$1.accept(ReferencePipeline.java:210) ~[?:1.8.0_172]

        at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) ~[?:1.8.0_172]

        at java.util.Iterator.forEachRemaining(Iterator.java:116) ~[?:1.8.0_172]

        at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801) ~[?:1.8.0_172]

        at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:580) ~[?:1.8.0_172]

        at java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:270) ~[?:1.8.0_172]

        at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193) ~[?:1.8.0_172]

        at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193) ~[?:1.8.0_172]

        at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1382) ~[?:1.8.0_172]

        at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) ~[?:1.8.0_172]

        at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) ~[?:1.8.0_172]

        at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708) ~[?:1.8.0_172]

        at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:1.8.0_172]

        at java.util.stream.IntPipeline.reduce(IntPipeline.java:456) ~[?:1.8.0_172]

        at java.util.stream.IntPipeline.sum(IntPipeline.java:414) ~[?:1.8.0_172]

        at org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner.cleanInternal(DefaultTicketRegistryCleaner.java:69) ~[cas-server-core-tickets-5.2.4.jar:5.2.4]

        at org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner.clean(DefaultTicketRegistryCleaner.java:52) ~[cas-server-core-tickets-5.2.4.jar:5.2.4]

        at org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner$$FastClassBySpringCGLIB$$29f046b2.invoke(<generated>) ~[cas-server-core-tickets-5.2.4.jar:5.2.4]

        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282) ~[spring-tx-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner$$EnhancerBySpringCGLIB$$c03bddb2.clean(<generated>) ~[cas-server-core-tickets-5.2.4.jar:5.2.4]

        at org.apereo.cas.config.CasCoreTicketsSchedulingConfiguration$TicketRegistryCleanerScheduler.run(CasCoreTicketsSchedulingConfiguration.java:90) ~[cas-server-core-tickets-5.2.4.jar:5.2.4]

        at sun.reflect.GeneratedMethodAccessor331.invoke(Unknown Source) ~[?:?]

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_172]

        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_172]

        at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65) ~[spring-context-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_172]

        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:1.8.0_172]

        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_172]

        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:1.8.0_172]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_172]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_172]

        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_172]

Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement

        at org.hibernate.dialect.Oracle8iDialect$3.convert(Oracle8iDialect.java:566) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:178) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:45) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3198) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3077) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3457) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:145) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:599) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:473) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:50) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1398) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.internal.SessionImpl.executeUpdate(SessionImpl.java:1507) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.query.internal.AbstractProducedQuery.doExecuteUpdate(AbstractProducedQuery.java:1526) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1504) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        ... 59 more

Caused by: java.sql.SQLException: ORA-00060: deadlock detected while waiting for resource

        at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:450) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:399) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1017) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:655) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:249) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:566) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:215) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:58) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:943) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1075) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3820) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.OraclePreparedStatement.executeUpdate(OraclePreparedStatement.java:3897) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeUpdate(OraclePreparedStatementWrapper.java:1361) ~[ojdbc7.jar-12.1.0.1.jar:12.1.0.1.0]

        at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-2.7.7.jar:?]

        at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-2.7.7.jar:?]

        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:45) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3198) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3077) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3457) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:145) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:599) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:473) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:50) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1398) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.internal.SessionImpl.executeUpdate(SessionImpl.java:1507) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.query.internal.AbstractProducedQuery.doExecuteUpdate(AbstractProducedQuery.java:1526) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1504) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        ... 59 more

2018-09-21 10:45:42,693 ERROR [org.springframework.scheduling.support.TaskUtils$LoggingErrorHandler] - <Unexpected error occurred in scheduled task.>

org.springframework.orm.jpa.JpaSystemException: Transaction was marked for rollback only; cannot commit; nested exception is org.hibernate.TransactionException: Transaction was marked for rollback only; cannot commit

        at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:333) ~[spring-orm-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:244) ~[spring-orm-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:521) ~[spring-orm-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:765) ~[spring-tx-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:734) ~[spring-tx-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:518) ~[spring-tx-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:292) ~[spring-tx-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673) ~[spring-aop-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner$$EnhancerBySpringCGLIB$$68446b18.clean(<generated>) ~[cas-server-core-tickets-5.2.4.jar:5.2.4]

        at org.apereo.cas.config.CasCoreTicketsSchedulingConfiguration$TicketRegistryCleanerScheduler.run(CasCoreTicketsSchedulingConfiguration.java:90) ~[cas-server-core-tickets-5.2.4.jar:5.2.4]

        at sun.reflect.GeneratedMethodAccessor337.invoke(Unknown Source) ~[?:?]

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_172]

        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_172]

        at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65) ~[spring-context-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_172]

        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:1.8.0_172]

        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_172]

        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:1.8.0_172]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_172]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_172]

        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_172]

Caused by: org.hibernate.TransactionException: Transaction was marked for rollback only; cannot commit

        at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:228) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:68) ~[hibernate-core-5.2.13.Final.jar:5.2.13.Final]

        at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517) ~[spring-orm-4.3.16.RELEASE.jar:4.3.16.RELEASE]

        ... 21 more

After pasting all that, one thing jumped out at me:

2018-09-21 10:45:42,693 ERROR [org.springframework.scheduling.support.TaskUtils$LoggingErrorHandler] - <Unexpected error occurred in scheduled task.>

org.springframework.orm.jpa.JpaSystemException: Transaction was marked for rollback only; cannot commit; nested exception is org.hibernate.TransactionException: Transaction was marked for rollback only; cannot commit

That may be why transactions were uncommitted, which caused deadlocks.

Our DBA reports that the un-commited statements are something like:

delete from CAS5_AUTH.TICKETGRANTINGTICKET where TICKETGRANTINGTICKET_ID=:1

delete from CAS5_AUTH.TICKETGRANTINGTICKET where ID=:1

The questions remain: 

1.  why is this happening?

2.  what can be done about it?

Thanks a lot!

Trev 

PS - Happy Canadian Thanksgiving!

--
- Website: https://apereo.github.io/cas
- Gitter Chatroom: https://gitter.im/apereo/cas
- List Guidelines: https://goo.gl/1VRrw7
- Contributions: https://goo.gl/mh7qDG
---
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 view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/a5f818d5-681c-4a3d-8aed-4973d6b530bf%40apereo.org.

[Trevor Fong]

<Bump>

Anyone have any ideas why we're getting deadlocks against the tables LOCKS, SERVICETICKET, TICKETGRANTINGTICKET?

Thanks a lot,
Trev

[Trevor Fong]

<Bump>

Anyone have any ideas why we're getting deadlocks against the tables LOCKS, SERVICETICKET, TICKETGRANTINGTICKET?

Thanks a lot
Trev

To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/a85092d1-a820-44a2-adf4-151e26259480%40apereo.org.

[saritha v]

Hi,

We are facing same issue. Were you able to resolve the problem. Any pointers of how you resolved it will help me.

Thank you

To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/f033d51e-f724-49a3-93d4-19aff2826511%40apereo.org.

['Tim Evdokimov' via CAS Community]

We have faced the very same issue (deadlocks on delete from TGT table) during our load tests, and resorted to re-write the ticket registry using pure JDBC (with Spring JdbcTemplate), taking Cassandra ticket registry as a reference/example.

It yields more than 2x lower overall request latency, and there are no deadlocks observed, either. 

Apparently because it doesn't use the default Java serialisation, as the JPA ticket registry does.

And, last but not least, it is encrypted at rest.

(surprisingly enough, current JPA implementation does accept crypto parameters (and complains about the absence of encryption/signing keys in config), but does not do any encryption)

Unfortunately, we can't yet submit our JDBC ticket registry code back to CAS open source, because we need a formal approval.

But it's like 2-3 days of work, not more than that, so you could try it yourself.

Kind regards,

Tim

To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/497f721c-6ef8-4f84-b445-c08814002934%40apereo.org.

[saritha v]

Thanks a lot Tim.

We came across this in our load test and we were missing indexes for foreign keys in ticketregistryticket and serviceticket table. Adding this has solved issue in load test but we are seeing same in production and deadlocks with indexes on.

We have cleaner running on one of the servers.

Did you include these two parameters? Do you know what these parameters do?

1 2	# cas.ticket.registry.jpa.ticketLockType=NONE # cas.ticket.registry.jpa.jpaLockingTimeout=3600

Any help is greatly appreciated. 

To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/222894e1-c8d5-448a-9a19-c692c9c9230b%40apereo.org.

[Bryan Wooten]

We started with JPA ticket registry back in the 3.x days. Ran into the same issue.

We moved to ehcache then to hazelcast.

We do about 300k (with Duo) logins per day. I would never recommend JPA because of this exact issue.

-Bryan

University of Utah

To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/CAG9x2GU6FKcJQNj0ryMYxG8YmiYwvEPgjT6KYW4bpWVOF6S0JA%40mail.gmail.com.