search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.77k stars 2.68k forks source link

Narayana transaction recovery doesn't work with Oracle 23 #35333

Open michalvavrik opened 1 year ago

michalvavrik commented 1 year ago

Describe the bug

I use Quarkus Narayana and JDBC Oracle with JDBC object store. When testing my application, I use Oracle 23 as that is default Dev Services for Oracle docker image and I didn't find anywhere which Oracle version is supported for Narayana. Well, strictly speaking I found here https://www.narayana.io/platform-support/index.html Oracle 8.1.7, 9i and 10g which I am hesitant to believe considering that we are now on 23 (and rising :-)).

Expected behavior

Transaction recovery works with Oracle 23 or it is documented which Oracle version is supported (in Quarkus Narayana documentation please).

Actual behavior

Exception is logged and recovery is not accomplished

2023-08-13 17:40:17,293 WARN  [com.arj.ats.jta] (Periodic Recovery) ARJUNA016027: Local XARecoveryModule.xaRecovery got XA exception XAException.XAER_RMERR: javax.transaction.xa.XAException
    at oracle.jdbc.xa.OracleXAResource.recover(OracleXAResource.java:764)
    at io.agroal.narayana.RecoveryXAResource.recover(RecoveryXAResource.java:31)
    at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass(XARecoveryModule.java:735)
    at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass(XARecoveryModule.java:249)
    at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.getNewXAResource(XARecoveryModule.java:357)
    at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.getNewXAResource(XARecoveryModule.java:449)
    at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.getNewXAResource(XAResourceRecord.java:1263)
    at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit(XAResourceRecord.java:459)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2906)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2822)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1878)
    at com.arjuna.ats.arjuna.recovery.RecoverAtomicAction.replayPhase2(RecoverAtomicAction.java:71)
    at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.doRecoverTransaction(AtomicActionRecoveryModule.java:152)
    at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactionsStatus(AtomicActionRecoveryModule.java:253)
    at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass(AtomicActionRecoveryModule.java:109)
    at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:816)
    at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:382)

How to Reproduce?

Reproducer:

  1. git clone git@github.com:michalvavrik/quarkus-narayana-crash-recovery.git
  2. cd quarkus-narayana-crash-recovery
  3. follow README, it has detailed steps and previous logs https://github.com/michalvavrik/quarkus-narayana-crash-recovery

Output of uname -a or ver

Linux fedora 6.4.7-200.fc38.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Jul 27 20:01:18 UTC 2023 x86_64 GNU/Linux

Output of java -version

OpenJDK Runtime Environment Temurin-17.0.7+7 (build 17.0.7+7)

GraalVM version (if different from Java)

22.3

Quarkus version or git rev

3.2.4.Final and 999-SNAPSHOT

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.9.3

Additional information

No response

michalvavrik commented 1 year ago

Hey @zhfeng ,

I am having problem to make it work for Oracle (while it already works for me with Postgres, MariaDB, MySQL), so I adjusted your project in order to verify that problem is not in my tests and it seems that recovery doesn't work with Oracle either, could you have a look / provide feedback, please?

\cc @mmusgrov

zhfeng commented 1 year ago

IIRC, the Oracle needs a different recovery credential to run the recovery process. Let me check the documents.

zhfeng commented 1 year ago

Hi @michalvavrik,

Please check https://access.redhat.com/documentation/en-us/red_hat_jboss_enterprise_application_platform/7.1/html/configuration_guide/datasource_management#vendor_specific_xa_recovery

GRANT SELECT ON sys.dba_pending_transactions TO USER;
GRANT SELECT ON sys.pending_trans$ TO USER;
GRANT SELECT ON sys.dba_2pc_pending TO USER;
GRANT EXECUTE ON sys.dbms_xa TO USER;

And it seems there is no user configuration for recovery right now in quarkus. So it should be the same with quarkus.datasource.username

michalvavrik commented 1 year ago

note: I didn't get to it this week, will try it next week.

michalvavrik commented 1 year ago

Hey @zhfeng, apologies for taking my while.

