从REQUIRES_NEW调用REQUIRES_NEW的方法导致TransactionalInterceptorRequiresNew中出现NullPointerException

Question

我很难理解我的代码出了什么问题……

有一个EJB：

@Singleton
public class MailJobScheduler {

    @Inject
    private NewJobSchedulerBA newJobSchedulerBA;

    @Schedule(hour = "*", minute = "*", second = "*/10")
    public void doCheckForLongRunningJobs() {
        try {
            LOG.info("Checking for long running mail jobs...");
            newJobSchedulerBA.checkForLongRunningJobs(mailJobDAO);
        } catch (Exception e) {
            LOG.error("Unknown error while checking for long running mail jobs", e);
        }
    }
}

它只是从NewJobSchedulerBA调用一个方法。具体实现如下：

    @Override
    @Transactional(Transactional.TxType.REQUIRES_NEW)
    public <T extends AbstractAsyncJobBE> void checkForLongRunningJobs(JobDAO<T> jobDAO) {
        JobDAO.LongRunningJobs longRunningJobs = jobDAO.findLongRunningJobs();
        longRunningJobs.getJobs().stream()
            .filter(job -> !job.wasWarningMailSent())
            .forEach(job -> {
                LOG.info("Found long running job: {}", job);
                // the update is done inside a new transaction, so if something goes wrong with updating
                // one job entity the other updates might still succeed
                jobMonitoringBA.markJobAsBeingNotified(job);
                jobMonitoringBA.sendWarningMail(job, longRunningJobs.getWarningTime());
            });
    }

它在一个CDI bean中，并用REQUIRES_NEW注释，所以如果里面出了什么问题，我不希望我的调度器清除计时器。

这反过来调用JobMonitoringBA.markJobAsBeingNotified(...) (它也是一个CDI bean)：

    @Override
    @Transactional(Transactional.TxType.REQUIRES_NEW)
    public void markJobAsBeingNotified(AbstractAsyncJobBE job) {
        LOG.info("Updating job...");
        job = this.entityManager.merge(job);
        job.setWasWarningMailSent(true);
        LOG.info("Done");
    }

这里的想法是，当单个作业不能被更新时(例如，由于OptimisticLockException，那么其他作业仍然应该被更新。

当我强制执行OptimisticLockException时，我会得到以下日志输出：

[2021-07-23T12:11:10.001+0200] [Payara 4.1] [INFO] [] [com.bmw.swhrl.job.processor.scheduler.MailJobScheduler] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070001] [levelValue: 800] [[
  Checking for long running mail jobs...]]

[2021-07-23T12:11:10.002+0200] [Payara 4.1] [INFO] [] [com.bmw.swhrl.dao.impl.AbstractJobDAOImpl] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070002] [levelValue: 800] [[
  Finding long running jobs...]]

[2021-07-23T12:11:10.002+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070002] [levelValue: 800] [[
  [EL Finer]: connection: 2021-07-23 12:11:10.002--ServerSession(1144457050)--Thread(Thread[__ejb-thread-pool4,5,main])--client acquired: 223416353
]]

[2021-07-23T12:11:10.003+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070003] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:10.003--UnitOfWork(60223483)--Thread(Thread[__ejb-thread-pool4,5,main])--TX binding to tx mgr, status=STATUS_ACTIVE
]]

[2021-07-23T12:11:10.003+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070003] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:10.003--ClientSession(223416353)--Thread(Thread[__ejb-thread-pool4,5,main])--acquire unit of work: 60223483
]]

[2021-07-23T12:11:10.003+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070003] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:10.003--UnitOfWork(60223483)--Thread(Thread[__ejb-thread-pool4,5,main])--begin unit of work flush
]]

[2021-07-23T12:11:10.003+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070003] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:10.003--UnitOfWork(60223483)--Thread(Thread[__ejb-thread-pool4,5,main])--end unit of work flush
]]

[2021-07-23T12:11:10.003+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070003] [levelValue: 800] [[
  [EL Fine]: sql: 2021-07-23 12:11:10.003--ServerSession(1144457050)--Connection(128547665)--Thread(Thread[__ejb-thread-pool4,5,main])--SELECT ID, job_name, num_jobs_per_execution, warning_time_in_seconds FROM swhrl.job_type_configuration WHERE (job_name = ?)
    bind => [MailJobBE]
]]

[2021-07-23T12:11:10.005+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070005] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:10.005--UnitOfWork(60223483)--Thread(Thread[__ejb-thread-pool4,5,main])--begin unit of work flush
]]

[2021-07-23T12:11:10.005+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070005] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:10.005--UnitOfWork(60223483)--Thread(Thread[__ejb-thread-pool4,5,main])--end unit of work flush
]]

[2021-07-23T12:11:10.005+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070005] [levelValue: 800] [[
  [EL Fine]: sql: 2021-07-23 12:11:10.005--ServerSession(1144457050)--Connection(1207842220)--Thread(Thread[__ejb-thread-pool4,5,main])--SELECT id, bcc_recipients, content, created_by, created_date, job_failure_reason, job_result, job_status, recipients, stages, start_date, stop_date, subject, version, was_warning_mail_sent, job_id FROM swhrl.mail_job WHERE ((job_status = ?) AND (start_date < ?))
    bind => [STARTED, 2021-07-23 11:56:10.004]
]]

