Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

XA transaction with queue and database access is not committed #8214

Open
mhdirkse opened this issue Jan 10, 2025 · 3 comments
Open

XA transaction with queue and database access is not committed #8214

mhdirkse opened this issue Jan 10, 2025 · 3 comments
Labels
JDBC JMS Transaction Manager

Comments

@mhdirkse
Copy link
Contributor

mhdirkse commented Jan 10, 2025 •
edited by philipsens
Loading

Current Behavior

I have a Frank configuration that reads a message from an Artemis queue and writes it to two database tables in a PostgreSQL database. This happens in an XA transaction. In Ladybug the resulting report shows no issues, but when I query my tables the data is not in.

A log is included in this issue.

My message also does not appear in the error store I configured:

image

Expected Behavior

The input message appears in the database.

Environment Information

This was run using Docker Compose.

Steps To Reproduce

Run adapter writeDbAsync in Test a Pipeline.

Configuration

See attached .zip file.

Input

No response

What database are you using?

No response

What browsers are you seeing the problem on?

No response

Relevant Log Output

2025-01-10 12:53:18,642 INFO  [http-nio-8080-exec-10] {mid=testmessageac1f0003--61af5f71_19450416f8a_-7fff, cid=Test a Pipeline 1, adapter=writeDbAsync} core.Adapter - Adapter [writeDbAsync] received message with messageId [testmessageac1f0003--61af5f71_19450416f8a_-7fff]
2025-01-10 12:53:18,740 INFO  [http-nio-8080-exec-10] {mid=testmessageac1f0003--61af5f71_19450416f8a_-7fff, cid=Test a Pipeline 1, adapter=writeDbAsync, pipe=enqueue, sender=enqueue} jms.JmsSender - [enqueue] message destination [ActiveMQQueue[myQueue]] JMSDeliveryMode=[2] JMSMessageID=[null] JMSCorrelationID=[Test a Pipeline 1] JMSReplyTo=[null]
2025-01-10 12:53:18,760 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeDb} receivers.Receiver - Receiver [JmsListener [dequeue]]  messageId [ID:dd82c48b-cf51-11ef-a380-0242ac1f0003] correlationId [Test a Pipeline 1] businessCorrelationId [Test a Pipeline 1]
2025-01-10 12:53:18,762 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeDb} core.Adapter - Adapter [writeDb] received message with messageId [ID:dd82c48b-cf51-11ef-a380-0242ac1f0003]
2025-01-10 12:53:18,777 INFO  [http-nio-8080-exec-10] {mid=testmessageac1f0003--61af5f71_19450416f8a_-7fff, cid=Test a Pipeline 1, adapter=writeDbAsync, pipe=enqueue} pipes.SenderPipe - sent message to [enqueue] messageID [ID:dd82c48b-cf51-11ef-a380-0242ac1f0003] linkMethod [CORRELATIONID]
2025-01-10 12:53:18,864 INFO  [http-nio-8080-exec-10] {mid=testmessageac1f0003--61af5f71_19450416f8a_-7fff, cid=Test a Pipeline 1, adapter=writeDbAsync} core.Adapter - Adapter [writeDbAsync] Pipeline finished processing message with messageId [testmessageac1f0003--61af5f71_19450416f8a_-7fff] with exit-state [SUCCESS]
2025-01-10 12:53:18,869 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeDb, pipe=writeTableMessage, sender=writeTableMessage} senders.FrankSender - Sending message to ADAPTER [writeTableMessage]
2025-01-10 12:53:18,872 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeTableMessage, pipe=writeTableMessage, sender=writeTableMessage} core.Adapter - Adapter [writeTableMessage] received message with messageId [null]
2025-01-10 12:53:18,872 ERROR [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeTableMessage, pipe=writeTableMessage, sender=writeTableMessage} processors.InputOutputPipeLineProcessor - null value for messageId, setting to [ac1f0003--61af5f71_19450416f8a_-7ffe]
2025-01-10 12:53:18,909 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeTableMessage, pipe=writeTableMessage, sender=writeTableMessage} pipes.SenderPipe - sent message to [writeTableMessage-sender] synchronously
2025-01-10 12:53:18,909 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeTableMessage, pipe=writeTableMessage, sender=writeTableMessage} core.Adapter - Adapter [writeTableMessage] Pipeline finished processing message with messageId [null] with exit-state [SUCCESS]
2025-01-10 12:53:18,926 INFO  [JmsListener [dequeue][1]] {} pipes.SenderPipe - sent message to [writeTableMessage] synchronously
2025-01-10 12:53:18,937 INFO  [JmsListener [dequeue][1]] {pipe=writeTableOtherMessage, sender=writeTableOtherMessage} senders.FrankSender - Sending message to ADAPTER [writeTableOtherMessage]
2025-01-10 12:53:18,937 INFO  [JmsListener [dequeue][1]] {cid=Test a Pipeline 1, adapter=writeTableOtherMessage, pipe=writeTableOtherMessage, sender=writeTableOtherMessage} core.Adapter - Adapter [writeTableOtherMessage] received message with messageId [null]
2025-01-10 12:53:18,938 ERROR [JmsListener [dequeue][1]] {cid=Test a Pipeline 1, adapter=writeTableOtherMessage, pipe=writeTableOtherMessage, sender=writeTableOtherMessage} processors.InputOutputPipeLineProcessor - null value for messageId, setting to [ac1f0003--61af5f71_19450416f8a_-7ffd]
2025-01-10 12:53:18,957 INFO  [JmsListener [dequeue][1]] {cid=Test a Pipeline 1, adapter=writeTableOtherMessage, pipe=writeTableOtherMessage, sender=writeTableOtherMessage} pipes.SenderPipe - sent message to [writeTableOtherMessage-sender] synchronously
2025-01-10 12:53:18,957 INFO  [JmsListener [dequeue][1]] {cid=Test a Pipeline 1, adapter=writeTableOtherMessage, pipe=writeTableOtherMessage, sender=writeTableOtherMessage} core.Adapter - Adapter [writeTableOtherMessage] Pipeline finished processing message with messageId [null] with exit-state [SUCCESS]
2025-01-10 12:53:18,970 INFO  [JmsListener [dequeue][1]] {} pipes.SenderPipe - sent message to [writeTableOtherMessage] synchronously
2025-01-10 12:53:18,981 INFO  [JmsListener [dequeue][1]] {} core.Adapter - Adapter [writeDb] Pipeline finished processing message with messageId [ID:dd82c48b-cf51-11ef-a380-0242ac1f0003] with exit-state [SUCCESS]
2025-01-10 12:53:18,981 INFO  [JmsListener [dequeue][1]] {} jms.JmsListener - [dequeue] no replyTo address found or not configured to use replyTo, and no sender, not sending the result.
2025-01-10 12:53:18,982 INFO  [JmsListener [dequeue][1]] {} unmanaged.SpringJmsConnector - SpringJmsConnector of Receiver [JmsListener [dequeue]]  A) JMSMessageTime [2025-01-10 12:53:18.740]
2025-01-10 12:53:18,982 INFO  [JmsListener [dequeue][1]] {} unmanaged.SpringJmsConnector - SpringJmsConnector of Receiver [JmsListener [dequeue]]  B) onMessageStart [2025-01-10 12:53:18.759] diff (~'queing' time) [19]
2025-01-10 12:53:18,982 INFO  [JmsListener [dequeue][1]] {} unmanaged.SpringJmsConnector - SpringJmsConnector of Receiver [JmsListener [dequeue]]  C) onMessageEnd   [2025-01-10 12:53:18.982] diff (process time) [223]
2025-01-10 12:53:19,019 WARN  [JmsListener [dequeue][1]] {} ats.jta - ARJUNA016041: prepare on < formatId=131077, gtrid_length=64, bqual_length=36, tx_uid=0:ffffac1f0003:8d7d:678116e5:6b2, node_name=809f78c5f310-ac1f0003--61af5f71_1945, branch_uid=0:ffffac1f0003:8d7d:678116e5:6b8, subordinatenodename=null, eis_name=0 > (org.postgresql.xa.PGXAConnection@17ed0311) failed with exception XAException.XAER_RMFAIL
org.postgresql.xa.PGXAException: Error preparing transaction. prepare xid=< formatId=131077, gtrid_length=64, bqual_length=36, tx_uid=0:ffffac1f0003:8d7d:678116e5:6b2, node_name=809f78c5f310-ac1f0003--61af5f71_1945, branch_uid=0:ffffac1f0003:8d7d:678116e5:6b8, subordinatenodename=null, eis_name=0 >
	at org.postgresql.xa.PGXAConnection.prepare(PGXAConnection.java:365) ~[postgresql.jar:42.7.4]
	at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:190) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2799) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2729) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2236) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1548) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:71) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:135) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1307) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:104) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1026) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:795) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:758) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.frankframework.jta.SpringTxManagerProxy.commit(SpringTxManagerProxy.java:72) ~[frankframework-core-9.1.0-20250107.042327.jar:9.1.0-20250107.042327]
	at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:253) ~[spring-jms-6.2.1.jar:6.2.1]
	at org.frankframework.jms.IbisMessageListenerContainer.receiveAndExecute(IbisMessageListenerContainer.java:96) ~[frankframework-core-9.1.0-20250107.042327.jar:9.1.0-20250107.042327]
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1420) ~[spring-jms-6.2.1.jar:6.2.1]
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1294) ~[spring-jms-6.2.1.jar:6.2.1]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
	at java.base/java.lang.Thread.run(Unknown Source) [?:?]
