Периодические ошибки запуска задач из планировщика

Вопросы и проблемы
#1

v7.2.6. Периодически выскакивают ошибки при запуске задач из scheduler’a.

09:47:20.886 ERROR c.h.c.core.app.scheduling.RunnerBean    - Error running ScheduledTask{88f9c9a0-21b1-e41c-f1de-d9df35bfbf3d, beanName=ev_GdprHeartbeatBackgroundService, methodName=getGdprHe
artbeat, singleton=true, period=30}
javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.7.3.7-cuba): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "sys_scheduled_execution_pkey"
  Detail: Key (id)=(537d5e0e-fcfb-a1a1-f246-7a3c22e93cb5) already exists.
Error Code: 0
Call: INSERT INTO SYS_SCHEDULED_EXECUTION (ID, CREATE_TS, CREATED_BY, FINISH_TIME, RESULT, SERVER, START_TIME, SYS_TENANT_ID, TASK_ID) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)
        bind => [537d5e0e-fcfb-a1a1-f246-7a3c22e93cb5, 2020-07-24 09:47:20.792, admin, 2020-07-24 09:47:20.803, gdprHeartbeat: available 2020-07-24T07:47:20.788Z, vlt-devapp01:8080/quantum-co
re, 2020-07-24 09:47:20.759, null, 88f9c9a0-21b1-e41c-f1de-d9df35bfbf3d]
Query: InsertObjectQuery(com.haulmont.cuba.core.entity.ScheduledExecution-537d5e0e-fcfb-a1a1-f246-7a3c22e93cb5 [managed])
        at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:979) ~[org.eclipse.persistence.jpa-2.7.3-7-cuba.jar:na]
        at com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport$ContainerResourceSynchronization.detachAll(PersistenceImplSupport.java:504) ~[cuba-core-7.2.6.jar:7.2.6]
        at com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport$ContainerResourceSynchronization.beforeCommit(PersistenceImplSupport.java:450) ~[cuba-core-7.2.6.jar:7.2.6]
        at org.springframework.transaction.support.TransactionSynchronizationUtils.triggerBeforeCommit(TransactionSynchronizationUtils.java:96) ~[spring-tx-5.2.3.RELEASE.jar:5.2.3.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerBeforeCommit(AbstractPlatformTransactionManager.java:920) ~[spring-tx-5.2.3.RELEASE.jar:5.2.3.RELE
ASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:728) ~[spring-tx-5.2.3.RELEASE.jar:5.2.3.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:712) ~[spring-tx-5.2.3.RELEASE.jar:5.2.3.RELEASE]
        at com.haulmont.cuba.core.sys.TransactionImpl.commit(TransactionImpl.java:104) ~[cuba-core-7.2.6.jar:7.2.6]
        at com.haulmont.cuba.core.app.scheduling.RunnerBean.registerExecutionFinish(RunnerBean.java:219) ~[cuba-core-7.2.6.jar:7.2.6]
        at com.haulmont.cuba.core.app.scheduling.RunnerBean.lambda$runTask$0(RunnerBean.java:142) ~[cuba-core-7.2.6.jar:7.2.6]
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
        at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: org.eclipse.persistence.exceptions.DatabaseException:

Наблюдаются только у задач с мылым интервалом запуска (1 минута и меньше). Частота вознисновения ~ раз в час.

#2

Добрый день,
А вы не можете проверить у себя, это попытка повторной вставки того же объекта с теми же атрибутами, или просто случайное совпадение UUID с каким-то ранее сохраненным объектом?

Проверьте в паре случаев по базе данных, например
select * from SYS_SCHEDULED_EXECUTION where id = ‘537d5e0e-fcfb-a1a1-f246-7a3c22e93cb5’

#3

Добрый день,

Нет это не collision UUID. В БД только одна запись с конфиликтующим UUID, и create_ts у нее равен моменту возникновения ошибки.

18:36:39.689 ERROR c.h.c.core.app.scheduling.RunnerBean    - Error running ScheduledTask{88f9c9a0-21b1-e41c-f1de-d9df35bfbf3d, beanName=ev_GdprHeartbeatBackgroundService, methodName=getGdprHe
artbeat, singleton=true, period=30}
javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.7.3.7-cuba): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "sys_scheduled_execution_pkey"
  Detail: Key (id)=(614b11a0-5c2a-30db-08be-0d7182b6cccf) already exists.