So I have tested your link as well as any other link I could find in regards to Oracle XA transactions and can't make it work. I created application that executes commands inside xaview.sql as well as above linked stuff. 

git clone git clone https://github.com/michalvavrik/quarkus-test-suite.git
git fetch
git checkout feature/narayana-baremetal-unfinished-business
cd sql-db/narayana-transactions
mvn clean verify -Dit.test=OracleTransactionGeneralUsageIT -B -Dquarkus.log.level=TRACE -Dquarkus.log.min-level=TRACE 2>&1 | tee log

you will see in your log that

22:04:13,581 INFO  [app] 22:04:12,493 BaseTransaction.begin
22:04:13,581 INFO  [app] 22:04:12,493 StateManager::StateManager( 2, 0 )
22:04:13,581 INFO  [app] 22:04:12,493 BasicAction::BasicAction()
22:04:13,581 INFO  [app] 22:04:12,493 BasicAction::Begin() for action-id 0:ffff0a0000b9:b435:64fe2118:51
22:04:13,581 INFO  [app] 22:04:12,493 BasicAction::actionInitialise() for action-id 0:ffff0a0000b9:b435:64fe2118:51
22:04:13,581 INFO  [app] 22:04:12,493 ActionHierarchy::ActionHierarchy(1)
22:04:13,582 INFO  [app] 22:04:12,493 ActionHierarchy::add(0:ffff0a0000b9:b435:64fe2118:51, 1)
22:04:13,582 INFO  [app] 22:04:12,493 BasicAction::addChildThread () action 0:ffff0a0000b9:b435:64fe2118:51 adding Thread[executor-thread-1,5,main]
22:04:13,582 INFO  [app] 22:04:12,493 BasicAction::addChildThread () action 0:ffff0a0000b9:b435:64fe2118:51 adding Thread[executor-thread-1,5,main] result = true
22:04:13,582 INFO  [app] 22:04:12,493 TransactionReaper::insert ( BasicAction: 0:ffff0a0000b9:b435:64fe2118:51 status: ActionStatus.RUNNING, 60 )
22:04:13,582 INFO  [app] 22:04:12,493 ReaperElement::ReaperElement ( BasicAction: 0:ffff0a0000b9:b435:64fe2118:51 status: ActionStatus.RUNNING, 60 )
22:04:13,582 INFO  [app] 22:04:12,494 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,494 TransactionSynchronizationRegistryImple.getResource
22:04:13,582 INFO  [app] 22:04:12,494 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,494 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,494 TransactionSynchronizationRegistryImple.getResource
22:04:13,582 INFO  [app] 22:04:12,494 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,494 TransactionSynchronizationRegistryImple.registerInterposedSynchronization - Class: class io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization HashCode: 1654470859 toString: io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization@629d38cb
22:04:13,582 INFO  [app] 22:04:12,494 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,494 TransactionSynchronizationRegistryImple.putResource
22:04:13,582 INFO  [app] 22:04:12,494 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,494 TransactionImple.enlistResource ( io.agroal.narayana.BaseXAResource@644c77d2 )
22:04:13,582 INFO  [app] 22:04:12,494 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,494 StateManager::StateManager( 1, 0 )
22:04:13,582 INFO  [app] 22:04:12,494 AbstractRecord::AbstractRecord (0:ffff0a0000b9:b435:64fe2118:54, 1)
22:04:13,582 INFO  [app] 22:04:12,494 XAResourceRecord.XAResourceRecord ( < formatId=131077, gtrid_length=38, bqual_length=36, tx_uid=0:ffff0a0000b9:b435:64fe2118:51, node_name=quarkus-qe, branch_uid=0:ffff0a0000b9:b435:64fe2118:53, subordinatenodename=null, eis_name=0 >, io.agroal.narayana.BaseXAResource@644c77d2 ), record id=0:ffff0a0000b9:b435:64fe2118:54
22:04:13,582 INFO  [app] 22:04:12,494 RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffff0a0000b9:b435:64fe2118:54
22:04:13,582 INFO  [app] 22:04:12,494 Datasource 'xa-ds-1': Acquire connection oracle.jdbc.driver.LogicalConnection@9355f6b
22:04:13,582 INFO  [app] 22:04:12,494 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,495 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,495 TransactionSynchronizationRegistryImple.getResource
22:04:13,582 INFO  [app] 22:04:12,495 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,495 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,495 TransactionSynchronizationRegistryImple.getResource
22:04:13,582 INFO  [app] 22:04:12,495 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,495 TransactionSynchronizationRegistryImple.registerInterposedSynchronization - Class: class io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization HashCode: 1376603070 toString: io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization@520d4bbe
22:04:13,582 INFO  [app] 22:04:12,495 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,495 TransactionSynchronizationRegistryImple.putResource
22:04:13,582 INFO  [app] 22:04:12,495 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,495 TransactionImple.enlistResource ( io.agroal.narayana.BaseXAResource@59dd6a54 )
22:04:13,582 INFO  [app] 22:04:12,495 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,495 StateManager::StateManager( 1, 0 )
22:04:13,582 INFO  [app] 22:04:12,495 AbstractRecord::AbstractRecord (0:ffff0a0000b9:b435:64fe2118:58, 1)
22:04:13,582 INFO  [app] 22:04:12,496 XAResourceRecord.XAResourceRecord ( < formatId=131077, gtrid_length=38, bqual_length=36, tx_uid=0:ffff0a0000b9:b435:64fe2118:51, node_name=quarkus-qe, branch_uid=0:ffff0a0000b9:b435:64fe2118:57, subordinatenodename=null, eis_name=0 >, io.agroal.narayana.BaseXAResource@59dd6a54 ), record id=0:ffff0a0000b9:b435:64fe2118:58
22:04:13,582 INFO  [app] 22:04:12,496 RecordList::insert(RecordList: 0:ffff0a0000b9:b435:64fe2118:54) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffff0a0000b9:b435:64fe2118:58
22:04:13,582 INFO  [app] 22:04:12,496 Datasource 'xa-ds-2': Acquire connection oracle.jdbc.driver.LogicalConnection@742fc9f
22:04:13,582 INFO  [app] 22:04:12,496 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_ACTIVE
22:04:13,582 INFO  [app] 22:04:12,497 BaseTransaction.commit
22:04:13,582 INFO  [app] 22:04:12,497 TransactionImple.commitAndDisassociate
22:04:13,582 INFO  [app] 22:04:12,497 SynchronizationImple.beforeCompletion - Class: class io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization HashCode: 1654470859 toString: io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization@629d38cb
22:04:13,582 INFO  [app] 22:04:12,497 SynchronizationImple.beforeCompletion - Class: class io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization HashCode: 1376603070 toString: io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization@520d4bbe
22:04:13,582 INFO  [app] 22:04:12,497 BasicAction::End() for action-id 0:ffff0a0000b9:b435:64fe2118:51
22:04:13,582 INFO  [app] 22:04:12,497 BasicAction::prepare () for action-id 0:ffff0a0000b9:b435:64fe2118:51
22:04:13,582 INFO  [app] 22:04:12,497 XAResourceRecord.topLevelPrepare for XAResourceRecord < resource:io.agroal.narayana.BaseXAResource@644c77d2, txid:< formatId=131077, gtrid_length=38, bqual_length=36, tx_uid=0:ffff0a0000b9:b435:64fe2118:51, node_name=quarkus-qe, branch_uid=0:ffff0a0000b9:b435:64fe2118:53, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3a6b677a >, record id=0:ffff0a0000b9:b435:64fe2118:54
22:04:13,582 INFO  [app] 22:04:12,498 BasicAction::doPrepare() result for action-id (0:ffff0a0000b9:b435:64fe2118:51) on record id: (0:ffff0a0000b9:b435:64fe2118:54) is (TwoPhaseOutcome.PREPARE_READONLY) node id: (quarkus-qe)
22:04:13,582 INFO  [app] 22:04:12,498 RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffff0a0000b9:b435:64fe2118:54
22:04:13,583 INFO  [app] 22:04:12,498 BasicAction::onePhaseCommit() for action-id 0:ffff0a0000b9:b435:64fe2118:51
22:04:13,583 INFO  [app] 22:04:12,498 XAResourceRecord.topLevelOnePhaseCommit for XAResourceRecord < resource:io.agroal.narayana.BaseXAResource@59dd6a54, txid:< formatId=131077, gtrid_length=38, bqual_length=36, tx_uid=0:ffff0a0000b9:b435:64fe2118:51, node_name=quarkus-qe, branch_uid=0:ffff0a0000b9:b435:64fe2118:57, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@2838b32 >, record id=0:ffff0a0000b9:b435:64fe2118:58
22:04:13,583 INFO  [app] 22:04:12,501 BasicAction::phase2Commit() for action-id 0:ffff0a0000b9:b435:64fe2118:51
22:04:13,583 INFO  [app] 22:04:12,501 BasicAction::updateState() for action-id 0:ffff0a0000b9:b435:64fe2118:51
22:04:13,583 INFO  [app] 22:04:12,501 BasicAction::End() result for action-id (0:ffff0a0000b9:b435:64fe2118:51) is (TwoPhaseOutcome.PREPARE_OK) node id: (quarkus-qe)
22:04:13,583 INFO  [app] 22:04:12,501 SynchronizationImple.afterCompletion - Class: class io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization HashCode: 1376603070 toString: io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization@520d4bbe
22:04:13,583 INFO  [app] 22:04:12,501 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_COMMITTED
22:04:13,583 INFO  [app] 22:04:12,501 Datasource 'xa-ds-2': Returning connection oracle.jdbc.driver.LogicalConnection@742fc9f
22:04:13,583 INFO  [app] 22:04:12,501 SynchronizationImple.afterCompletion - Class: class io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization HashCode: 1654470859 toString: io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization@629d38cb
22:04:13,583 INFO  [app] 22:04:12,501 TransactionImple.getStatus: jakarta.transaction.Status.STATUS_COMMITTED
22:04:13,583 INFO  [app] 22:04:12,501 Datasource 'xa-ds-1': Returning connection oracle.jdbc.driver.LogicalConnection@9355f6b
22:04:13,583 INFO  [app] 22:04:12,501 BasicAction::removeChildThread () action 0:ffff0a0000b9:b435:64fe2118:51 removing 1
22:04:13,583 INFO  [app] 22:04:12,501 BasicAction::removeChildThread () action 0:ffff0a0000b9:b435:64fe2118:51 removing 1 result = true
22:04:13,583 INFO  [app] 22:04:12,501 TransactionReaper::remove ( BasicAction: 0:ffff0a0000b9:b435:64fe2118:51 status: ActionStatus.COMMITTED )