Caused by: org.postgresql.util.PSQLException: ERROR: prepared transactions are disabled
  Hint: Set "max_prepared_transactions" to a nonzero value.
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2733) ~[postgresql.jar:42.7.4]
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2420) ~[postgresql.jar:42.7.4]
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:372) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:517) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:434) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:356) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:341) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:317) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeUpdate(PgStatement.java:290) ~[postgresql.jar:42.7.4]
	at org.postgresql.xa.PGXAConnection.prepare(PGXAConnection.java:357) ~[postgresql.jar:42.7.4]
	... 20 more
2025-01-10 12:53:19,025 WARN  [JmsListener [dequeue][1]] {} ats.arjuna - ARJUNA012073: BasicAction.End() - prepare phase of action-id 0:ffffac1f0003:8d7d:678116e5:6b2 failed.
2025-01-10 12:53:19,025 WARN  [JmsListener [dequeue][1]] {} ats.arjuna - ARJUNA012075: Action Aborting
2025-01-10 12:53:19,031 WARN  [JmsListener [dequeue][1]] {} ats.jta - ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=64, bqual_length=36, tx_uid=0:ffffac1f0003:8d7d:678116e5:6b2, node_name=809f78c5f310-ac1f0003--61af5f71_1945, branch_uid=0:ffffac1f0003:8d7d:678116e5:6b8, subordinatenodename=null, eis_name=0 > (org.postgresql.xa.PGXAConnection@17ed0311) failed with exception code XAException.XAER_RMERR
org.postgresql.xa.PGXAException: Error rolling back prepared transaction. rollback xid=< formatId=131077, gtrid_length=64, bqual_length=36, tx_uid=0:ffffac1f0003:8d7d:678116e5:6b2, node_name=809f78c5f310-ac1f0003--61af5f71_1945, branch_uid=0:ffffac1f0003:8d7d:678116e5:6b8, subordinatenodename=null, eis_name=0 >, preparedXid=< formatId=131077, gtrid_length=64, bqual_length=36, tx_uid=0:ffffac1f0003:8d7d:678116e5:6b2, node_name=809f78c5f310-ac1f0003--61af5f71_1945, branch_uid=0:ffffac1f0003:8d7d:678116e5:6b8, subordinatenodename=null, eis_name=0 >, currentXid=null
	at org.postgresql.xa.PGXAConnection.rollback(PGXAConnection.java:485) ~[postgresql.jar:42.7.4]
	at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:318) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3158) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3137) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:2056) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1564) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:71) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:135) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1307) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:104) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1026) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:795) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:758) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.frankframework.jta.SpringTxManagerProxy.commit(SpringTxManagerProxy.java:72) ~[frankframework-core-9.1.0-20250107.042327.jar:9.1.0-20250107.042327]
	at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:253) ~[spring-jms-6.2.1.jar:6.2.1]
	at org.frankframework.jms.IbisMessageListenerContainer.receiveAndExecute(IbisMessageListenerContainer.java:96) ~[frankframework-core-9.1.0-20250107.042327.jar:9.1.0-20250107.042327]
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1420) ~[spring-jms-6.2.1.jar:6.2.1]
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1294) ~[spring-jms-6.2.1.jar:6.2.1]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
	at java.base/java.lang.Thread.run(Unknown Source) [?:?]