image

При этом видно, что сам exception успешно залогировался в базе.
У задач с интервалом запуска 3-5 минут и больше такого не наблюдается.

#5

@pavel
Добавьте пожалуйста в свой проект такой бин-листенер:

import com.haulmont.cuba.core.app.events.EntityPersistingEvent;
import com.haulmont.cuba.core.entity.ScheduledExecution;
import com.haulmont.cuba.core.listener.BeforeAttachEntityListener;
import com.haulmont.cuba.core.sys.events.AppContextInitializedEvent;
import com.haulmont.cuba.core.sys.listener.EntityListenerManager;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.context.event.EventListener;
import org.springframework.stereotype.Component;

import javax.inject.Inject;

@Component("schedex_ScheduledExecutionListener")
public class ScheduledExecutionListener implements BeforeAttachEntityListener<ScheduledExecution> {

    private static final Logger log = LoggerFactory.getLogger(ScheduledExecutionListener.class);
    @Inject
    private EntityListenerManager entityListenerManager;

    @EventListener
    public void onInit(AppContextInitializedEvent event) {
        entityListenerManager.addListener(ScheduledExecution.class, "schedex_ScheduledExecutionListener");
    }

    @EventListener
    public void beforePersist(EntityPersistingEvent<ScheduledExecution> event) {
        log.debug("beforePersist: {} @{}", event.getEntity(), System.identityHashCode(event.getEntity()));
    }

    @Override
    public void onBeforeAttach(ScheduledExecution entity) {
        log.debug("beforeAttach: {} @{}", entity, System.identityHashCode(entity));
    }
}

Он будет выдавать в лог сообщения такого характера:

2020-07-31 17:36:59.705 DEBUG [ScheduledRunnerThread-2/app-core/admin] com.company.schedex.listeners.ScheduledExecutionListener - beforePersist: com.haulmont.cuba.core.entity.ScheduledExecution-ed7c6d0c-775d-0aa4-938a-5705bb1eec83 [new] @594730370
2020-07-31 17:36:59.716 DEBUG [ScheduledRunnerThread-2/app-core/admin] com.haulmont.cuba.core.app.TestingServiceBean - execute started
2020-07-31 17:36:59.820 DEBUG [ScheduledRunnerThread-2/app-core/admin] com.company.schedex.listeners.ScheduledExecutionListener - beforeAttach: com.haulmont.cuba.core.entity.ScheduledExecution-ed7c6d0c-775d-0aa4-938a-5705bb1eec83 [detached] @594730370

После возникновения ошибки, приложите сюда пожалуйста стектрейс и сообщения от листенера до и после ошибки.

#7

Константин, добрый день

Лог с listener при возникновении ошибки

10:20:04.214 DEBUG r.m.e.c.h.ScheduledExecutionListener    - beforePersist: com.haulmont.cuba.core.entity.ScheduledExecution-d5db38aa-d341-dc80-6364-12720e284be8 [new] @545755214
10:20:04.295 DEBUG r.m.e.c.h.ScheduledExecutionListener    - beforeAttach: com.haulmont.cuba.core.entity.ScheduledExecution-d5db38aa-d341-dc80-6364-12720e284be8 [detached] @545755214
10:20:04.392 DEBUG r.m.e.c.h.ScheduledExecutionListener    - beforeAttach: com.haulmont.cuba.core.entity.ScheduledExecution-d5db38aa-d341-dc80-6364-12720e284be8 [detached] @545755214
10:20:04.465 ERROR c.h.c.core.app.scheduling.RunnerBean    - Error running ScheduledTask{88f9c9a0-21b1-e41c-f1de-d9df35bfbf3d, beanName=ev_GdprHeartbeatBackgroundService, methodName=getGdprHe
artbeat, singleton=true, period=30}
javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.7.3.7-cuba): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "sys_scheduled_execution_pkey"
  Detail: Key (id)=(d5db38aa-d341-dc80-6364-12720e284be8) already exists.
