Atomikos Forum

ROLLBACK for XA transaction fails because PREPARE failed

hello everybody,

i'm trying to get XA transactions running with PostgreSQL and ActiveMQ. i am using Spring Framework 3.0.0 (declarative transactions), Hibernate 3.3.2, PostgreSQL 8.4 + JDBC4 Driver 8.4-701 (also tested with PostgreSQL 8.3 + JDBC3 Driver 8.3-603), ActiveMQ 5.3.0, Atomikos TransactionEssentials 3.6.5 (AtomikosDataSourceBean)

the application selects the current transaction timestamp from the database and sends a JMS message with ActiveMQ every 5 seconds.
the application is running and i force a shutdown of the database system after BEGIN but before PREPARE (to simulate a failure).
when i restart the database system a ROLLBACK PREPARED 'xid' is executed on the new connection.

the ROLLBACK PREPARED statement is executed over and over again. is there a way to limit the retry count?
why is ROLLBACK PREPARED executed when PREPARE was never executed for the transaction?

thanks,
tscho

Atomikos Log:

2010-05-28 14:25:14,946 [Atomikos:9] DEBUG atomikos  - XA resource 'dataSourceJTA': prepare for XID '31302E31302E312E332E746D30303034353030303031:31302E31302E312E332E746D3837' raised -3: the XA resource detected an internal error
org.postgresql.xa.PGXAException: Error preparing transaction
    at org.postgresql.xa.PGXAConnection.prepare(PGXAConnection.java:254)
    at com.atomikos.datasource.xa.XAResourceTransaction.prepare(XAResourceTransaction.java:591)
    at com.atomikos.icatch.imp.PrepareMessage.send(PrepareMessage.java:63)
    at com.atomikos.icatch.imp.PropagationMessage.submit(PropagationMessage.java:114)
    at com.atomikos.icatch.imp.Propagator$PropagatorThread.run(Propagator.java:90)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)
Caused by: org.postgresql.util.PSQLException: FATAL: terminating connection due to administrator command
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:1592)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1327)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:192)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:451)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:336)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:282)
    at org.postgresql.xa.PGXAConnection.prepare(PGXAConnection.java:242)
    ... 7 more
2010-05-28 14:25:14,947 [DefaultMessageListenerContainer-1] DEBUG atomikos  - Coordinator 10.10.1.3.tm0004500001 entering state: ABORTING
2010-05-28 14:25:14,947 [DefaultMessageListenerContainer-1] DEBUG atomikos  - (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@8e683a
2010-05-28 14:25:14,948 [Atomikos:9] INFO  atomikos  - XAResource.rollback ( 31302E31302E312E332E746D30303034353030303031:31302E31302E312E332E746D3837 ) on resource dataSourceJTA represented by XAResource instance org.postgresql.xa.PGXAConnection@da1c9f
2010-05-28 14:25:14,949 [Atomikos:9] WARN  atomikos  - XA resource 'dataSourceJTA': rollback for XID '31302E31302E312E332E746D30303034353030303031:31302E31302E312E332E746D3837' raised -3: the XA resource detected an internal error
org.postgresql.xa.PGXAException: Error rolling back prepared transaction
    at org.postgresql.xa.PGXAConnection.rollback(PGXAConnection.java:357)
    at com.atomikos.datasource.xa.XAResourceTransaction.rollback(XAResourceTransaction.java:659)
    at com.atomikos.icatch.imp.RollbackMessage.send(RollbackMessage.java:74)
    at com.atomikos.icatch.imp.PropagationMessage.submit(PropagationMessage.java:114)
    at com.atomikos.icatch.imp.Propagator$PropagatorThread.run(Propagator.java:90)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)
Caused by: org.postgresql.util.PSQLException: An I/O error occured while sending to the backend.
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:218)
    at org.postgresql.jdbc2.AbstractJdbc2Connection.executeTransactionCommand(AbstractJdbc2Connection.java:650)
    at org.postgresql.jdbc2.AbstractJdbc2Connection.commit(AbstractJdbc2Connection.java:670)
    at org.postgresql.jdbc2.AbstractJdbc2Connection.setAutoCommit(AbstractJdbc2Connection.java:633)
    at org.postgresql.xa.PGXAConnection.rollback(PGXAConnection.java:343)
    ... 7 more
Caused by: java.net.SocketException: Broken pipe
    at java.net.SocketOutputStream.socketWrite0(Native Method)
    at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
    at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
    at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
    at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
    at org.postgresql.core.PGStream.flush(PGStream.java:508)
    at org.postgresql.core.v3.QueryExecutorImpl.sendSync(QueryExecutorImpl.java:676)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:191)
    ... 11 more
    
=== shutdown/restart ===

