EntityChangedEvent генерируется не всегда при одинаковых условиях

[artemaa (Artem Areshko)]

Попал на плавающую ошибку: при одних и тех же условиях и действиях, EntityChangedEvent не всегда отправляется/перехватывается. Причем пока только на одной машине (ессно в проде) для конкретного проекта.

• Win 10 Pro (1909)

Из подтверждения есть логи, где при изменении одного и того же поля (на которое настроен Listener) в одном случае:

2020-09-09 16:07:32.064 DEBUG [] com.haulmont.cuba.core.app.SavedEntitiesHolder - Created SavedEntitiesHolder@556f2d
2020-09-09 16:07:32.064 DEBUG [] com.haulmont.cuba.core.app.SavedEntitiesHolder - SavedEntitiesHolder@556f2d updates entities: [-d2de25a2-76cb-b663-a10e-697270e0239f [managed]]
2020-09-09 16:07:32.064 DEBUG [] com.haulmont.cuba.core.app.SavedEntitiesHolder - Released SavedEntitiesHolder@556f2d

а в другом отрабатывает listener:

2020-09-09 16:07:41.404 DEBUG [] com.haulmont.cuba.core.app.SavedEntitiesHolder - Created SavedEntitiesHolder@107c780
2020-09-09 16:07:41.404 DEBUG [] com.haulmont.cuba.core.app.SavedEntitiesHolder - SavedEntitiesHolder@107c780 updates entities: [-d2de25a2-76cb-b663-a10e-697270e0239f [managed]]
2020-09-09 16:07:41.404 DEBUG [] com.haulmont.cuba.core.app.RdbmsStore - load: metaClass=_Request, id=d2de25a2-76cb-b663-a10e-697270e0239f, view=
2020-09-09 16:07:41.419 INFO  [] ChangedListener - Executor changed for request d2de25a2-76cb-b663-a10e-697270e0239f

Встречались ли с такой проблемой? Куда можно капнуть?

[artemaa (Artem Areshko)]

upd:

1. Версия платформы: 2.7.2
2. Аналогичное поведение (с тем, что не отрабатывают Listener) возникает при открытии отчетов. Т.к. полосы и все настройки считываются на событии deattach, иногда отчет открывается пустой (без полос/форматирования и т.д., иногда нормальный)

[krivopustov (Konstantin Krivopustov)]

Артем,
Во первых, уточните пожалуйста версию платформы (2.7.2 не существует).
Если у вас ниже чем 7.2.7, то обновите.

В течение ближайшей недели мы выпустим 7.2.8 с более детальным логгированием отсылки EntityChangedEvent. Так что если проблема останется, обновитесь на 7.2.8 и включите логгирование TRACE следующим образом:

    <appender name="File" class="ch.qos.logback.core.rolling.RollingFileAppender">
...
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>TRACE</level>
        </filter>
...
    <logger name="com.haulmont.cuba.core.sys.persistence.EntityChangedEventManager" level="TRACE"/>

Присылайте лог, будем думать дальше.

С уважением,
Константин

[artemaa (Artem Areshko)]

Да, версия 7.2.7.

А что на счет https://doc.cuba-platform.com/manual-latest-ru/entity_listeners.html - deattch для отчетов тоже ведет себя крайне странно

[krivopustov (Konstantin Krivopustov)]

Добавьте в лог следующее:

<logger name="com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport" level="TRACE"/>
<logger name="com.haulmont.cuba.core.sys.listener.EntityListenerManager" level="TRACE"/>

[artemaa (Artem Areshko)]

Upd:

Явно не зависит от системы. Поставил на машине docker и запустил приложение в нем - почти сразу началась та же фигня…

[artemaa (Artem Areshko)]

Добавил логирование. Вот лог и скриншоты от 2х последовательных открытий отчета:

1. Пустой отчет

2020-09-21 10:56:04.595 DEBUG [qtp26266051-1552/russcomservice-core/admin] com.haulmont.cuba.core.app.RdbmsStore - load: metaClass=report$Report, id=d21d1e22-43b7-ac09-abad-062b340bf8ab, view=com.haulmont.reports.entity.Report/report.edit
2020-09-21 10:56:04.609 TRACE [qtp26266051-1552/russcomservice-core/admin] com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport - ContainerResourceHolder.registerInstanceForUnitOfWork: instance = com.haulmont.reports.entity.ReportGroup-604008fc-7717-20a7-4a24-f224fffd1247 [], UnitOfWork = UnitOfWork(
	DatabaseAccessor(connected)
	CubaPostgreSQLPlatform)
