Uploaded image for project: 'Syncope'
  1. Syncope
  2. SYNCOPE-1244

Error creating bean with name 'logicInitializer' on startup related to quartz clustering

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 2.0.2
    • Fix Version/s: 2.0.7, 2.1.0
    • Component/s: core
    • Labels:
      None

      Description

      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:

      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]
      

      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 :

                          // 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);
                              }
                          }
      
      

      The LockException happens during the first call to register.
      The exception is caught.
      Problem is in the logged stackTrace I see:

      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]
      

      Postgres says `commands ignored until end of transaction block`.

      And the real exception happens when we call reportDAO.findAll(), with

      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]
      

      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

        Attachments

        1. TPSVC-3882.zip
          65 kB
          gonzalad
        2. SYNCOPE-1244-5.diff
          4 kB
          Francesco Chicchiriccò
        3. SYNCOPE-1244-4.diff
          3 kB
          gonzalad
        4. SYNCOPE-1244-3.diff
          3 kB
          Francesco Chicchiriccò
        5. SYNCOPE-1244-2.diff
          2 kB
          gonzalad
        6. SYNCOPE-1244.diff
          1 kB
          Francesco Chicchiriccò

          Activity

            People

            • Assignee:
              ilgrosso Francesco Chicchiriccò
              Reporter:
              gonzalad gonzalad
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: