search

OpenLiberty / open-liberty

Open Liberty is a highly composable, fast to start, dynamic application server runtime environment
https://openliberty.io
Eclipse Public License 2.0
1.14k stars 587 forks source link

J2CA0030E: Method enlist caught java.lang.IllegalStateException: Illegal attempt to enlist 2PC XAResource without recovery information #25886

Open krismarc opened 1 year ago

krismarc commented 1 year ago

Hi there,

one of our applications (pretty legacy one) using XAtransactions with DB2 started to fail with below error. After switching from 23.0.0.1 to 23.0.0.6. No code or java version changes except Liberty.

I've reviewed history of related classes changes and seems like indeed something was done. https://github.com/OpenLiberty/open-liberty/commits/cada2b83d9ca4a79f2e57a0366dc1d89fb14f938/dev/com.ibm.ws.jdbc/src/com/ibm/ws/rsadapter/impl https://github.com/OpenLiberty/open-liberty/commits/cada2b83d9ca4a79f2e57a0366dc1d89fb14f938/dev/com.ibm.ws.jca.cm/src/com/ibm/ejs/j2c https://github.com/OpenLiberty/open-liberty/commits/cada2b83d9ca4a79f2e57a0366dc1d89fb14f938/dev/com.ibm.ws.transaction/src/com/ibm/ws/transaction/services https://github.com/OpenLiberty/open-liberty/commits/cada2b83d9ca4a79f2e57a0366dc1d89fb14f938/dev/com.ibm.tx.jta/src/com/ibm/tx/jta/impl

@nmittles, @jmstephensgit, @tabishop @neilgsyoung, @jonhawkes, @dazavala could you please take a look? You have contributed recently 🥇 