Caused by: org.postgresql.util.PSQLException: ERROR: prepared transaction with identifier "131077_AAAAAAAAAAAAAP//rB8AAwAAjX1ngRblAAAGsjgwOWY3OGM1ZjMxMC1hYzFmMDAwMy0tNjFhZjVmNzFfMTk0NQ==_AAAAAAAAAAAAAP//rB8AAwAAjX1ngRblAAAGuAAAAAAAAAAA" does not exist
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2733) ~[postgresql.jar:42.7.4]
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2420) ~[postgresql.jar:42.7.4]
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:372) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:517) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:434) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:356) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:341) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:317) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeUpdate(PgStatement.java:290) ~[postgresql.jar:42.7.4]
	at org.postgresql.xa.PGXAConnection.rollback(PGXAConnection.java:462) ~[postgresql.jar:42.7.4]
	... 20 more
2025-01-10 12:53:19,032 WARN  [JmsListener [dequeue][1]] {} ats.arjuna - ARJUNA012089: Top-level abort of action 0:ffffac1f0003:8d7d:678116e5:6b2 received heuristic decision: TwoPhaseOutcome.HEURISTIC_HAZARD
2025-01-10 12:53:19,041 WARN  [JmsListener [dequeue][1]] {} jms.IbisMessageListenerContainer - Setup of JMS message listener invoker failed for destination 'ActiveMQQueue[myQueue]' - trying to recover. Cause: Heuristic completion: outcome state is mixed
2025-01-10 12:53:19,046 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeDb} receivers.Receiver - Receiver [JmsListener [dequeue]]  messageId [ID:dd82c48b-cf51-11ef-a380-0242ac1f0003] correlationId [Test a Pipeline 1] businessCorrelationId [Test a Pipeline 1]
2025-01-10 12:53:19,046 WARN  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeDb} receivers.Receiver - Receiver [JmsListener [dequeue]]  message with messageId [ID:dd82c48b-cf51-11ef-a380-0242ac1f0003] has receive count [2]
2025-01-10 12:53:19,046 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeDb} core.Adapter - Adapter [writeDb] received message with messageId [ID:dd82c48b-cf51-11ef-a380-0242ac1f0003]
2025-01-10 12:53:19,072 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeDb, pipe=writeTableMessage, sender=writeTableMessage} senders.FrankSender - Sending message to ADAPTER [writeTableMessage]
2025-01-10 12:53:19,073 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeTableMessage, pipe=writeTableMessage, sender=writeTableMessage} core.Adapter - Adapter [writeTableMessage] received message with messageId [null]
2025-01-10 12:53:19,073 ERROR [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeTableMessage, pipe=writeTableMessage, sender=writeTableMessage} processors.InputOutputPipeLineProcessor - null value for messageId, setting to [ac1f0003--61af5f71_19450416f8a_-7ffc]
2025-01-10 12:53:19,085 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeTableMessage, pipe=writeTableMessage, sender=writeTableMessage} pipes.SenderPipe - sent message to [writeTableMessage-sender] synchronously
2025-01-10 12:53:19,086 INFO  [JmsListener [dequeue][1]] {mid=ID:dd82c48b-cf51-11ef-a380-0242ac1f0003, cid=Test a Pipeline 1, adapter=writeTableMessage, pipe=writeTableMessage, sender=writeTableMessage} core.Adapter - Adapter [writeTableMessage] Pipeline finished processing message with messageId [null] with exit-state [SUCCESS]
2025-01-10 12:53:19,098 INFO  [JmsListener [dequeue][1]] {} pipes.SenderPipe - sent message to [writeTableMessage] synchronously
2025-01-10 12:53:19,098 INFO  [JmsListener [dequeue][1]] {pipe=writeTableOtherMessage, sender=writeTableOtherMessage} senders.FrankSender - Sending message to ADAPTER [writeTableOtherMessage]
2025-01-10 12:53:19,099 INFO  [JmsListener [dequeue][1]] {cid=Test a Pipeline 1, adapter=writeTableOtherMessage, pipe=writeTableOtherMessage, sender=writeTableOtherMessage} core.Adapter - Adapter [writeTableOtherMessage] received message with messageId [null]
2025-01-10 12:53:19,099 ERROR [JmsListener [dequeue][1]] {cid=Test a Pipeline 1, adapter=writeTableOtherMessage, pipe=writeTableOtherMessage, sender=writeTableOtherMessage} processors.InputOutputPipeLineProcessor - null value for messageId, setting to [ac1f0003--61af5f71_19450416f8a_-7ffb]
2025-01-10 12:53:19,111 INFO  [JmsListener [dequeue][1]] {cid=Test a Pipeline 1, adapter=writeTableOtherMessage, pipe=writeTableOtherMessage, sender=writeTableOtherMessage} pipes.SenderPipe - sent message to [writeTableOtherMessage-sender] synchronously
2025-01-10 12:53:19,112 INFO  [JmsListener [dequeue][1]] {cid=Test a Pipeline 1, adapter=writeTableOtherMessage, pipe=writeTableOtherMessage, sender=writeTableOtherMessage} core.Adapter - Adapter [writeTableOtherMessage] Pipeline finished processing message with messageId [null] with exit-state [SUCCESS]
2025-01-10 12:53:19,125 INFO  [JmsListener [dequeue][1]] {} pipes.SenderPipe - sent message to [writeTableOtherMessage] synchronously
2025-01-10 12:53:19,127 INFO  [JmsListener [dequeue][1]] {} core.Adapter - Adapter [writeDb] Pipeline finished processing message with messageId [ID:dd82c48b-cf51-11ef-a380-0242ac1f0003] with exit-state [SUCCESS]
2025-01-10 12:53:19,127 INFO  [JmsListener [dequeue][1]] {} jms.JmsListener - [dequeue] no replyTo address found or not configured to use replyTo, and no sender, not sending the result.
2025-01-10 12:53:19,127 INFO  [JmsListener [dequeue][1]] {} unmanaged.SpringJmsConnector - SpringJmsConnector of Receiver [JmsListener [dequeue]]  A) JMSMessageTime [2025-01-10 12:53:18.740]
2025-01-10 12:53:19,127 INFO  [JmsListener [dequeue][1]] {} unmanaged.SpringJmsConnector - SpringJmsConnector of Receiver [JmsListener [dequeue]]  B) onMessageStart [2025-01-10 12:53:19.046] diff (~'queing' time) [306]
2025-01-10 12:53:19,127 INFO  [JmsListener [dequeue][1]] {} unmanaged.SpringJmsConnector - SpringJmsConnector of Receiver [JmsListener [dequeue]]  C) onMessageEnd   [2025-01-10 12:53:19.127] diff (process time) [81]
2025-01-10 12:53:19,156 WARN  [JmsListener [dequeue][1]] {} ats.jta - ARJUNA016041: prepare on < formatId=131077, gtrid_length=64, bqual_length=36, tx_uid=0:ffffac1f0003:8d7d:678116e5:6bb, node_name=809f78c5f310-ac1f0003--61af5f71_1945, branch_uid=0:ffffac1f0003:8d7d:678116e5:6c1, subordinatenodename=null, eis_name=0 > (org.postgresql.xa.PGXAConnection@17ed0311) failed with exception XAException.XAER_RMFAIL
org.postgresql.xa.PGXAException: Error preparing transaction. prepare xid=< formatId=131077, gtrid_length=64, bqual_length=36, tx_uid=0:ffffac1f0003:8d7d:678116e5:6bb, node_name=809f78c5f310-ac1f0003--61af5f71_1945, branch_uid=0:ffffac1f0003:8d7d:678116e5:6c1, subordinatenodename=null, eis_name=0 >
	at org.postgresql.xa.PGXAConnection.prepare(PGXAConnection.java:365) ~[postgresql.jar:42.7.4]
	at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:190) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2799) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2729) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2236) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1548) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:71) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:135) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1307) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:104) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1026) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:795) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:758) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.frankframework.jta.SpringTxManagerProxy.commit(SpringTxManagerProxy.java:72) ~[frankframework-core-9.1.0-20250107.042327.jar:9.1.0-20250107.042327]
	at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:253) ~[spring-jms-6.2.1.jar:6.2.1]
	at org.frankframework.jms.IbisMessageListenerContainer.receiveAndExecute(IbisMessageListenerContainer.java:96) ~[frankframework-core-9.1.0-20250107.042327.jar:9.1.0-20250107.042327]
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1420) ~[spring-jms-6.2.1.jar:6.2.1]
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1294) ~[spring-jms-6.2.1.jar:6.2.1]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
	at java.base/java.lang.Thread.run(Unknown Source) [?:?]
