Bug 1342392

Summary: [upgrade] Exception in candlepin logs: javax.persistence.PersistenceException: unexpected error when rollbacking
Product: Red Hat Satellite Reporter: Sachin Ghai <sghai>
Component: Content ManagementAssignee: Partha Aji <paji>
Status: CLOSED ERRATA QA Contact: Sachin Ghai <sghai>
Severity: high Docs Contact:
Priority: unspecified    
Version: 6.2.0CC: abalakht, bbuckingham, bcourt, ehelms, kdixon
Target Milestone: UnspecifiedKeywords: Triaged
Target Release: Unused   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: katello-3.0.0-8 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-02-21 16:54:37 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1335807    
Attachments:
Description Flags
Complete exception from candlepin logs
none
foreman-debug logs none

Description Sachin Ghai 2016-06-03 07:33:50 UTC
Description of problem: I got following exception in candlepin.log when sat6.1.9 -> 6.2 GA snap14.2 upgrade was running with installer step:

At first look, it seems that this is being raised as postgresql db is down. But still I would like to check with respective devs and get a confirmation if its harmless. And If its harmless, can we suppress this one or two lines ?

==> /var/log/candlepin/candlepin.log <==
2016-06-03 02:29:20,021 [thread=QuartzScheduler_Worker-8] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] WARN  org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 57P01
2016-06-03 02:29:20,021 [thread=QuartzScheduler_Worker-5] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] WARN  org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 57P01
2016-06-03 02:29:20,021 [thread=QuartzScheduler_Worker-8] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - FATAL: terminating connection due to administrator command
2016-06-03 02:29:20,021 [thread=QuartzScheduler_Worker-5] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - FATAL: terminating connection due to administrator command
2016-06-03 02:29:20,021 [thread=QuartzScheduler_Worker-8] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] WARN  org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 08006
2016-06-03 02:29:20,022 [thread=QuartzScheduler_Worker-5] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] WARN  org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 08006
2016-06-03 02:29:20,022 [thread=QuartzScheduler_Worker-5] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - An I/O error occured while sending to the backend.
2016-06-03 02:29:20,022 [thread=QuartzScheduler_Worker-8] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - An I/O error occured while sending to the backend.
2016-06-03 02:29:20,028 [thread=QuartzScheduler_Worker-5] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] WARN  com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
2016-06-03 02:29:20,030 [thread=QuartzScheduler_Worker-8] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] WARN  com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
2016-06-03 02:29:20,040 [thread=QuartzScheduler_Worker-5] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] WARN  com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] Another error has occurred [ org.postgresql.util.PSQLException: This connection has been closed. ] which will not be reported to listeners!
org.postgresql.util.PSQLException: This connection has been closed.
	at org.postgresql.jdbc2.AbstractJdbc2Connection.checkClosed(AbstractJdbc2Connection.java:714) ~[postgresql-9.0-801.jdbc4.jar:na]
	at org.postgresql.jdbc2.AbstractJdbc2Connection.rollback(AbstractJdbc2Connection.java:731) ~[postgresql-9.0-801.jdbc4.jar:na]
	at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:855) ~[c3p0-0.9.1.2.jar:0.9.1.2]
	at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doRollback(JdbcTransaction.java:163) [hibernate-core-4.2.5.Final.jar:4.2.5.Final]
	at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.rollback(AbstractTransactionImpl.java:209) [hibernate-core-4.2.5.Final.jar:4.2.5.Final]
	at org.hibernate.ejb.TransactionImpl.rollback(TransactionImpl.java:106) [hibernate-entitymanager-4.2.5.Final.jar:4.2.5.Final]
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.rollbackIfNecessary(JpaLocalTxnInterceptor.java:149) [guice-persist-3.0.jar:na]
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:70) [guice-persist-3.0.jar:na]
	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72) [guice-3.0.jar:na]
	at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:52) [guice-3.0.jar:na]
	at org.candlepin.model.JobCurator$$EnhancerByGuice$$6a18aec5.find(<generated>) [guice-3.0.jar:na]
	at org.candlepin.pinsetter.core.PinsetterJobListener.updateJob(PinsetterJobListener.java:127) [PinsetterJobListener.class:na]
	at org.candlepin.pinsetter.core.PinsetterJobListener.updateJob(PinsetterJobListener.java:122) [PinsetterJobListener.class:na]
	at org.candlepin.pinsetter.core.PinsetterJobListener.jobToBeExecuted(PinsetterJobListener.java:72) [PinsetterJobListener.class:na]
	at org.quartz.core.QuartzScheduler.notifyJobListenersToBeExecuted(QuartzScheduler.java:1945) [quartz-2.2.1.jar:na]
	at org.quartz.core.JobRunShell.notifyListenersBeginning(JobRunShell.java:324) [quartz-2.2.1.jar:na]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:173) [quartz-2.2.1.jar:na]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [quartz-2.2.1.jar:na]