[8/3/23 11:09:13:317 UTC] 00000059 com.ibm.ejs.j2c.XATransactionWrapper                         E J2CA0030E: Method enlist caught java.lang.IllegalStateException: Illegal attempt to enlist 2PC XAResource without recovery information
        at com.ibm.tx.jta.impl.TransactionImpl.enlistResource(TransactionImpl.java:2077)
        at com.ibm.tx.jta.embeddable.impl.EmbeddableTranManagerSet.enlist(EmbeddableTranManagerSet.java:141)
        at com.ibm.ws.transaction.services.TransactionManagerService.enlist(TransactionManagerService.java:419)
        at com.ibm.ejs.j2c.XATransactionWrapper.enlist(XATransactionWrapper.java:460)
        at com.ibm.ejs.j2c.ConnectionManager.lazyEnlist(ConnectionManager.java:1429)
        at com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl.lazyEnlistInGlobalTran(WSRdbManagedConnectionImpl.java:1831)
        at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.beginTransactionIfNecessary(WSJdbcConnection.java:391)
        at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.getMetaData(WSJdbcConnection.java:1616)
        at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:70)
        at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:35)
        at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.initiateService(StandardServiceRegistryImpl.java:101)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.createService(AbstractServiceRegistryImpl.java:263)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:237)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:214)
        at org.hibernate.id.factory.internal.DefaultIdentifierGeneratorFactory.injectServices(DefaultIdentifierGeneratorFactory.java:152)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.injectDependencies(AbstractServiceRegistryImpl.java:286)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:243)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:214)
        at org.hibernate.boot.internal.InFlightMetadataCollectorImpl.<init>(InFlightMetadataCollectorImpl.java:175)
        at org.hibernate.boot.model.process.spi.MetadataBuildingProcess.complete(MetadataBuildingProcess.java:118)
        at org.hibernate.boot.model.process.spi.MetadataBuildingProcess.build(MetadataBuildingProcess.java:83)
        at org.hibernate.boot.internal.MetadataBuilderImpl.build(MetadataBuilderImpl.java:473)
        at org.hibernate.boot.internal.MetadataBuilderImpl.build(MetadataBuilderImpl.java:84)
        at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:689)
        at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:724)
        at org.springframework.orm.hibernate5.LocalSessionFactoryBean.buildSessionFactory(LocalSessionFactoryBean.java:616)
        at org.springframework.orm.hibernate5.LocalSessionFactoryBean.afterPropertiesSet(LocalSessionFactoryBean.java:600)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1863)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1800)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:620)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542)
        at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:330)
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:113)
        at org.springframework.beans.factory.support.ConstructorResolver.resolveConstructorArguments(ConstructorResolver.java:707)
        at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:198)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:1372)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1222)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:582)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542)
        at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:953)
        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918)
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:583)
        at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:144)
        at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:95)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:211)
        at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:117)
        at org.springframework.beans.factory.support.ConstructorResolver.instantiate(ConstructorResolver.java:311)
        at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:296)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:1372)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1222)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:582)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542)
        at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:953)
        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918)
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:583)
        at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:144)
        at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:85)
        at com.*.as1.common5.spring.util.AS1SpringContainers.doRegisterContainer(AS1SpringContainers.java:133)
        at com.*.as1.common5.spring.util.AS1SpringContainers.registerMainContainer(AS1SpringContainers.java:115)
        at com.*.as1.common5.spring.util.AS1SpringContainers.registerMainContainer(AS1SpringContainers.java:82)
        at com.*.a14.ejb.A14ApplicationInitialization.initializeApplication(A14ApplicationInitialization.java:47)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:202)
        at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:587)
        at com.ibm.ws.cdi.ejb.impl.InterceptorChain.proceed(InterceptorChain.java:121)
        at com.ibm.ws.cdi.ejb.impl.EJBCDIInterceptorWrapper.invokeInterceptors(EJBCDIInterceptorWrapper.java:133)
        at com.ibm.ws.cdi.ejb.impl.EJBCDIInterceptorWrapper.postConstruct(EJBCDIInterceptorWrapper.java:69)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:191)
        at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:579)
        at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73)
        at com.ibm.ws.cdi.ejb.interceptor.WeldSessionBeanInterceptorWrapper.aroundInvoke(WeldSessionBeanInterceptorWrapper.java:60)
        at com.ibm.ws.cdi.ejb.interceptor.WeldSessionBeanInterceptorWrapper.postConstruct(WeldSessionBeanInterceptorWrapper.java:69)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:191)
        at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:579)
        at com.ibm.ejs.container.interceptors.InvocationContextImpl.doLifeCycle(InvocationContextImpl.java:328)
        at com.ibm.ejs.container.SingletonBeanO.callTransactionalLifecycleInterceptors(SingletonBeanO.java:223)
        at com.ibm.ejs.container.SingletonBeanO.initialize(SingletonBeanO.java:309)
        at com.ibm.ejs.container.BeanOFactory.create(BeanOFactory.java:105)
        at com.ibm.ejs.container.EJSHome.createSingletonBeanO(EJSHome.java:3478)
        at com.ibm.ejs.csi.EJBApplicationMetaData.createStartupBeans(EJBApplicationMetaData.java:1005)
        at com.ibm.ejs.csi.EJBApplicationMetaData.startedModule(EJBApplicationMetaData.java:739)
        at com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl.start(EJBRuntimeImpl.java:1123)
        at com.ibm.ws.ejbcontainer.osgi.internal.EJBModuleRuntimeContainerImpl.startModule(EJBModuleRuntimeContainerImpl.java:166)
        at com.ibm.ws.app.manager.module.internal.ModuleHandlerBase.deployModule(ModuleHandlerBase.java:101)
        at com.ibm.ws.app.manager.module.internal.DeployedModuleInfoImpl.installModule(DeployedModuleInfoImpl.java:51)
        at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.deployModules(SimpleDeployedAppInfoBase.java:599)
        at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.installApp(SimpleDeployedAppInfoBase.java:513)
        at com.ibm.ws.app.manager.module.internal.DeployedAppInfoBase.deployApp(DeployedAppInfoBase.java:351)
        at com.ibm.ws.app.manager.ear.internal.EARApplicationHandlerImpl.install(EARApplicationHandlerImpl.java:79)
        at com.ibm.ws.app.manager.internal.statemachine.StartAction.execute(StartAction.java:184)
        at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.enterState(ApplicationStateMachineImpl.java:1369)
        at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.run(ApplicationStateMachineImpl.java:912)
        at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:247)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:826)
 while trying to enlist resources from DataSource jdbc/A14 with the Transaction Manager for the current transaction, and threw a ResourceException.
