syncope-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "gonzalad (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (SYNCOPE-1244) Error creating bean with name 'logicInitializer' on startup related to quartz clustering
Date Tue, 05 Dec 2017 11:50:00 GMT

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

gonzalad commented on SYNCOPE-1244:
-----------------------------------

Hi Francesco, thanks for your great support and sorry for the delay.

The patch works (I've restarted a few time, and didn't get the issue).
But, looking at the code, it doesn't solve all cases (I think it diminishes the failure window,
but the window is there even if tiny).

i.e. in JobManagerImpl#load, we could have the following case :
1 - instance 1 *and* instance 2 call register(task) at a similar time (hence both call registerJob)
2 - both instance call isRunning check at a similar time, so the job is not running.
3 - and then we run the risk of having the initial error (call to SELECT * FROM QRTZ_LOCKS
WHERE SCHED_NAME = 'scheduler' AND LOCK_NAME = ? FOR UPDATE by both instance)
=> at this moment, one of the 2 transaction instance is maked as failed by postgres.
4 - the failed instance calls reportDAO.findAll
    This generates an error and the instance startup fails.

I'm attaching a patch SYNCOPE-1244-2.diff (based on yours) that should solve this issue.
My patch code is brittle, another solution would be just to stop load method execution on
first error.

wdyt ?


> 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
>          Components: core
>    Affects Versions: 2.0.2
>            Reporter: gonzalad
>             Fix For: 2.0.7, 2.1.0
>
>         Attachments: SYNCOPE-1244-2.diff, SYNCOPE-1244.diff, 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)

Mime
View raw message