search

atomikos / transactions-essentials

Development repository for next major release of
https://www.atomikos.com/Main/TransactionsEssentials
Other
461 stars 139 forks source link

Atomikos is returning null in the logs for IBM MQ XA Connection #225

Closed ravee1928 closed 3 weeks ago

ravee1928 commented 3 months ago

Our application is a JAVA back end app running inside a Tomcat. In a high level it reads input from IBM MQ, process it, persists it in the ORACLE DB and writes the output to an MQ. It is a distributed two phase commit transaction world where Atomikos serves as a transaction manager. We use Spring JMS API. Currently the set up is we are in JAVA 11 and now we are trying to upgrade the app to JAVA 17.

We use org.springframework.jms.connection.CachingConnectionFactory with com.atomikos.jms.AtomikosConnectionFactoryBean as connection factory bean. For every polling of the MQ messages in JAVA 11, the below logs gets printed out from org.springframework.jms.core.JmsTemplate.class in the spring-jms jar. "Executing callback on JMS Session: Cached JMS Session: com.ibm.mq.jms.MQXAQueueSession@39f839d6"

Dependencies used: com.ibm.mq.allclient - 7.5.0.0, spring-jms - 5.3.x, Atomikos - 5.0.8 (free version)

Now when we upgraded to JAVA 17, the dependencies are also upgraded to the latest compatible.

Dependeicies used: com.ibm.mq.jakarta.client - 9.4.0.0, spring-jms - 6.1.5, Atomikos - 6.0.0 (free version)

But now, after this upgrade, we get the logs as, "Executing callback on JMS Session: Cached JMS Session: Cached JMS Session: null"

Enabling the log trace of Atomikos and IBM MQ jars, we get,

With com.ibm.mq.allclient - 7.5.0.0, spring-jms - 5.3.x, Atomikos - 5.0.8 (free version)