[8/3/23 11:09:13:377 UTC] 00000059 com.ibm.ws.logging.internal.impl.IncidentImpl                I FFDC1015I: An FFDC Incident has been created: "javax.resource.ResourceException: enlist: caught Exception com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.beginTransactionIfNecessary 324" at ffdc_23.08.03_13.09.13.2.log
[8/3/23 11:09:13:385 UTC] 00000059 com.ibm.ws.logging.internal.impl.IncidentImpl                I FFDC1015I: An FFDC Incident has been created: "java.sql.SQLException: enlist: caught Exception com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.getMetaData 922" at ffdc_23.08.03_13.09.13.3.log

Best regards, K.M.

jmstephensgit commented 1 year ago

If you have support, please open a skill case for this issue. It's likely we will need to request trace and do more extensive work to figure out this problem.

If you are using open Liberty without support and this is easy to recreate, to help narrow down the commit causing the issue, can you run on 23.0.0.3? If the problem still exist, then next run on 23.0.0.2 or if the problem does not exist, run on 23.0.0.4 or .5?

If neither of the two options above are available, please let me know.

Thanks,

krismarc commented 1 year ago

We have got IBM's support. However, I'd prefer to use Open Source community channel.

I've just tested all versions between 23.0.0.1 and 23.0.0.6. The issue starts to appear in 23.0.0.4. While using 23.0.0.3 it's yet working fine.

so I am just switching liberty sources using symlinks: lrwxrwxrwx 1 root root 37 Aug 7 17:03 .liberty -> ../liberties/openliberty-23.0.0.4/wlp

Launching defaultServer (Open Liberty 23.0.0.4/wlp-1.0.76.cl230420230418-0035) on Eclipse OpenJ9 VM, version 1.8.0_372-b07 (en_US)

I couldn't spot related commit yet. https://openliberty.io/blog/2023/05/02/23.0.0.4.html https://github.com/OpenLiberty/open-liberty/issues?q=label%3Arelease%3A23004+label%3A%22release+bug%22 https://github.com/OpenLiberty/open-liberty/compare/gm-23.0.0.3...gm-23.0.0.4

Please let me know in what logs/traces would you be interested in. Thx!

update: No luck with the newest 23.0.0.7 - just tested.

krismarc commented 1 year ago

@jmstephensgit we would highly appreciate if we could have any update on this.

jmstephensgit commented 1 year ago

Sorry for the delay, reviewing your latest update and reviewing commits between 23.0.0.3 and 23.0.0.4.

djmatthews commented 1 year ago

@krismarc Hi, I've looked at changes in the transaction service and can't see anything obvious at 23.0.0.4 that would account for this. Moreover, given that the enilstment of XAResources is bread-and-butter functionality that works both in the tests and other customer environments, I suspect there is something going on thath is subtle and environment related. There are instances in the code where a recoveryId of -1 can be returned that are related to the transaction service not being in the correct state and there were changes that could potentially affect that in the instantOn support that was added around this fixpack time but it isn't obvious if that is causing an issue. Consequently I think we need to collect doc from the customer's system.

