Transaction state passed on to next transactional method causing Infinispan to complain

[jvskriubakken]

Hi people!

I'm wondering if anyone as a good advice on this one.

I'm having an ear application more or less as outlined below (in pseudo-style, hopefully understandable):

ear {
  ejb {

    @Startup
    @Singleton
    @TransactionManagement(TransactionManagementType.CONTAINER)
    @TransactionAttribute(TransactionAttributeType.NOT_SUPPORTED)
    SchedulerBean {

      @Timeout 
      timeout() {

        Something something;
        try {
          something = someService.getById("unknown-id") // throws as expected an NotFoundException 
        }
        cath(NotFoundException e) {
          errors.addError(e)
        }

        SomethingElse sometingElse = somethingElseService.getById() // throws java.lang.IllegalStateException:
                                
      }
    }

    ...

    SomethingService {

      @Transactional(TxType.REQUIRED)
      getById(id) throws NotFoundException {
        ...
      }
    }
  }
}

We are having a "SchedulerBean" triggering execution in our application, which is marked with @TransactionAttribute(TransactionAttributeType.NOT_SUPPORTED), while our service methods are with @Transactional and the default REQUIRED type. The effect we want is that there is no transaction outside the service methods marked with @Transactinal, and that those methods transactions are done after method invocation. However, what we are experiencing is that if SomeService.getById throws an exception (and then "rollbacked"), then the state of this transaction seems to be brought along to the next invoked service method marked as @Transactional. Because, since we are using Hibernate second level cache, we get the following exception from infinispan:

2017-11-07 10:56:00,477 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (EJB default - 2) ISPN000136: Error executing command GetKeyValueCommand, writing keys []: java.lang.IllegalStateException: Transaction TransactionImple < ac, BasicAction: 0:ffffc0a8e63f:-5d0b8c54:5a0019b0:6c13 status: ActionStatus.ABORT_ONLY > is not in a valid state to be invoking cache operations on.

        at org.infinispan.interceptors.TxInterceptor.enlist(TxInterceptor.java:395)

        at org.infinispan.interceptors.TxInterceptor.enlistIfNeeded(TxInterceptor.java:351)

        at org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:345)

        at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:331)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:43)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)

        at org.infinispan.interceptors.CacheMgmtInterceptor.visitDataReadCommand(CacheMgmtInterceptor.java:103)

        at org.infinispan.interceptors.CacheMgmtInterceptor.visitGetKeyValueCommand(CacheMgmtInterceptor.java:91)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:43)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)

        at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:114)

        at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:83)

        at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:43)

        at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:335)

        at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:411)

        at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:403)

        at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:286)

        at org.hibernate.cache.infinispan.access.InvalidationCacheAccessDelegate.get(InvalidationCacheAccessDelegate.java:61)

        at org.hibernate.cache.infinispan.entity.ReadOnlyAccess.get(ReadOnlyAccess.java:44)

        at org.hibernate.engine.internal.CacheHelper.fromSharedCache(CacheHelper.java:32)

        at org.hibernate.event.internal.DefaultLoadEventListener.getFromSharedCache(DefaultLoadEventListener.java:651)

        at org.hibernate.event.internal.DefaultLoadEventListener.loadFromSecondLevelCache(DefaultLoadEventListener.java:595)

        at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:462)

        at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:219)

        at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:278)

        at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:121)

        at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:89)

        at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1129)

        at org.hibernate.internal.SessionImpl.access$2600(SessionImpl.java:164)

        at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2696)

        at org.hibernate.internal.SessionImpl.get(SessionImpl.java:975)

        at org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1075)

        at org.hibernate.jpa.spi.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:1033)

        at org.jboss.as.jpa.container.AbstractEntityManager.find(AbstractEntityManager.java:213)

        at no.logiq.common.jpa.dao.JpaUtil.get(JpaUtil.java:79)

        at no.logiq.common.jpa.dao.AbstractJpaDao.getById(AbstractJpaDao.java:79)

        at no.logiq.wjnordic.core.dao.organization.OrganizationDaoImpl.getByIdOrNotFoundException(OrganizationDaoImpl.java:46)

        at no.logiq.wjnordic.core.service.organization.OrganizationServiceImpl.getById(OrganizationServiceImpl.java:160)

        at no.logiq.wjnordic.core.service.organization.OrganizationServiceImpl$Proxy$_$$_WeldSubclass.getById$$super(Unknown Source)

        at sun.reflect.GeneratedMethodAccessor243.invoke(Unknown Source)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

        at java.lang.reflect.Method.invoke(Method.java:498)

        at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:49)

        at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:77)

        at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.invokeInCallerTx(TransactionalInterceptorBase.java:129)

        at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:55)

        at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:76)

        at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:47)

        at sun.reflect.GeneratedMethodAccessor146.invoke(Unknown Source)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

        at java.lang.reflect.Method.invoke(Method.java:498)

        at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:74)

        at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)

        at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)

        at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)

        at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)

        at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)

        at no.logiq.wjnordic.core.service.organization.OrganizationServiceImpl$Proxy$_$$_WeldSubclass.getById(Unknown Source)

        at java.util.HashMap.computeIfAbsent(HashMap.java:1126)

        at no.logiq.wjnordic.core.service.organization.CachingOrganizationCatalogue.getById(CachingOrganizationCatalogue.java:33)

        at no.logiq.wjnordic.core.domain.product.reader.AbstractProductReader.getProductReadResult(AbstractProductReader.java:244)

        at no.logiq.wjnordic.core.domain.product.reader.ProductCsvReader.read(ProductCsvReader.java:11)

        at no.logiq.wjnordic.core.domain.product.imp.ProductImportFileReader.read(ProductImportFileReader.java:64)

        at no.logiq.wjnordic.engine.service.product.imp.ProductImportServiceImpl.execute(ProductImportServiceImpl.java:177)

        at no.logiq.wjnordic.engine.ejb.product.imp.ProductImportSchedulerBean.doJob(ProductImportSchedulerBean.java:51)

