Entity log PK violates unique constraint sec_entity_log_pkey

Support
#1

Hi,

I’m occasionally getting a unique constraint error for Entity Log from my clients.
I’m unable to reproduce the error. And i’m unsure how to debug this.
The primary key of sec entity log is e UUID and collisions with UUID should be very rare right? But I have already have about 10 confirmed cases in the past 6 months and they happen for different tables.

2019-04-15 08:34:15.703 ERROR [http-nio-8080-exec-17/xxxx] com.haulmont.cuba.core.sys.ServiceInterceptor - Exception: 
org.springframework.transaction.TransactionSystemException: Could not commit JPA transaction; nested exception is javax.persistence.RollbackException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.6.2.cuba23): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "sec_entity_log_pkey"
  Detail: Key (id)=(b8fac962-9673-e339-283b-a6b98e088729) already exists.
Error Code: 0
Call: INSERT INTO SEC_ENTITY_LOG (ID, CHANGES, CREATE_TS, CREATED_BY, ENTITY, EVENT_TS, CHANGE_TYPE, ENTITY_ID, INT_ENTITY_ID, LONG_ENTITY_ID, STRING_ENTITY_ID, USER_ID) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
	bind => [b8fac962-9673-e339-283b-a6b98e088729
....

If i look in the Entity log the UUID mentioned is indeed already there, created 1 second before the error time stamp. It appears to be the exact same data in a few cases I investigated.
So the error message is clear, but whats going wrong with the Entity Log UUID generation?

Cuba Platform 6.9.8 with PostgreSQL.
I’m not doing any manual logging. Just standard setup via Administration module.

The complete error log is attached (some usernames and bind data where changed)
sec_entity_log_pkey.log (35.0 KB)

#3

Same problem.
Platform version 6.10.10

javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.6.2.cuba26): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "sec_entity_log_pkey"
  Подробности: Key (id)=(7c852dd9-f5cd-3348-4271-4dde93bd2b22) already exists.
Error Code: 0
Call: INSERT INTO SEC_ENTITY_LOG (ID, CHANGES, CREATE_TS, CREATED_BY, ENTITY, ENTITY_INSTANCE_NAME, EVENT_TS, CHANGE_TYPE, ENTITY_ID, INT_ENTITY_ID, LONG_ENTITY_ID, STRING_ENTITY_ID, USER_ID) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
        bind => [7c852dd9-f5cd-3348-4271-4dde93bd2b22, uuid=11d574f6-1a6b-0de6-0ad1-4c7d99a693c2
shop=а
date=2019-07-05 11\:00\:20.343
moveDoc=а
opertype=а
comment=
operIdTemporary=
shopId=90
giftcard=####\####### (Не выдан)
, 2019-07-05 11:01:59.829, bt, nl$GiftCardPrepaidUsageList, Fri Jul 05 11:01:57 MSK 2019 15000#27039 (Не выдан), 2019-07-05 11:01:57.68, C, null, null, 434453, null, 4374ab72-dbed-16cd-7336-4d5761df3081]
Query: InsertObjectQuery(com.haulmont.cuba.security.entity.EntityLogItem-7c852dd9-f5cd-3348-4271-4dde93bd2b22 [managed])
        at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:883) ~[eclipselink-2.6.2.cuba26.jar:2.6.2.cuba26]
        at com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport$ContainerResourceSynchronization.detachAll(PersistenceImplSupport.java:496) ~[cuba-core-6.10.10.jar:6.10.10]
        at com.haulmont.cuba.core.sys.persistence.PersistenceImplSupport$ContainerResourceSynchronization.beforeCommit(PersistenceImplSupport.java:449) ~[cuba-core-6.10.10.jar:6.10.10]
        at org.springframework.transaction.support.TransactionSynchronizationUtils.triggerBeforeCommit(TransactionSynchronizationUtils.java:95) ~[spring-tx-4.3.23.RELEASE.jar:4.3.23.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerBeforeCommit(AbstractPlatformTransactionManager.java:936) ~[spring-tx-4.3.23.RELEASE.jar:4.3.23.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:748) ~[spring-tx-4.3.23.RELEASE.jar:4.3.23.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:734) ~[spring-tx-4.3.23.RELEASE.jar:4.3.23.RELEASE]
        at com.haulmont.cuba.core.sys.TransactionImpl.commit(TransactionImpl.java:104) ~[cuba-core-6.10.10.jar:6.10.10]
        at com.haulmont.cuba.security.app.EntityLog$1.afterCommit(EntityLog.java:215) ~[cuba-core-6.10.10.jar:6.10.10]
        at org.springframework.transaction.support.TransactionSynchronizationUtils.invokeAfterCommit(TransactionSynchronizationUtils.java:133) ~[spring-tx-4.3.23.RELEASE.jar:4.3.23.RELEASE]
        at org.springframework.transaction.support.TransactionSynchronizationUtils.triggerAfterCommit(TransactionSynchronizationUtils.java:121) ~[spring-tx-4.3.23.RELEASE.jar:4.3.23.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerAfterCommit(AbstractPlatformTransactionManager.java:962) ~[spring-tx-4.3.23.RELEASE.jar:4.3.23.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:807) ~[spring-tx-4.3.23.RELEASE.jar:4.3.23.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:734) ~[spring-tx-4.3.23.RELEASE.jar:4.3.23.RELEASE]
        at com.haulmont.cuba.core.sys.TransactionImpl.commit(TransactionImpl.java:104) ~[cuba-core-6.10.10.jar:6.10.10]
        at com.haulmont.cuba.core.app.RdbmsStore.commit(RdbmsStore.java:476) ~[cuba-core-6.10.10.jar:6.10.10]
        at com.haulmont.cuba.core.app.DataManagerBean.commit(DataManagerBean.java:161) ~[cuba-core-6.10.10.jar:6.10.10]
        at com.haulmont.cuba.core.app.DataServiceBean.commit(DataServiceBean.java:41) ~[cuba-core-6.10.10.jar:6.10.10]
        at sun.reflect.GeneratedMethodAccessor12346.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_212]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_212]
#4

It’s difficult to understand what is wrong. Could you please create a small test project that reproduces the issue?

#5

I think It’s difficult to create small test project.
Problem is with standard fucntional of platform.
When added entity logging appeared this problem.

Perhaps this is important. Entity Listener is used BeforeInsertEntityListener and AfterInsert.
Before listener may change entity, afterInsert is empty and not change anything.
Now I removed AfterInsertListener.