Please can the customer supply a "system dump" and trace (as per https://www.ibm.com/support/pages/set-trace-and-get-full-dump-websphere-liberty) using trace string "*=info:RRA=all:WAS.j2c=all:com.ibm.ws.jdbc.=all:Transaction=all"

Trace should be taken so that it includes app server startup as well as the failure occuring.

Thanks

krismarc commented 1 year ago

Ok, I'll produce this tomorrow. Thank you.

krismarc commented 1 year ago

@djmatthews I've produced system dump after reproducing a problem with enabled trace spec you have recommended. How could I share it with you? I don't really want to widely publish system dump of our business app.

Here's a part of the trace file just before error occurs: 

[8/29/23 11:42:45:209 CEST] 0000002b WSRdbManagedC 3   Correlator: DB2, ID: ::10.92.143.186.33870.DDD1CEAC83A5 Transaction : com.ibm.ws.rsadapter.impl.WSRdbXaResourceImpl@ab9af112 BEGIN
[8/29/23 11:42:45:209 CEST] 0000002b ConnectionMan >  lazyEnlist Entry
[8/29/23 11:42:45:209 CEST] 0000002b ConnectionMan 3   Used mc WSRdbManagedConnectionImpl@20ac2dcd to find mcWrapper MCWrapper id 875b1306  Managed connection WSRdbManagedConnectionImpl@20ac2dcd  State:STATE_TRAN_WRAPPER_INUSE Thread Id: 0000002b Thread Name: Default Executor-thread-2 Connections being held 1

[8/29/23 11:42:45:209 CEST] 0000002b ConnectionMan 3   Coordinator in effect: com.ibm.tx.jta.embeddable.impl.EmbeddableTransactionImpl@356a39a2#tid=45210168,active=1,suspended=0,thread=0000002B
[8/29/23 11:42:45:209 CEST] 0000002b MCWrapper     >  getCurrentTranWrapper Entry
[8/29/23 11:42:45:209 CEST] 0000002b MCWrapper     <  getCurrentTranWrapper Exit
                                 XATXWRAPPER
[8/29/23 11:42:45:209 CEST] 0000002b XATransaction >  enlist Entry
                                 com.ibm.tx.jta.embeddable.impl.EmbeddableTransactionImpl@356a39a2#tid=45210168,active=1,suspended=0,thread=0000002B
[8/29/23 11:42:45:209 CEST] 0000002b TransactionMa >  enlist Entry
                                 com.ibm.tx.jta.embeddable.impl.EmbeddableTransactionImpl@356a39a2#tid=45210168,active=1,suspended=0,thread=0000002B
                                 XATransactionWrapper@ 665d0708  XAResource: com.ibm.ws.rsadapter.impl.WSRdbXaResourceImpl@ab9af112  enlisted: falseHas Tran Rolled Back = false  mcWrapper.hashCode()-2024074490
                                 -1
                                 0
[8/29/23 11:42:45:209 CEST] 0000002b TransactionMa >  etm Entry
[8/29/23 11:42:45:209 CEST] 0000002b EmbeddableTra >  getTransactionManager Entry
[8/29/23 11:42:45:209 CEST] 0000002b EmbeddableTra <  getTransactionManager Exit
                                 com.ibm.tx.jta.embeddable.impl.EmbeddableTranManagerSet@4843773a
[8/29/23 11:42:45:209 CEST] 0000002b TransactionMa <  etm Exit
                                 com.ibm.tx.jta.embeddable.impl.EmbeddableTranManagerSet@4843773a
[8/29/23 11:42:45:209 CEST] 0000002b EmbeddableTra >  enlist Entry
                                 XATransactionWrapper@ 665d0708  XAResource: com.ibm.ws.rsadapter.impl.WSRdbXaResourceImpl@ab9af112  enlisted: falseHas Tran Rolled Back = false  mcWrapper.hashCode()-2024074490
                                 -1
                                 0
[8/29/23 11:42:45:209 CEST] 0000002b TransactionIm >  enlistResource Entry
                                 (SPI)
                                 XATransactionWrapper@ 665d0708  XAResource: com.ibm.ws.rsadapter.impl.WSRdbXaResourceImpl@ab9af112  enlisted: falseHas Tran Rolled Back = false  mcWrapper.hashCode()-2024074490
                                 -1
                                 0
[8/29/23 11:42:45:209 CEST] 0000002b TransactionSt 3   getState
                                 STATE_ACTIVE
[8/29/23 11:42:45:243 CEST] 0000002b IncidentImpl  I   FFDC1015I: An FFDC Incident has been created: "java.lang.IllegalStateException: Illegal attempt to enlist 2PC XAResource without recovery information com.ibm.tx.jta.TransactionImpl.enlistResource 1934" at ffdc_23.08.29_11.42.45.0.log
[8/29/23 11:42:45:245 CEST] 0000002b TransactionIm <  enlistResource Exit
                                 (SPI)
                                 java.lang.IllegalStateException: Illegal attempt to enlist 2PC XAResource without recovery information
        at com.ibm.tx.jta.impl.TransactionImpl.enlistResource(TransactionImpl.java:2077)
        at [internal classes]
        at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:70)
krismarc commented 1 year ago

I've compared traces from 23.0.0.3 and newer one.

