从 REQUIRES_NEW 调用的 REQUIRES_NEW 方法导致 TransactionalInterceptorRequiresNew 中的 NullPointerException答案

【问题标题】：Method with REQUIRES_NEW called from REQUIRES_NEW causes NullPointerException in TransactionalInterceptorRequiresNew从 REQUIRES_NEW 调用的 REQUIRES_NEW 方法导致 TransactionalInterceptorRequiresNew 中的 NullPointerException
【发布时间】：2021-09-30 12:21:33
【问题描述】：

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

有一个@Singleton 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没有日志输出。

NullPointerException 在TransactionalInterceptorRequiresNew 尝试获取事务状态时被抛出：

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

有谁知道为什么交易突然变成null。事务管理器是否返回已经完成的事务B？

编辑：例如，当我尝试在checkForLongRunningJobs() 内的forEach() 之后更新一个实体时，会抛出一个异常，表明需要一个事务。所以进程从markJobAsBeingNotified()返回后，为checkForLongRunningJobs()创建的事务就消失了。

【问题讨论】：

标签： jpa transactions cdi

【解决方案1】：

我想我明白了：是 OptimisticLockException 搞砸了。

这是TransactionalInterceptorRequiresNew的代码sn-p：

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，应该如何处理异常？

【讨论】：