CDI events: Transactional observer called BEFORE_COMPLETION causes INSERT statements to be executed twice

Question

I'm having problems with transactional CDI events. I want to perform some operations at the end of a transaction, before the commit. Currently I'm using transactional CDI events for this.

Here ist the code that saves an entity (or gets it, if it's already present):

@Override
public MyEntity getOrSave(MyEntity il) {
    return fetchByName(il.getName()).orElseGet(() -> {
        getEm().persist(il);
        getEm().flush();
        return il;
    });
}

Later an event is triggered that should perform an update of a table:

softwareRelatedActionPerformedEvent.fire(new SoftwareRelatedActionPerformedEvent(softwareId));

An observer listens to these events:

@Transactional(Transactional.TxType.REQUIRED)
public class UpdateSoftwareReadModelObserver {
    private static final Logger LOG = LoggerFactory.getLogger(UpdateSoftwareReadModelObserver.class);

    @Inject
    private SoftwareSearchViewDAO softwareSearchViewDAO;

    public void onSoftwareChange(@Observes(during = TransactionPhase.BEFORE_COMPLETION)
                                 @Nonnull final SoftwareRelatedActionPerformedEvent event) {
        LOG.debug("UPDATE OBS START000");
        final List<SoftwareSearchView> softwareSearchViews
            = softwareSearchViewDAO.fetchSoftwareSearchViewById(event.getSoftwareId());
        LOG.debug("UPDATE OBS END000");
    }
}

The DAO simply fetches some data:

@Inject
private EntityManager entityManager;

@Nonnull
@Override
public List<SoftwareSearchView> fetchSoftwareSearchViewById(@Nonnull Long softwareId) {
    return new JPAQuery<SoftwareSearchView>(entityManager).from(softwareSearchView)
        .where(softwareSearchView.softwareSearchId.id.eq(softwareId))
        .fetch();
}

Now the confusing part is that in the log I can see that the INSERT statement for MyEntity is executed twice, which causes a duplicate entry exception:

[2021-09-08T06:04:53.493+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093493] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-09-08 06:04:53.493--UnitOfWork(660360545)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--begin unit of work flush
]]

[2021-09-08T06:04:53.494+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093494] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-09-08 06:04:53.494--ClientSession(1676448281)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--TX beginTransaction, status=STATUS_ACTIVE
]]

[2021-09-08T06:04:53.494+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093494] [levelValue: 800] [[
  [EL Fine]: sql: 2021-09-08 06:04:53.494--ClientSession(1676448281)--Connection(1328559837)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--INSERT INTO swhrl.myentity (name) VALUES (?)
    bind => [I020-21-07-200]
]]

[2021-09-08T06:04:53.495+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093495] [levelValue: 800] [[
  [EL Fine]: sql: 2021-09-08 06:04:53.495--ClientSession(1676448281)--Connection(1328559837)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--select lastval()
]]

[2021-09-08T06:04:53.496+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093496] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-09-08 06:04:53.496--UnitOfWork(660360545)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--end unit of work flush
]]

[2021-09-08T06:04:53.496+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093496] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-09-08 06:04:53.496--UnitOfWork(660360545)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--resume unit of work
]]

[2021-09-08T06:04:53.500+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093500] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-09-08 06:04:53.5--UnitOfWork(660360545)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--TX beforeCompletion callback, status=STATUS_ACTIVE
]]

[2021-09-08T06:04:53.501+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093501] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-09-08 06:04:53.501--UnitOfWork(660360545)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--begin unit of work commit
]]

[2021-09-08T06:04:53.503+0000] [Payara 5.23.0] [FINE] [] [com.bmw.swhrl.kcmgmt.observer.UpdateSoftwareReadModelObserver] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093503] [levelValue: 500] [CLASSNAME: com.bmw.swhrl.kcmgmt.observer.UpdateSoftwareReadModelObserver] [METHODNAME: onSoftwareChange] [[
  UPDATE OBS START000]]

[2021-09-08T06:04:53.505+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093505] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-09-08 06:04:53.505--UnitOfWork(660360545)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--begin unit of work flush
]]

[2021-09-08T06:04:53.505+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093505] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-09-08 06:04:53.505--ClientSession(1676448281)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--TX beginTransaction, status=STATUS_ACTIVE
]]

[2021-09-08T06:04:53.505+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093505] [levelValue: 800] [[
  [EL Fine]: sql: 2021-09-08 06:04:53.505--ClientSession(1676448281)--Connection(148360781)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--INSERT INTO swhrl.myentity (name) VALUES (?)
    bind => [I020-21-07-200]
]]

[2021-09-08T06:04:53.511+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093511] [levelValue: 800] [[
  [EL Fine]: sql: 2021-09-08 06:04:53.511--ClientSession(1676448281)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--SELECT 1
]]

[2021-09-08T06:04:53.516+0000] [Payara 5.23.0] [INFO] [] [] [tid: _ThreadID=85 _ThreadName=http-thread-pool::http-listener-1(4)] [timeMillis: 1631081093516] [levelValue: 800] [[
  [EL Warning]: 2021-09-08 06:04:53.514--UnitOfWork(660360545)--Thread(Thread[http-thread-pool::http-listener-1(4),5,main])--Local Exception Stack: 
Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.7.7.payara-p3): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "myentity_name_key"
  Detail: Key (name)=(I020-21-07-200) already exists.

The first INSERT statement is executed when persist() is called. The second one when fetch() is called in fetchSoftwareSearchViewById().

You can also see that the observer is called during the beforeCompletion phase of the transaction.

Everything works when I comment out the database query in fetchSoftwareSearchViewById(), so executing this query somehow causes the INSERT statement to be executed again. I've checked the EntityManager instances used in getOrSave() and fetchSoftwareSearchViewById(), both are the same instances.

I have no idea what is going on here...

I'm using JDK 11 and Payara 5.23.

`MyEntity.name` is not the primary key/JPA ID, just a field with a unique constraint right? Also, have you tried removing the `@Transactional(Transactional.TxType.REQUIRED)` from the observer - it will run in the same transaction anyway. — Nikos Paraskevopoulos, Sep 08 '21 at 12:20

CDI events: Transactional observer called BEFORE_COMPLETION causes INSERT statements to be executed twice

0 Answers0