NullPointerException in com.sun.jts.CosTransactions.RecoveryManager when restoring EJB timers

chrjohn · October 12, 2021, 10:22am

Hi,

we came across this issue with Payara 5.2020.4 and I just wanted to check if my understanding is correct.
One of our instances threw the following exception during startup:

[2021-09-09 06:03:54,145] [INFO ] [javax.enterprise.system.container.ejb.com.sun.ejb.containers] [Thread-21] [#1] ejb.timer_service_started [2021-09-09 06:03:54,145] [INFO ] [javax.enterprise.system.container.ejb.com.sun.ejb.containers] [Thread-21] [#1] ==> Restoring Timers ...
[2021-09-09 06:03:54,280] [INFO ] [org.eclipse.persistence.session./file:/home/xxx/applications/ejb-timer-service-app/WEB-INF/classes/___EJB__Timer__App] [Thread-21] [#1] EclipseLink, version: Eclipse Persistence Services - 2.7.6.payara-p1
[2021-09-09 06:04:01,096] [WARN ] [javax.enterprise.system.core.transaction.com.sun.jts.CosTransactions] [Thread-21] [#1] jts.unexpected_error_in_begin java.lang.NullPointerException at com.sun.jts.CosTransactions.RecoveryManager.waitForResync(RecoveryManager.java:1465)
    at com.sun.jts.CosTransactions.TransactionFactoryImpl.localCreate(TransactionFactoryImpl.java:180)
    at com.sun.jts.CosTransactions.CurrentImpl.begin(CurrentImpl.java:428)
    at com.sun.jts.jta.TransactionManagerImpl.begin(TransactionManagerImpl.java:296)
    at com.sun.enterprise.transaction.jts.JavaEETransactionManagerJTSDelegate.beginJTS(JavaEETransactionManagerJTSDelegate.java:496)
    at com.sun.enterprise.transaction.jts.JavaEETransactionManagerJTSDelegate.startJTSTx(JavaEETransactionManagerJTSDelegate.java:397)
    at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.startJTSTx(JavaEETransactionManagerSimplified.java:491)
    at com.sun.enterprise.transaction.jts.JavaEETransactionManagerJTSDelegate.enlistLAOResource(JavaEETransactionManagerJTSDelegate.java:316)
    at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.enlistResource(JavaEETransactionManagerSimplified.java:414)
    at com.sun.enterprise.resource.rm.SystemResourceManagerImpl.enlistResource(SystemResourceManagerImpl.java:103)

If I am not mistaken, the underlying source code should be this:

github.com

payara/Payara/blob/8761aec9e026e40214b53e70fae7f9a862a7a2b3/appserver/transaction/jts/src/main/java/com/sun/jts/CosTransactions/RecoveryManager.java#L1465

    
      
               */
              public static void waitForResync() {
          
          
        if (resyncInProgress != null) {
                      try {
          
          
                //
                          if (recoveryResynchTimeout == 0) {
                              resyncInProgress.waitEvent();
                          } else {
                              resyncInProgress.waitTimeoutEvent(recoveryResynchTimeout);
                          }
                      } catch (InterruptedException exc) {
          		_logger.log(Level.SEVERE,"jts.wait_for_resync_complete_interrupted");
          		 String msg = LogFormatter.getLocalizedMessage(_logger,
          			"jts.wait_for_resync_complete_interrupted");
                           throw  new org.omg.CORBA.INTERNAL(msg);
                      }
                  }
              }

The field which is checked for NULL is static volatile but AFAIK this does not prevent other threads from NULLing the field concurrently after it has been checked, for example here:

github.com

payara/Payara/blob/8761aec9e026e40214b53e70fae7f9a862a7a2b3/appserver/transaction/jts/src/main/java/com/sun/jts/CosTransactions/RecoveryManager.java#L697

    
      
              // Perform a keypoint of the log if required.
          
          
    if (keypointRequired) {
                  CoordinatorLog.keypoint();
              }
          
          
    // Post the resync in progress event semaphore.
          
          
    if (resyncInProgress != null) {
                  resyncInProgress.post();
                  resyncInProgress = null;
              }
          }
          
          
/**
           * Returns a reference to the Coordinator object that corresponds to the
           * local identifier passed as a parameter.
           *
           * @param localTID  The local identifier for the transaction.
           *
           * @return  The Coordinator object.

Is someone able to confirm this? This issue occurred only once up to now.

Many thanks in advance and best regards,

Chris.

pdudits · October 19, 2021, 7:18am

Yes, you’re right Chris, and congratulations to being that lucky hitting that race condition

The fix would be to assign resyncInProgress to local variable before checking, as the semaphore would synchronize interleaved post and wait calls properly.

rudy.de.busscher · October 19, 2021, 7:11pm

Hi Chris,

Can you create a Github issue for this so that we can address this problem in a future version? A PR for this is also appreciated.

Thanks.

chrjohn · October 21, 2021, 10:00am

Thanks for your replies and sorry for not responding earlier. I was expecting to get an email for new posts but somehow I didn’t. (unrelated question: how can I enable mail notifications?)

I will open a github issue and maybe even a PR (as time permits).

Thanks again.

chrjohn · November 6, 2021, 11:56pm

Created Bug Report: NullPointerException in com.sun.jts.CosTransactions.RecoveryManager · Issue #5491 · payara/Payara · GitHub

Topic		Replies	Views
Trialing Payara 5 Enterprise: application not deploying due to java.lang.NullPointerException at fish.payara.nucleus.microprofile.config.source.DirConfigSource.parsePropertyNameFromPath Technical Discussion	3	145	October 19, 2023
"java.lang.IllegalStateException: Cannot modify frozen instance for com.sun.gjc.monitoring.JdbcStatsProvider Technical Discussion	3	188	October 13, 2022
Deploying jax-rs war on 5.2022.2 causes NPE Technical Discussion	2	707	April 27, 2022
Problem with non-persistent EJBTimer Payara Server	1	192	July 26, 2023
Migration from Weblogic server 12.2 to Payara server 5 Technical Discussion	7	583	July 16, 2022

NullPointerException in com.sun.jts.CosTransactions.RecoveryManager when restoring EJB timers

Related Topics