Bug 1013719 - Production nonthreadsafe Exceptions
Summary: Production nonthreadsafe Exceptions
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Candlepin
Classification: Community
Component: candlepin
Version: 0.9
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
: ---
Assignee: Jesus M. Rodriguez
QA Contact: Katello QA List
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-09-30 16:13 UTC by Dennis Crissman
Modified: 2015-05-14 14:53 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-10-21 14:12:41 UTC
Embargoed:

Attachments (Terms of Use)

Description Dennis Crissman 2013-09-30 16:13:05 UTC 
Getting these exceptions in production. There are 4 of them, and they appear to reoccur in this order over and over again.

Possibly related to:
https://bugzilla.redhat.com/show_bug.cgi?id=1006374
https://bugzilla.redhat.com/show_bug.cgi?id=1006377

One difference from the two bzs above, is that I do NOT see any 'derived' pools w/out 'masters'.

Please investigate.


Sep 30 12:07:02 [ITClusteredScheduler_Worker-1] ERROR org.hibernate.event.def.AbstractFlushingEventListener - Could not synchronize database state with session
org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.candlepin.model.Pool#8a85f986401105de01403b973f52419c]
	at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1782)
	at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2541)
	at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2715)
	at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:96)
	at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:278)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:262)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:171)
	at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
	at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:64)
	at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:999)
	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1633)
	at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:306)
	at org.candlepin.model.PoolCurator.entitlementsIn(PoolCurator.java:307)
	at org.candlepin.model.PoolCurator$$EnhancerByGuice$$db56c5bd.CGLIB$entitlementsIn$22(<generated>)
	at org.candlepin.model.PoolCurator$$EnhancerByGuice$$db56c5bd$$FastClassByGuice$$94ad6790.invoke(<generated>)
	at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:58)
	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
	at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:52)
	at org.candlepin.model.PoolCurator$$EnhancerByGuice$$db56c5bd.entitlementsIn(<generated>)
	at org.candlepin.controller.CandlepinPoolManager.deletePool(CandlepinPoolManager.java:948)
	at org.candlepin.controller.CandlepinPoolManager$$EnhancerByGuice$$d2831c0.CGLIB$deletePool$14(<generated>)
	at org.candlepin.controller.CandlepinPoolManager$$EnhancerByGuice$$d2831c0$$FastClassByGuice$$fe27173e.invoke(<generated>)
	at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:58)
	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
	at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:52)
	at org.candlepin.controller.CandlepinPoolManager$$EnhancerByGuice$$d2831c0.deletePool(<generated>)
	at org.candlepin.controller.CandlepinPoolManager.refreshPoolsWithoutRegeneration(CandlepinPoolManager.java:192)
	at org.candlepin.controller.Refresher.run(Refresher.java:90)
	at org.candlepin.pinsetter.tasks.RefreshPoolsJob.execute(RefreshPoolsJob.java:75)
	at org.candlepin.pinsetter.tasks.RefreshPoolsJob$$EnhancerByGuice$$161e1ff0.CGLIB$execute$0(<generated>)
	at org.candlepin.pinsetter.tasks.RefreshPoolsJob$$EnhancerByGuice$$161e1ff0$$FastClassByGuice$$61495743.invoke(<generated>)
	at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:66)
	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
	at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:52)
	at org.candlepin.pinsetter.tasks.RefreshPoolsJob$$EnhancerByGuice$$161e1ff0.execute(<generated>)
	at org.candlepin.pinsetter.core.TransactionalPinsetterJob.execute(TransactionalPinsetterJob.java:50)
	at org.quartz.core.JobRunShell.run(Unknown Source)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(Unknown Source)



Sep 30 12:07:02 [ITClusteredScheduler_Worker-1] ERROR org.candlepin.pinsetter.tasks.RefreshPoolsJob - RefreshPoolsJob encountered a problem.
org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.candlepin.model.Pool#8a85f986401105de01403b973f52419c]
	at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1782)
	at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2541)
	at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2715)
	at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:96)
	at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:278)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:262)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:171)
	at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
	at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:64)
	at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:999)
	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1633)
	at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:306)
	at org.candlepin.model.PoolCurator.entitlementsIn(PoolCurator.java:307)
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:58)
	at org.candlepin.controller.CandlepinPoolManager.deletePool(CandlepinPoolManager.java:948)
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:58)
	at org.candlepin.controller.CandlepinPoolManager.refreshPoolsWithoutRegeneration(CandlepinPoolManager.java:192)
	at org.candlepin.controller.Refresher.run(Refresher.java:90)
	at org.candlepin.pinsetter.tasks.RefreshPoolsJob.execute(RefreshPoolsJob.java:75)
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:66)
	at org.candlepin.pinsetter.core.TransactionalPinsetterJob.execute(TransactionalPinsetterJob.java:50)
	at org.quartz.core.JobRunShell.run(Unknown Source)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(Unknown Source)