In 23.0.0.3, there's such an exception. However, it doesn't prevent the app from getting started. [8/29/23 12:00:05:077 CEST] 0000002c WSJdbcStateme < executeUpdate Exit com.ibm.db2.jcc.am.SqlSyntaxErrorException: TEC* DOES NOT HAVE THE PRIVILEGE TO PERFORM OPERATION DELETE ON OBJECT A14.TA14_LMGR. SQLCODE=-551, SQLSTATE=42501, DRIVER=4.31.10 at com.ibm.db2.jcc.am.b7.a(b7.java:810) at com.ibm.db2.jcc.am.b7.a(b7.java:66) at com.ibm.db2.jcc.am.b7.a(b7.java:140) at com.ibm.db2.jcc.am.k_.c(k_.java:2844) at com.ibm.db2.jcc.am.k_.d(k_.java:2828) at com.ibm.db2.jcc.am.k_.b(k_.java:2188) at com.ibm.db2.jcc.t4.ab.k(ab.java:444) at com.ibm.db2.jcc.t4.ab.c(ab.java:102) at com.ibm.db2.jcc.t4.p.b(p.java:38) at com.ibm.db2.jcc.t4.av.h(av.java:124) at com.ibm.db2.jcc.am.k_.ak(k_.java:2183) at com.ibm.db2.jcc.am.k_.a(k_.java:3387) at com.ibm.db2.jcc.am.k_.c(k_.java:792) at com.ibm.db2.jcc.am.k_.executeUpdate(k_.java:771) at com.ibm.ws.rsadapter.jdbc.WSJdbcStatement.executeUpdate(WSJdbcStatement.java:618) at org.springframework.jdbc.core.JdbcTemplate$1UpdateStatementCallback.doInStatement(JdbcTemplate.java:546) at org.springframework.jdbc.core.JdbcTemplate$1UpdateStatementCallback.doInStatement(JdbcTemplate.java:543) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:381) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:558) at com.*.a14.dao.scheduler.AiqSchedulerDaoImpl.deleteSchedulerEntry(AiqSchedulerDaoImpl.java:27) at com.*.a14.ejb.A14ApplicationInitialization.initializeApplication(A14ApplicationInitialization.java:60) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:202) at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:587) at com.ibm.ws.cdi.ejb.impl.InterceptorChain.proceed(InterceptorChain.java:121) at com.ibm.ws.cdi.ejb.impl.EJBCDIInterceptorWrapper.invokeInterceptors(EJBCDIInterceptorWrapper.java:133) at com.ibm.ws.cdi.ejb.impl.EJBCDIInterceptorWrapper.postConstruct(EJBCDIInterceptorWrapper.java:69) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:191) at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:579) at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73) at com.ibm.ws.cdi.ejb.interceptor.WeldSessionBeanInterceptorWrapper.aroundInvoke(WeldSessionBeanInterceptorWrapper.java:60) at com.ibm.ws.cdi.ejb.interceptor.WeldSessionBeanInterceptorWrapper.postConstruct(WeldSessionBeanInterceptorWrapper.java:69) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:191) at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:579) at com.ibm.ejs.container.interceptors.InvocationContextImpl.doLifeCycle(InvocationContextImpl.java:328) at com.ibm.ejs.container.SingletonBeanO.callTransactionalLifecycleInterceptors(SingletonBeanO.java:223) at com.ibm.ejs.container.SingletonBeanO.initialize(SingletonBeanO.java:309) at com.ibm.ejs.container.BeanOFactory.create(BeanOFactory.java:105) at com.ibm.ejs.container.EJSHome.createSingletonBeanO(EJSHome.java:3485) at com.ibm.ejs.csi.EJBApplicationMetaData.createStartupBeans(EJBApplicationMetaData.java:1003) at com.ibm.ejs.csi.EJBApplicationMetaData.startedModule(EJBApplicationMetaData.java:737) at com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl.start(EJBRuntimeImpl.java:1123) at com.ibm.ws.ejbcontainer.osgi.internal.EJBModuleRuntimeContainerImpl.startModule(EJBModuleRuntimeContainerImpl.java:166) at com.ibm.ws.app.manager.module.internal.ModuleHandlerBase.deployModule(ModuleHandlerBase.java:101) at com.ibm.ws.app.manager.module.internal.DeployedModuleInfoImpl.installModule(DeployedModuleInfoImpl.java:51) at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.deployModules(SimpleDeployedAppInfoBase.java:599) at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.installApp(SimpleDeployedAppInfoBase.java:513) at com.ibm.ws.app.manager.module.internal.DeployedAppInfoBase.deployApp(DeployedAppInfoBase.java:351) at com.ibm.ws.app.manager.ear.internal.EARApplicationHandlerImpl.install(EARApplicationHandlerImpl.java:79) at com.ibm.ws.app.manager.internal.statemachine.StartAction.execute(StartAction.java:184) at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.enterState(ApplicationStateMachineImpl.java:1369) at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.run(ApplicationStateMachineImpl.java:912) at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:247) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:826)