which means 2-phase commit is not used. I don't suggest it's Narayana issue, but in my eyes we should keep this issue open because saying you must have configured Oracle properly is not enough for users. At the very least this link https://access.redhat.com/documentation/en-us/red_hat_jboss_enterprise_application_platform/7.1/html/configuration_guide/datasource_management#vendor_specific_xa_recovery is not working for me for I tried that and many other combinations, here is my latest version https://github.com/quarkus-qe/quarkus-test-suite/commit/29278c895f2858d5de65980ad2cf3e1d6f39d4d9#diff-2e77feabb96016a247be60ca9bcbcb8efa6b0193587404ab6e886236f515cd6f where you can see I set a lot of grants manually (that xaview.sql is not executed, instead I execute it's content). Also I did try to start container manually and execute these in SQL Plus just to be sure.

Is Narayana transaction logs for 2-phase commit actually tested with Oracle somewhere? If so, I can read these tests and see how Oracle is configured and spawned there, please point me there. Otherwise I suggested we need better link for users.

jhalliday commented 1 year ago 
sqlplus sys/myuser@127.0.0.1:1521/mydb as sysdba;
  GRANT SELECT ON sys.DBA_PENDING_TRANSACTIONS TO myuser;
  GRANT FORCE TRANSACTION TO myuser;
marcosgopen commented 3 weeks ago

@michalvavrik Could I ask you to verify whether Oracle 23 doesn't work even when executing the GRANTs Jonathan mentioned above?