Mailing-List: contact dev-help@syncope.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@syncope.apache.org
Date: Sun, 3 Dec 2017 22:37:01 +0000 (UTC)
From: "gonzalad (JIRA)" <jira@apache.org>
To: dev@syncope.apache.org
Message-ID: <JIRA.13122461.1512332411000.374796.1512340621306@Atlassian.JIRA>
In-Reply-To: <JIRA.13122461.1512332411000@Atlassian.JIRA>
References: <JIRA.13122461.1512332411000@Atlassian.JIRA> <JIRA.13122461.1512332411592@jira-lw-us.apache.org>
Subject: [jira] [Comment Edited] (SYNCOPE-1244) Error creating bean with
 name 'logicInitializer' on startup related to quartz clustering
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
archived-at: Sun, 03 Dec 2017 22:37:08 -0000


    [ https://issues.apache.org/jira/browse/SYNCOPE-1244?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16276137#comment-16276137 ] 

gonzalad edited comment on SYNCOPE-1244 at 12/3/17 10:36 PM:
-------------------------------------------------------------

This is related to postgresql behaviour, https://stackoverflow.com/a/13103690 gives a good description :

{quote}
I got this error using Java and postgresql doing an insert on a table. I will illustrate how you can reproduce this error:
org.postgresql.util.PSQLException: ERROR: 
current transaction is aborted, commands ignored until end of transaction block

Summary:
The reason you get this error is because you have entered a transaction and one of your SQL Queries failed, and you gobbled up that failure and ignored it. But that wasn't enough,
THEN you used that same connection, using the SAME TRANSACTION to run another query. The exception gets thrown on the second, correctly formed query because you are
using a broken transaction to do additional work. Postgresql by default stops you from doing this
{quote}


was (Author: gonzalad):
This is related to postregsql behaviour, https://stackoverflow.com/a/13103690 gives a good description :

{quote}
I got this error using Java and postgresql doing an insert on a table. I will illustrate how you can reproduce this error:
org.postgresql.util.PSQLException: ERROR: 
current transaction is aborted, commands ignored until end of transaction block

Summary:
The reason you get this error is because you have entered a transaction and one of your SQL Queries failed, and you gobbled up that failure and ignored it. But that wasn't enough,
THEN you used that same connection, using the SAME TRANSACTION to run another query. The exception gets thrown on the second, correctly formed query because you are
using a broken transaction to do additional work. Postgresql by default stops you from doing this
{quote}


> Error creating bean with name 'logicInitializer' on startup related to quartz clustering 
> -----------------------------------------------------------------------------------------
>
>                 Key: SYNCOPE-1244
>                 URL: https://issues.apache.org/jira/browse/SYNCOPE-1244
>             Project: Syncope
>          Issue Type: Bug
>    Affects Versions: 2.0.2
>            Reporter: gonzalad
>         Attachments: TPSVC-3882.zip
>
>
> I use syncope 2.0.2 in high availability mode (4 instances).
> I'm using syncope with postgresql db.
> Sometimes on startup I have the following error, and the instance fails to start:
> {code}
> 17-12-03 18:39:10.781 ERROR - [syncope] - [localhost-startStop-5] org.springframework.web.context.ContextLoader - Context initialization failed
> org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'logicInitializer' defined in URL [jar:file:/usr/local/tomcat/webapps/syncope/WEB-INF/lib/syncope-core-logic-2.0.2_1.jar!/org/apache/syncope/core/logic/init/LogicInitializer.class]: Invocation of init method failed; nested exception is <openjpa-2.4.2-r422266:1777108 fatal general error> org.apache.openjpa.persistence.PersistenceException: ERROR: current transaction is aborted, commands ignored until end of transaction block {prepstmnt 977966121 SELECT t0.id, t0.active, t0.cronExpression, t0.name, t1.id, t1.csvTemplate, t1.foTemplate, t1.htmlTemplate FROM Report t0 INNER JOIN ReportTemplate t1 ON t0.template_id = t1.id} [code=0, state=25P02]
> FailedObject: SELECT e FROM JPAReport e [java.lang.String]
> 	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1628) ~[spring-beans-4.3.6.RELEASE.jar:4.3.6.RELEASE]
> 	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:555) ~[spring-beans-4.3.6.RELEASE.jar:4.3.6.RELEASE]
> 	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:483) ~[
> Caused by: org.apache.openjpa.persistence.PersistenceException: ERROR: current transaction is aborted, commands ignored until end of transaction block {prepstmnt 977966121 SELECT t0.id, t0.active, t0.cronExpression, t0.name, t1.id, t1.csvTemplate, t1.foTemplate, t1.htmlTemplate FROM Report t0 INNER JOIN ReportTemplate t1 ON t0.template_id = t1.id} [code=0, state=25P02]
> 	at org.apache.openjpa.jdbc.sql.DBDictionary.narrow(DBDictionary.java:5003) ~[openjpa-jdbc-2.4.2.jar:2.4.2]
> ...
> 	at org.apache.openjpa.persistence.QueryImpl.getResultList(QueryImpl.java:290) ~[openjpa-persistence-2.4.2.jar:2.4.2]
> 	at org.apache.syncope.core.persistence.jpa.dao.JPAReportDAO.findAll(JPAReportDAO.java:55) ~[syncope-core-persistence-jpa-2.0.2_1.jar:2.0.2_1]
> ...
> 	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) ~[spring-aop-4.3.6.RELEASE.jar:4.3.6.RELEASE]
> 	at com.sun.proxy.$Proxy427.findAll(Unknown Source) ~[?:?]
> 	at org.apache.syncope.core.logic.init.JobManagerImpl$3.exec(JobManagerImpl.java:327) ~[syncope-core-logic-2.0.2_1.jar:2.0.2_1]
> 	at org.apache.syncope.core.logic.init.JobManagerImpl$3.exec(JobManagerImpl.java:310) ~[syncope-core-logic-2.0.2_1.jar:2.0.2_1]
> 	at org.apache.syncope.core.spring.security.AuthContextUtils.execWithAuthContext(AuthContextUtils.java:114) ~[syncope-core-spring-2.0.2_1.jar:2.0.2_1]
> 	at org.apache.syncope.core.logic.init.JobManagerImpl.load(JobManagerImpl.java:310) ~[syncope-core-logic-2.0.2_1.jar:2.0.2_1]
> 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_131]
> 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_131]
> ...
> 	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) ~[spring-aop-4.3.6.RELEASE.jar:4.3.6.RELEASE]
> 	at com.sun.proxy.$Proxy428.load(Unknown Source) ~[?:?]
> 	at org.apache.syncope.core.logic.init.LogicInitializer.afterPropertiesSet(LogicInitializer.java:70) ~[syncope-core-logic-2.0.2_1.jar:2.0.2_1]
> Caused by: org.apache.openjpa.lib.jdbc.ReportingSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block {prepstmnt 977966121 SELECT t0.id, t0.active, t0.cronExpression, t0.name, t1.id, t1.csvTemplate, t1.foTemplate, t1.htmlTemplate FROM Report t0 INNER JOIN ReportTemplate t1 ON t0.template_id = t1.id} [code=0, state=25P02]
> ...
> 	at org.apache.openjpa.persistence.QueryImpl.execute(QueryImpl.java:274) ~[openjpa-persistence-2.4.2.jar:2.4.2]
> 	at org.apache.openjpa.persistence.QueryImpl.getResultList(QueryImpl.java:290) ~[openjpa-persistence-2.4.2.jar:2.4.2]
> 	at org.apache.syncope.core.persistence.jpa.dao.JPAReportDAO.findAll(JPAReportDAO.java:55) ~[syncope-core-persistence-jpa-2.0.2_1.jar:2.0.2_1]
> ...
> 	at org.apache.syncope.core.logic.init.JobManagerImpl$3.exec(JobManagerImpl.java:327) ~[syncope-core-logic-2.0.2_1.jar:2.0.2_1]
> {code} 
> From what I understand, this happens when one instance already holds the quartz lock, hence the other instance tries to grasp it and fails with a LockException.
> The JobManagerImpl executes this kind of code
> https://github.com/apache/syncope/blob/cea47da1a1510446b7bd62fbc8e45cc8757d6611/core/provisioning-java/src/main/java/org/apache/syncope/core/provisioning/java/job/JobManagerImpl.java#L326-L351 :
> {code}
>                     // 1. jobs for SchedTasks
>                     Set<SchedTask> tasks = new HashSet<>(taskDAO.<SchedTask>findAll(TaskType.SCHEDULED));
>                     tasks.addAll(taskDAO.<PullTask>findAll(TaskType.PULL));
>                     tasks.addAll(taskDAO.<PushTask>findAll(TaskType.PUSH));
>                     for (SchedTask task : tasks) {
>                         try {
>                             register(task, task.getStartAt(), conf.getRight());
>                         } catch (Exception e) {
>                             LOG.error("While loading job instance for task " + task.getKey(), e);
>                         }
>                     }
>                     // 2. jobs for Reports
>                     for (Report report : reportDAO.findAll()) {
>                         try {
>                             register(report, null, conf.getRight());
>                         } catch (Exception e) {
>                             LOG.error("While loading job instance for report " + report.getName(), e);
>                         }
>                     }
> {code}
> The LockException happens during the first call to register.
> The exception is caught.
> Problem is in the logged stackTrace I see:
> {code}
> 17-12-03 18:39:06.659 ERROR - [syncope] - [localhost-startStop-5] org.apache.syncope.core.provisioning.api.job.JobManager - Could not remove job taskJobe84fd2bc-e472-48a1-8fd2-bce472c8a1ba
> org.quartz.impl.jdbcjobstore.LockException: Failure obtaining db row lock: ERROR: current transaction is aborted, commands ignored until end of transaction block {prepstmnt 1348492786 SELECT * FROM QRTZ_LOCKS WHERE SCHED_NAME = 'scheduler' AND LOCK_NAME = ? FOR UPDATE} [code=0, state=25P02]
> {code}
> Postgres says `commands ignored until end of transaction block`.
> And the real exception happens when we call reportDAO.findAll(), with 
> {code}
> Caused by: <openjpa-2.4.2-r422266:1777108 fatal general error> org.apache.openjpa.persistence.PersistenceException: ERROR: current transaction is aborted, commands ignored until end of transaction block {prepstmnt 977966121 SELECT t0.id, t0.active, t0.cronExpression, t0.name, t1.id, t1.csvTemplate, t1.foTemplate, t1.htmlTemplate FROM Report t0 INNER JOIN ReportTemplate t1 ON t0.template_id = t1.id} [code=0, state=25P02]
> FailedObject: SELECT e FROM JPAReport e [java.lang.String]
> {code}
> So postgresql seems to fulfill its promise and raise an error on any subsequent SQL statement issued under the same transaction context.
> Perhaps, we need either :
>  * to start a new transaction on each call to register.
>  * to stop the jobManagerImpl.load method execution on the first error.
>    I don't know if that would be enough (i.e. what happend when the TransactionInterceptor surrounding JobManagerImpl executes - would it throw an error ?) 
>  
> I'll attach the full logs (the interesting part starts at line 4405).
> Thanks,
> Adrian


--
This message was sent by Atlassian JIRA
(v6.4.14#64029)