(Periodic Recovery) ARJUNA016027 occurs on long-running jbatch job

[xkylex]

I have a long-running jbatch job and this exception occurs several times.

What is the cause of this exception?

Or I didn't found any side-effects so can I just ignore this?

Environment:

• WildFly 8.0.0.Final
• jBeret-1.0.1.CR2-SNAPSHOT
• PostgreSQL 9.2.6
• postgresql-9.3-1100.jdbc41.jar

I had setup XA datasources that both of application and jberet job repository. they have their own database on the same PostgreSQL instance. also "max_prepared_transactions = 100" (same number to max_connections) of postgresql.conf but it didn't help.

2014-03-17 20:34:09,090 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016027: Local XARecoveryModule.xaRecovery got XA exception XAException.XAER_NOTA: org.postgresql.xa.PGXAException: 準備トランザクションのロールバックエラー

        at org.postgresql.xa.PGXAConnection.rollback(PGXAConnection.java:418)

        at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.rollback(XAManagedConnection.java:346)

        at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.rollback(XAResourceWrapperImpl.java:186)

        at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.handleOrphan(XARecoveryModule.java:786) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]

        at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:692) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]

        at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:431) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]

        at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:212) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]

        at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:789) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]

        at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) [narayana-jts-jacorb-5.0.0.Final.jar:5.0.0.Final (revision: 9aa71)]

Caused by: org.postgresql.util.PSQLException: ERROR: prepared transaction with identifier "131077_AAAAAAAAAAAAAP//CgABCECroNhTJq/xAAWSZzE=_AAAAAAAAAAAAAP//CgABCECroNhTJq/xAAWS4wAAAAEAAAAA" does not exist

        at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2161)

        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1890)

        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)

        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:560)

        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:403)

        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:331)

        at org.postgresql.xa.PGXAConnection.rollback(PGXAConnection.java:406)

        ... 8 more

[jamezp]

Is there anything in the log that indicates it's coming from JBeret or your application by chance? What I mean by coming from JBeret is coming from the JBeret JDBC repository type.

--

James R. Perkins

[xkylex]

Thanks for the response. I can't find anything indicates it's coming from JBeret or my application. only I can see that seems to be related were many logs of SkipListener. Also I tried that grep by "com.arjuna.ats.jta", it produces like this:

...

2014-03-17 20:32:55,129 WARN  [com.arjuna.ats.jta] (batch-batch - 24) ARJUNA016087: TransactionImple.delistResource - unknown resource

2014-03-17 20:33:31,129 WARN  [com.arjuna.ats.jta] (batch-batch - 27) ARJUNA016087: TransactionImple.delistResource - unknown resource

2014-03-17 20:34:09,087 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016027: Local XARecoveryModule.xaRecovery got XA exception XAException.XAER_NOTA: org.postgresql.xa.PGXAException: 準備トランザクションのロールバックエラー

2014-03-17 20:34:09,090 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016027: Local XARecoveryModule.xaRecovery got XA exception XAException.XAER_NOTA: org.postgresql.xa.PGXAException: 準備トランザクションのロールバックエラー

2014-03-17 20:34:13,243 WARN  [com.arjuna.ats.jta] (batch-batch - 30) ARJUNA016087: TransactionImple.delistResource - unknown resource

2014-03-17 20:34:50,904 WARN  [com.arjuna.ats.jta] (batch-batch - 35) ARJUNA016087: TransactionImple.delistResource - unknown resource

...

I'm starting thinking that merging job repository and application database into one database might help.

[jamezp]

If you're using different data sources I would think that wouldn't matter. I'll see if I can't find some time to create a SkipListener and see if I can't reproduce it. Of course if you have one that's easy enough to share, I'd be happy to take a look

--

James R. Perkins

[jesper.pedersen]

XAER_NOTA is def not good - and it seems that the XAResource for the batch job wasn't enlisted.

Please, provide full TRACE log, and share the application code for the batch job

[xkylex]

I would create some example and share it. because the batch job is a part of my production code so I can't share you as it is.

Do you mean ARJUNA016087 is not good too? could you tell me what it means? I'm good to know that because It appears more frequently on my batch jobs but I didn't found any side-effects so I've been ignoring it.

[jamezp]

Yeah that doesn't look right at all. I've filed a JIRA, [WFLY-3135] ARJUNA016087 warning message in batch jobs when committing transactions - JBoss Issue Tracker, but I need to talk to the transaction team.

--

James R. Perkins

[mnovak]

This is probably the same thing as https://bugzilla.redhat.com/show_bug.cgi?id=1009981 -  "Periodic recovery on committed transactions". If it's so then it's warm-less.

[xkylex]

Thanks for the information. I don't know whether it came from the same thing, but I guess that the situation "When the server is under an excessive load" is same as this case. because I can't reproduce it easily. it occurs every day in production environment which run at higher load for long time, but still I can't reproduce it on local development environment so I guess that some kind of such condition might be related.

[mnovak]

There is property com.arjuna.ats.jta.orphanSafetyInterval (default is 10000 ms) which can be set to higher value not to get those exceptions. This is configurable from version jbossjts-jacorb-4.17.15 if I'm correct. For our testing environment those warnings disappeared for value 40000 (ms).

From feedback from Tom Jenkinson it seems to be hard to get rid of those warnings as they're caused by high load.

[xkylex]

Thank you all, I got solved problems.

ARJUNA016027 disappeared with com.arjuna.ats.jta.orphanSafetyInterval=40000.

Also ARJUNA016087 disappeared with changing my ItemReader implementation to fetch primary keys in open(), then fetch each rows in readItem(). I implemented my ItemReader using ResultSet.HOLD_CURSORS_OVER_COMMIT to use ResultSet continuously across transactions. this is the cause.