2016-06-03 02:29:20,040 [thread=QuartzScheduler_Worker-8] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] WARN  com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] Another error has occurred [ org.postgresql.util.PSQLException: This connection has been closed. ] which will not be reported to listeners!
org.postgresql.util.PSQLException: This connection has been closed.
	at org.postgresql.jdbc2.AbstractJdbc2Connection.checkClosed(AbstractJdbc2Connection.java:714) ~[postgresql-9.0-801.jdbc4.jar:na]
	at org.postgresql.jdbc2.AbstractJdbc2Connection.rollback(AbstractJdbc2Connection.java:731) ~[postgresql-9.0-801.jdbc4.jar:na]
	at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:855) ~[c3p0-0.9.1.2.jar:0.9.1.2]
	at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doRollback(JdbcTransaction.java:163) [hibernate-core-4.2.5.Final.jar:4.2.5.Final]
	at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.rollback(AbstractTransactionImpl.java:209) [hibernate-core-4.2.5.Final.jar:4.2.5.Final]
	at org.hibernate.ejb.TransactionImpl.rollback(TransactionImpl.java:106) [hibernate-entitymanager-4.2.5.Final.jar:4.2.5.Final]
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.rollbackIfNecessary(JpaLocalTxnInterceptor.java:149) [guice-persist-3.0.jar:na]
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:70) [guice-persist-3.0.jar:na]
	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72) [guice-3.0.jar:na]

::::<snip>:::::::


2016-06-03 02:29:20,044 [thread=QuartzScheduler_Worker-5] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] ERROR org.candlepin.pinsetter.core.PinsetterJobListener - jobToBeExecuted encountered a problem. Usually means there was a problem storing the job status. Job will run.
javax.persistence.PersistenceException: unexpected error when rollbacking
	at org.hibernate.ejb.TransactionImpl.rollback(TransactionImpl.java:109) ~[hibernate-entitymanager-4.2.5.Final.jar:4.2.5.Final]
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.rollbackIfNecessary(JpaLocalTxnInterceptor.java:149) ~[guice-persist-3.0.jar:na]
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:70) ~[guice-persist-3.0.jar:na]
	at org.candlepin.pinsetter.core.PinsetterJobListener.updateJob(PinsetterJobListener.java:127) ~[PinsetterJobListener.class:na]
	at org.candlepin.pinsetter.core.PinsetterJobListener.updateJob(PinsetterJobListener.java:122) ~[PinsetterJobListener.class:na]
	at org.candlepin.pinsetter.core.PinsetterJobListener.jobToBeExecuted(PinsetterJobListener.java:72) ~[PinsetterJobListener.class:na]
	at org.quartz.core.QuartzScheduler.notifyJobListenersToBeExecuted(QuartzScheduler.java:1945) [quartz-2.2.1.jar:na]
	at org.quartz.core.JobRunShell.notifyListenersBeginning(JobRunShell.java:324) [quartz-2.2.1.jar:na]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:173) [quartz-2.2.1.jar:na]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [quartz-2.2.1.jar:na]
Caused by: org.hibernate.TransactionException: rollback failed
	at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.rollback(AbstractTransactionImpl.java:215) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
	at org.hibernate.ejb.TransactionImpl.rollback(TransactionImpl.java:106) ~[hibernate-entitymanager-4.2.5.Final.jar:4.2.5.Final]
	... 9 common frames omitted
Caused by: org.hibernate.TransactionException: unable to rollback against JDBC connection
	at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doRollback(JdbcTransaction.java:167) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
	at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.rollback(AbstractTransactionImpl.java:209) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
	... 10 common frames omitted
Caused by: org.postgresql.util.PSQLException: This connection has been closed.
	at org.postgresql.jdbc2.AbstractJdbc2Connection.checkClosed(AbstractJdbc2Connection.java:714) ~[postgresql-9.0-801.jdbc4.jar:na]
	at org.postgresql.jdbc2.AbstractJdbc2Connection.rollback(AbstractJdbc2Connection.java:731) ~[postgresql-9.0-801.jdbc4.jar:na]
	at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:855) ~[c3p0-0.9.1.2.jar:0.9.1.2]
	at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doRollback(JdbcTransaction.java:163) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
	... 11 common frames omitted
