1240597 – ERROR taskomatic org.hibernate.event.def.AbstractFlushingEventListener - Could not synchronize database state with session

Bug 1240597 - ERROR taskomatic org.hibernate.event.def.AbstractFlushingEventListener - Could not synchronize database state with session

Summary: ERROR taskomatic org.hibernate.event.def.AbstractFlushingEventListener - Coul...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Satellite 5
Classification:	Red Hat
Component:	Server
Sub Component:
Version:	570
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Assignee:	Jan Dobes
QA Contact:	Lukáš Hellebrandt
Docs Contact:
URL:
Whiteboard:
Duplicates (1):	1267546 (view as bug list)
Depends On:
Blocks:	sat5-errata 1406453
TreeView+	depends on / blocked

Reported:	2015-07-07 10:29 UTC by Pavel Studeník
Modified:	2017-02-13 12:20 UTC (History)
CC List:	5 users (show)
Fixed In Version:	spacewalk-java-2.3.8-157
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Clones:	1406453 (view as bug list)
Environment:
Last Closed:	2017-02-01 15:55:27 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHBA-2017:0236	0	normal	SHIPPED_LIVE	Satellite 5.7 bug fix update	2017-02-01 20:55:02 UTC

Description Pavel Studeník 2015-07-07 10:29:34 UTC

Description of problem:

I found traceback in taskomatic log, when I investigate why taskomatic doesn't generate metadata. It is not deterministic and it does
sometimes per week. Consequence is that taskomatic is frozen (it doesn't pick up tasks) and we need restart it. After restart I got emails about new errata from taskomatic - old tasks keeps in queue.


Version-Release number of selected component (if applicable):
spacewalk-taskomatic-2.3.8-106.el6sat.noarch

How reproducible:
sometimes

Steps to Reproduce:
1. our automation (stable satellite)

Actual results:
traceback in taskomatic log

Expected results:
without traceback

Additional info:
# tail /var/log/rhn/rhn_taskomatic_daemon.log
...
INFO   | jvm 1    | 2015/07/06 19:11:00 | 2015-07-06 19:11:00,117 [DefaultQuartzScheduler_Worker-7] INFO  com.redhat.rhn.taskomatic.task.ErrataCacheTask - In the queue: 4
INFO   | jvm 1    | 2015/07/06 19:11:15 | 2015-07-06 19:11:15,368 [DefaultQuartzScheduler_Worker-9] WARN  com.redhat.rhn.manager.kickstart.cobbler.CobblerProfileCommand - We could not find a default kickstart session for this ksdata: kvm-qemu-auto-mon06jul2015_21_47_11_22
INFO   | jvm 1    | 2015/07/06 19:15:00 | 2015-07-06 19:15:00,069 [DefaultQuartzScheduler_Worker-4] INFO  com.redhat.rhn.taskomatic.task.SessionCleanup - 6 stale session(s) deleted
INFO   | jvm 1    | 2015/07/06 19:15:00 | 2015-07-06 19:15:00,271 [DefaultQuartzScheduler_Worker-10] INFO  com.redhat.rhn.taskomatic.task.ErrataCacheTask - In the queue: 6
INFO   | jvm 1    | 2015/07/06 19:16:06 | 2015-07-06 19:16:06,372 [DefaultQuartzScheduler_Worker-9] ERROR org.hibernate.event.def.AbstractFlushingEventListener - Could not synchronize database state with session

INFO   | jvm 1    | 2015/07/06 19:16:06 | org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:85)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:70)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:47)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2421)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2325)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2625)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:115)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:278)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:262)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:167)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1030)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:367)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:137)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.common.hibernate.ConnectionManager.commitTransaction(ConnectionManager.java:233)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.common.hibernate.HibernateFactory.commitTransaction(HibernateFactory.java:331)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.taskomatic.task.RhnJavaJob.execute(RhnJavaJob.java:101)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.taskomatic.TaskoJob.execute(TaskoJob.java:169)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)
INFO   | jvm 1    | 2015/07/06 19:16:06 | 2015-07-06 19:16:06,372 [DefaultQuartzScheduler_Worker-9] ERROR org.quartz.core.JobRunShell - Job DEFAULT.cobbler-sync-default threw an unhandled Exception: 
INFO   | jvm 1    | 2015/07/06 19:16:06 | org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:85)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:70)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:47)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2421)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2325)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2625)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:115)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:278)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:262)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:167)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1030)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:367)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:137)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.common.hibernate.ConnectionManager.commitTransaction(ConnectionManager.java:233)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.common.hibernate.HibernateFactory.commitTransaction(HibernateFactory.java:331)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.taskomatic.task.RhnJavaJob.execute(RhnJavaJob.java:101)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.taskomatic.TaskoJob.execute(TaskoJob.java:169)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)
INFO   | jvm 1    | 2015/07/06 19:16:06 | 2015-07-06 19:16:06,372 [DefaultQuartzScheduler_Worker-9] ERROR org.quartz.core.ErrorLogger - Job (DEFAULT.cobbler-sync-default threw an exception.
INFO   | jvm 1    | 2015/07/06 19:16:06 | org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1]
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.quartz.core.JobRunShell.run(JobRunShell.java:227)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)
INFO   | jvm 1    | 2015/07/06 19:16:06 | Caused by: org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:85)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:70)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:47)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2421)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2325)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2625)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:115)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:278)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:262)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:167)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1030)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:367)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:137)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.common.hibernate.ConnectionManager.commitTransaction(ConnectionManager.java:233)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.common.hibernate.HibernateFactory.commitTransaction(HibernateFactory.java:331)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.taskomatic.task.RhnJavaJob.execute(RhnJavaJob.java:101)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at com.redhat.rhn.taskomatic.TaskoJob.execute(TaskoJob.java:169)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
INFO   | jvm 1    | 2015/07/06 19:16:06 |       ... 1 more