Caused by: org.postgresql.util.PSQLException: ERROR: prepared transactions are disabled
  Hint: Set "max_prepared_transactions" to a nonzero value.
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2733) ~[postgresql.jar:42.7.4]
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2420) ~[postgresql.jar:42.7.4]
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:372) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:517) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:434) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:356) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:341) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:317) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeUpdate(PgStatement.java:290) ~[postgresql.jar:42.7.4]
	at org.postgresql.xa.PGXAConnection.prepare(PGXAConnection.java:357) ~[postgresql.jar:42.7.4]
	... 20 more
2025-01-10 12:53:19,158 WARN  [JmsListener [dequeue][1]] {} ats.arjuna - ARJUNA012073: BasicAction.End() - prepare phase of action-id 0:ffffac1f0003:8d7d:678116e5:6bb failed.
2025-01-10 12:53:19,158 WARN  [JmsListener [dequeue][1]] {} ats.arjuna - ARJUNA012075: Action Aborting
2025-01-10 12:53:19,168 WARN  [JmsListener [dequeue][1]] {} ats.jta - ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=64, bqual_length=36, tx_uid=0:ffffac1f0003:8d7d:678116e5:6bb, node_name=809f78c5f310-ac1f0003--61af5f71_1945, branch_uid=0:ffffac1f0003:8d7d:678116e5:6c1, subordinatenodename=null, eis_name=0 > (org.postgresql.xa.PGXAConnection@17ed0311) failed with exception code XAException.XAER_RMERR
org.postgresql.xa.PGXAException: Error rolling back prepared transaction. rollback xid=< formatId=131077, gtrid_length=64, bqual_length=36, tx_uid=0:ffffac1f0003:8d7d:678116e5:6bb, node_name=809f78c5f310-ac1f0003--61af5f71_1945, branch_uid=0:ffffac1f0003:8d7d:678116e5:6c1, subordinatenodename=null, eis_name=0 >, preparedXid=< formatId=131077, gtrid_length=64, bqual_length=36, tx_uid=0:ffffac1f0003:8d7d:678116e5:6bb, node_name=809f78c5f310-ac1f0003--61af5f71_1945, branch_uid=0:ffffac1f0003:8d7d:678116e5:6c1, subordinatenodename=null, eis_name=0 >, currentXid=null
	at org.postgresql.xa.PGXAConnection.rollback(PGXAConnection.java:485) ~[postgresql.jar:42.7.4]
	at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:318) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3158) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3137) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:2056) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1564) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:71) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:135) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1307) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:104) ~[narayana-jta-7.1.0.Final.jar:7.1.0.Final (revision: ab602)]
	at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1026) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:795) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:758) ~[spring-tx-6.2.1.jar:6.2.1]
	at org.frankframework.jta.SpringTxManagerProxy.commit(SpringTxManagerProxy.java:72) ~[frankframework-core-9.1.0-20250107.042327.jar:9.1.0-20250107.042327]
	at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:253) ~[spring-jms-6.2.1.jar:6.2.1]
	at org.frankframework.jms.IbisMessageListenerContainer.receiveAndExecute(IbisMessageListenerContainer.java:96) ~[frankframework-core-9.1.0-20250107.042327.jar:9.1.0-20250107.042327]
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1420) ~[spring-jms-6.2.1.jar:6.2.1]
	at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1294) ~[spring-jms-6.2.1.jar:6.2.1]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]
	at java.base/java.lang.Thread.run(Unknown Source) [?:?]