2016-06-03 02:29:20,045 [thread=QuartzScheduler_Worker-5] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] WARN  com.mchange.v2.c3p0.impl.NewPooledConnection - [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
2016-06-03 02:29:20,045 [thread=QuartzScheduler_Worker-8] [job=UnpauseJob-48e5971d-1462-40f2-8453-387df03e7539, org=] ERROR org.candlepin.pinsetter.core.PinsetterJobListener - jobToBeExecuted encountered a problem. Usually means there was a problem storing the job status. Job will run.
javax.persistence.PersistenceException: unexpected error when rollbacking


Version-Release number of selected component (if applicable):
sat6.1.9 -> 6.2 GA snap14.2 upgrade on rhel7

How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:
No exception should be raised in logs while performing upgrade

Additional info:

Comment 1 Sachin Ghai 2016-06-03 07:34:41 UTC
Created attachment 1164360 [details]
Complete exception from candlepin logs

Comment 2 Sachin Ghai 2016-06-03 07:35:36 UTC
Created attachment 1164362 [details]
foreman-debug logs

Comment 4 Sachin Ghai 2016-06-03 08:35:18 UTC
Reproducible version:
-----------------------
upgrade from sat6.1.9 -> sat6.2 GA snap14.1 on rhel7. 
Rpm version is 14.2

satellite-6.2.0-14.2.el7sat.noarch

Comment 5 Brad Buckingham 2016-06-06 00:58:04 UTC
Hi Barnaby, can you take a look at the error Sachin observed in the Satellite 6.1.9 to 6.2 upgrade?  Thanks!

Comment 6 Barnaby Court 2016-06-06 13:58:07 UTC
The most likely reason for this is that the DB went down while Candlepin was still running. Instead of blocking the error (as discussed in comment 1) the installer should make sure that Candlepin/tomcat has been stopped before stopping the database.

Comment 7 Brad Buckingham 2016-06-06 14:11:43 UTC
Barnaby, thanks for the feedback.

Looking at the code, this could indeed be the condition that we are hitting.  While the installer does stop candlepin and then the database, it looks like the stopping of candlepin does not properly wait for shutdown prior to stopping postgresql. 

It looks like this is captured by http://projects.theforeman.org/issues/15146 and fixed upstream.

Comment 8 Sachin Ghai 2016-06-10 06:35:27 UTC
Note for QE: reproducible with upgrade to sat6.2 with snap15.1

Comment 9 Sachin Ghai 2016-06-27 11:52:09 UTC
The reported issue is reproducible when performing upgrade from sat6.1.9 -> sat6.2 snap17 on rhel7

	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [quartz-2.2.1.jar:na]
2016-06-27 07:40:50,057 [thread=QuartzScheduler_Worker-6] [job=UnpauseJob-945b0203-be70-4b94-8437-6336b510bf7f, org=] ERROR org.candlepin.pinsetter.core.PinsetterJobListener - jobToBeExecuted encountered a problem. Usually means there was a problem storing the job status. Job will run.
javax.persistence.PersistenceException: unexpected error when rollbacking
	at org.hibernate.ejb.TransactionImpl.rollback(TransactionImpl.java:109) ~[hibernate-entitymanager-4.2.5.Final.jar:4.2.5.Final]
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.rollbackIfNecessary(JpaLocalTxnInterceptor.java:149) ~[guice-persist-3.0.jar:na]
	at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:70) ~[guice-persist-3.0.jar:na]
	at org.candlepin.pinsetter.core.PinsetterJobListener.updateJob(PinsetterJobListener.java:127) ~[PinsetterJobListener.class:na]
	at org.candlepin.pinsetter.core.PinsetterJobListener.updateJob(PinsetterJobListener.java:122) ~[PinsetterJobListener.class:na]
	at org.candlepin.pinsetter.core.PinsetterJobListener.jobToBeExecuted(PinsetterJobListener.java:72) ~[PinsetterJobListener.class:na]
	at org.quartz.core.QuartzScheduler.notifyJobListenersToBeExecuted(QuartzScheduler.java:1945) [quartz-2.2.1.jar:na]
	at org.quartz.core.JobRunShell.notifyListenersBeginning(JobRunShell.java:324) [quartz-2.2.1.jar:na]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:173) [quartz-2.2.1.jar:na]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [quartz-2.2.1.jar:na]
Caused by: org.hibernate.TransactionException: rollback failed

Comment 10 Bryan Kearney 2016-06-27 12:15:28 UTC
Upstream bug component is Content Management

Comment 12 Partha Aji 2016-07-22 17:54:38 UTC
Sachin
I am unable to reproduce this. Can you verify the occurrence of this error.

Comment 16 Sachin Ghai 2017-12-21 10:20:02 UTC
Verified with sat6.2.z -> 6.3 snap29 upgrades. I don't see reported issue. Moreover, I tried a few different dbs and reported issue is not reproducible.


Also, I tested same with 6.2 -> 6.2.13 snap2 upgrades. This issue is no longer reproducible.

Comment 17 Satellite Program 2018-02-21 16:54:37 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://access.redhat.com/errata/RHSA-2018:0336