This problem seems to go away if we mark our service methods with @Transactional(REQUIRES_NEW),

but is this really the preferred way? Could the TransactionAttribute on the SchedulerBean be set to something else instead to avoid my problem?

Or could it be something wrong with my hibernate cache config? Like the transaction mode?

<cache-container name="hibernate" default-cache="local-query" module="org.hibernate.infinispan" statistics-enabled="true">
  <transport lock-timeout="60000"/>
  <local-cache name="local-query" statistics-enabled="true">
  <eviction strategy="LRU" max-entries="10000"/>
  <expiration max-idle="100000"/>
  </local-cache>
  <invalidation-cache name="entity" statistics-enabled="true" mode="SYNC">
  <transaction mode="NON_XA"/>
  <eviction strategy="LRU" max-entries="10000"/>
  <expiration max-idle="100000"/>
  </invalidation-cache>
  <replicated-cache name="timestamps" statistics-enabled="true" mode="ASYNC"/>
</cache-container>

Thanks for any guidance!!

Jørund

[jaikiran]

The behaviour you are seeing (or what you explain with that exception stacktrace) seems to imply that the Timeout method (within which all the other calls happen) seems to be already running in a transaction (something like a REQUIRED or REQUIRES_NEW semantics on the timeout method). Which exact version of WildFly is this and is this code that you pasted replicate the exact same semantics (including classes extending other classes etc...)?

[jvskriubakken]

Hi,

The Timeout-method has no transaction marker (as outlined in the pseudo-code above), the only additional transaction marker outside the service methods is the one on top of the SchedulerBean, saying: @TransactionAttribute(TransactionAttributeType.NOT_SUPPORTED).

I'm running version 10.1.0.1 of Wildfly.

[pferraro]

Are you able to reproduce this issue on 11.0.0.Final?

[jvskriubakken]

No, we have not tried. Neither are we able to just upgrade to WF11.

Do you mean by this question that my configured should have worked like it is? And that I might have encountered a bug that might have been solved in WF11?

I was hoping that you expert guys on transactions, would know if my tx-config of having Tx = NOT_SUPPPORTED on the EJB Bean and Tx = REQUIRED is sound config or if I should have something else on the EJB Bean or leave the EJB Bean as is and apply Tx = REQUIRES_NEW on every service method invoked within the bean?

Thanks!

[jaikiran]

Jørund Vier Skriubakken wrote:

Do you mean by this question that my configured should have worked like it is? And that I might have encountered a bug that might have been solved in WF11?

We are not sure yet. Typically, we ask users to use latest released version of WildFly, if possible, since that makes it lot easier for WildFly developers to check the server code and if it does turn out to be a bug, allows us to push a fix to subsequent releases.

I was hoping that you expert guys on transactions, would know if my tx-config of having Tx = NOT_SUPPPORTED on the EJB Bean and Tx = REQUIRED is sound config or if I should have something else on the EJB Bean or leave the EJB Bean as is and apply Tx = REQUIRES_NEW on every service method invoked within the bean?

The snippet you pasted has multiple things going on - (Container managed transactional) EJBs and CDI beans with transactional annotations, which makes it a bit complex to understand what's going on. Furthermore, I don't remember the EJB3 spec around @Timeout callback methods and the transaction semantics on it. I will have to read it up afresh, probably tomorrow, or someone else who's more aware of it might be able to help.

In the meantime though, can you try adding the following annotation on your EJB's timeout method and see if makes any difference to your use case:

@TransactionAttribute(TransactionAttributeType.NOT_SUPPORTED) 
SchedulerBean { 



      @Timeout 
  @TransactionAttribute(TransactionAttributeType.NOT_SUPPORTED) 
  timeout() {
    ....

Finally, if it's possible to reproduce this in a simple application that you can attach, then that might help us narrow down on whether or not this is a bug.