..while in 23.0.0.4+ we get this:

[8/29/23 11:42:51:246 CEST] 0000002b A14Applicatio I com.*.a14.ejb.A14ApplicationInitialization initializeApplication Error at cleaning of existing scheduler entry in database: org.springframework.jdbc.UncategorizedSQLException: StatementCallback; uncategorized SQLException for SQL [delete from A14.TA14_LMGR]; SQL state [null]; error code [0]; enlist: caught Exception; nested ex ception is java.sql.SQLException: enlist: caught Exception at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1542) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:393) at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:558) at com.*.a14.dao.scheduler.AiqSchedulerDaoImpl.deleteSchedulerEntry(AiqSchedulerDaoImpl.java:27) at com.*.a14.ejb.A14ApplicationInitialization.initializeApplication(A14ApplicationInitialization.java:60) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:202) at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:587) at com.ibm.ws.cdi.ejb.impl.InterceptorChain.proceed(InterceptorChain.java:121) at com.ibm.ws.cdi.ejb.impl.EJBCDIInterceptorWrapper.invokeInterceptors(EJBCDIInterceptorWrapper.java:133) at com.ibm.ws.cdi.ejb.impl.EJBCDIInterceptorWrapper.postConstruct(EJBCDIInterceptorWrapper.java:69) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:191) at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:579) at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73) at com.ibm.ws.cdi.ejb.interceptor.WeldSessionBeanInterceptorWrapper.aroundInvoke(WeldSessionBeanInterceptorWrapper.java:60) at com.ibm.ws.cdi.ejb.interceptor.WeldSessionBeanInterceptorWrapper.postConstruct(WeldSessionBeanInterceptorWrapper.java:69) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.ibm.ejs.container.interceptors.InterceptorProxy.invokeInterceptor(InterceptorProxy.java:191) at com.ibm.ejs.container.interceptors.InvocationContextImpl.proceed(InvocationContextImpl.java:579) at com.ibm.ejs.container.interceptors.InvocationContextImpl.doLifeCycle(InvocationContextImpl.java:328) at com.ibm.ejs.container.SingletonBeanO.callTransactionalLifecycleInterceptors(SingletonBeanO.java:223) at com.ibm.ejs.container.SingletonBeanO.initialize(SingletonBeanO.java:309) at com.ibm.ejs.container.BeanOFactory.create(BeanOFactory.java:105) at com.ibm.ejs.container.EJSHome.createSingletonBeanO(EJSHome.java:3478) at com.ibm.ejs.csi.EJBApplicationMetaData.createStartupBeans(EJBApplicationMetaData.java:1005) at com.ibm.ejs.csi.EJBApplicationMetaData.startedModule(EJBApplicationMetaData.java:739) at com.ibm.ws.ejbcontainer.osgi.internal.EJBRuntimeImpl.start(EJBRuntimeImpl.java:1123) at com.ibm.ws.ejbcontainer.osgi.internal.EJBModuleRuntimeContainerImpl.startModule(EJBModuleRuntimeContainerImpl.java:166) at com.ibm.ws.app.manager.module.internal.ModuleHandlerBase.deployModule(ModuleHandlerBase.java:101) at com.ibm.ws.app.manager.module.internal.DeployedModuleInfoImpl.installModule(DeployedModuleInfoImpl.java:51) at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.deployModules(SimpleDeployedAppInfoBase.java:599) at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.installApp(SimpleDeployedAppInfoBase.java:513) at com.ibm.ws.app.manager.module.internal.DeployedAppInfoBase.deployApp(DeployedAppInfoBase.java:351) at com.ibm.ws.app.manager.ear.internal.EARApplicationHandlerImpl.install(EARApplicationHandlerImpl.java:79) at com.ibm.ws.app.manager.internal.statemachine.StartAction.execute(StartAction.java:184) at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.enterState(ApplicationStateMachineImpl.java:1369) at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.run(ApplicationStateMachineImpl.java:912) at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:247) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:826) Caused by: java.sql.SQLException: enlist: caught Exception at com.ibm.ws.rsadapter.AdapterUtil.toSQLException(AdapterUtil.java:871) at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.beginTransactionIfNecessary(WSJdbcConnection.java:435) at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.createStatement(WSJdbcConnection.java:1077) at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.createStatement(WSJdbcConnection.java:1061) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:379) ... 49 more