Sep 30 12:07:02 [ITClusteredScheduler_Worker-1] ERROR org.hibernate.AssertionFailure - an assertion failure occured (this may indicate a bug in Hibernate, but is more likely due to unsafe use of the session)
org.hibernate.AssertionFailure: possible nonthreadsafe access to session
	at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:106)
	at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:278)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:262)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:171)
	at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
	at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
	at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1030)
	at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:367)
	at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:137)
	at org.hibernate.ejb.TransactionImpl.commit(TransactionImpl.java:54)
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:71)
	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
	at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:52)
	at org.candlepin.pinsetter.tasks.RefreshPoolsJob$$EnhancerByGuice$$161e1ff0.execute(<generated>)
	at org.candlepin.pinsetter.core.TransactionalPinsetterJob.execute(TransactionalPinsetterJob.java:50)
	at org.quartz.core.JobRunShell.run(Unknown Source)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(Unknown Source)



Sep 30 12:07:02 [ITClusteredScheduler_Worker-1] ERROR org.candlepin.pinsetter.core.PinsetterJobListener - Job [refresh_pools_a14cca70-3df6-4f48-ad15-aba6902e97e8] failed.
org.quartz.JobExecutionException: javax.persistence.RollbackException: Error while commiting the transaction [See nested exception: javax.persistence.RollbackException: Error while commiting the transaction]
	at org.candlepin.pinsetter.core.TransactionalPinsetterJob.execute(TransactionalPinsetterJob.java:71)
	at org.quartz.core.JobRunShell.run(Unknown Source)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(Unknown Source)
Caused by: javax.persistence.RollbackException: Error while commiting the transaction
	at org.hibernate.ejb.TransactionImpl.commit(TransactionImpl.java:71)
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:71)
	at org.candlepin.pinsetter.core.TransactionalPinsetterJob.execute(TransactionalPinsetterJob.java:50)
	... 2 more
Caused by: org.hibernate.AssertionFailure: possible nonthreadsafe access to session
	at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:106)
	at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:278)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:262)
	at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:171)
	at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
	at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
	at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1030)
	at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:367)
	at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:137)
	at org.hibernate.ejb.TransactionImpl.commit(TransactionImpl.java:54)
	... 4 more
Comment 1 Dennis Crissman 2013-09-30 17:50:21 UTC 
The subscription expired yesterday (Sun Sep 29 00:00:00 -0400 2013), so by all accounts candlepin should just delete the pool.

The exceptions started around 2am this morning, which correlates to refreshes done this morning.

NOTE: the first row in the result set was my attempt at a manual refresh in hopes to clean this up, but it did not work.

mysql> select * from cp_job where targetId = '7001381' order by created DESC;
+----------------------------------------------------+---------------------+---------------------+---------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------+-------+-------------+-----------------+----------+------------+
    | id                                                 | created             | updated             | finishTime          | result                                                                                                                                                  | startTime           | state | jobGroup    | principalName   | targetId | targetType |
    +----------------------------------------------------+---------------------+---------------------+---------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------+-------+-------------+-----------------+----------+------------+
    | refresh_pools_a3c0d67b-22ee-4a05-beb0-8a99a4120c00 | 2013-09-30 13:02:59 | 2013-09-30 13:03:04 | 2013-09-30 13:03:00 | Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.candlepin.model.Pool#8a85f986401105de01403b973f52419c] | 2013-09-30 13:02:59 |     3 | async group | candlepin_admin | 7001381  |          0 |
    | refresh_pools_e062dd2b-1244-408f-bf46-d67d018b50d5 | 2013-09-30 02:25:02 | 2013-09-30 13:03:05 | 2013-09-30 02:25:03 | Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.candlepin.model.Pool#8a85f986401105de01403b973f52419c] | 2013-09-30 02:25:02 |     3 | async group | candlepin_admin | 7001381  |          0 |
    | refresh_pools_a14cca70-3df6-4f48-ad15-aba6902e97e8 | 2013-09-30 02:22:01 | 2013-09-30 13:03:05 | 2013-09-30 02:22:02 | Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.candlepin.model.Pool#8a85f986401105de01403b973f52419c] | 2013-09-30 02:22:02 |     3 | async group | candlepin_admin | 7001381  |          0 |
    | refresh_pools_ef818763-720c-44ae-b9bb-2c9ca40073fa | 2013-09-30 02:02:01 | 2013-09-30 13:03:05 | 2013-09-30 02:02:02 | Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.candlepin.model.Pool#8a85f986401105de01403b973f52419c] | 2013-09-30 02:02:02 |     3 | async group | candlepin_admin | 7001381  |          0 |
    +----------------------------------------------------+---------------------+---------------------+---------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------+-------+-------------+-----------------+----------+------------+
    4 rows in set (0.00 sec)
Comment 2 Andrew Edwards 2013-09-30 19:01:34 UTC 
This expired pool had one entitlement associated with it. Removing the entitlement from the account allowed the refresh to complete and remove the pool.
Comment 3 Jesus M. Rodriguez 2014-03-28 16:06:01 UTC 
Fixed by 2fb5386e21c62e679f697c147b9fd72da3c49b59
https://github.com/candlepin/candlepin/pull/542
Comment 4 Jesus M. Rodriguez 2014-03-28 16:06:14 UTC 
Fixed by 2fb5386e21c62e679f697c147b9fd72da3c49b59
https://github.com/candlepin/candlepin/pull/542
Note You need to log in before you can comment on or make changes to this bug.