Error Code: 0
Call: INSERT INTO SYS_SCHEDULED_EXECUTION (ID, CREATE_TS, CREATED_BY, FINISH_TIME, RESULT, SERVER, START_TIME, SYS_TENANT_ID, TASK_ID) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)
        bind => [d5db38aa-d341-dc80-6364-12720e284be8, 2020-08-03 10:20:04.311, admin, 2020-08-03 10:20:04.335, gdprHeartbeat: available 2020-08-03T08:20:04.294Z, vlt-devapp01:8080/quantum-co
re, 2020-08-03 10:20:04.214, null, 88f9c9a0-21b1-e41c-f1de-d9df35bfbf3d]

предыдущий успешный запуск:

10:19:33.200 DEBUG r.m.e.c.h.ScheduledExecutionListener    - beforePersist: com.haulmont.cuba.core.entity.ScheduledExecution-f19f62de-11d7-ef40-2bfd-f4d3d7314674 [new] @882027159
10:19:33.214 DEBUG r.m.e.c.h.ScheduledExecutionListener    - beforeAttach: com.haulmont.cuba.core.entity.ScheduledExecution-f19f62de-11d7-ef40-2bfd-f4d3d7314674 [detached] @882027159
#9

Судя по логу задача выполняется нормально, но при сохранении истории (ScheduledExecution) EclipseLink воспринимает detached объект как новый и пытается сделать INSERT вместо UPDATE (или после того как UPDATE не затронул ни одной существующей записи).

Сообщите пожалуйста следующее:

  • настройки entity cache (если есть)
  • настройки кластера (если есть)
  • настройки данного шедулера
  • версия PostgreSQL
#11

Константин, добрый день.

  • entity cache - отключен
  • кластер - включен
<config xmlns="urn:org:jgroups"
        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
        xsi:schemaLocation="urn:org:jgroups http://www.jgroups.org/schema/jgroups.xsd">

    <TCP 
        bind_addr="NON_LOOPBACK"
        bind_port="46588"
         recv_buf_size="${tcp.recv_buf_size:130k}"
         send_buf_size="${tcp.send_buf_size:130k}"
         max_bundle_size="64K"
         sock_conn_timeout="300"

         thread_pool.min_threads="0"
         thread_pool.max_threads="20"
         thread_pool.keep_alive_time="30000"/>

    <TCPPING async_discovery="true"
             initial_hosts="${jgroups.tcpping.initial_hosts:10.220.1.131[46588],10.220.1.132[46588]}"
             port_range="2"/>    
        <MERGE3 max_interval="30000"
            min_interval="10000"/>
    <FD_SOCK/>
    <FD_ALL/>
    <VERIFY_SUSPECT timeout="1500"/>
    <BARRIER/>
    <pbcast.NAKACK2 use_mcast_xmit="false"
                   discard_delivered_msgs="true"/>
    <UNICAST3/>
    <RSVP resend_interval="2000" timeout="10000"/>
    <pbcast.STABLE stability_delay="1000"
                   desired_avg_gossip="50000"
                   max_bytes="1M"/>
    <pbcast.GMS join_timeout="3000"
                view_bundling="true"/>
    <MFC max_credits="500K" min_threshold="0.20"/>
    <FRAG2/>
    <pbcast.STATE_TRANSFER/>

</config>
  • Postgres 11.8
  • задание:
    image
#12

Ничего подозрительного не вижу.
Остается включить логгирование по максимуму и потом смотреть участок в районе ошибки:

file appender - TRACE
com.haulmont.cuba.core.app.scheduling - TRACE
eclipselink.sql - DEBUG