[DEBUG] taskScheduler-21/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: createConnection()...
[INFO] taskScheduler-21/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: init...
[INFO] taskScheduler-21/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: initializing with [ xaConnectionFactory=|   com.ibm.mq.jms.MQXAQueueConnectionFactory  :-
[TRACE] taskScheduler-21/<processName> - com.atomikos.datasource.xa.XATransactionalResource - Installing recovery service on resource xxxJms_MQSeries_XA_RMIQD0133
[TRACE] taskScheduler-21/<processName> - com.atomikos.datasource.pool.ConnectionPool - atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133': initializing...
[TRACE] taskScheduler-21/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: registering listener atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133'
[TRACE] taskScheduler-21/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: registering listener atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133'
[TRACE] taskScheduler-21/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: registering listener atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133'
.
.
.
.
[DEBUG] taskScheduler-21/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: getReference()...
[TRACE] taskScheduler-21/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: getReference() returning Reference Class Name: com.atomikos.jms.AtomikosConnectionFactoryBean
[TRACE] taskScheduler-21/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: init done.
[TRACE] taskScheduler-21/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: updating last time acquired
[TRACE] taskScheduler-21/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d: calling native toString
[TRACE] taskScheduler-21/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d: toString returning com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d
[TRACE] taskScheduler-21/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: returning proxy com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d
[TRACE] taskScheduler-21/<processName> - com.atomikos.datasource.pool.ConnectionPool - atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133': current size: 99/100
[TRACE] taskScheduler-21/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d: calling native toString
[TRACE] taskScheduler-21/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d: toString returning com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d
[TRACE] taskScheduler-21/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: createConnection() returning com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d
[TRACE] taskScheduler-21/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d: calling native setExceptionListener(org.springframework.jms.connection.SingleConnectionFactory$AggregatedExceptionListener@1225b7f)
[TRACE] taskScheduler-21/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d: setExceptionListener returning null
[TRACE] taskScheduler-21/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d: calling native toString
[TRACE] taskScheduler-21/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d: toString returning com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d
[DEBUG] taskScheduler-21/<processName> - org.springframework.jms.connection.CachingConnectionFactory - Established shared JMS Connection: com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d

With com.ibm.mq.jakarta.client - 9.4.0.0, spring-jms - 6.1.5, Atomikos - 6.0.0 (free version)

[DEBUG] taskScheduler-218/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: createConnection()...
[INFO] taskScheduler-218/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: init...
[INFO] taskScheduler-218/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: initializing with [ xaConnectionFactory=|   com.ibm.mq.jakarta.jms.MQXAQueueConnectionFactory@c79b6829  :-
[TRACE] taskScheduler-218/<processName> - com.atomikos.datasource.xa.XATransactionalResource - Installing recovery service on resource xxxJms_MQSeries_XA_RMIQD0133
[TRACE] taskScheduler-218/<processName> - com.atomikos.datasource.pool.ConnectionPool - atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133': initializing...
[TRACE] taskScheduler-218/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: registering listener atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133'
[TRACE] taskScheduler-218/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: registering listener atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133'
[TRACE] taskScheduler-218/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: registering listener atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133'
[TRACE] taskScheduler-218/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: registering listener atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133'
[TRACE] taskScheduler-218/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: registering listener atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133'
.
.
.
.
[DEBUG] taskScheduler-218/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: getReference()...
[TRACE] taskScheduler-218/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: getReference() returning Reference Class Name: com.atomikos.jms.AtomikosConnectionFactoryBean
[TRACE] taskScheduler-218/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: init done.
[TRACE] taskScheduler-218/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: updating last time acquired
[TRACE] taskScheduler-218/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance null: calling native toString
[TRACE] taskScheduler-218/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance null: toString returning null
[TRACE] taskScheduler-218/<processName> - com.atomikos.datasource.pool.AbstractXPooledConnection - atomikosPooledJmsConnection for resource xxxJms_MQSeries_XA_RMIQD0133: returning proxy null
[TRACE] taskScheduler-218/<processName> - com.atomikos.datasource.pool.ConnectionPool - atomikos connection pool 'xxxJms_MQSeries_XA_RMIQD0133': current size: 99/100
[TRACE] taskScheduler-218/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance null: calling native toString
[TRACE] taskScheduler-218/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance null: toString returning null
[TRACE] taskScheduler-218/<processName> - com.atomikos.jms.AtomikosConnectionFactoryBean - xxxJms_MQSeries_XA_RMIQD0133: createConnection() returning null
[TRACE] taskScheduler-218/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance null: calling native setExceptionListener(org.springframework.jms.connection.SingleConnectionFactory$AggregatedExceptionListener@7d71c781)
[TRACE] taskScheduler-218/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance null: setExceptionListener returning null
[TRACE] taskScheduler-218/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance null: calling native toString
[TRACE] taskScheduler-218/<processName> - com.atomikos.util.DynamicProxySupport - atomikosJmsConnectionProxy (isAvailable = false)  for vendor instance null: toString returning null
[DEBUG] taskScheduler-218/<processName> - org.springframework.jms.connection.CachingConnectionFactory - Established shared JMS Connection: null

We can see that in the first set of logs, we have the com.ibm.mq.jms.MQXAQueueConnection@6bd9b89d object getting printed but not in the upgraded app logs where we have null. This is the discrepancy we want to understand.

We are not allowed to connect directly to the test queue managers from local machine hence with a limited debugging opportunity, we found that when we upgrade the com.ibm.mq.allclient jar iteratively, things are fine until 9.2.3.0 and this cached session prints out to null starting from 9.2.4.0 which is the IBM version which was upgraded to JAVA 17. Hence I believe for this issue there is some correlation between IBM MQ jars and Atomikos after upgrading to JAVA 17. I'm exactly not sure what/which is the fault here but with the logs I'm suspecting on atomikos.

Can you please kindly have a look?

ravee1928 commented 3 weeks ago

Apologies, this issues was finally found out to be MQ related and not Atomikos transaction. Hence closing it.