[2021-07-23T12:11:10.010+0200] [Payara 4.1] [INFO] [] [com.bmw.swhrl.dao.impl.AbstractJobDAOImpl] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070010] [levelValue: 800] [[
  Found 1 jobs]]

[2021-07-23T12:11:10.011+0200] [Payara 4.1] [INFO] [] [com.bmw.swhrl.job.processor.control.impl.NewJobSchedulerBAImpl] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070011] [levelValue: 800] [[
  Found long running job: MailJobBE[ id=1 ]]]

[2021-07-23T12:11:10.011+0200] [Payara 4.1] [INFO] [] [com.bmw.swhrl.job.processor.control.impl.JobMonitoringBAImpl] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070011] [levelValue: 800] [[
  Updating job...]]

[2021-07-23T12:11:10.012+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070012] [levelValue: 800] [[
  [EL Finer]: connection: 2021-07-23 12:11:10.012--ServerSession(1144457050)--Thread(Thread[__ejb-thread-pool4,5,main])--client acquired: 2016554542
]]

[2021-07-23T12:11:10.012+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070012] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:10.012--UnitOfWork(613966548)--Thread(Thread[__ejb-thread-pool4,5,main])--TX binding to tx mgr, status=STATUS_ACTIVE
]]

[2021-07-23T12:11:10.013+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070013] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:10.013--ClientSession(2016554542)--Thread(Thread[__ejb-thread-pool4,5,main])--acquire unit of work: 613966548
]]

[2021-07-23T12:11:10.017+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035070017] [levelValue: 800] [[
  [EL Fine]: sql: 2021-07-23 12:11:10.017--ServerSession(1144457050)--Connection(1633715874)--Thread(Thread[__ejb-thread-pool4,5,main])--SELECT id, bcc_recipients, content, created_by, created_date, job_failure_reason, job_result, job_status, recipients, stages, start_date, stop_date, subject, version, was_warning_mail_sent, job_id FROM swhrl.mail_job WHERE (id = ?)
    bind => [1]
]]

[2021-07-23T12:11:50.863+0200] [Payara 4.1] [INFO] [] [com.bmw.swhrl.job.processor.control.impl.JobMonitoringBAImpl] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035110863] [levelValue: 800] [[
  Done]]

[2021-07-23T12:11:50.863+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035110863] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:50.863--UnitOfWork(613966548)--Thread(Thread[__ejb-thread-pool4,5,main])--TX beforeCompletion callback, status=STATUS_ACTIVE
]]

[2021-07-23T12:11:50.864+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035110864] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:50.864--UnitOfWork(613966548)--Thread(Thread[__ejb-thread-pool4,5,main])--begin unit of work commit
]]

[2021-07-23T12:11:50.880+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035110880] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:50.88--ClientSession(2016554542)--Thread(Thread[__ejb-thread-pool4,5,main])--TX beginTransaction, status=STATUS_ACTIVE
]]

[2021-07-23T12:11:50.881+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035110881] [levelValue: 800] [[
  [EL Fine]: sql: 2021-07-23 12:11:50.881--ClientSession(2016554542)--Connection(1452902274)--Thread(Thread[__ejb-thread-pool4,5,main])--UPDATE swhrl.mail_job SET was_warning_mail_sent = ?, version = ? WHERE ((id = ?) AND (version = ?))
    bind => [true, 4, 1, 3]
]]

[2021-07-23T12:11:50.886+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035110886] [levelValue: 800] [[
  [EL Warning]: 2021-07-23 12:11:50.884--UnitOfWork(613966548)--Thread(Thread[__ejb-thread-pool4,5,main])--Local Exception Stack: 
Exception [EclipseLink-5006] (Eclipse Persistence Services - 2.6.4.qualifier): org.eclipse.persistence.exceptions.OptimisticLockException
Exception Description: The object [MailJobBE[ id=1 ]] cannot be updated because it has changed or been deleted since it was last read. 
Class> com.bmw.swhrl.entities.domain.MailJobBE Primary Key> 1
    at org.eclipse.persistence.exceptions.OptimisticLockException.objectChangedSinceLastReadWhenUpdating(OptimisticLockException.java:144)
    ...

[2021-07-23T12:11:50.887+0200] [Payara 4.1] [WARNING] [] [javax.enterprise.resource.jta.com.sun.enterprise.transaction] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035110887] [levelValue: 900] [[
  DTX5014: Caught exception in beforeCompletion() callback:
javax.persistence.OptimisticLockException: Exception [EclipseLink-5006] (Eclipse Persistence Services - 2.6.4.qualifier): org.eclipse.persistence.exceptions.OptimisticLockException
Exception Description: The object [MailJobBE[ id=1 ]] cannot be updated because it has changed or been deleted since it was last read. 
Class> com.bmw.swhrl.entities.domain.MailJobBE Primary Key> 1
    at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl$1.handleException(EntityManagerSetupImpl.java:743)
    ...

[2021-07-23T12:11:50.890+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035110890] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:50.89--UnitOfWork(613966548)--Thread(Thread[__ejb-thread-pool4,5,main])--TX afterCompletion callback, status=ROLLEDBACK
]]

[2021-07-23T12:11:50.890+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035110890] [levelValue: 800] [[
  [EL Finer]: transaction: 2021-07-23 12:11:50.89--UnitOfWork(613966548)--Thread(Thread[__ejb-thread-pool4,5,main])--release unit of work
]]

[2021-07-23T12:11:50.890+0200] [Payara 4.1] [INFO] [] [] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035110890] [levelValue: 800] [[
  [EL Finer]: connection: 2021-07-23 12:11:50.89--ClientSession(2016554542)--Thread(Thread[__ejb-thread-pool4,5,main])--client released
]]