krismarc commented 11 months ago

Hi there,

do we have any update on this? Lack of access for the tech user is not a root cause here. We have disabled this part of code and OL still leads to the same initial problem.

I went deeper with understanding of our customer's app and the debug.

They use H2 database for transaction logging purposes. I've enabled debug on it's driver.

The issue pops up here (not a case with previous versions of Liberties:

[9/19/23 12:24:30:219 CEST] 0000002a id=00000000 ibm.ws.recoverylog.custom.jdbc.impl.SQLMultiScopeRecoveryLog 3 Could not find HA Lock row, unable to retrieve timestamp

[9/19/23 12:24:30:217 CEST] 0000002a id=00000000 SystemOut                                                    O 2023-
09-19 12:24:30 jdbc[3]: Plan       : calculate cost for plan [PUBLIC.WAS_PARTNER_LOG]
[9/19/23 12:24:30:217 CEST] 0000002a id=00000000 SystemOut                                                    O 2023-
09-19 12:24:30 jdbc[3]: Plan       :   for table filter PUBLIC.WAS_PARTNER_LOG
[9/19/23 12:24:30:217 CEST] 0000002a id=00000000 SystemOut                                                    O 2023-
09-19 12:24:30 jdbc[3]: Table      :     potential plan item cost 10,200 index PUBLIC.WAS_PARTNER_LOG.tableScan
[9/19/23 12:24:30:218 CEST] 0000002a id=00000000 SystemOut                                                    O 2023-
09-19 12:24:30 jdbc[3]: Table      :     potential plan item cost 320 index PUBLIC.IXWSPARTNER_LOG
[9/19/23 12:24:30:218 CEST] 0000002a id=00000000 SystemOut                                                    O 2023-
09-19 12:24:30 jdbc[3]: Plan       :   best plan item cost 316.8 index PUBLIC.IXWSPARTNER_LOG
[9/19/23 12:24:30:218 CEST] 0000002a id=00000000 SystemOut                                                    O 2023-
09-19 12:24:30 jdbc[3]: Plan       : plan cost 317.8
[9/19/23 12:24:30:219 CEST] 0000002a id=00000000 SystemOut                                                    O 2023-
09-19 12:24:30 jdbc[3]:
/*SQL */SELECT SERVER_NAME, RUSECTION_ID FROM WAS_PARTNER_LOG WHERE RU_ID=-1 FOR UPDATE;
[9/19/23 12:24:30:219 CEST] 0000002a id=e086c443 com.ibm.ws.rsadapter.jdbc.WSJdbcResultSet                    > <init
> Entry
                                                                                                               org.h2
.jdbc.JdbcResultSet@2bd9bba0
                                                                                                               com.ib
m.ws.rsadapter.jdbc.v42.WSJdbc42Statement@65430b6d
[9/19/23 12:24:30:219 CEST] 0000002a id=e086c443 com.ibm.ws.rsadapter.jdbc.WSJdbcResultSet                    < <init
> Exit
[9/19/23 12:24:30:219 CEST] 0000002a id=65430b6d com.ibm.ws.rsadapter.jdbc.WSJdbcStatement                    < execu
teQuery Exit
                                                                                                               com.ib
m.ws.rsadapter.jdbc.v42.WSJdbc42ResultSet@e086c443
[9/19/23 12:24:30:219 CEST] 0000002a id=33afabf8 com.ibm.ws.rsadapter.jdbc.WSJdbcConnection                   > begin
TransactionIfNecessary Entry
                                                                                                               NO_TRA
NSACTION_ACTIVE
[9/19/23 12:24:30:219 CEST] 0000002a id=33afabf8 com.ibm.ws.rsadapter.jdbc.WSJdbcConnection                   < begin
TransactionIfNecessary Exit
                                                                                                               no-op
enlistment is disabled
[9/19/23 12:24:30:219 CEST] 0000002a id=dd6ec7ea com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl         > enfor
ceAutoCommit Entry
                                                                                                               false
[9/19/23 12:24:30:219 CEST] 0000002a id=dd6ec7ea com.ibm.ws.rsadapter.impl.WSRdbManagedConnectionImpl         < enfor
ceAutoCommit Exit
[9/19/23 12:24:30:219 CEST] 0000002a id=00000000 SystemOut                                                    O 2023-
09-19 12:24:30 jdbc[3]:
/**/rs5.next();
[9/19/23 12:24:30:219 CEST] 0000002a id=00000000 ibm.ws.recoverylog.custom.jdbc.impl.SQLMultiScopeRecoveryLog 3 Could not find HA Lock row, unable to retrieve timestamp
[9/19/23 12:24:30:219 CEST] 0000002a id=e086c443 com.ibm.ws.rsadapter.jdbc.WSJdbcResultSet                    > close Entry
[9/19/23 12:24:30:219 CEST] 0000002a id=e086c443 com.ibm.ws.rsadapter.jdbc.WSJdbcResultSet                    1 state --> CLOSED
[9/19/23 12:24:30:219 CEST] 0000002a id=00000000 SystemOut                                                    O 2023-09-19 12:24:30 jdbc[3]:
/**/rs5.close();

New liberty on the left, old on the right. image image

Best regards, K.M.

tschurins commented 2 months ago

Hello, Strangely enough, we have the same problem popping up with different versions of OpenLiberty: everything is working fine with version 24.0.0.3, and it begins to fail with the same exception on 24.0.0.4.

Do you have any update on this issue?

djmatthews commented 2 months ago

@tschurins I take it you're referring to the original issue here - the IllegalStateException. We'll need additional info... Please supply a "system dump" and trace (as per https://www.ibm.com/support/pages/set-trace-and-get-full-dump-websphere-liberty) using trace string "*=info:RRA=all:WAS.j2c=all:com.ibm.ws.jdbc.=all:Transaction=all"

Trace should be taken so that it includes app server startup as well as the failure occuring. There's a two-step process here. The enlist/enlistResource is the second step - it passes in a recoveryIndex parameter (-1 in earlier trace snippet) - that -1 indicates a failure in the first step where the recoveryIndex is generated by a call to registerResourceInfo which will default to -1 if there's a failure. Looking at the code, it's possible that there some timing window that that method is called before the transaction service is ready that the current tests don't run into. It doesn't look like the code will either wait, nor retry in the event of this condition which I find surprising.

As Jim noted previously "If you have support, please open a skill case for this issue. It's likely we will need to request trace and do more extensive work to figure out this problem."

jmstephensgit commented 2 months ago

@tschurins , Please open a skill case for this issue. We will need working and failing trace to help spot differences. You mention working 23.0.0.3 and failing 23.0.0.4 and working 24.0.0.3 and failing 24.0.0.4. Please include all of the releases you are noticing it is working and it failing if there are others, in case this information helps, but as Dan mentioned it's likely related to your environment and not to liberty.

tschurins commented 2 months ago

Hello, I was putting a comment here because we have the same problem: server does not start with a very similar exception. So, I was hoping that a solution had been found, to see if I could leverage it. However, the versions are not the same: we have the problem while migrating from 24.0.0.3 to the next, while the original issue was while migrating from 23.0.0.3 to the next version. Maybe we should rename this issue as the x.0.0.3 to x.0.0.4 curse? :) I have followed your advice and created a case at IBM support and attached the logs and system dump.

tschurins commented 2 months ago

For my problem (migration from 24.0.0.3 to 24.0.0.4), it seems to be caused by https://github.com/OpenLiberty/open-liberty/issues/27927 when JVM sys prop WLP_USER_DIR is not set. So the workaround is to specify the environment variable "WLP_USER_DIR".

jonhawkes commented 2 months ago

Right. I am working on a fix for that. I will probably associate it with issue 27211 when it's ready.