2020-09-21 10:56:04.609 TRACE [qtp26266051-1552/russcomservice-core/admin] com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport - ContainerResourceHolder.registerInstanceForUnitOfWork: instance = com.haulmont.reports.entity.ReportTemplate-7b5dfe2e-69df-3a05-cfd2-3392b48653c7 [], UnitOfWork = UnitOfWork(
	DatabaseAccessor(connected)
	CubaPostgreSQLPlatform)
2020-09-21 10:56:04.609 TRACE [qtp26266051-1552/russcomservice-core/admin] com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport - ContainerResourceHolder.registerInstanceForUnitOfWork: instance = com.haulmont.reports.entity.Report-d21d1e22-43b7-ac09-abad-062b340bf8ab [], UnitOfWork = UnitOfWork(
	DatabaseAccessor(connected)
	CubaPostgreSQLPlatform)

2. Корректный отчет

2020-09-21 10:56:42.533 DEBUG [qtp26266051-21/russcomservice-core/admin] com.haulmont.cuba.core.app.RdbmsStore - load: metaClass=report$Report, id=d21d1e22-43b7-ac09-abad-062b340bf8ab, view=com.haulmont.reports.entity.Report/report.edit
2020-09-21 10:56:42.541 TRACE [qtp26266051-21/russcomservice-core/admin] com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport - ContainerResourceHolder.registerInstanceForUnitOfWork: instance = com.haulmont.reports.entity.ReportGroup-604008fc-7717-20a7-4a24-f224fffd1247 [], UnitOfWork = UnitOfWork(
	DatabaseAccessor(connected)
	CubaPostgreSQLPlatform)
2020-09-21 10:56:42.541 TRACE [qtp26266051-21/russcomservice-core/admin] com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport - ContainerResourceHolder.registerInstanceForUnitOfWork: instance = com.haulmont.reports.entity.ReportTemplate-7b5dfe2e-69df-3a05-cfd2-3392b48653c7 [], UnitOfWork = UnitOfWork(
	DatabaseAccessor(connected)
	CubaPostgreSQLPlatform)
2020-09-21 10:56:42.541 TRACE [qtp26266051-21/russcomservice-core/admin] com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport - ContainerResourceHolder.registerInstanceForUnitOfWork: instance = com.haulmont.reports.entity.Report-d21d1e22-43b7-ac09-abad-062b340bf8ab [], UnitOfWork = UnitOfWork(
	DatabaseAccessor(connected)
	CubaPostgreSQLPlatform)
2020-09-21 10:56:42.541 TRACE [qtp26266051-21/russcomservice-core/admin] com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport - ContainerResourceSynchronization.beforeCommit: instances=[com.haulmont.reports.entity.Report-d21d1e22-43b7-ac09-abad-062b340bf8ab [managed], com.haulmont.reports.entity.ReportTemplate-7b5dfe2e-69df-3a05-cfd2-3392b48653c7 [managed], com.haulmont.reports.entity.ReportGroup-604008fc-7717-20a7-4a24-f224fffd1247 [managed]], readOnly=true
2020-09-21 10:56:42.541 DEBUG [qtp26266051-21/russcomservice-core/admin] com.haulmont.cuba.core.sys.listener.EntityListenerManager - Executing BEFORE_DETACH entity listener for com.haulmont.reports.entity.Report id=d21d1e22-43b7-ac09-abad-062b340bf8ab
2020-09-21 10:56:42.546 TRACE [qtp26266051-21/russcomservice-core/admin] com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport - ContainerResourceSynchronization.afterCompletion: instances = [com.haulmont.reports.entity.Report-d21d1e22-43b7-ac09-abad-062b340bf8ab [detached], com.haulmont.reports.entity.ReportTemplate-7b5dfe2e-69df-3a05-cfd2-3392b48653c7 [detached], com.haulmont.reports.entity.ReportGroup-604008fc-7717-20a7-4a24-f224fffd1247 [detached]]

[artemaa (Artem Areshko)]

Приложение завернуто в UberJar

[krivopustov (Konstantin Krivopustov)]

Хотелось бы увидеть более полный лог. Можете выслать его мне в личном сообщении.