2010-05-28 14:25:24,949 [Atomikos:9] DEBUG atomikos  - Propagator: retrying message: RollbackMessage to XAResourceTransaction: 31302E31302E312E332E746D30303034353030303031:31302E31302E312E332E746D3837
2010-05-28 14:25:24,949 [Atomikos:9] DEBUG atomikos  - dataSourceJTA: forcing refresh of XAConnection...
2010-05-28 14:25:24,972 [Atomikos:9] INFO  atomikos  - XAResource.rollback ( 31302E31302E312E332E746D30303034353030303031:31302E31302E312E332E746D3837 ) on resource dataSourceJTA represented by XAResource instance org.postgresql.xa.PGXAConnection@f1036f
2010-05-28 14:25:24,973 [Atomikos:9] WARN  atomikos  - XA resource 'dataSourceJTA': rollback for XID '31302E31302E312E332E746D30303034353030303031:31302E31302E312E332E746D3837' raised -3: the XA resource detected an internal error
org.postgresql.xa.PGXAException: Error rolling back prepared transaction
    at org.postgresql.xa.PGXAConnection.rollback(PGXAConnection.java:357)
    at com.atomikos.datasource.xa.XAResourceTransaction.rollback(XAResourceTransaction.java:659)
    at com.atomikos.icatch.imp.RollbackMessage.send(RollbackMessage.java:74)
    at com.atomikos.icatch.imp.PropagationMessage.submit(PropagationMessage.java:114)
    at com.atomikos.icatch.imp.Propagator$PropagatorThread.run(Propagator.java:90)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)
Caused by: org.postgresql.util.PSQLException: ERROR: prepared transaction with identifier "1096044365_MTAuMTAuMS4zLnRtMDAwNDUwMDAwMQ==_MTAuMTAuMS4zLnRtODc=" does not exist
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:1592)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1327)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:192)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:451)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:336)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:282)
    at org.postgresql.xa.PGXAConnection.rollback(PGXAConnection.java:347)
    ... 7 more

    
Database Log:
    
2010-05-28 14:25:05.216 CEST - postgres@10.10.1.3 testdb [4bffb5e5.214b|1/1409] LOG:  duration: 0.016 ms  bind S_1: BEGIN
2010-05-28 14:25:05.216 CEST - postgres@10.10.1.3 testdb [4bffb5e5.214b|1/1409] LOG:  duration: 0.004 ms  execute S_1: BEGIN
2010-05-28 14:25:05.216 CEST - postgres@10.10.1.3 testdb [4bffb5e5.214b|1/1409] LOG:  duration: 0.074 ms  parse <unnamed>: select cast(now() as timestamptz(3))
2010-05-28 14:25:05.216 CEST - postgres@10.10.1.3 testdb [4bffb5e5.214b|1/1409] LOG:  duration: 0.018 ms  bind <unnamed>: select cast(now() as timestamptz(3))
2010-05-28 14:25:05.216 CEST - postgres@10.10.1.3 testdb [4bffb5e5.214b|1/1409] LOG:  duration: 0.011 ms  execute <unnamed>: select cast(now() as timestamptz(3))
2010-05-28 14:25:06.213 CEST - @  [4bffae25.e61|] LOG:  received fast shutdown request
2010-05-28 14:25:06.213 CEST - @  [4bffae25.e61|] LOG:  aborting any active transactions
2010-05-28 14:25:06.213 CEST - postgres@10.10.1.3 testdb [4bffb5f3.216b|12/0] FATAL:  terminating connection due to administrator command
2010-05-28 14:25:06.213 CEST - postgres@10.10.1.3 testdb [4bffb5e5.2152|8/0] FATAL:  terminating connection due to administrator command
2010-05-28 14:25:06.213 CEST - postgres@10.10.1.3 testdb [4bffb5f2.2162|11/0] FATAL:  terminating connection due to administrator command
2010-05-28 14:25:06.213 CEST - postgres@10.10.1.3 testdb [4bffb5e5.2154|10/0] FATAL:  terminating connection due to administrator command

=== shutdown/restart ===

2010-05-28 14:25:16.554 CEST - [unknown]@ [unknown] [4bffb62c.222b|] LOG:  connection received: host=10.10.1.3 port=49073
2010-05-28 14:25:16.554 CEST - postgres@10.10.1.3 testdb [4bffb62c.222b|] LOG:  connection authorized: user=postgres database=testdb
2010-05-28 14:25:16.559 CEST - postgres@10.10.1.3 testdb [4bffb62c.222b|1/8] LOG:  duration: 0.185 ms  parse <unnamed>: ROLLBACK PREPARED '1096044365_MTAuMTAuMS4zLnRtMDAwNDUwMDAwMQ==_MTAuMTAuMS4zLnRtODc='
2010-05-28 14:25:16.559 CEST - postgres@10.10.1.3 testdb [4bffb62c.222b|1/8] LOG:  duration: 0.008 ms  bind <unnamed>: ROLLBACK PREPARED '1096044365_MTAuMTAuMS4zLnRtMDAwNDUwMDAwMQ==_MTAuMTAuMS4zLnRtODc='
2010-05-28 14:25:16.559 CEST - postgres@10.10.1.3 testdb [4bffb62c.222b|1/8] ERROR:  prepared transaction with identifier "1096044365_MTAuMTAuMS4zLnRtMDAwNDUwMDAwMQ==_MTAuMTAuMS4zLnRtODc=" does not exist
2010-05-28 14:25:16.559 CEST - postgres@10.10.1.3 testdb [4bffb62c.222b|1/8] STATEMENT:  ROLLBACK PREPARED '1096044365_MTAuMTAuMS4zLnRtMDAwNDUwMDAwMQ==_MTAuMTAuMS4zLnRtODc='
Tscho T Send private email
Friday, May 28, 2010
 
 

This topic is archived. No further replies will be accepted.

Other recent topics Other recent topics