[2021-07-23T12:12:16.311+0200] [Payara 4.1] [WARNING] [] [com.bmw.swhrl.job.processor.control.impl.NewJobSchedulerBAImpl] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035136311] [levelValue: 900] [[
  Error while trying to send warning message for job: [MailJobBE, id=1, error=Managed bean with Transactional annotation and TxType of REQUIRES_NEW encountered exception during commit javax.transaction.RollbackException: Transaction marked for rollback.]]]

[2021-07-23T12:12:25.409+0200] [Payara 4.1] [SEVERE] [] [com.bmw.swhrl.job.processor.scheduler.MailJobScheduler] [tid: _ThreadID=116 _ThreadName=__ejb-thread-pool4] [timeMillis: 1627035145409] [levelValue: 1000] [[
  Unknown error while checking for long running mail jobs
javax.transaction.TransactionalException: Managed bean with Transactional annotation and TxType of REQUIRES_NEW encountered exception during commit java.lang.NullPointerException
    at org.glassfish.cdi.transaction.TransactionalInterceptorRequiresNew.transactional(TransactionalInterceptorRequiresNew.java:122)
    ...
Caused by: java.lang.NullPointerException
    at org.glassfish.cdi.transaction.TransactionalInterceptorRequiresNew.transactional(TransactionalInterceptorRequiresNew.java:111)
    ... 51 more
]]

在这里，我不理解NullPointerException。根据事务的日志输出，可以看到在进入checkForLongRunningJobs()时创建了一个新事务(A)，在进入markJobAsBeingNotified()时创建了另一个事务(B)。回滚后一个事务B，但随后不会对事务A进行日志输出。

当TransactionalInterceptorRequiresNew尝试获取事务的状态时，将抛出NullPointerException：

if(getTransactionManager().getTransaction().getStatus() == Status.STATUS_MARKED_ROLLBACK) {
   getTransactionManager().rollback();
} else {
   getTransactionManager().commit();
}

有人知道为什么事务突然变成了null吗？事务管理器是否返回已完成的事务B？

编辑:例如，当我试图在checkForLongRunningJobs()中的forEach()之后更新一个实体时，抛出了一个异常，说明需要一个事务。因此，流程从markJobAsBeingNotified()返回后，为checkForLongRunningJobs()创建的事务就消失了。

Answer 1

我想我明白了:是OptimisticLockException把事情搞乱了。

以下是TransactionalInterceptorRequiresNew的代码片段

try {
    proceed = proceed(ctx);
} finally {
    try {
        TransactionManager tm = getTransactionManager();
        if (tm instanceof TransactionManagerHelper) {
           ((TransactionManagerHelper)tm).postInvokeTx(false,true);
        }
        // Exception handling for proceed method call above can set TM/TRX as setRollbackOnly
        if(getTransactionManager().getTransaction().getStatus() == Status.STATUS_MARKED_ROLLBACK) {
            getTransactionManager().rollback();
        } else {
            getTransactionManager().commit(); // <---- OptimisticLockException is thrown
        }
    } catch (Exception exception) {
        String messageString =
                "Managed bean with Transactional annotation and TxType of REQUIRES_NEW " +
                        "encountered exception during commit " +
                        exception;
        _logger.log(java.util.logging.Level.FINE, CDI_JTA_MBREQNEWCT, exception);
        throw new TransactionalException(messageString, exception);  <---- new Exception is thrown
    }
    if (suspendedTransaction != null) {
        try {
            getTransactionManager().resume(suspendedTransaction); <---- suspended transaction is not resumed
        } catch (Exception exception) {
            String messageString =
                    "Managed bean with Transactional annotation and TxType of REQUIRED " +
                            "encountered exception during resume " +
                            exception;
            _logger.log(java.util.logging.Level.FINE, CDI_JTA_MBREQNEWRT, exception);
            throw new TransactionalException(messageString, exception);
        }
    }

它在调用getTransactionManager().commit()时抛出。捕获此异常并抛出一个新的TransactionalException。但是挂起的事务不会恢复，因此当控制返回到checkForLongRunningJobs()时，此上下文中的事务不会恢复，并且当方法返回并且拦截器尝试获取事务的状态时，将抛出NullPointerException。

这是一种故意的行为吗？在OptimisticLockException的情况下，异常处理应该如何完成