[artemaa (Artem Areshko)]

Да, конечно. Обновился на 7.2.8. Проблемы не ушли. Включу логирование на EntityChangedEventManager, PersistenceImplSupport, EntityListenerManager, соберу данные и вышлю.
На сколько полный лог вы ожидаете?

[krivopustov (Konstantin Krivopustov)]

@artemaa

На сколько полный лог вы ожидаете?

Лучше весь с момента старта сервера. Если большая загрузка и лог слишком большой - как минимум на несколько секунд до и после проблемного места.

[krivopustov (Konstantin Krivopustov)]

Спасибо за логи.

К сожалению, ситуация прежнему непонятная, и мы сталкиваемся с ней впервые.

Нет ли каких-то специфических настроек в данном проекте, например Entity Cache? Возможно, что-то еще отличает данное приложение или его environment? Какова нагрузка (количество одновременных пользователей, частота вызова заданий)? Один инстанс приложения или кластер?

В дальнейшем давайте разделим обсуждение на две проблемы.

1. Проблема с onDetach entity listener.

Выглядит так как будто не происходит синхронизации с коммитом транзакции при чтении отчета. Добавьте пожалуйста еще один логгер:

<logger name="org.springframework.orm.jpa.JpaTransactionManager" level="TRACE"/>

Редактирование отчета вызывается обычным образом, просто экран открывается из меню?

2. Проблема с EntityChangedEvent.

Нужен исходный код сущности RepairRequest и всего что с ней происходит при изменении - все сервисы, листенеры и пр. через которые она проходит.

[artemaa (Artem Areshko)]

Спасибо

По поводу настроек:

1. Entity Cache не настраивался
2. Количество одновременных пользователей (сессий) маленькое: 10-15
3. Каких-то особрых настроек окружения не было. Проверялось на dev стенде с таким же вариантов развертывания. Приложение поднималось в docker (Docker Descktop, Linux Containers) - проблемы сохраняются
4. Самое частое задание: на отправку email: раз в минуту по cron (было 30 сек по Period)
5. Один инстанс

Мне создать отдельную тему для проблемы с onDeatach entity listener?

[krivopustov (Konstantin Krivopustov)]

Раз ничего особенного в настройках нет, придется смотреть все целиком. Присылайте мне в личку исходники проекта и скрипты сборки/запуска в докере.

[artemaa (Artem Areshko)]

Константин, спасибо за помощь!

Попробую предварительно подключиться дебаггером к проблемному инстансу и понять, что происходит. Может найду какие-то зацепки

[artemaa (Artem Areshko)]

@krivopustov наблюдал за detached событием и наблюдение номер раз: проблема начинает проявлятся при некоторое нагрузке (количестве сессий). 3-5 сессий (без учета админских и анонимной) - все ок. Когда из штук 10 - видна проблема. Как можно съэмулировать нагрузку из разных сессий на локальном окружении?

[krivopustov (Konstantin Krivopustov)]

@artemaa

Как можно съэмулировать нагрузку из разных сессий на локальном окружении?

С помощью JMeter: https://www.cuba-platform.com/discuss/t/performance-testing-for-web-ui-with-jmeter/5729

[artemaa (Artem Areshko)]

Зафиксирую тут некоторые моменты дебага, которые проводил для Detach события, потому как нет ничего навернутого мной, просто открываю экран отчета из интерфейса.

Проблема с тем, что не срабатывает событие действительно связано с тем, что теряется объект синхронизации при обработке транзакции. А конкретно ContainerResourceSynchronization с ContainerResourceHolder.

Проблема начинается с

ContainerResourceHolder holder =
                (ContainerResourceHolder) TransactionSynchronizationManager.getResource(RESOURCE_HOLDER_KEY);
if (holder == null) {

в PersistenceSupportImpl.getInstanceContainerResourceHolder(). Иногда holder не null (при начале транзакции) и уже синхронизирован с транзакцией (и в нем куча непонятных UnitOfWork). Соответственно новая синхронизация не регистрируется.

Судя по всему в какой-то момент для потока не происходит очистка ресурсов после транзакции и они остаются висеть, периодически попадая в обработку, если поток отдается пользователю.

Есть ощущение, что проблема с EntityChangedEvent растет отсюда же…

[krivopustov (Konstantin Krivopustov)]

У вас один data store или несколько?

[artemaa (Artem Areshko)]

Только один, MAIN