Caused by: org.postgresql.util.PSQLException: ERROR: prepared transaction with identifier "131077_AAAAAAAAAAAAAP//rB8AAwAAjX1ngRblAAAGuzgwOWY3OGM1ZjMxMC1hYzFmMDAwMy0tNjFhZjVmNzFfMTk0NQ==_AAAAAAAAAAAAAP//rB8AAwAAjX1ngRblAAAGwQAAAAAAAAAA" does not exist
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2733) ~[postgresql.jar:42.7.4]
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2420) ~[postgresql.jar:42.7.4]
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:372) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:517) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:434) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:356) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:341) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:317) ~[postgresql.jar:42.7.4]
	at org.postgresql.jdbc.PgStatement.executeUpdate(PgStatement.java:290) ~[postgresql.jar:42.7.4]
	at org.postgresql.xa.PGXAConnection.rollback(PGXAConnection.java:462) ~[postgresql.jar:42.7.4]
	... 20 more
2025-01-10 12:53:19,172 WARN  [JmsListener [dequeue][1]] {} ats.arjuna - ARJUNA012089: Top-level abort of action 0:ffffac1f0003:8d7d:678116e5:6bb received heuristic decision: TwoPhaseOutcome.HEURISTIC_HAZARD

Anything else?

v510.zip
@mhdirkse
Copy link
Contributor Author

Tim tried to help me. He suggested that the issue can be fixed by setting max_prepared_transactions. This is done in the PostgreSQL test image used by the core team.

@nielsm5
Copy link
Member

nielsm5 commented Jan 13, 2025

The real problem here seems to be that he message is failing, but the application is not aware of this happening.
Rollback seems to happen after the application thinks it's done.

@philipsens philipsens removed the Bug label Jan 17, 2025
@MLenterman
Copy link

The real problem here seems to be that he message is failing, but the application is not aware of this happening. Rollback seems to happen after the application thinks it's done.

I have observed several other scenario's where a rollback happens after the adapter finished successfully that are not related to max_prepared_transactions not being set. The only common element I could see between them is that the transaction runs in to a timeout for some unknown reason, triggering a rollback. Interestingly enough, the adapter finishes as SUCCESS, but the message still ends up in the ErrorStore after the rollback.

Not sure if it is at all related, but maybe it helps.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
JDBC JMS Transaction Manager
Projects
Frank!Framework
Status: No status
Milestone
No milestone
Development

No branches or pull requests
4 participants
@nielsm5 @mhdirkse @MLenterman @philipsens