Comment 2 Tomas Lestach 2016-10-12 14:05:58 UTC

*** Bug 1267546 has been marked as a duplicate of this bug. ***

Comment 4 Jan Dobes 2016-10-26 17:01:59 UTC

Steps to reproduce:

1. Have some kickstartable tree synced, fedora-24-server in this case
2. Create some kickstart profiles (may not be needed), e.g. by following python script:
====
#!/usr/bin/python
import xmlrpclib

SATELLITE_URL = "http://localhost/rpc/api"
SATELLITE_LOGIN = "admin"
SATELLITE_PASSWORD = "nimda"

client = xmlrpclib.Server(SATELLITE_URL, verbose=0)
key = client.auth.login(SATELLITE_LOGIN, SATELLITE_PASSWORD)

for i in range(0, 100):
    client.kickstart.createProfile(key, 'X-ks-profile-%s' % i, 'none', 'fedora-24-server', 'localhost', '1234', 'none')

client.auth.logout(key)
====

3. Keep running following script:
====
#!/usr/bin/python
import xmlrpclib
import time

SATELLITE_URL = "http://localhost/rpc/api"
SATELLITE_LOGIN = "admin"
SATELLITE_PASSWORD = "nimda"

client = xmlrpclib.Server(SATELLITE_URL, verbose=0)
key = client.auth.login(SATELLITE_LOGIN, SATELLITE_PASSWORD)

try:
    client.kickstart.deleteProfile(key, 'ks-profile-test')
except:
    pass

while True:
    client.kickstart.createProfile(key, 'ks-profile-test', 'none', 'fedora-24-server', 'localhost', '1234', 'none')
    print("CREATED")
    client.kickstart.deleteProfile(key, 'ks-profile-test')
    print("DELETED")

client.auth.logout(key)
====

4. Cobbler sync is triggered every 1 minute, it should generate first uncaught org.hibernate.StaleStateException soon
5. All other taskomatic tasks will stop running soon

Comment 5 Jan Dobes 2016-10-26 17:07:07 UTC

fixed in spacewalk master:

d41ffbf2abde6ad194c7683527d4ef483cb19c90
e312d95fbde47e718b5c2605066607594833ae08

Comment 9 Lukáš Hellebrandt 2016-11-29 14:58:05 UTC

FailedQA

Tested this on sat57 with spacewalk-java-2.3.8-157 with reproducer from comment 4 and exactly the same errors are present in the log file.

Comment 10 Jan Dobes 2016-11-30 13:43:13 UTC

Based on discussion, switching back to ON_QA because we print catched exceptions into taskomatic log.

Comment 13 Lukáš Hellebrandt 2016-12-06 13:35:14 UTC

The bug is fixed in SW and Sat5.7.

The bug is not fixed at all in Sat5.8.

The erratum introduces a new problem reproduced on our stable Sat5.7:
After some time, the channel repodata cease being built. The channel-repodata bunch's status is "SKIPPED" indefinitely (it keeps refreshing every minute, though). This message is printed in /var/log/rhn/rhn_taskomatic_daemon.log every minute:
***
INFO   | jvm 1    | 2016/12/05 14:39:03 | 2016-12-05 14:39:03,434 [DefaultQuartzScheduler_Worker-5] WARN  com.redhat.rhn.taskomatic.task.ChannelRepodata - Maximum number of workers already put ... skipping.
***

Comment 21 Lukáš Hellebrandt 2017-02-01 11:23:23 UTC

After discussion with developers, I am verifying this BZ:

- The bug is fixed
- The newly found bug appears not to be a regression
- The messages in log do not point to any change to worse - they just started to be visible in default configuration

While there is still some bug present in Taskomatic causing tasks to stop, it is probably not caused by the erratum this bug is in. Also, it seems the state after applying the fix is much better. We are going to ship the erratum and make a separate bug for the issue.

Verified with Sat 5.8, spacewalk-java-2.5.14-48, used reproducer from comment 4.

Comment 23 errata-xmlrpc 2017-02-01 15:55:27 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2017-0236.html

Comment 25 Lukáš Hellebrandt 2017-02-13 12:20:20 UTC

The follow-up bug is bug 1421674

Note You need to log in before you can comment on or make changes to this bug.