A deeper dive into Transaction Timeouts with JEE7,Wildfly and Oracle RAC

Potential Transaction Timeouts in a JEE7 / RAC 12.1.0.2 env

  1.  JTA Transaction Timeout triggering an OracleXAResource.rollback operation on our TM side [ Wildfly 8.2 ]
  2. JTA Transaction Timeout occuring on the RM side [ ORA-24756 ]
  3. DISTRIBUTED LOCK TIMEOUT occuring on the RM side [ ORA-2049 ]
  4. HTTPSession Object Timeout

Rule of Thumb

  •  JTA transaction timeout  <  DISTRIBUTED_LOCK_TIMEOUT  <  HTTP Session Timeout
  • In a working JTA env we only want to see JTA timeouts triggered by our TM  [ see 1. ]

Overview Bean Managed Transaction with JTA

  • Each JTA transaction is associated with an Execution Thread
  • Only a single Transaction can be active within an  Execution Thread
  • If one Transaction is active the user can’t start an new one until the TX was committed suspended or rolled back
  • The setTransactionTimeout() method causing  the transaction to roll back after reaching the timeout limit
  • Do not invoke the getRollbackOnly and setRollbackOnly methods of the EJBContext interface in bean-managed transactions [ BMT ]
  • For bean-managed transactions, invoke the getStatus and rollback methods of the UserTransaction interface
  • If a session times out within Oracle, then the Oracle database Process Monitor (PMON) will delete the transaction branch if not prepared or cause the transaction to become in-doubt if prepared.
  • We can track the Transaction Timeout at RM side using Event 10246
         alter system set event=”10246 trace name context forever, level 1″ scope=spfile sid=’*’;
  • If the PMON terminates the transaction branch you should get error: ORA-24756: transaction does not exist
  • If the Transaction can’t get a database lock you should get error: ORA-02049: timeout: distributed transaction waiting for lock
  • During this JPA test we use OnePhaseCommit [ means no 2PC / no prepare call ]
  • We always want that our TM is controlling the Transaction
  • If runnig with correct timeout settings we should not see any ORA-2049 or ORA-24756 errors

How to track the XA transaction at database level

  • FORMATID, GLOBALID, BRANCHID build our  XA Xid
  • TIGHTLY COUPLED means we serialize using a DX lock [ can lead to a performance problem ]  and can use RAC ClusterWide Transaction Feature
  • PREPARECOUNT=0 this Tx is not yet prepared
  • STATE ACTIVE means this transaction is active
SQL> select FORMATID, GLOBALID, BRANCHID, BRANCHES, REFCOUNT, PREPARECOUNT, STATE, 
     FLAGS, COUPLING  from v$global_transaction;

  FORMATID GLOBALID
---------- ----------------------------------------------------------------
BRANCHID
--------------------------------------------------------------------------------------------------------------------------------
  BRANCHES   REFCOUNT PREPARECOUNT STATE                       FLAGS COUPLING
---------- ---------- ------------ -------------------------------------- ---------- ---------------
    131077 00000000000000000000FFFFC0A805C935ABDAA855FBBB600000046931
00000000000000000000FFFFC0A805C935ABDAA855FBBB600000046C0000000200000000
     1        1         0 ACTIVE                       0 TIGHTLY COUPLED

TEST 1:  Testing global JTA Timeout

  • The service routine will run 60 seconds before committing the data
  • The JPA timeout will rollback the transaction after the JTA timeout [ 30 seconds ]
  • The Transaction Reaper Wildfly Thread will rollback the transaction after 30 second
  • Later on the commit fails as we don’t run inside a transaction anymore
Setup
HTTP Session Timeout       : 1800 seconds
JTA Timeout                :   30 seconds
ut.setTransactionTimeout() :  not active
Service routine sleep      :   60 seconds 

Setup and verify  JTA Transaction Timeout : 30 seconds:

$ $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9990 '/subsystem=transactions/:write-attribute(name=default-timeout,value=30)';
{
    "outcome" => "success",
    "result" => 30,
    "response-headers" => {"process-state" => "reload-required"}
}

$  $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9990 '/subsystem=transactions/:read-attribute(name=default-timeout)'
{
    "outcome" => "success",
    "result" => 30
}

-> Restart Wildfly
-> Run test test case
 
Wildfly Logs:
10:18:52,211 INFO  [stdout] (default task-15) +++ HttpSessionListenerImpl:: sessionCreated()....
10:18:55,489 INFO  [org.eclipse.persistence.connection] (default task-36) 
        Connected: jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka
    User: SCOTT
    Database: Oracle  Version: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
    Driver: Oracle JDBC driver  Version: 12.1.0.2.0
...
2015-09-17 10:18:55,500 INFO  [org.eclipse.persistence.connection] (default task-17) vfs:/usr/local/wildfly-8.2.0.Final/standalone/deployments/WFJPA2EL-1.0.war/WEB-INF/classes/_jpaELPU login successful
10:19:27,365 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffc0a805c9:6a216e79:55fa71c5:72 in state  RUN
10:19:27,367 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffc0a805c9:6a216e79:55fa71c5:72 invoked while multiple threads active within it.
10:19:27,368 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffffc0a805c9:6a216e79:55fa71c5:72 aborting with 1 threads active!
10:19:27,383 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffffc0a805c9:6a216e79:55fa71c5:72
10:19:57,381 WARN  [com.arjuna.ats.arjuna] (default task-17) ARJUNA012077: Abort called on already aborted atomic action 0:ffffc0a805c9:6a216e79:55fa71c5:72

-> JPA connection returned at 10:18:55
   About 32 seconds later the global JTA timeout kicks in and terminates the transaction a

Stack :
10:19:57.382 Error in top level function: timeoutTest()
10:19:57.384 ARJUNA016102: The transaction is not active! Uid is 0:ffffc0a805c9:6a216e79:55fa71c5:72
10:19:57.385 javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffffc0a805c9:6a216e79:55fa71c5:72
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1156)
    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
    at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
    at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:173)
    at com.hhu.wfjpa2el.JPATestBean.timeoutTest(JPATestBean.java:456)

TEST 2: Overriding global JTA Timeout with  ut.setTransactionTimeout()

  • This test is similar to TEST 1
  • it only overrides the JTA transaction timeout with setTransactionTimeout()
Setup 
HTTP Session Timeout       : 1800 seconds
JTA Timeout                :   30 seconds
ut.setTransactionTimeout() :   15 seconds
Service routine sleep      :   60 seconds 

Java Code 
     ...
     ut  = (UserTransaction)new InitialContext().lookup("java:comp/UserTransaction");          
     ut.setTransactionTimeout(getTxTimeout());                     
     ut.begin();
     ...

Wildfly Log :
2015-09-17 10:58:58,426 INFO  [org.eclipse.persistence.connection] (default task-36) 
        Connected: jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka
    User: SCOTT
    Database: Oracle  Version: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
    Driver: Oracle JDBC driver  Version: 12.1.0.2.0
2015-09-17 10:58:58,431 INFO  [org.eclipse.persistence.connection] (default task-36) vfs:/usr/local/wildfly-8.2.0.Final/standalone/deployments/WFJPA2EL-1.0.war/WEB-INF/classes/_jpaELPU login successful
2015-09-17 10:59:15,094 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffc0a805c9:6a216e79:55fa71c5:11a in state  RUN
2015-09-17 10:59:15,096 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffc0a805c9:6a216e79:55fa71c5:11a invoked while multiple threads active within it.
2015-09-17 10:59:15,097 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffffc0a805c9:6a216e79:55fa71c5:11a aborting with 1 threads active!
2015-09-17 10:59:15,115 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffffc0a805c9:6a216e79:55fa71c5:11a

-> JPA connection returned at  10:58:58,
-> About 17 seconds later the Timeout value set by ut.setTransactionTimeout()  kicks in and terminates the transaction a
-> As in TEST 1 the commit fail with a similar stack  

TEST 3 : Stop all TM Threads and  let the RM [ Resource Manager ] terminate the transaction

  • In this test set a breakpoint at OracleXAResource.commit to stop all WildFly Threads
  • This will avoid that any WildFly Thread is running a ROLLBACK
  • You may read following article to setup a XA Breakpoints with Netbeans
  • As no client ROLLBACK operation can terminate the transaction PMON takes over control and terminates the TX
Setup 
HTTP Session Timeout       : 1800 seconds
JTA Timeout                :   30 seconds
ut.setTransactionTimeout() :   20 seconds
Service routine sleep      :  not active

PMON Tracing 
Enable PMON tracing   for our RAC 12.1.0.2 database 
SQL> alter system set event="10246 trace name context forever, level 1" scope=spfile sid='*';
SQL> startup force
SQL> show parameter event
SQL>
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
even t                                string      10246 trace name context forever, level 1

PMON trace 
*** 2015-09-18 11:47:04.143
 bno=1 timeout=20 dtime=1442569601 ctime=1442569623 ser=1 evt=1
ksuprog() called at ktur.c:3906
[claim lock 0x74cb0100 for dead session/txn in procp 0x76b29430.18437][hist x424224a1]
deleted branch 0x72558fc0 in first attempt
PMON last posted from location=FILE:/ade/b/2502491802/oracle/rdbms/src/hdir/ksa2.h LINE:294 ID:ksasnr, process=47, post_num=41

-> timeout=20  translates to our JTA timing set with  ut.setTransactionTimeout(20); 
-> The RM ( Oracle Database ) has terminated this Transaction 
-> The transaction timeout was to 20 [ timeout=20 ] 

Errors  :
  XA Failure     : XAException.XAER_NOTA: oracle.jdbc.xa.OracleXAException
  ORacle Failure : java.sql.SQLException: ORA-24756: transaction does not exist
 
Java Stack :
Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Advanced Analytics and Real Application Testing options jndiName=java:jboss/datasources/xa_rac12g_banka]) failed with exception XAException.XAER_NOTA: oracle.jdbc.xa.OracleXAException
    at oracle.jdbc.driver.T4CXAResource.kputxrec(T4CXAResource.java:965)
    at oracle.jdbc.driver.T4CXAResource.doCommit(T4CXAResource.java:454)
    at oracle.jdbc.xa.client.OracleXAResource.commit(OracleXAResource.java:583)
    at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.commit(XAManagedConnection.java:338)
    at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.commit(XAResourceWrapperImpl.java:107)
    at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:679) [jbossjta-4.16.6.Final.jar:]
    at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2317) [jbossjta-4.16.6.Final.jar:]
    at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1475) [jbossjta-4.16.6.Final.jar:]
    at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96) [jbossjta-4.16.6.Final.jar:]
    at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [jbossjta-4.16.6.Final.jar:]
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1166) [jbossjta-4.16.6.Final.jar:]
    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [jbossjta-4.16.6.Final.jar:]
    at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
    at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:173)
    at com.hhu.wfjpa2el.JPATestBean.timeoutTest(JPATestBean.java:466) [classes:]

Caused by: java.sql.SQLException: ORA-24756: transaction does not exist
    at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:450)
    at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:392)
    at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:385)
    at oracle.jdbc.driver.T4CTTIfun.processError(T4CTTIfun.java:1018)
    at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:522)
    at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:257)
    at oracle.jdbc.driver.T4CTTIOtxen.doOTXEN(T4CTTIOtxen.java:166)
    at oracle.jdbc.driver.T4CXAResource.doTransaction(T4CXAResource.java:757)
    at oracle.jdbc.driver.T4CXAResource.doCommit(T4CXAResource.java:428)

TEST 4 : Understand and Testing DISTRIBUTED_LOCK_TIMEOUT

  • DISTRIBUTED_LOCK_TIMEOUT default value is 60 seconds
  • If a DML can get the lock within DISTRIBUTED_LOCK_TIMEOUT ORA-2049 is thrown
If the locking transaction runs for longer than the database DISTRIBUTED_LOCK_TIMEOUT  (e.g. a single phase trans
action with no timeout) a deadlock  type situation occurs and the XA / Oracle distributed transactions can fail 
with “ORA-02049: timeout: distributed transaction waiting for lock”. If the ordering of timeouts is correct, then 
this error should never be received within a XA distributed transaction since the TM timeout should be exceeded 
before the DISTRIBUTED_LOCK_TIMEOUT is reached

Setup 
HTTP Session Timeout       : 1800 seconds
JTA Timeout                :   30 seconds
ut.setTransactionTimeout() :  120 seconds
DISTRIBUTED_LOCK_TIMEOUT   :   60 seconds

As ut.setTransactionTimeout() < DISTRIBUTED_LOCK_TIMEOUT  the database will throw ORA-2049 errors


Prepare test  
SQL>  show parameter dist
NAME                     TYPE     VALUE
------------------------------------ ----------- ------------------------------
distributed_lock_timeout         integer     60
Note PMON runs only every 60 seconds so we can see a delay between 60 and 120 seconds untill we hot ORA-2049

Lock the records
SQL> select * from emp2 for update;
     EMPNO ENAME      JOB           SAL
---------- ---------- --------- ----------
      9997 Helmut     Progr.         63206

Our JPA code will start a BMT and update the same record resulting in a ORA-2049 error 
  UPDATE EMP2 SET SAL = ? WHERE (EMPNO = ?)

Call flow 
  ut.begin()
  JPA update gets blocked untill we hit ORA-2049 error

Verify the Transation status before getting ORA-2049
SQL> select FORMATID, GLOBALID, BRANCHID, BRANCHES, REFCOUNT, PREPARECOUNT, STATE, FLAGS, COUPLING
           from v$global_transaction;

  FORMATID GLOBALID
---------- ----------------------------------------------------------------
BRANCHID
--------------------------------------------------------------------------------------------------------------------------------
  BRANCHES   REFCOUNT PREPARECOUNT STATE                       FLAGS COUPLING
---------- ---------- ------------ -------------------------------------- ---------- ---------------
    131077 00000000000000000000FFFFC0A805C935ABDAA855FBBB60000003C931
00000000000000000000FFFFC0A805C935ABDAA855FBBB60000003CC0000000200000000
     1        1         0 ACTIVE                       0 TIGHTLY COUPLED


Error Stacks 
12:06:04.535 Error in top level function: timeoutTest()

12:06:04.536 Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.5.2.v20140319-9ad6abd): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLSyntaxErrorException: ORA-02049: timeout: distributed transaction waiting for lock

Error Code: 2049
Call: UPDATE EMP2 SET SAL = ? WHERE (EMPNO = ?)
    bind => [2 parameters bound]
Query: UpdateObjectQuery(com.hhu.wfjpa2el.Emp2[ empno=9997 ])

12:06:04.539 javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.5.2.v20140319-9ad6abd): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLSyntaxErrorException: ORA-02049: timeout: distributed transaction waiting for lock

Error Code: 2049
Call: UPDATE EMP2 SET SAL = ? WHERE (EMPNO = ?)
    bind => [2 parameters bound]
Query: UpdateObjectQuery(com.hhu.wfjpa2el.Emp2[ empno=9997 ])
    at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:868)
    at com.hhu.wfjpa2el.JPATestBean.timeoutTest(JPATestBean.java:472)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)


2015-09-18 12:27:05,295 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use 
for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, 
  tx_uid=0:ffffc0a805c9:35abdaa8:55fbbb60:49, node_name=1, branch_uid=0:ffffc0a805c9:35abdaa8:55fbbb60:4c, subordinatenodename=null, 
  eis_name=java:jboss/datasources/xa_rac12g_banka >, heuristic:   TwoPhaseOutcome.FINISH_OK, product: 
  Oracle/Oracle Database 12c12:27:05,295 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: 
    Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord 
       < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a805c9:35abdaa8:55fbbb60:49, 
       node_name=1, branch_uid=0:ffffc0a805c9:35abdaa8:55fbbb60:4c, subordinatenodename=null, eis_name=java:jboss/datasources/xa_rac12g_banka >, 
    heuristic: TwoPhaseOutcome.FINISH_OK, product: Oracle/Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production


As we don't rollback the Transaction in our sample this is done by the Transaction Reaper Wildfly thread 
"Transaction Reaper Worker 1"
oracle.jdbc.xa.client.OracleXAResource.rollback(OracleXAResource.java:945)
org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.rollback(XAManagedConnection.java:346)
org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.rollback(XAResourceWrapperImpl.java:196)
com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:355)
com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2939)
com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2918)
com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1632)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:116)
com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:377)
com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)

TEST 5 : Testing HTTP session Timeout

  • In this test the service routine runs 5 seconds longer [ see sleep 20 s ] compared to our HTTP session limit
  • When returned from our service routine the HTTP session object was already deleted
  • Again The XA transaction will be rolled back by the Wildfly Transaction Reaper Worker Thread
Setup :
HTTP Session Timeout                :   15 seconds
JTA Timeout                         :   30 seconds
ut.setTransactionTimeout()          :   not active
Service routine duration/sleep      :   20 seconds 

Java Code : 
  HttpSession session;
  ...
  session.setMaxInactiveInterval(getSessTimeout());

Wildfly Log reports :
15:55:35,839 SEVERE [javax.enterprise.resource.webcontainer.jsf.application] (default task-5) Error Rendering View[/index.xhtml]: java.lang.IllegalStateException: UT000010: Session not found Iu250lTlBLzIu_FlPHWNxq5_
    at io.undertow.server.session.InMemorySessionManager$SessionImpl.getAttribute(InMemorySessionManager.java:353) [undertow-core-1.1.0.Final.jar:1.1.0.Final]
    at io.undertow.servlet.spec.HttpSessionImpl.getAttribute(HttpSessionImpl.java:121) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]
    at com.sun.faces.context.SessionMap.get(SessionMap.java:118) [jsf-impl-2.2.8-jbossorg-1.jar:]
    at com.sun.faces.application.view.FaceletViewHandlingStrategy.getResponseEncoding(FaceletViewHandlingStrategy.java:1271) [jsf-impl-2.2.8-jbossorg-1.jar:]
    at com.sun.faces.application.view.FaceletViewHandlingStrategy.createResponseWriter(FaceletViewHandlingStrategy.java:1182) [jsf-impl-2.2.8-jbossorg-1.jar:]
    at com.sun.faces.application.view.FaceletViewHandlingStrategy.renderView(FaceletViewHandlingStrategy.java:403) [jsf-impl-2.2.8-jbossorg-1.jar:]
    at com.sun.faces.application.view.MultiViewHandler.renderView(MultiViewHandler.java:133) [jsf-impl-2.2.8-jbossorg-1.jar:]
    at javax.faces.application.ViewHandlerWrapper.renderView(ViewHandlerWrapper.java:337) [jboss-jsf-api_2.2_spec-2.2.8.jar:2.2.8]
    at javax.faces.application.ViewHandlerWrapper.renderView(ViewHandlerWrapper.java:337) [jboss-jsf-api_2.2_spec-2.2.8.jar:2.2.8]
    at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:120) [jsf-impl-2.2.8-jbossorg-1.jar:]
    at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101) [jsf-impl-2.2.8-jbossorg-1.jar:]
    at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:219) [jsf-impl-2.2.8-jbossorg-1.jar:]
    at javax.faces.webapp.FacesServlet.service(FacesServlet.java:647) [jboss-jsf-api_2.2_spec-2.2.8.jar:2.2.8]
    at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85) [undertow-servlet-1.1.0.Final.jar:1.1.0.Final]

Which Thread is rolling back the transaction ?

Setting a breakpoint on OracleXAResource.rollback shows that the Transaction Reaper is rolling back the Transaction 
"Transaction Reaper Worker 2"
oracle.jdbc.xa.client.OracleXAResource.rollback(OracleXAResource.java:945)
org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.rollback(XAManagedConnection.java:346)
org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.rollback(XAResourceWrapperImpl.java:196)
com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:355)
com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2939)
com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2918)
com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1632)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:116)
com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:377)
com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)

JAVA Test CODE

 public String timeoutTest()  
      {
        EntityManager em;
        String methodName = "timeoutTest()";
        UserTransaction ut =null;
        cleanall();
          try
          {    
            setRunTimeInfo("Calling " + methodName  +  " in progress .. ");
            setRunTimeInfo("Requesting Entity Manager.. ");
            
            HttpSession session = (HttpSession) FacesContext.getCurrentInstance().getExternalContext().getSession(true);
            if ( session == null)
              {
                throw new IllegalArgumentException(methodName+ ": Could not get HTTP session : ");    
              }                        
            /*
                HTTP session object is not thread safe. We need to syncronoise on session id.
                For datails read :  http://yet-another-dev.blogspot.de/2009/08/synchronizing-httpsession.html
            */
            final Object lock = session.getId().intern();  
            Emp2 e = null;
            long eno = -1;
            synchronized(lock) 
              {
                
                if ( getTestMode() == 4)
                  {
                    setSessTimeout(15);
                    setTxTimeout(100); 
                    session.setMaxInactiveInterval(getSessTimeout());
                    setRunTimeInfo("HTTP SessionTimeout() set to: " 
                            + getSessTimeout()  + " seconds");
                  }
                
                if ( getTestMode() == 3)
                  {
                    setTxTimeout(100);  
                    //setSessTimeout(15);
                    setRunTimeInfo("ut.setTransactionTimeout() set to: " 
                            + getTxTimeout()  + " seconds");
                    
                  } 
                
                if ( getTestMode() == 2)
                  {
                    setTxTimeout(20);  
                    //setSessTimeout(15);
                    setRunTimeInfo("Overriding global JTA Timeout : 30 seconds with  ut.setTransactionTimeout() set to: " 
                            + getTxTimeout()  + " seconds");
                    
                  }  
                if ( getTestMode() == 1)
                  {
                    setTxTimeout(15);    
                    setRunTimeInfo("Overriding global JTA Timeout : 30 seconds with  ut.setTransactionTimeout() set to: " 
                            + getTxTimeout()  + " seconds");
                    
                  }    
                if ( getTestMode() == 0)
                  {
                    setRunTimeInfo("Testing global JTA Timeout : 30 seconds");
                  }   
                
                // startAndSuspendSimple(session);
                trackSession(session, methodName );
                em=getEntityManager();
                eno= getEmpno();              
                setRunTimeInfo("Inside " + methodName + " - Empno: " + eno + " - Thread: " +  Thread.currentThread().getName());                             
                e = em.find(Emp2.class, eno );
                checkEntity(e,em);
                e.setSal(e.getSal().add(increaseSalStep1) );
                ut  = (UserTransaction)new InitialContext().lookup("java:comp/UserTransaction");
                String tx_status_before = returnTXStatus(ut);                  
            
                if ( getTestMode() == 1 ||  getTestMode() == 2 || getTestMode() == 3 )
                  {
                    ut.setTransactionTimeout(getTxTimeout());
                    setRunTimeInfo("JTA Transation started with  ut.setTransactionTimeout() set to  : " + getTxTimeout() + " seconds");
                  }    
                ut.begin();
                em.joinTransaction();
                e.setSal(e.getSal().add(increaseSalStep1) );
                em.merge(e);
                    // Update database record 
                em.flush();
                int sleep_time = 20;
                sleep(sleep_time*1000);
               
                ut.commit();
                setRunTimeInfo("Commit Called ");
               
                String tx_status_after = returnTXStatus(ut);     
                setRunTimeInfo(methodName + ": em.flush() // but NO ut.commit   - Before " + tx_status_before
                    + " - After " + tx_status_after);
                checkEntity(e,em);
                setRunTimeInfo("Closing  Entity Manager.. !");
                closeEntityManager();
              }
          } catch ( Throwable t1)
          { 
            // ut.rollback() operation is missing here !           
            setRunTimeInfo("FATAL ERROR in :  "  + methodName  );
                // Use Throwable as we don't want to loose any important imformation
                // Note: Throwable is super class of Exception class          
            genericException("Error in top level function: " + methodName , (Exception)t1);            
          }
        closeEntityManager();            
        setRunTimeInfo("Leaving " + methodName + " - Entity manager  closed !\n");
        return "index";
      }

 

Reference

WildFly 8.2 Installation and First Steps

Installation of Wildfly 8.2

Download Wildfly 8.2 from http://wildfly.org/downloads/

$ cd /home/oracle/WILDFLY
$ unzip  /media/sf_kits/JEE/wildfly-8.2.0.Final.zip

In case you have multiple Wildfly instances runing  you can easily rename top level directory 
$ mv wildfly-8.2.0.Final wildfly-8.2.0.Final_PRODUCITON

Some useful SHELL variables 
export WILDFLY_HOME=/home/oracle/WILDFLY/wildfly-8.2.0.Final_PRODUCITON
alias wf=$WILDFLY_HOME/bin/standalone.sh
alias wfd='cd $WILDFLY_HOME'

Start and stop  Wildfly 
Start WildFly in standalone mode;
[oracle@wls1 local]$ $WILDFLY_HOME/bin/standalone.sh 
=========================================================================

  JBoss Bootstrap Environment
  JBOSS_HOME: /usr/local/wildfly-8.2.0.Final
  JAVA: /usr/java/jdk1.7.0_71/bin/java
  JAVA_OPTS:  -server -Xms64m -Xmx512m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true
...

Now test that we can display the first WEB Page using the default WILDFLY HTTP PORT number:
$ firefox localhost:8080

Stop the Server 
[oracle@wls1 ~]$ $WILDFLY_HOME/bin/jboss-cli.sh --connect command=:shutdown
{"outcome" => "success"} 

Add an Admin User

$ add-user.sh
What type of user do you wish to add? 
 a) Management User (mgmt-users.properties) 
 b) Application User (application-users.properties)
(a): 
Enter the details of the new user to add.
Using realm 'ManagementRealm' as discovered from the existing property files.
Username : oracle
....

Changing Ports [in case you need to run as 2.nd WILDFLY instance on your System ]

Edit  $WILDFLY_HOME/standalone/configuration/standalone.xml
Change
   <socket-binding-group name="standard-sockets" default-interface="public" port-offset="${jboss.socket.binding.port-offset:0}">
        <socket-binding name="management-http" interface="management" port="${jboss.management.http.port:9990}"/>
        <socket-binding name="management-https" interface="management" port="${jboss.management.https.port:9993}"/>
        <socket-binding name="ajp" port="${jboss.ajp.port:8009}"/>
        <socket-binding name="http" port="${jboss.http.port:8080}"/>
        <socket-binding name="https" port="${jboss.https.port:8443}"/>
        <socket-binding name="txn-recovery-environment" port="4712"/>
        <socket-binding name="txn-status-manager" port="4713"/>
        <outbound-socket-binding name="mail-smtp">
            <remote-destination host="localhost" port="25"/>
        </outbound-socket-binding>
</socket-binding-group>
to 
    <socket-binding-group name="standard-sockets" default-interface="public" port-offset="${jboss.socket.binding.port-offset:0}">
        <socket-binding name="management-http" interface="management" port="${jboss.management.http.port:9980}"/>
        <socket-binding name="management-https" interface="management" port="${jboss.management.https.port:9983}"/>
        <socket-binding name="ajp" port="${jboss.ajp.port:8010}"/>
        <socket-binding name="http" port="${jboss.http.port:8081}"/>
        <socket-binding name="https" port="${jboss.https.port:8444}"/>
        <socket-binding name="txn-recovery-environment" port="4702"/>
        <socket-binding name="txn-status-manager" port="4703"/>
        <outbound-socket-binding name="mail-smtp">
            <remote-destination host="localhost" port="26"/>
        </outbound-socket-binding>
    </socket-binding-group>

Restart your server and verify the new Ports:  
$ $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9980 command=:shutdown
{"outcome" => "success"}
$ $WILDFLY_HOME/bin/standalone.sh 

$ firefox localhost:8081  --> Should display the Wildfly default page
$ firefox localhost:9980  --> You should be able to successfully login to the Management Console 

Use jboss.cli to connect to new Management Controller 
$ $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9980 

Server.log should report the changed PORT numbers:
10:58:40,755 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-3) JBAS017519: Undertow HTTP listener default listening on /127.0.0.1:8081
..
10:58:41,737 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015961: Http management interface listening on http://127.0.0.1:9980/management
10:58:41,738 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015951: Admin console listening on http://127.0.0.1:9980

 

Setup Oracle JDBC driver and a RAC datasource

Step 1: Add Oracle JDBC driver as a module 
[oracle@wls1 WILDFLY]$ cat add_module.cli 
module add --name=com.oracle.ojdbc --resources=/home/oracle/JDBC/Driver/ojdbc7.jar --dependencies=javax.api,javax.transaction.api

$ $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9980  --file=add_module.cli 

Verify that the proper module.xml was created 
$ ls modules/com/oracle/ojdbc/main/
module.xml  ojdbc7.jar
$ cat  modules/com/oracle/ojdbc/main/module.xml 
<?xml version="1.0" ?>
<module xmlns="urn:jboss:module:1.1" name="com.oracle.ojdbc">
    <resources>
        <resource-root path="ojdbc7.jar"/>
    </resources>
    <dependencies>
        <module name="javax.api"/>
        <module name="javax.transaction.api"/>
    </dependencies>
<module>

Step 2: Deploy the JDBC driver
$ cat add_jdbc_driver.cli
/subsystem=datasources/jdbc-driver=oracle/:add(driver-name=oracle, driver-module-name=com.oracle.ojdbc, driver-xa-datasource-class-name=oracle.jdbc.xa.client.OracleXADataSource) 
$  $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9980  --file=add_jdbc_driver.cli
{"outcome" => "success"} 

Verify Driver 
[oracle@wls1 WILDFLY]$   $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9980   /subsystem=datasources:installed-drivers-list
 {
    "outcome" => "success",
    "result" => [
        {
            "driver-name" => "oracle",
            "deployment-name" => undefined,
            "driver-module-name" => "com.oracle.ojdbc",
            "module-slot" => "main",
            "driver-datasource-class-name" => "",
            "driver-xa-datasource-class-name" => "oracle.jdbc.xa.client.OracleXADataSource",
            "driver-class-name" => "oracle.jdbc.OracleDriver",
            "driver-major-version" => 12,
            "driver-minor-version" => 1,
            "jdbc-compliant" => true
        },
..
Verify Server.log :
11:29:33,533 INFO  [org.jboss.as.connector.subsystems.datasources] (management-handler-thread - 4) JBAS010403: Deploying JDBC-compliant driver class oracle.jdbc.OracleDriver (version 12.1)
11:29:33,534 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-6) JBAS010417: Started Driver service with driver-name = oracle

Step 3 : Add and verify a DataSource 
$ cat add_ds.cli
if (outcome != success) of /subsystem=datasources/data-source=myRacDS:read-resource
    data-source add \
        --name=myRacDS \
        --driver-name=oracle \
        --jndi-name=java:jboss/datasources/myRacDS \
        --user-name="scott"\
        --password="tiger"\
        --use-java-context=true \
        --use-ccm=true \
        --min-pool-size=5 \
        --max-pool-size=10 \
        --pool-prefill=true \
        --allocation-retry=1 \
        --prepared-statements-cache-size=32 \
        --share-prepared-statements=true \
        --connection-url="jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka"
end-if

$ $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9980  --file=add_ds.cli
$ $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9980 /subsystem=datasources/data-source=myRacDS:read-resource
{
    "outcome" => "success",
    "result" => {
        "allocation-retry" => 1,
        ...
        "connection-url" => "jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka",
        "datasource-class" => undefined,
        "driver-class" => undefined,
        "driver-name" => "oracle",
        "enabled" => true,
        ..
        "jndi-name" => "java:jboss/datasources/myRacDS",
        "jta" => true,
        "max-pool-size" => 10,
        "min-pool-size" => 5,
        ...
        }
    }
}

Test the Connection 
-> Ping the SCAN address
[oracle@wls1 WILDFLY]$  ping ract2-scan.grid12c.example.com
PING ract2-scan.grid12c.example.com (192.168.5.221) 56(84) bytes of data.
64 bytes from 192.168.5.221: icmp_seq=1 ttl=64 time=0.534 ms
64 bytes from 192.168.5.221: icmp_seq=2 ttl=64 time=0.298 ms

Test test Connection
$WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9980  /subsystem=datasources/data-source=myRacDS:test-connection-in-pool
{
    "outcome" => "success",
    "result" => [true]
}

Display and change JTA Transaction Timeout

Display JTA Transaction Timeout 
$  $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9990
      '/subsystem=transactions/:read-attribute(name=default-timeout)'
{
    "outcome" => "success",
    "result" => 30
}
--> JTA Transaction Timeout : 30 seconds

Change JTA Transaction Timeout 
$ $WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9990 
    '/subsystem=transactions/:write-attribute(name=default-timeout,value=60)'
{
    "outcome" => "success",
    "response-headers" => {
        "operation-requires-reload" => true,
        "process-state" => "reload-required"
    }
}

Deploy a compiled Web application project

Assume we have already created and tested WFJPA2EL-1.0.war and want to deploy this to our new Wildfly server :
$ cp WFJPA2EL-1.0.war /home/oracle/WILDFLY/wildfly-8.2.0.Final_PRODUCITON/standalone/deployments 
$ touch /home/oracle/WILDFLY/wildfly-8.2.0.Final_PRODUCITON/standalone/deployments/WFJPA2EL-1.0.war.dodeploy

For Redeployment run: touch /home/oracle/WILDFLY/wildfly-8.2.0.Final_PRODUCITON/standalone/deployments/WFJPA2EL-1.0.war.dodeploy
Server.log should report: 
15:32:08,432 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-4) JBAS017534: Registered web context: /WFJPA2EL-1.0
15:32:08,465 INFO  [org.jboss.as.server] (DeploymentScanner-threads - 1) JBAS018565: Replaced deployment "WFJPA2EL-1.0.war" with deployment "WFJPA2EL-1.0.war"

Now test the project 
$ firefox http://localhost:8081/WFJPA2EL-1.0

15:30:46.253 Calling  getRacInfo() in progress ... 
15:30:46.254 EclipseLink Version: 2.5.2 - [ EclipseLink 2.5.2 == JPA 2.1] 
15:30:46.255 Driver Name             : Oracle JDBC driver
15:30:46.256 Driver Version          : 12.1.0.2.0
15:30:46.257 Database Product Version: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Advanced Analytics and Real Application Testing options
15:30:46.439 DB Name:  BANKA
15:30:46.440 1. Instance Name: bankA_3 - Host: hract21.example.com
15:30:46.440 Leaving getRacInfo() without Exceptions !

Remove a single prepared transaction from WildFly LOG Store

Cleanup Wildfly LOG STORE

  • Be careful don’t run thes commands on a production system as you can easily corrupt your system
  • These commands should only used on your test system

Check for prepared transactions 

$ cat prepared_xa.cli
/subsystem=transactions/log-store=log-store/:probe()
ls /subsystem=transactions/log-store=log-store/transactions $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=prepared_xa.cli
{"outcome" => "success"}
0:ffffc0a805c9:-18c2b06f:55fac789:137
0:ffffc0a805c9:-18c2b06f:55fac789:145
0:ffffc0a805c9:-18c2b06f:55fac789:153
0:ffffc0a805c9:-18c2b06f:55fac789:fa
0:ffffc0a805c9:35abdaa8:55fbbb60:11b
0:ffffc0a805c9:35abdaa8:55fbbb60:355
0:ffffc0a805c9:35abdaa8:55fbbb60:49
0:ffffc0a805c9:35abdaa8:55fbbb60:5b
0:ffffc0a805c9:35abdaa8:55fbbb60:f1

Verify TX Object Store at File System Level
$ ls -1 ./standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/
0_ffffc0a805c9_-18c2b06f_55fac789_137
0_ffffc0a805c9_-18c2b06f_55fac789_145
0_ffffc0a805c9_-18c2b06f_55fac789_153
0_ffffc0a805c9_-18c2b06f_55fac789_fa
0_ffffc0a805c9_35abdaa8_55fbbb60_11b
0_ffffc0a805c9_35abdaa8_55fbbb60_355
0_ffffc0a805c9_35abdaa8_55fbbb60_49
0_ffffc0a805c9_35abdaa8_55fbbb60_5b
0_ffffc0a805c9_35abdaa8_55fbbb60_f1

Shutdown Wildfly and delete all prepared Transactions 
$WILDFLY_HOME/bin/jboss-cli.sh  --connect --controller=localhost:9990 command=:shutdown
$ rm ./standalone/data/tx-object-store/ShadowNoFileLockStore/defaultStore/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction/*

Restart Wildfly and verify LOG STORE  $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=prepared_xa.cli
{"outcome" => "success"}

Reference

Using logback with Logfile Separation for your Wildfly project

Overview

Logback is intended as a successor to the popular log4j project.
In this sample we will configure Logback to write logging info to an application specific logfile 
and to the Wildlfy server.log file. For a first check we many read the application loggin file. 
If you are interested in timing considerations for generic Wildfly errors and your application 
errors you may review Wildflys server.log file

Logging Separation 
Assuming your container supports child-first class loading, separation of logging can be 
accomplished by embedding a copy of slf4j and logback jar files in each of your applications. 
For web-applications, placing slf4j and logback jar files under the WEB-INF/lib directory of 
the web-application is sufficient to endow each web-application with a separate logging 
environment. A copy of the logback.xml configuration file placed under WEB-INF/classes will 
be picked up when logback is loaded into memory.

By virtue of class loader separation provided by the container, each web-application will 
load its own copy of LoggerContext which will pickup its own copy of logback.xml.

XML configuration files

pom.xml 
     <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.7</version> 
        </dependency>
        
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>1.1.3</version>
        </dependency>

        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-core</artifactId>
            <version>1.1.3</version>
        </dependency>

Disable server logging features: ./src/main/webapp/WEB-INF/jboss-deployment-structure.xml
<?xml version="1.0" encoding="UTF-8"?>
<jboss-deployment-structure>
  <deployment>
    <exclusions>
      <module name="org.apache.commons.logging" />
      <module name="org.apache.log4j" />
      <module name="org.jboss.logging" />
      <module name="org.jboss.logging.jul-to-slf4j-stub" />
      <module name="org.jboss.logmanager" />
      <module name="org.jboss.logmanager.log4j" />
      <module name="org.slf4j" />
      <module name="org.slf4j.impl" />
    </exclusions>
  </deployment>

Logback configuration file:  ./src/main/resources/logback.xml

-> Writes logging Info to /tmp/JPATestBean.log and Wildfly server.log 
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                   %d{HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n
            </Pattern>
        </layout>
    </appender>
        <appender name="FILE" class="ch.qos.logback.core.FileAppender">  
            <file>/tmp/JPATestBean.log</file>  
            <layout class="ch.qos.logback.classic.PatternLayout">    
                <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>  
            </layout>
        </appender>
  
    <root level="debug">
        <appender-ref ref="STDOUT" />
        <appender-ref ref="FILE" />
    </root>
</configuration>

Java Code

Initialize logger :
public class JPATestBean implements Serializable
  {
    // private static final org.slf4j.Logger logger = LoggerFactory.getLogger(JPATestBean.class);
    final static Logger logger = LoggerFactory.getLogger(JPATestBean.class);
......     
        logger.info("\nWeb Application shutdown ..." );
....
        logger.error("FATAL ERROR: Closing Entitiy Manager Factory ..." );

 

Reference

A deep dive into 2-Phase-Commit with Wildfly and Oracle RAC

Overview and Key Facts

  • JTA uses  javax.transaction.UserTransaction API to manage transaction bounderies
  • Each UserTransaction is associated with a Thread and this thread can only  handle 1 active Transaction in parallel
  • If a UserTransaction times out the Transaction will be rolled back and Transaction status will be set to :  STATUS_ROLLING_BACK
  • To manage Transaction Timout use following API:  ut.setTransactionTimeout(txTimeout)
  • In this sample 2 Wildfly we have configured RAC XA datasources : 
    • RAC bankA maintained and running in London
    • RAC bankB maintained and running in Frankfurt
  • A typical XA transaction consists out of at least 3 different processing steps
    • Step 1:  Data processing : xa_start  DML operation xa_end
    • Step 2:  Prepare the transaction:  xa_prepare
    • Step 3:  Commit the transaction: xa_commit
    • Step 2 and 3 are called 2-Phase-Commit or short 2PC
    • If clusterwide XA transaction are enabled any RAC instance can run any of the above steps
  • 2PC Commit Protocol details:
    • Prepare phase: The TM asks participating RMs to promise to commit (or rollback) the transaction as requested, even if there is a failure. If any RM cannot prepare, the transaction is rolled back.
    •  Commit phase:  If all RMs respond to the TM that they are prepared, then the TM asks all RMs commit the transaction.
  • ut.begin() starts the XA transaction whereas ut.commit() ends, prepares and commits the XA transaction
  • DBA_PENDING_TRANSACTIONS describes unresolved transactions (either due to failure or if the coordinator has not sent a commit/rollback).
  • DBA_2PC_PENDING  describes in-doubt transactions ( after tx timeout the RAC database records these XA transactions missing a commit/rollback)
  • A global XA transaction can span Oracle RAC instances by default ( if not using DTP services ) –
  • The GLOBAL_TXN_PROCESSES initialization parameter, which is set to 1 by default, specifies the initial number of GTX n background processes for each Oracle RAC instance.
  • If GLOBAL_TXN_PROCESSES > 1 clusterwide XA transactions are enabled.

Configuration and Setup

  • Test Framework – click on the image below to find out details !

Framwork_XaTesting

Display_Driver
JDK Version:     1.7.0_71
JDBC-Driver:     Oracle JDBC driver - Version: 12.1.0.2.0

Check_running_Instances
DB Name:     BANKA
Running Instances:     
10:06:16.646 Instance Name: bankA_1 - Host: hract22.example.com
10:06:16.647 Instance Name: bankA_3 - Host: hract21.example.com
DB Name:     BANKB
Running Instances:     
10:06:17.029 Instance Name: bankb_3 - Host: hract22.example.com
10:06:17.029 Instance Name: bankb_1 - Host: hract21.example.com

In this tutorial we will test and evaluate a 2-Phase-Commit scenario between: 
  RAC database bankA and RAC database bankB

RAC db version: 12.1.0.2 / Wildfyl 8.0.2 

To run this code you need to create 2 Oracle XA datasources named 
   java:jboss/datasources/xa_rac12g_banka
   java:jboss/datasources/xa_rac12g_bankb

For details creating a XA datasource with Oracle RAC please read following article:
  Setup a XA Datasource by using the RAC SCAN address

Java Code to run the 2-Phase-Commit operation

  
  @Named("xaTestBean")
  @SessionScoped
  public class XaTestBean implements Serializable
    {   
    @Resource(lookup="java:jboss/datasources/xa_rac12g_banka")
    private DataSource ds1;
   
    @Resource(lookup="java:jboss/datasources/xa_rac12g_bankb")
    private DataSource ds2;
 
    @Resource 
    private UserTransaction ut;
    ..   

   public String transferMoney()
      {
        initTopLevel();
        setTxInfo(Tools.add_hmtl_pre_tag("Calling transferMoney() in progress - try getting XA connections !" )) ;
        try 
          {          
            try ( Connection c1 = ds1.getConnection();
                  Connection c2 = ds2.getConnection(); )              
              {                 
               
                setSess1(Tools.add_hmtl_pre_tag(c1.getMetaData().getURL()));
                setSess2(Tools.add_hmtl_pre_tag(c2.getMetaData().getURL()));               
                setSess1(getSess1() + Tools.add_hmtl_pre_tag(getSessionInfo(c1)));
                System.out.println(getSess1()); System.out.flush();
                setSess2(getSess2() + Tools.add_hmtl_pre_tag( getSessionInfo(c2)));
                System.out.println(getSess2() ); System.out.flush();
                          
                setTxInfo(Tools.add_hmtl_pre_tag("No TX active - before ut.begin() "  + returnUtStatus(ut) + " - Transaction Timeout: " + txTimeout )) ;              
                ut.setTransactionTimeout(txTimeout) ;
                setTxInfo(getTxInfo() + Tools.add_hmtl_pre_tag("Setting New Tansaction Timeout : " + txTimeout)); 
                ut.begin();              
                setTxInfo(getTxInfo() + Tools.add_hmtl_pre_tag("After  ut.begin() "  + returnUtStatus(ut) )) ;
                doUpdate(c1, " - Session 1", "update Accounts set balance = balance - 4000");
                doUpdate(c2, " - Session 2", "update Accounts set balance = balance + 4000");
                setTxInfo(getTxInfo() + Tools.add_hmtl_pre_tag("Tx status before ut.commit() - "  + returnUtStatus(ut) + " - Now sleeping : " 
                        + sleepTime + " [ seconds] " )) ;      
                Thread.sleep(1000*sleepTime); 
                ut.commit();
                setTxInfo(getTxInfo() + Tools.add_hmtl_pre_tag("Tx status after ut.commit() "  + returnUtStatus(ut) )) ;                         
                    // Update Status in index.html too 
                setBankOperation(getBankOperation() + Tools.add_hmtl_pre_tag(getAccountinfo(c1)));
                setBankOperation(getBankOperation() + Tools.add_hmtl_pre_tag(getAccountinfo(c2)));
                setBankOperation(getBankOperation() +  Tools.add_hmtl_pre_tag("Leaving transferMoney() without any errors"));
                c1.close();              
                c2.close();
                setTxInfo(getTxInfo() + Tools.add_hmtl_pre_tag("Leaving transferMoney() without any errors")); 
              }
           
          } catch ( Exception ex ) 
          {   
            String e = ex.getMessage();
            genericExp("Error in JSF top level function: transferMoney() - Need to ROLLBACK transaction", ex);
            setBankOperation(getBankOperation()  + Tools.add_hmtl_pre_tag("FATAL ERROR in transferMoney(): " + e )); 
            try 
              {
                 setTxInfo(getTxInfo() + Tools.add_hmtl_pre_tag("FATAL ERROR: "));
                 setTxInfo(getTxInfo() + Tools.add_hmtl_pre_tag(  "Tx status after Exception before ut.rollback(): "  + 
                         returnUtStatus(ut)  + " - Exception: "+ e));              
                ut.rollback();
                setTxInfo(getTxInfo() + Tools.add_hmtl_pre_tag("Tx status after Exception - but  sucessful ut.rollback(): "   + returnUtStatus(ut)  ));               
              } catch( Exception e2 )
                    {
                       setTxInfo(getTxInfo() +Tools.add_hmtl_pre_tag( "Tx status after Exception: FATAL error during ut.rollback() :"  + 
                                returnUtStatus(ut)  + " - Exception: "  +e2));                   
                    }                    
            return "bankInfo";
          }  
        return "bankInfo";
      }

Testing SQL Exceptions in function transferMoney():

Prepared Test case:
Press : Init_Accounts
Press Transfer Money 3x : TransferMoney_via_2PC 

Output from index.xhtml:
09:59:54.830 Calling  checkAccounts() in progress ... 
09:59:54.835 Database Name:BANKA -- Account: User99_at_BANKA -- Balance: 10000.0
09:59:54.839 Database Name:BANKB -- Account: User98_at_BANKB -- Balance: 10000.0
09:59:54.839 Leaving checkAccounts() without any Error 

10:00:12.397 Database Name:BANKA -- Account: User99_at_BANKA -- Balance: 6000.0
10:00:12.405 Database Name:BANKB -- Account: User98_at_BANKB -- Balance: 14000.0
10:00:12.405 Leaving transferMoney() without any errors

10:00:18.232 Database Name:BANKA -- Account: User99_at_BANKA -- Balance: 2000.0
10:00:18.248 Database Name:BANKB -- Account: User98_at_BANKB -- Balance: 18000.0
10:00:18.249 Leaving transferMoney() without any errors

10:00:21.376 FATAL ERROR in transferMoney(): ORA-02290: check constraint (SCOTT.S_LOWER_CHK) violated


Last SQL:     
10:00:21.373 update Accounts set balance = balance - 4000  - Session 1

Last SQL Error:     
10:00:21.373 Exception in Class: com.hhu.XaTestBean - Methode: doUpdate
java.sql.SQLIntegrityConstraintViolationException: ORA-02290: check constraint (SCOTT.S_LOWER_CHK) violated
  Url: jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka User: SCOTT
   Stmt: update Accounts set balance = balance - 4000   - Session 1

TX Info:     

10:00:21.267 No TX active - before ut.begin() TX status:  6 - STATUS_NO_TRANSACTION - Transaction Timeout: 5
10:00:21.267 Setting New Tansaction Timeout : 5
10:00:21.273 After  ut.begin() TX status:  0 - STATUS_ACTIVE
10:00:21.377 FATAL ERROR: 
10:00:21.377 Tx status after Exception before ut.rollback(): TX status:  0 - STATUS_ACTIVE 
             - Exception: ORA-02290: check constraint (SCOTT.S_LOWER_CHK) violated
10:00:21.383 Tx status after Exception - but  sucessful ut.rollback(): TX status:  6 - STATUS_NO_TRANSACTION

Code Explanation

  • After calling transferMoney() a 3rd time the database  check contraint gets fired as our balance moves to a negative value
  • Inside the exeception handler the XA transaction was successfully rolled back and our thread ends up with setting its XA status to  : STATUS_NO_TRANSACTION

 

Testing automatic transaction recovery after a COMMIT record was written to Wildlfly LOG-STORE

  • Both XA resources have voted to COMMIT the transaction
  • Wildfly has written a COMMIT record to the  Wildlfly LOG-STORE
  • After this all transaction branches needs to be committed [ either by application server or by the DB admin ]
  • After a system crash Periodic Recovery Thread should use
    XA recover and XA commit to commit this transaction without any user intervention
Setup Testcase :

Press Init Accounts :Init_Accounts
11:04:21.039 Calling  checkAccounts() in progress ... 
11:04:21.088 Database Name:BANKA -- Account: User99_at_BANKA -- Balance: 10000.0
11:04:21.128 Database Name:BANKB -- Account: User98_at_BANKB -- Balance: 10000.0
11:04:21.128 Leaving checkAccounts() without any Error 

Breakpoints : Class oracle.jdbc.xa.OracleXAResource : Methode entry for prepare()  and commit()

Start application by pressing                : TransferMoney_via_2PC

Use debugger and stop processing at Entry to first OracleXAResource.commit call [ Press F5 until you reach this code point ]
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.prepare at line 693 by thread default task-6.
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.prepare at line 693 by thread default task-6.
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.commit at line 553 by thread default task-6.
-> Note:  Wildfly has already written this transaction to its log 

Verify Wildfly LOG-STORE
[oracle@wls1 XA]$  $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=xa.cli
{"outcome" => "success"}
0:ffffc0a805c9:-46761d77:55438636:7ee
-> Wildfly has saved the transaction to its LOG-STORE

Check transaction status at Database level
SQL> select host_name,instance_name from v$instance;
HOST_NAME               INSTANCE_NAME
------------------------------ ----------------
hract22.example.com           bankA_1

SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
  2       to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME,
  3       HOST, OS_USER, COMMIT# from dba_2pc_pending;

STATE         LOCAL_TRAN_ID        GLOBAL_TRAN_ID
---------------- ---------------------- --------------------------------------------------------------------------------
FAIL_TIME       FORCE_TIME          RETRY_TIME     HOST               OS_USER       COMMIT#
------------------ ------------------ ------------------ ------------------------- --------------- ----------------
prepared     7.6.4154        131077.00000000000000000000FFFFC0A805C9B989E28955438636000007EE31
03-MAY-15 08:44:32              03-MAY-15 08:45:05 wls1.example.com       oracle       24656988

SQL> select host_name,instance_name from v$instance;
HOST_NAME               INSTANCE_NAME
------------------------------ ----------------
hract22.example.com           bankb_3

SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
  2       to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME,
  3       HOST, OS_USER, COMMIT# from dba_2pc_pending;

STATE         LOCAL_TRAN_ID        GLOBAL_TRAN_ID
---------------- ---------------------- --------------------------------------------------------------------------------
FAIL_TIME       FORCE_TIME          RETRY_TIME     HOST               OS_USER       COMMIT#
------------------ ------------------ ------------------ ------------------------- --------------- ----------------
prepared     16.17.405        131077.00000000000000000000FFFFC0A805C9B989E28955438636000007EE31
03-MAY-15 08:44:29              03-MAY-15 08:45:20 wls1.example.com       oracle       9841282
**********************************************************
***  -> kill java process/program and restart Wildlfy ****  
**********************************************************
[oracle@wls1 XA]$ ps -elf | grep java
0 S oracle    9264  9210 19  80   0 - 414974 futex_ May02 ?       01:44:51 /usr/java/latest/bin/java -D[Standalone] -Xms128m -Xmx512m -XX:MaxPermSize=256m -server ..
[oracle@wls1 XA]$ kill -9 9264

-> Restart Wildfly - Wildfly Server Log reports 

2015-05-03 08:50:45,017 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: 
  Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord 
  < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, 
   tx_uid=0:ffffc0a805c9:-46761d77:55438636:7ee, node_name=1, 
     branch_uid=0:ffffc0a805c9:-46761d77:55438636:7f0, subordinatenodename=null, 
     eis_name=java:jboss/datasources/xa_rac12g_bankb >, 
   heuristic: TwoPhaseOutcome.FINISH_OK, product: 
     Oracle/Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
     With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
     Advanced Analytics and Real Application Testing options, 
    jndiName: java:jboss/datasources/xa_rac12g_bankb com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@519e22cc >

2015-05-03 08:50:45,017 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: 
Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord 
  < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, 
   tx_uid=0:ffffc0a805c9:-46761d77:55438636:7ee, node_name=1, 
   branch_uid=0:ffffc0a805c9:-46761d77:55438636:7f3, subordinatenodename=null, 
   eis_name=java:jboss/datasources/xa_rac12g_banka >, 
   heuristic: TwoPhaseOutcome.FINISH_OK, 
     product: Oracle/Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
     With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
     Advanced Analytics and Real Application Testing options, 
    jndiName: java:jboss/datasources/xa_rac12g_banka com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@64fea8f0 >

-> Periodic Recovery Thread successfully re-connects to both databases
   Periodic Recovery Thread calls XA recover to retrieve the prepared XIDs from the server
   Periodic Recovery Thread finally commits the data as Wildfly LOG-STORE confirms that all branches are prepared  

Verify that that the data was really committed 
GLOBAL_NAME
--------------------------------------------------------------------------------
BANKA
ACCOUNT                 BALANCE
-------------------------------- ----------
User99_at_BANKA                6000


GLOBAL_NAME
--------------------------------------------------------------------------------
BANKB
ACCOUNT                 BALANCE
-------------------------------- ----------
User98_at_BANKB               14000

Verify Wildfly log :
[oracle@wls1 XA]$  $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=xa.cli
{"outcome" => "success"}

-> After Wildfly restart the transaction was committed and the Wildfly LOG-Store was cleaned !

Testing automatic transaction recovery before a COMMIT record was written to Wildlfly LOG-STORE

  • Only one XA resources have voted to COMMIT the transaction [ ==only 1 prepared  XA transaction branch ]
  • Therefore Wildfly has not written a COMMIT record to  the  Wildlfly LOG-STORE
  • After a system crash the whole transaction should be rolled back
  • After a system crash Periodic Recovery Thread should use  XA recover and  XA rollback to rollback this transaction without any user intervention
Prepare Testcase

Press Init Accounts : Init_Accounts
11:04:21.039 Calling  checkAccounts() in progress ... 
11:04:21.088 Database Name:BANKA -- Account: User99_at_BANKA -- Balance: 10000.0
11:04:21.128 Database Name:BANKB -- Account: User98_at_BANKB -- Balance: 10000.0
11:04:21.128 Leaving checkAccounts() without any Error 

Set Breakpoints : Class oracle.jdbc.xa.OracleXAResource : Methode entry for prepare(), commit() and rollback()
-> Don't forget to set breackpoint for rollback to avoid the Periodic Recovery Thread to rollback the 
   transaction before we have rebooted Wildfly server !

Start Application by pressing: TransferMoney_via_2PC
Use debugger and stop at Entry of 2.nd  oracle.jdbc.xa.client.OracleXAResource.prepare call
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.prepare at line 693 by thread default task-6.
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.prepare at line 693 by thread default task-6.

Verify Wildfly LOG-STORE
[oracle@wls1 XA]$   $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=xa.cli
{"outcome" => "success"}
-> No transaction reference in Wildfly LOG-STORE

SQL> select host_name,instance_name from v$instance;
HOST_NAME               INSTANCE_NAME
------------------------------ ----------------
hract22.example.com           bankA_1

SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
  2       to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME,
  3       HOST, OS_USER, COMMIT# from dba_2pc_pending;
no rows selected

SQL> set echo off
Connected.
SQL> select host_name,instance_name from v$instance;
HOST_NAME               INSTANCE_NAME
------------------------------ ----------------
hract22.example.com           bankb_3
SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
  2       to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME,
  3       HOST, OS_USER, COMMIT# from dba_2pc_pending;
STATE         LOCAL_TRAN_ID        GLOBAL_TRAN_ID
---------------- ---------------------- --------------------------------------------------------------------------------
FAIL_TIME       FORCE_TIME          RETRY_TIME     HOST               OS_USER       COMMIT#
------------------ ------------------ ------------------ ------------------------- --------------- ----------------
prepared     14.2.389        131077.00000000000000000000FFFFC0A805C9614B927B5545C53A000000A631
03-MAY-15 09:23:47              03-MAY-15 09:26:12 wls1.example.com       oracle       9848205
-> No entry in Wildfls LOG-STORE - only one Transaction Branch is prepared on instance bankb_3

Note : During testing Periodic recovery Threads stops at our breakpoint in oracle.jdbc.xa.client.OracleXAResource.rollback
"Periodic Recovery"
oracle.jdbc.xa.client.OracleXAResource.rollback(OracleXAResource.java:945)
org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.rollback(XAManagedConnection.java:346)
org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.rollback(XAResourceWrapperImpl.java:196)
com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.handleOrphan(XARecoveryModule.java:786)
com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:692)
com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:431)
com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:212)
com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:789)
com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371)
-> This means with a breakpoint at rollback() the Periodic Recovery Thread would have already 
   delete this XA transaction. 

Now Kill Java program and verify whether records can be locked  for DML operations: 
[oracle@wls1 XA]$ ps -elf | grep java
0 S oracle   14493 14438 18  80   0 - 413832 futex_ 08:50 ?       00:07:13 /usr/java/latest/bin/java -D[Standalone] -Xms128m -Xmx512m -XX:MaxPermSize=256m -server ...
[oracle@wls1 XA]$ kill -9 14493
GLOBAL_NAME
--------------------------------------------------------------------------------
BANKA
ACCOUNT                 BALANCE
-------------------------------- ----------
User99_at_BANKA               10000
Connected.
--> No problem at bankA

GLOBAL_NAME
--------------------------------------------------------------------------------
BANKB
select * from accounts for update              *
ERROR at line 1:
ORA-01591: lock held by in-doubt distributed transaction 14.2.389
-> As we have only one prepared Transaction - ORA-1591 comes up only at bankB

-> Now Restart Wildfly to fix the ORA-1591 problem 
SQL> @check_it
GLOBAL_NAME
--------------------------------------------------------------------------------
BANKA
ACCOUNT                 BALANCE
-------------------------------- ----------
User99_at_BANKA               10000

GLOBAL_NAME
--------------------------------------------------------------------------------
BANKB
ACCOUNT                 BALANCE
-------------------------------- ----------
User98_at_BANKB               10000
-> After Wildfly restart the transaction was rolled back and we can access 
   both records for DML operations. 

Heuristically committed transaction – A major Pitfall for DBAs

Assume we have following configruation:
System A : RAC database running database bankA running London
System B : RAC database running database bankB running in Frankfurt 
System C : Wildfly application server 

After a network outage all the systems are not able to communicate with each other but 
these systems are still up and running.
 
Now System C - our Wildfly server - is crashing during a 2-Phase-Commit. 
The crash occurs after having prepared both transaction an for database bankA, bankB 
and Wildfly has already written a COMMIT record to its LOG-STAORE.

Setup testcase: Init_Accounts
09:10:41.653 Calling  checkAccounts() in progress ... 
09:10:41.677 Database Name:BANKA -- Account: User99_at_BANKA -- Balance: 10000.0
09:10:41.717 Database Name:BANKB -- Account: User98_at_BANKB -- Balance: 10000.0
09:10:41.719 Leaving checkAccounts() without any Error 

Setup testcase:
Tx Timeout : 60  Change_Timeout

-> Set breakpoint in commit() metode of oracle.jdbc.xa.OracleXAResource 
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.commit at line 553 by thread default task-10.
Thread default task-10 stopped at OracleXAResource.java:553.

Start the application by pressing: TransferMoney_via_2PC
-> Wait until we get ORA-1591 accessing these records:
BANKA:
SQL> connect scott/tiger@ract2-scan.grid12c.example.com:1521/banka
SQL> select * from accounts for update;
select * from accounts for update              *
ERROR at line 1:
ORA-01591: lock held by in-doubt distributed transaction 18.24.2100

BANKB:
SQL> connect scott/tiger@ract2-scan.grid12c.example.com:1521/bankb
Connected.
SQL> select * from accounts for update;
select * from accounts for update
ERROR at line 1:
ORA-01591: lock held by in-doubt distributed transaction 12.26.389

Now a lot of end users calls in and raise complaints to their DBAs that a major application running 
on RAC DB bankA and RAC DB bankB are not working  anymore.

The DBA on bankA ( London)  checks   dba_2pc_pending and found a prepared TX:
SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
  2       to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME,
  3       HOST, OS_USER, COMMIT# from dba_2pc_pending;

STATE         LOCAL_TRAN_ID        GLOBAL_TRAN_ID
---------------- ---------------------- --------------------------------------------------------------------------------
FAIL_TIME       FORCE_TIME          RETRY_TIME     HOST               OS_USER       COMMIT#
------------------ ------------------ ------------------ ------------------------- --------------- ----------------
prepared     18.24.2100        131077.00000000000000000000FFFFC0A805C9B989E289554386360000038B31
02-MAY-15 09:12:03              02-MAY-15 09:17:31 wls1.example.com       oracle       24303841
 
The DBA on bankB ( Frankfurt ) checks  dba_2pc_pending and found a prepared TX: 
SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
  2       to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME,
  3       HOST, OS_USER, COMMIT# from dba_2pc_pending;

STATE         LOCAL_TRAN_ID        GLOBAL_TRAN_ID
---------------- ---------------------- --------------------------------------------------------------------------------
FAIL_TIME       FORCE_TIME          RETRY_TIME     HOST               OS_USER       COMMIT#
------------------ ------------------ ------------------ ------------------------- --------------- ----------------
prepared     12.26.389        131077.00000000000000000000FFFFC0A805C9B989E289554386360000038B31
02-MAY-15 09:12:02              02-MAY-15 09:18:30 wls1.example.com       oracle       9400626

Now things goes wrong. 
-> The database itself does not have any ideas whether Wildfly has written a COMMIT record to the LOG-STORE or not. 
   The DBAs doesn't check the Wildfly LOG-STORE 
   Due to the pressure to get ONLINE asap the  DBA's does the following :

DBA for RAC DB bankA ( London) 
SQL> connect sys/sys@ract2-scan.grid12c.example.com:1521/bankA as sysdba
Connected.
SQL> select STATE, LOCAL_TRAN_ID  from dba_2pc_pending;
STATE         LOCAL_TRAN_ID
---------------- ----------------------
prepared     18.24.2100

SQL> rollback force '18.24.2100';
Rollback complete.

DBA for RAC DB bankB ( Frankfurt) 
SQL>  connect sys/sys@ract2-scan.grid12c.example.com:1521/bankB as sysdba
Connected.
SQL>  select STATE, LOCAL_TRAN_ID  from dba_2pc_pending;
STATE         LOCAL_TRAN_ID
---------------- ----------------------
prepared     12.26.389
SQL> commit force '12.26.389';
Commit complete.

Now both DBAs verify whether we can access these records for DML operation
SQL> connect scott/tiger@ract2-scan.grid12c.example.com:1521/banka
Connected.
SQL> 
SQL> select * from accounts for update;
ACCOUNT                 BALANCE
-------------------------------- ----------
User99_at_BANKA               10000


SQL> connect scott/tiger@ract2-scan.grid12c.example.com:1521/bankb
SQL> select * from accounts for update;
ACCOUNT                 BALANCE
-------------------------------- ----------
User98_at_BANKB               14000

-> Works fine - really ?
   The DBAs have logically corrupted ozr system integrity !!
   We have successfully added the money to User98_at_BANKB but not reduced the money 
   from account  User99_at_BANKA !
   
Note this should never happen at your production system -  or you may loose your DBA job very easily !!
                         
How we can avoid this problem ?
1. Check whether Wildfly has written a commit record 
[oracle@wls1 XA]$  $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=xa.cli
{"outcome" => "success"}
0:ffffc0a805c9:-46761d77:55438636:38b
--> There is a  COMMIT record for XID :  0:ffffc0a805c9:-46761d77:55438636:38b -  so it is save to call : 
       COMMIT FORCE 'Local_Tran_ID'
    If we can't find the XID within Wildfly it is save to call on all involved databases : 
       ROLLBACK FORCE 'Local_Tran_ID';   

A closer look on Exceptions 
ut.commit() fail with :
TX Info:     
10:21:58.711 No TX active - before ut.begin() TX status:  6 - STATUS_NO_TRANSACTION - Transaction Timeout: 60
10:21:58.720 Setting New Tansaction Timeout : 60
10:22:04.640 After  ut.begin() TX status:  0 - STATUS_ACTIVE
10:22:04.709 Tx status before ut.commit() - TX status:  0 - STATUS_ACTIVE - Now sleeping : 1 [ seconds] 
10:28:03.579 FATAL ERROR: 
10:28:03.582 Tx status after Exception before ut.rollback(): TX status:  6 - STATUS_NO_TRANSACTION - Exception: null
10:28:03.585 Tx status after Exception: FATAL error during ut.rollback() :TX status:  6 - STATUS_NO_TRANSACTION 

Java Code throws javax.transaction.HeuristicMixedException : 
10:28:03.558 Error in JSF top level function: transferMoney() - Need to ROLLBACK transaction
10:28:03.576 javax.transaction.HeuristicMixedException
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1174)
    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
    at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
    at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:173)
    at com.hhu.XaTestBean.transferMoney(XaTestBean.java:778)

Wildfly server.log reports :
2015-05-02 10:27:56,445 WARN  [com.arjuna.ats.jta] (default task-1) 
ARJUNA016036: commit on < formatId=131077, gtrid_length=29, bqual_length=36, 
tx_uid=0:ffffc0a805c9:-46761d77:55438636:4d3, node_name=1, 
branch_uid=0:ffffc0a805c9:-46761d77:55438636:4d5, subordinatenodename=null, 
eis_name=java:jboss/datasources/xa_rac12g_bankb > (XAResourceWrapperImpl@172657b2[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@489e2cb1 pad=false 
  overrideRmValue=null productName=Oracle productVersion=Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Advanced Analytics and Real Application Testing options 
 jndiName=java:jboss/datasources/xa_rac12g_bankb]) 
  failed with exception $XAException.XAER_NOTA: oracle.jdbc.xa.OracleXAException
        at oracle.jdbc.driver.T4CXAResource.kputxrec(T4CXAResource.java:965)
        at oracle.jdbc.driver.T4CXAResource.doCommit(T4CXAResource.java:454)
        at oracle.jdbc.xa.client.OracleXAResource.commit(OracleXAResource.java:583)
        at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.commit(XAManagedConnection.java:338)
        at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.commit(XAResourceWrapperImpl.java:107)
        at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit(XAResourceRecord.java:461)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2810)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2726)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1820)
        at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1504)
        at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96)
        at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1166)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
        at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
        at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:173)
        at com.hhu.XaTestBean.transferMoney(XaTestBean.java:778) [classes:]
->  JAVA Code is failing with $XAException.XAER_NOTA: oracle.jdbc.xa.OracleXAException as the related XA transaction is 
    already committed using COMMIT FORCE 'Local_Tran_ID'  or rolled back using ROLLBACK force  'Local_Tran_ID' at Database level.

Cleanup system state after above getting a heuristically committed XA transaction 
 - Try to repair the logical corruption from any logfile we can find tracking SQL change and TX id.
 - Cleanup the system [ Wildfly LOG-STORE and Oracle dba_2pc_pending table ]

Cleanup Wildfly LOG-STORE
Verify currents XA transaction status  
[oracle@wls1 XA]$  $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=xa.cli
{"outcome" => "success"}
0:ffffc0a805c9:-46761d77:55438636:38b
0:ffffc0a805c9:-46761d77:55438636:439
0:ffffc0a805c9:-46761d77:55438636:4d3

SQL> connect sys/sys@ract2-scan.grid12c.example.com:1521/bankb as sysdba
SQL>  select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID from dba_2pc_pending;
STATE         LOCAL_TRAN_ID        GLOBAL_TRAN_ID
---------------- ---------------------- ----------------------------------------------------------------------
forced commit     12.26.389        131077.00000000000000000000FFFFC0A805C9B989E289554386360000038B31
forced commit     17.21.390        131077.00000000000000000000FFFFC0A805C9B989E289554386360000043931
forced commit     14.26.382        131077.00000000000000000000FFFFC0A805C9B989E28955438636000004D331

SQL> connect sys/sys@ract2-scan.grid12c.example.com:1521/banka as sysdba
SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID from dba_2pc_pending;
STATE         LOCAL_TRAN_ID        GLOBAL_TRAN_ID
---------------- ---------------------- ----------------------------------------------------------------------
forced rollback  18.24.2100        131077.00000000000000000000FFFFC0A805C9B989E289554386360000038B31
forced rollback  14.1.2092        131077.00000000000000000000FFFFC0A805C9B989E289554386360000043931
forced rollback  16.4.2077        131077.00000000000000000000FFFFC0A805C9B989E28955438636000004D331

Purge the XA transaction from Wildfly LOG-STORE
$WILDFLY_HOME/bin/jboss-cli.sh --connect 
   "/subsystem=transactions/log-store=log-store/transactions=0\:ffffc0a805c9\:-46761d77\:55438636\:38b:delete"
{"outcome" => "success"}
[oracle@wls1 XA]$ $WILDFLY_HOME/bin/jboss-cli.sh --connect
    "/subsystem=transactions/log-store=log-store/transactions=0\:ffffc0a805c9\:-46761d77\:55438636\:439:delete"
{"outcome" => "success"}
[oracle@wls1 XA]$  $WILDFLY_HOME/bin/jboss-cli.sh --connect 
     "/subsystem=transactions/log-store=log-store/transactions=0\:ffffc0a805c9\:-46761d77\:55438636\:4d3:delete"
{"outcome" => "success"}
[oracle@wls1 XA]$ $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=xa.cli
{"outcome" => "success"}

Finally purge XA transactions at DB level run on both RAC nodes:
SQL> execute DBMS_TRANSACTION.PURGE_MIXED('18.24.2100');
SQL> execute DBMS_TRANSACTION.PURGE_MIXED('14.1.2092');
SQL> execute DBMS_TRANSACTION.PURGE_MIXED('16.4.2077');

Understanding ORA-1591 : lock held by in-doubt distributed transaction

Change Transaction Timeout: 60  Change_Timeout 
Set Breakpoints in : oracle.jdbc.xa.OracleXAResource prepare() and commit() functions 
Press F5 untill we reach first Commit breakpoint:
  Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.prepare at line 693 by thread default task-1.
  Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.prepare at line 693 by thread default task-1.
  Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.commit at line 553 by thread default task-1.

Press : TransferMoney_via_2PC
Transaction status - immediate after stopping: 
Connected.
SQL> select host_name,instance_name from v$instance;
HOST_NAME               INSTANCE_NAME
------------------------------ ----------------
hract22.example.com           bankA_2

SQL> select * from  sys.dba_pending_transactions;
  FORMATID GLOBALID                                                      BRANCHID
---------- ------------------------------------------------------------ -------------------------------------------------------
    131077 00000000000000000000FFFFC0A805C9B989E289554386360000005931    00000000000000000000FFFFC0A805C9B989E289554386360000005
                                                                         E0000000200000000

SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
  2       to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME,
  3       HOST, OS_USER, COMMIT# from dba_2pc_pending;
no rows selected


SQL> select host_name,instance_name from v$instance;
HOST_NAME               INSTANCE_NAME
------------------------------ ----------------
hract22.example.com           bankb_3

SQL> select * from  sys.dba_pending_transactions;
  FORMATID GLOBALID                                                      BRANCHID
---------- ------------------------------------------------------------ -------------------------------------------------------
    131077 00000000000000000000FFFFC0A805C9B989E289554386360000005931    00000000000000000000FFFFC0A805C9B989E289554386360000005
                                                                         B0000000300000000

SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
  2       to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME,
  3       HOST, OS_USER, COMMIT# from dba_2pc_pending;
no rows selected

Script to track XA transactions within Wildfly:
[oracle@wls1 XA]$ cat xa.cli
/subsystem=transactions/log-store=log-store/:probe()
ls /subsystem=transactions/log-store=log-store/transactions

[oracle@wls1 XA]$  $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=xa.cli
{"outcome" => "success"}
0:ffffc0a805c9:-46761d77:55438636:59

-> The prepared transaction branchess are visible in sys.dba_pending_transactions - but not yet in  dba_2pc_pending
   Wildfly reports the transaction in its LOG-STORE

Now wait 60 seconds until Oracle times out the XA Transaction and  creates an in-doubt transaction 
SQL> select host_name,instance_name from v$instance;
HOST_NAME                      INSTANCE_NAME
------------------------------ ----------------
hract22.example.com            bankA_2
SQL> select * from  sys.dba_pending_transactions;
  FORMATID GLOBALID                                                     BRANCHID
---------- ------------------------------------------------------------ -------------------------------------------------------
    131077 00000000000000000000FFFFC0A805C9B989E289554386360000005931    00000000000000000000FFFFC0A805C9B989E289554386360000005
                                                                         E0000000200000000
SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
  2       to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME,
  3       HOST, OS_USER, COMMIT# from dba_2pc_pending;
STATE         LOCAL_TRAN_ID        GLOBAL_TRAN_ID
---------------- ---------------------- --------------------------------------------------------------------------------
FAIL_TIME       FORCE_TIME          RETRY_TIME     HOST               OS_USER       COMMIT#
------------------ ------------------ ------------------ ------------------------- --------------- ----------------
prepared     3.18.4315        131077.00000000000000000000FFFFC0A805C9B989E289554386360000005931
01-MAY-15 16:15:02              01-MAY-15 16:15:35 wls1.example.com       oracle       24161321

SQL> select host_name,instance_name from v$instance;
HOST_NAME               INSTANCE_NAME
------------------------------ ----------------
hract22.example.com           bankb_3

SQL> select * from  sys.dba_pending_transactions;
  FORMATID GLOBALID                                                      BRANCHID
---------- ------------------------------------------------------------ -------------------------------------------------------
    131077 00000000000000000000FFFFC0A805C9B989E289554386360000005931    00000000000000000000FFFFC0A805C9B989E289554386360000005
                                                                         B0000000300000000
SQL> select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
  2       to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME,
  3       HOST, OS_USER, COMMIT# from dba_2pc_pending;
STATE         LOCAL_TRAN_ID        GLOBAL_TRAN_ID
---------------- ---------------------- --------------------------------------------------------------------------------
FAIL_TIME       FORCE_TIME          RETRY_TIME     HOST               OS_USER       COMMIT#
------------------ ------------------ ------------------ ------------------------- --------------- ----------------
prepared     15.23.381        131077.00000000000000000000FFFFC0A805C9B989E289554386360000005931
01-MAY-15 16:15:00              01-MAY-15 16:15:51 wls1.example.com       oracle       9263234

-> The prepared transaction branches  are visible in sys.dba_pending_transactions and  dba_2pc_pending
   Wildfly reports the transactions as stored in the log store !

Note: Accessing a record  being part of a prepared distributed transaction will throw ORA-1591 
      and print out the local transaction ID. 

Connected.
select * from accounts for update              *
ERROR at line 1:
ORA-01591: lock held by in-doubt distributed transaction 3.18.4315

Connected.
select * from accounts for update
ERROR at line 1:
ORA-01591: lock held by in-doubt distributed transaction 15.23.381
 
Now Press F5 again until we get back control via our HTML page

Note: Even the entry was in dba_2pc_pending running the commit sucessfully finshed the distributed transaction 
      Entries in  sys.dba_pending_transactions and  dba_2pc_pending are removed and Wildfly LOG-STORE 
      was cleaned up.

Understanding ORA-2049 error: distributed transaction waiting for lock

Lock a record via sqlplus 
SQL>  select BALANCE from Accounts for update;
   BALANCE
----------
     10000
Press:  TransferMoney_via_2PC
 
Generic Error:     
17:05:19.248 Error in JSF top level function: transferMoney() - Need to ROLLBACK transaction
17:05:19.248 ORA-02049: timeout: distributed transaction waiting for lock
17:05:19.249 java.sql.SQLSyntaxErrorException: ORA-02049: timeout: distributed transaction waiting for lock
    at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:450)
    at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:399)
    at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1059)
    at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:522)
    at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:257)
    at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:587)
    at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:210)
    at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:30)
    at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:931)
    at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1150)
    at oracle.jdbc.driver.OracleStatement.executeUpdateInternal(OracleStatement.java:1707)
    at oracle.jdbc.driver.OracleStatement.executeUpdate(OracleStatement.java:1670)
    at oracle.jdbc.driver.OracleStatementWrapper.executeUpdate(OracleStatementWrapper.java:310)
    at org.jboss.jca.adapters.jdbc.WrappedStatement.executeUpdate(WrappedStatement.java:375)
    at com.hhu.XaTestBean.doUpdate(XaTestBean.java:603)

Transaction status 
17:04:18.911 No TX active - before ut.begin() TX status:  6 - STATUS_NO_TRANSACTION - Transaction Timeout: 5
17:04:18.911 Setting New Tansaction Timeout : 5
17:04:18.990 After  ut.begin() TX status:  0 - STATUS_ACTIVE
17:05:19.250 FATAL ERROR: 
17:05:19.250 Tx status after Exception before ut.rollback(): TX status:  9 - STATUS_ROLLING_BACK 
            - Exception: ORA-02049: timeout: distributed transaction waiting for lock
17:05:19.284 Tx status after Exception - but  successful ut.rollback(): TX status:  6 - STATUS_NO_TRANSACTION 

Verify the related database init.ora parameter
SQL> show parameter distributed_lock_timeout
NAME                     TYPE     VALUE
------------------------------------ ----------- ------------------------------
distributed_lock_timeout         integer     60


 Note: It's not a good idea to increase distributed_lock_timeout without understanding what is going on.
       In a first approach try to re-run the failed code.
       Any OLTP application should not lock a record for more than 60 seconds
   
       It if a session times out within Oracle, then the Oracle database’s Process Monitor (PMON) will delete 
         the transaction branch if not prepared  or cause the transaction to become in-doubt if prepared.
      
     Generic Timeout Settings : Transaction Timeout for JDBC  <  DISTRIBUTED_LOCK_TIMEOUT . 

Explanation:

  • The java code tries to lock the record which is locked by our sqlplus session
  • After waiting 60 seconds the SQL processing returns an exception:
          java.sql.SQLSyntaxErrorException: ORA-02049: timeout: distributed transaction waiting for lock
  •  This wait time is controlled by the init.ora parameter distributed_lock_timeout
    SQL> show parameter distributed_lock_timeout
    NAME                        TYPE     VALUE
    —————————— ———– —————-
    distributed_lock_timeout         integer     60
  • As for any other exception the XA transactions needs to be rolled back. 

 

Understanding Transaction Timeout

Setup testcase: 
Transaction Timeout: 5         
Sleep Time:         10  Change_Timeout
Press                :  TransferMoney_via_2PC

Error Stack 
17:53:21.729 Error in JSF top level function: transferMoney() - Need to ROLLBACK transaction
17:53:21.729 ARJUNA016102: The transaction is not active! Uid is 0:ffffc0a805c9:410b1af0:55424451:c6
17:53:21.730 javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffffc0a805c9:410b1af0:55424451:c6
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1156)
    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
    at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
    at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:173)
    at com.hhu.XaTestBean.transferMoney(XaTestBean.java:769)

Tx Status:
17:53:11.556 No TX active - before ut.begin() TX status:  6 - STATUS_NO_TRANSACTION - Transaction Timeout: 5
17:53:11.556 Setting New Tansaction Timeout : 5
17:53:11.563 After  ut.begin() TX status:  0 - STATUS_ACTIVE
17:53:11.726 Tx status before ut.commit() - TX status:  0 - STATUS_ACTIVE - Now sleeping : 10 [ seconds] 
17:53:21.730 FATAL ERROR: 
17:53:21.730 Tx status after Exception before ut.rollback(): TX status:  6 - STATUS_NO_TRANSACTION - 
             Exception: ARJUNA016102: The transaction is not active! Uid is 0:ffffc0a805c9:410b1af0:55424451:c6
17:53:21.730 Tx status after Exception: FATAL error during ut.rollback() :TX status:  6 - STATUS_NO_TRANSACTION - 
             Exception: java.lang.IllegalStateException: BaseTransaction.rollback - ARJUNA016074: no transaction!

Note :
  Transaction Timeout for JDBC  <  DISTRIBUTED_LOCK_TIMEOUT ( default : 60 seconds ) .

Code  Explanation:

  • After 10 seconds [ our sleeptime ] the transaction processing step has finished and ut.commit() is called
  • Because we have reached transaction Timeout of 5 seconds the ut.commit() call fails
  • In the exception handler the ut.rollback() call becomes a NOOP as the parent transaction was already deleted.

 

Debugging  UserTransaction API and XAResource API by using a Netbeans Debugger

Using Netbeans to debug the JAVA XA code more in detail 
1. Start Wildfly in Debug Mode
2. Add Breakpoint: 
   Debugger   : JAVA    Breakpoint Type : Methode
   Class Name :  oracle.jdbc.xa.OracleXAResource       
   Check      : All methods for a given Class
   Method Name: <all methods>
   Stop on    : Method Entry 
3. Debug -> Debug Main Program
4. Set breakpoint at line ut.begin() 
5. Debug -> Run to Cursor  
6. Press F5 until our HTML page gets  back control 

Breakpoint hit at line 762 in class com.hhu.XaTestBean by thread default task-15.
Thread default task-15 stopped at XaTestBean.java:762.

ut.beginn() translates to the following XA calls
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.setTransactionTimeout at line 1063 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.start at line 163 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.saveAndAlterAutoCommitModeForGlobalTransaction at line 797 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.checkError at line 1188 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.createOrUpdateXid at line 296 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.getMatchingXidListEntry at line 234 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.enterGlobalTxnMode at line 1179 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isSameRM at line 995 by thread default task-15.
-> Transaction for bankA is started, isSameRM() is used to check whether bankA and bankB are using the same Resource Manager 
   As we have 2 different RAC systems this call should return false ! 

Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.getConnection at line 945 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.setTransactionTimeout at line 1063 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.start at line 163 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.saveAndAlterAutoCommitModeForGlobalTransaction at line 797 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.checkError at line 1188 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.createOrUpdateXid at line 296 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.getMatchingXidListEntry at line 234 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.enterGlobalTxnMode at line 1179 by thread default task-15.
-> Transaction for bankB is started 

ut.commit() translates to the following XA calls 
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.end at line 358 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.suspendStacked at line 430 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isSameXid at line 256 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isXidSuspended at line 398 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.getMatchingXidListEntry at line 234 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.removeXidFromList at line 244 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isSameXid at line 256 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isXidListEmpty at line 274 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.exitGlobalTxnMode at line 1167 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.checkError at line 1188 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.restoreAutoCommitModeForGlobalTransaction at line 768 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.prepare at line 693 by thread default task-15.
-> For bankA the XA transaction is finished by OracleXAResource.end() and prepared by OracleXAResource.prepare()

Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.end at line 358 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.suspendStacked at line 430 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isSameXid at line 256 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isXidSuspended at line 398 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.getMatchingXidListEntry at line 234 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.removeXidFromList at line 244 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isSameXid at line 256 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isXidListEmpty at line 274 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.exitGlobalTxnMode at line 1167 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.checkError at line 1188 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.restoreAutoCommitModeForGlobalTransaction at line 768 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.prepare at line 693 by thread default task-15.
--> For bankB the XA transaction is finished by OracleXAResource.end() and prepared by OracleXAResource.prepare()
    Now as all XA branches are prepared the global transaction can be commited !

Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.commit at line 553 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.removeXidFromList at line 244 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isSameXid at line 256 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.exitGlobalTxnMode at line 1167 by thread default task-15.
--> Commit XA transaction at bankA 

Method breakpoint hit in oracle.jdbc.xa.client.OracleXAResource.commit at line 553 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.removeXidFromList at line 244 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.isSameXid at line 256 by thread default task-15.
Method breakpoint hit in oracle.jdbc.xa.OracleXAResource.exitGlobalTxnMode at line 1167 by thread default task-15.
--> Commit XA transaction at bankB 

Note : The Periodic Recovery Thread is also using our XAResources and tries to complete any failed XA transaction
        

 

SQL Scripts and Wildfly Scripts

Create tables : cr_tab.sql
connect scott/tiger@ract2-scan.grid12c.example.com:1521/banka 
drop table ACCOUNTS;
CREATE TABLE ACCOUNTS
( ACCOUNT varchar2(32) CONSTRAINT ACCOUNTS_PK PRIMARY KEY,
  BALANCE NUMBER(10,2) constraint S_LOWER_CHK  check (BALANCE >= 0)
);
insert into ACCOUNTS values ('User99_at_BANKA', 10000);
commit;
select * from global_name;
select * from accounts;
update Accounts set balance = balance - 11000;
rollback;

connect scott/tiger@ract2-scan.grid12c.example.com:1521/bankb 
drop table ACCOUNTS;
CREATE TABLE ACCOUNTS
( ACCOUNT varchar2(32) CONSTRAINT ACCOUNTS_PK PRIMARY KEY,
  BALANCE NUMBER(10,2) constraint S_LOWER_CHK  check (BALANCE >= 0)
);

insert into ACCOUNTS values ('User98_at_BANKB', 10000);
commit;
select global_name from global_name;
select * from accounts;
update Accounts set balance = balance - 11000;
rollback;

Test whether the records are locked : check_it.sql
connect scott/tiger@ract2-scan.grid12c.example.com:1521/banka 
select * from global_name;
select * from accounts for update;

connect scott/tiger@ract2-scan.grid12c.example.com:1521/bankb 
select global_name from global_name;
select * from accounts for update;

Generic script the test XA staus of both RAC databases: check_xa.sql 
set echo on
connect sys/sys@ract2-scan.grid12c.example.com:1521/banka as sysdba
@tx 
connect sys/sys@ract2-scan.grid12c.example.com:1521/bankb as sysdba
@tx 
exit

Script to display database details for distributed transactions: tx.sql
/*
   If you run a 2PC you need to run  tx.sql on both RAC databases .
   Sample:
    sqlplus  sys/sys@ract2-scan.grid12c.example.com:1521/banka as sysdba @tx
    sqlplus  sys/sys@ract2-scan.grid12c.example.com:1521/bankb as sysdba @tx
*/ 
set echo off
set linesize 132
set pagesize 132
col HOST_NAME format A30
col GLOBAL_TRAN_ID format A80
col GLOBALID format A60
col BRANCHID format A55
col HOST format A25
col OS_USER format A15
set echo on 
select host_name,instance_name from v$instance;
select * from  sys.dba_pending_transactions;
select STATE, LOCAL_TRAN_ID, GLOBAL_TRAN_ID , to_char(FAIL_TIME,'DD-MON-YY HH24:MI:SS') FAIL_TIME,
    to_char(FORCE_TIME,'DD-MON-YY HH24:MI:SS') FORCE_TIME,  to_char(RETRY_TIME,'DD-MON-YY HH24:MI:SS') RETRY_TIME, 
    HOST, OS_USER, COMMIT# from dba_2pc_pending;
set echo off

Script to track XA transactions within Wildfly:
[oracle@wls1 XA]$ cat xa.cli
/subsystem=transactions/log-store=log-store/:probe()
ls /subsystem=transactions/log-store=log-store/transactions

Source Code

  JSF Code: 
        bankInfo.xhtml  - JSF page to display Transaction Info, Exception Info, failed SQL
        index.xhtml     - Main Entry JSF page - displays Account details 
        jdbc_info.xhtml - JSF Page to diplay JDBC driver details, Exceptions, Transaction processing Steps
        rac_info.xhtml  - JSF Page to display RAC instances details

  Maven Project Object Model    
       pom.xml

  JAVA Code:  
       XaTestBean.java

Reference

Wildfly: Testing Oracle JDBC driver UCP Connection pool setup with Arquillian/JUnit

 

Why you should use Arquillian/Junit ?

  • Arquillian simplifies integration testing for Java apps
  • Integrates  Test runners like Junit
  • Integrates  Containers like JBoss,Glassfish,..
  • During the deplyoment step [ @Deployment ] ShrinkWrap utility does the following
    • creates a test archive on the fly like test.war,..
    • adds libraries if needed:  like addAsLibraries(new File(LOCAL_MAVEN_REPO + “/com/oracle/ojdbc7/12.1.0.2/ojdbc7-12.1.0.2.jar”));
    • loads all classes referenced in addPackage method: .addPackage(DriverBean.class.getPackage());
    • adds resources like bean.xml :     .addAsWebInfResource(EmptyAsset.INSTANCE, “beans.xml”) ;
  • Arquillian can inject Beans, EBJs by using Jnject annotations [ @Inject DriverBean db ] -> This makes Arquillian to a pretty cool and complete test framework
  • Uses @Test annotation to find the test methods to be run

pom.xml Configuration for Arquillian, UCP, ONS and Oracle JDBC driver

    <dependencyManagement>
        <dependencies>
        <!-- Override dependency resolver with latest version.  This must go *BEFORE* the Arquillian BOM. -->
        <dependency>
            <groupId>org.jboss.shrinkwrap.resolver</groupId>
            <artifactId>shrinkwrap-resolver-bom</artifactId>
            <version>2.0.2</version>
            <scope>import</scope>
            <type>pom</type>
        </dependency>    
        <dependency>            
            <groupId>org.jboss.arquillian</groupId>
            <artifactId>arquillian-bom</artifactId>
            <version>1.1.8.Final</version>
            <scope>import</scope>
            <type>pom</type>
        </dependency>         
    </dependencies>
    </dependencyManagement>
    
    <dependencies>
        <dependency>
            <groupId>javax</groupId>
            <artifactId>javaee-web-api</artifactId>
            <version>7.0</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>com.oracle</groupId>
            <artifactId>ojdbc7</artifactId>
            <version>12.1.0.2</version>
             <scope>runtime</scope>
        </dependency>  
        <dependency>
            <groupId>com.oracle</groupId>
            <artifactId>ucp</artifactId>
            <version>12.1.0.2</version>
        </dependency> 
        <dependency>
            <groupId>com.oracle</groupId>
            <artifactId>ons</artifactId>
            <version>12.1.0.2</version>
        </dependency> 
       <dependency>
            <groupId>junit</groupId>
            <artifactId>junit</artifactId>
            <version>4.11</version>
        </dependency> 
        
        <!-- Add support for enterprise feature like Transactions, EJBs  -->
        <dependency>
            <groupId>org.jboss.arquillian.junit</groupId>
            <artifactId>arquillian-junit-container</artifactId>
            <scope>test</scope>
        </dependency> 
        
        <!-- Add support Resolver support to load JDBC, UCP and ONS jar for Unit testing  -->
       <dependency>
            <groupId>org.jboss.shrinkwrap.resolver</groupId>
            <artifactId>shrinkwrap-resolver-depchain</artifactId>      
            <scope>test</scope>
            <type>pom</type>
       </dependency>                
    </dependencies>

Configure  arquillian.xml [ located at src/main/resources ]

<arquillian xmlns="http://jboss.org/schema/arquillian" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="
        http://jboss.org/schema/arquillian
        http://jboss.org/schema/arquillian/arquillian_1_0.xsd">
    <container qualifier="wildfly" default="true">
        <configuration>
            <property name="jbossHome">/usr/local/wildfly-8.2.0.Final</property>
            <property name="modulePath">/usr/local/wildfly-8.2.0.Final/modules</property>
            <!-- <property name="allowConnectingToRunningServer">true</property> -->
           <property name="allowConnectingToRunningServer">true</property>
        </configuration>
    </container>
</arquillian>

Write your JAVA testing class TestDriverBean.java [ located in src/test/java ]

Source Code:
import com.hhu.DriverBean;
import java.io.File;
import javax.inject.Inject;
import org.jboss.arquillian.container.test.api.Deployment;
import org.jboss.arquillian.junit.Arquillian;
import org.jboss.shrinkwrap.api.Archive;
import org.jboss.shrinkwrap.api.ShrinkWrap;
import org.jboss.shrinkwrap.api.asset.EmptyAsset;
import org.jboss.shrinkwrap.api.spec.WebArchive;
import static org.junit.Assert.assertFalse;
import static org.junit.Assert.assertNull;
import org.junit.Test;
import org.junit.runner.RunWith;

@RunWith(Arquillian.class)
public class TestDriverBean
    {
    private static final String LOCAL_MAVEN_REPO =  
         System.getProperty("maven.repo.local") != null ?  
               System.getProperty("maven.repo.local") :  
               (System.getProperty("user.home") + File.separatorChar +  
               ".m2" + File.separatorChar + "repository");
     
   @Deployment
    public static Archive<?> createTestArchive() { 
 
        System.out.println("****************** Inside createTestArchive()" );
        System.out.println("****************** Local Maven Repsository: " + LOCAL_MAVEN_REPO );
        
        WebArchive res = ShrinkWrap.create(WebArchive.class, "testDriverBean.war");
     
        res.addPackage(DriverBean.class.getPackage());    
        res.addAsLibraries(new File(LOCAL_MAVEN_REPO + "/com/oracle/ojdbc7/12.1.0.2/ojdbc7-12.1.0.2.jar"));
        res.addAsLibraries(new File(LOCAL_MAVEN_REPO + "/com/oracle/ucp/12.1.0.2/ucp-12.1.0.2.jar"));
        res.addAsLibraries(new File(LOCAL_MAVEN_REPO + "/com/oracle/ons/12.1.0.2/ons-12.1.0.2.jar"));
        res.addAsWebInfResource(EmptyAsset.INSTANCE, "beans.xml") ;        
        System.out.println(res.toString(true));    
        System.out.println("****************** Leaving createTestArchive()" );
        return res;                
    }
 
    @Inject DriverBean db;
    
    @Test
    public void driverTest() throws Exception
      {
      System.out.println("-------------- driverTest() running ---------------");
      db.setPoolInfo(null);
      db.setJdbcInfo(null);
      db.setExceptInfo(null);
      db.setClname("oracle.jdbc.OracleDriver");  
      String drvRet =db.checkDriver();     
      System.out.println("driverTest() - return         : " + drvRet );
      System.out.println("driverTest() - JDBC INFO      : " + db.getJdbcInfo() );
      System.out.println("driverTest() - Exception INFO : " + db.getExceptInfo() );  
      assertNull( db.getExceptInfo());
      System.out.println("-------------- driverTest() finished --------------");             
      }
    
    @Test
    public void driverTest2() throws Exception
      {
      System.out.println("-------------- driverTest2() running - Creating a Class not found Exception ---------------");   
            // This will trigger a ClassNotFound Exception
      db.setClname("This_is_not_the_Oracle_JDBC_driver_class");  
      db.setPoolInfo(null);
      db.setJdbcInfo(null);
      db.setExceptInfo(null);
      String drvRet = db.checkDriver();
      System.out.println("driverTest2() - return         : " + drvRet );
      System.out.println("driverTest2() - JDBC INFO      : " + db.getJdbcInfo() );
      System.out.println("driverTest2() - Exception INFO : " + db.getExceptInfo() );     
      assertNull( db.getExceptInfo());
      System.out.println("-------------- driverTest2() finished --------------");          
      }
    
    @Test
    public void poolTest() throws Exception
      {
        System.out.println("-------------- poolTest() running ---------------");
        db.setPoolInfo(null);
        db.setExceptInfo(null);
        db.setJdbcInfo(null);
        String drvRet =db.initPool();     
        System.out.println("poolTest() - return         : " + drvRet );
        System.out.println("poolTest() - Pool INFO      : " + db.getPoolInfo() );
        System.out.println("poolTest() - Exception INFO : " + db.getExceptInfo() );
        String RACDB = "RAC DB: BANKB";
        if ( db.getPoolInfo().contains(RACDB))
            System.out.println("poolTest() - found: " + RACDB);
        else
          {
            int idx = db.getPoolInfo().indexOf("RAC DB:");
            String dbFound = db.getPoolInfo().substring( idx + 8 , idx+13);
              // assertFalse will fail if the checked value is ture  and assertTrue will do the opposite
            assertFalse("poolTest() does not found: " + RACDB +  " - found: " + dbFound,true);
          }
        System.out.println("-------------- poolTest() finished --------------");
      }
    }


Code details :

@RunWith(Arquillian.class)
-> Junit will use Arquillian runner to execute this class

private static final String LOCAL_MAVEN_REPO .. 
-> LOCAL_MAVEN_REPO defines our local Maven repository storing JDBC,UCP and ONS Maven archetypes

WebArchive res = ShrinkWrap.create(WebArchive.class, "testDriverBean.war");
-> Creates a Webarchive named testDriverBean.war. This War will be deployed to our Wildfly server  

res.addAsLibraries(new File(LOCAL_MAVEN_REPO + "/com/oracle/ojdbc7/12.1.0.2/ojdbc7-12.1.0.2.jar"));
-> Adds a Maven archetype from our local Maven repository 

System.out.println(res.toString(true));    
-> Display the content of our "testDriverBean.war" War file

@Inject DriverBean db;
--> Inject DriverBean

Run the test Class

Deployment step createTestArchive() should create the following output: 
Running TestDriverBean
****************** Inside createTestArchive()
****************** Local Maven Repsository: /home/oracle/.m2/repository
testDriverBean.war:
/WEB-INF/
/WEB-INF/lib/
/WEB-INF/lib/ons-12.1.0.2.jar
/WEB-INF/lib/ucp-12.1.0.2.jar
/WEB-INF/lib/ojdbc7-12.1.0.2.jar
/WEB-INF/beans.xml
/WEB-INF/classes/
/WEB-INF/classes/com/
/WEB-INF/classes/com/hhu/
/WEB-INF/classes/com/hhu/DriverBean.class
/WEB-INF/classes/com/hhu/Tools.class
****************** Leaving createTestArchive()
 -> Here we can see that our Deploy Step really adds the needed JAR files to use 
    Oracle JDBC driver with ONS and UCP.
 
Running the Maven Unit Tests
$ mvn -e test 
Results :
Failed tests:   
  poolTest(TestDriverBean): poolTest() does not found: RAC DB: BANKB - found: BANKA
  driverTest2(TestDriverBean): expected null, but was:<<pre>Error in checkDriver()</pre><pre>This_is_not_the_Oracle_JDBC_driver_class from [Module "deployment.testDriverBean.war:main" from Service Module Loader]</pre><pre>java.lang.ClassNotFoundException: This_is_not_the_Oracle_JDBC_driver_class from [Module "deployment.testDriverBean.war:main" from Service Module Loader]
Tests run: 3, Failures: 2, Errors: 0, Skipped: 0
  -> Two out of our three tests  failed: 
     The failed test are :  poolTest(TestDriverBean) and   driverTest2(TestDriverBean)

Review driverTest() method
Source Code: 
@Test
    public void driverTest() throws Exception
      {
      System.out.println("-------------- driverTest() running ---------------");
      db.setPoolInfo(null);
      db.setJdbcInfo(null);
      db.setExceptInfo(null);
      db.setClname("oracle.jdbc.OracleDriver");  
      String drvRet =db.checkDriver();     
      System.out.println("driverTest() - return         : " + drvRet );
      System.out.println("driverTest() - JDBC INFO      : " + db.getJdbcInfo() );
      System.out.println("driverTest() - Exception INFO : " + db.getExceptInfo() );  
      assertNull( db.getExceptInfo());
      System.out.println("-------------- driverTest() finished --------------");             
      }
Methode  driverTest() - prints out the following to Wildfly Server logs
14:26:40,760 INFO  [stdout] (default task-4) -------------- driverTest() running ---------------
14:26:40,761 INFO  [stdout] (default task-4) driverTest() - return         : index
14:26:40,762 INFO  [stdout] (default task-4) driverTest() - JDBC INFO      : 
                                            <pre>JDBC Driver Check - Loading Driver class ok : oracle.jdbc.OracleDriver</pre>
                                            <pre>JDK Version: 1.7.0_71</pre>
                                            <pre>ClassPath  : /usr/local/wildfly-8.2.0.Final/jboss-modules.jar</pre>
                                            <pre>Driver Name             : Oracle JDBC driver</pre>
                                            <pre>Driver Version          : 12.1.0.2.0</pre>
                                            <pre>Database Product Version: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
14:26:40,762 INFO  [stdout] (default task-4) With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
14:26:40,762 INFO  [stdout] (default task-4) Advanced Analytics and Real Application Testing options</pre>
14:26:40,762 INFO  [stdout] (default task-4) driverTest() - Exception INFO : null
14:26:40,763 INFO  [stdout] (default task-4) -------------- driverTest() finished --------------
   --> This test runs successfully as we have provided the correct Classname for the Oracle JDBC driver !
    
Review driverTest2() method
Source Code: 
 public void driverTest2() throws Exception
      {
      System.out.println("-------------- driverTest2() running - Creating a Class not found Exception ---------------");   
         // this creates a ClassNotFoundException
      db.setClname("This_is_not_the_Oracle_JDBC_driver_class");  
      db.setPoolInfo(null);
      db.setJdbcInfo(null);
      db.setExceptInfo(null);
      String drvRet = db.checkDriver();
      System.out.println("driverTest2() - return         : " + drvRet );
      System.out.println("driverTest2() - JDBC INFO      : " + db.getJdbcInfo() );
      System.out.println("driverTest2() - Exception INFO : " + db.getExceptInfo() );     
      assertNull( db.getExceptInfo());
      System.out.println("-------------- driverTest2() finished --------------");          
      }
 ->  - db.checkDriver() does not throw an exception as checkDriver() is a top level JSF function.
     - Instead all Exceptions are stored in an Exception String. 
     - If all works  db.getExceptInfo() should be still a null string. 
     - If not  db.getExceptInfo() returns the  Exception and the later  JUnit test:
: 
          assertNull( db.getExceptInfo());  will fail

Methode  driverTest2() - prints out the following to Wildfly Server logs
14:43:14,483 INFO  [stdout] (default task-5) -------------- driverTest2() running - Creating a Class not found Exception ---------------
14:43:14,486 INFO  [stdout] (default task-5) driverTest2() - return         : index
14:43:14,486 INFO  [stdout] (default task-5) driverTest2() - JDBC INFO      : null
14:43:14,486 INFO  [stdout] (default task-5) driverTest2() - Exception INFO : <pre>Error in checkDriver()</pre><pre>This_is_not_the_Oracle_JDBC_driver_class from [Module "deployment.testDriverBean.war:main" from Service Module Loader]</pre><pre>java.lang.ClassNotFoundException: This_is_not_the_Oracle_JDBC_driver_class from [Module "deployment.testDriverBean.war:main" from Service Module Loader]
14:43:14,487 INFO  [stdout] (default task-5)     at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:213)
14:43:14,487 INFO  [stdout] (default task-5)     at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:459)
14:43:14,487 INFO  [stdout] (default task-5)     at org.jboss.modules.ConcurrentClassLoader.performLoadClassChecked(ConcurrentClassLoader.java:408)
14:43:14,487 INFO  [stdout] (default task-5)     at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:389)
14:43:14,487 INFO  [stdout] (default task-5)     at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:134)
14:43:14,487 INFO  [stdout] (default task-5)     at java.lang.Class.forName0(Native Method)
14:43:14,488 INFO  [stdout] (default task-5)     at java.lang.Class.forName(Class.java:191)
14:43:14,488 INFO  [stdout] (default task-5)     at com.hhu.DriverBean.checkDriver(DriverBean.java:163)
--> The stack shows we are failing in line 163 com.hhu.DriverBean.checkDriver because assertNull( db.getExceptInfo()); founds 
    that db.getExceptInfo() is not null 

Review poolTest() method
Source Code: 
    @Test
    public void poolTest() throws Exception
      {
        System.out.println("-------------- poolTest() running ---------------");
        db.setPoolInfo(null);
        db.setExceptInfo(null);
        db.setJdbcInfo(null);
        String drvRet =db.initPool();     
        System.out.println("poolTest() - return         : " + drvRet );
        System.out.println("poolTest() - Pool INFO      : " + db.getPoolInfo() );
        System.out.println("poolTest() - Exception INFO : " + db.getExceptInfo() );
        String RACDB = "RAC DB: BANKB";
        if ( db.getPoolInfo().contains(RACDB))
            System.out.println("poolTest() - found: " + RACDB);
        else
          {
            int idx = db.getPoolInfo().indexOf("RAC DB:");
            String dbFound = db.getPoolInfo().substring( idx + 8 , idx+13);
              // assertFalse will fail if the checked value is ture  and assertTrue will do the opposite
            assertFalse("poolTest() does not found: " + RACDB +  " - found: " + dbFound,true);
          }
        System.out.println("-------------- poolTest() finished --------------");
      }
    }
Methode  poolTest() - prints out the following to Wildfly Server logs
14:43:12,559 INFO  [stdout] (default task-10) -------------- poolTest() running ---------------
14:43:13,129 INFO  [oracle.ucp.common.UniversalConnectionPoolBase] (default task-10) inactive connection timeout timer scheduled
14:43:14,382 INFO  [stdout] (default task-10) poolTest() - return         : index
14:43:14,385 INFO  [stdout] (default task-10) poolTest() - Pool INFO      : <pre>Initializing UCP Pool in progress ...</pre>
            <pre>UCP Pool initialized ! </pre>   RAC DB: BANKA
            <pre>Instance Name:bankA_2 - Host: hract22.example.com</pre>
            <pre>Instance Name:bankA_1 - Host: hract21.example.com</pre>
            <pre>Instance Name:bankA_1 - Session Count 1</pre>
            <pre>Instance Name:bankA_2 - Session Count 49</pre>
14:43:14,386 INFO  [stdout] (default task-10) poolTest() - Exception INFO : null
--> poolTest() found RAC DB: BANKA but tested for Database name BANKB. 
    This makes assertFalse() failing and reporting a test failure !
    Note:  In this case we will not reach the statement : 
        System.out.println("-------------- poolTest() finished --------------");
    The Assert itself reports :  
    Failed tests:   poolTest(TestDriverBean): poolTest() does not found: RAC DB: BANKB - found: BANKA
    

 Summary

  • run Maven at least with -e switch to get a stack trace
  • careeful read the  Maven test summary :  Tests run: 3, Failures: 2, Errors: 0, Skipped: 0, Time elapsed: 10.197 sec <<< FAILURE! –> Results-> Failed tests
  • Check the Server logfile for stack traces

Download Source

Project Object Modul           ./pom.xml
Arquillian Config file         ./src/main/resources/arquillian.xml
JSF file                       ./src/main/webapp/index.xhtml 
Java Test program              ./src/test/java/TestDriverBean.java  
Java Bean                      ./src/main/java/com/hhu/DriverBean.java 

 

Reference

Framework for testing UCP Pool & RAC 12.1.0.2 with Wildfly 8.2

Overview

  • This Framework is easily extensible to test add. UCP features
  • Currently Implemented Features are : FCF, Standard Pool Operations, some Timeouts
  • Note: Using XA Datasoruce and UCP does not work with Wildfly !!
  • The Framework display Instance Status, Session Status, Pool Status and FCF Status
  • All top level function starting with jsf* should catch all excepetions and display these Exceptions via an Exception Window
  • getConnection() initializes the Pooled Datasource  and returns a Connection object
  • getConnection() stores the Pooled Datasource in a static variable and it is only loaded once per JVM during first usage of UCPPoolBean class
  • initPool() creates and starts the named UCP pool :   my_ucp_pool
  • Following UCP Pool Operations are supported : INIT  STOP  START  DESTROY  PURGE REFRESH
  • The JNDI functions creates its own JNDI entry named:  java:global/myUcpDs
  • The Code expects that you have created a Datasource named myRacDS
  • This Datasource is created via Annotations:  @Resource(lookup=”java:jboss/datasources/myRacDS”)  
  • Above mentioned datasource myRACDS is only used in jsfCheckDriver() function and works even without the UCP POOL
  • Take A first look on the Operation Panel – Click on the image to see details !UCP_Panel

Source Code:  getConnection() –  An important Code Detail

Central part of the Java Code is the getConnection() Function     
public class UcpPoolBean
    {
    private static oracle.ucp.jdbc.PoolDataSource pds = null;
    ..      
    public Connection getConnection() throws Exception
      {
        Connection c = null;
        if (pds == null )
          {
            setPoolStats("UCP POOL not yet initialized - creating  UCP pool in getConection()  !");
            initPool();
              // This is just an informational message that the Pooled Datasource was recreated !              
            genericExp("INFO: UCP pool created via getConnection() as Pooled DataSource == null ! ", null);
          }
        if ( pds == null )
            genericExp("FATAL: Pooled DataSource == null after init in getConnection()  ", null);       
        else
            c = pds.getConnection();
         return c;
      }

 

Framework: Generic Display Options

Instance status :  CheckInstance

11:51:32.479:    RAC DB: BANKA
Instance Name:bankA_1 - Host: hract21.example.com
Instance Name:bankA_2 - Host: hract22.example.com
Instance Name:bankA_1 - Session Count 5
Instance Name:bankA_2 - Session Count 2

UCP Pool status :  CheckUCPPool  
Press -> Check UCP Pool Status 
11:52:49.906: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@932eae2
11:52:49.907: Available Pools:  my_ucp_pool
11:52:49.907:   Connection Count : Total : 5 - Available: 5 - Borrowed: 0
11:52:49.907:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
11:52:49.907:   PoolLifeCycle state:  Running
11:52:49.907:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
     
Session Info :  CheckUCPSessions    
12:04:46.824: Available Connections in UCP POOL: 5
12:04:46.876: Instance Name:bankA_2 - Host: hract22.example.com
12:04:46.944: Instance Name:bankA_1 - Host: hract21.example.com
12:04:46.946: Instance Name:bankA_2 - Host: hract22.example.com
12:04:46.948: Instance Name:bankA_1 - Host: hract21.example.com
12:04:46.950: Instance Name:bankA_2 - Host: hract22.example.com

To display all of the above statistics press : CheckAll

Testing Abandon Connection Timeout

The abandoned connection timeout (ACT) enables borrowed connections to be
reclaimed back into the connection pool after a connection has not been used for a
specific amount of time. Abandonment is determined by monitoring calls to the
database. This timeout feature helps maximize connection reuse and conserves system
resources that are otherwise lost on maintaining borrowed connections that are no
longer in use.

Settings:
Set Connection Count         : 5   
Abandoned Connection Timeout : 10 [seconds ]
   AllocateConnections
UCP Pool Status:
12:31:41.341: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@932eae2
12:31:41.341: Available Pools:  my_ucp_pool
12:31:41.341:   Connection Count : Total : 5 - Available: 0 - Borrowed: 5
12:31:41.341:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
12:31:41.341:   PoolLifeCycle state:  Running
12:31:41.341:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
12:31:41.341: Connections in static ArrayList  jsfOpenConnections(): 5
12:31:41.341: jsfOpenConnections(): Connection - Opened:  5
-> 5 connections are now in use !

Session INFO :
12:31:41.335: jsfOpenConnections(): Connections newly Opened:  5
12:31:41.335: verifyConnections() - Connections in static ArrayList :
12:31:41.336: Instance Name:bankA_2 - Host: hract22.example.com
12:31:41.336: Instance Name:bankA_2 - Host: hract22.example.com
12:31:41.339: Instance Name:bankA_2 - Host: hract22.example.com
12:31:41.340: Instance Name:bankA_1 - Host: hract21.example.com
12:31:41.340: Instance Name:bankA_2 - Host: hract22.example.com

Now wait about 30 seconds and press : CheckUCPPool

12:35:27.493: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@932eae2
12:35:27.494: Available Pools:  my_ucp_pool
12:35:27.494:   Connection Count : Total : 5 - Available: 5 - Borrowed: 0
12:35:27.494:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
12:35:27.494:   PoolLifeCycle state:  Running
12:35:27.494:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
-> The connections are reclaimed by the UCP pool after reaching the timeout

Verify the connection status by pressing : VerifyConnections

Exceptions :
12:37:12.567: Error in retSessionInfo() - Failed SQL:
12:37:12.567: The connection is closed: The connection is closed
12:37:12.568: java.sql.SQLException: The connection is closed: The connection is closed
at oracle.ucp.util.UCPErrorHandler.newSQLException(UCPErrorHandler.java:464)
at oracle.ucp.util.UCPErrorHandler.newSQLException(UCPErrorHandler.java:448)
at oracle.ucp.jdbc.proxy.JDBCConnectionProxyFactory.invoke(JDBCConnectionProxyFactory.java:307)
at oracle.ucp.jdbc.proxy.ConnectionProxyFactory.invoke(ConnectionProxyFactory.java:50)
at com.sun.proxy.$Proxy17.createStatement(Unknown Source)
at UcpPool.UcpPoolBean.retSessionInfo(UcpPoolBean.java:1201)
at UcpPool.UcpPoolBean.verifyConnections(UcpPoolBean.java:1113)
-> The connections are reclaimed by the pool - Note : the above Exception is expected !

Release the stale Connections 
Finally Press ReleaseConnections  to cleanup the static Connection Pool Array

The Release Operation should report:
12:43:33.146: Connections in static ArrayList  jsfCloseConnections(): 0
12:43:33.146: jsfCloseConnections(): Connections Closed:  1

 

Testing Inactive Connection Timeout

The inactive connection timeout specifies how long an available connection can remain
idle before it is closed and removed from the pool. This timeout property is only
applicable to available connections and does not affect borrowed connections. This
property helps conserve resources that are otherwise lost on maintaining connections
that are no longer being used. The inactive connection timeout (together with the
Note: UCP for JDBC either cancels or rolls back connections that
have local transactions pending before reclaiming connections for
reuse.

Settings: 
Set Connection Count       :  4  
Inactive Connection Timeout:     30
Press 2x:  AllocateConnections
Press 2x:  ReleaseConnections

UCP Pool Status :     
12:54:32.053: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@359db23
12:54:32.054: Available Pools:  my_ucp_pool
12:54:32.054:   Connection Count : Total : 8 - Available: 8 - Borrowed: 0
12:54:32.054:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
12:54:32.054:   PoolLifeCycle state:  Running
12:54:32.054:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
12:54:32.054: Connections in static ArrayList  jsfCloseConnections(): 0
12:54:32.054: jsfCloseConnections(): Connections Closed:  4

Session Info :     
12:57:24.381: Available Connections in UCP POOL: 8
12:57:24.383: Instance Name:bankA_1 - Host: hract21.example.com
12:57:24.384: Instance Name:bankA_2 - Host: hract22.example.com
12:57:24.385: Instance Name:bankA_2 - Host: hract22.example.com
12:57:24.386: Instance Name:bankA_1 - Host: hract21.example.com
12:57:24.387: Instance Name:bankA_2 - Host: hract22.example.com
12:57:24.388: Instance Name:bankA_2 - Host: hract22.example.com
12:57:24.389: Instance Name:bankA_2 - Host: hract22.example.com
12:57:24.390: Instance Name:bankA_1 - Host: hract21.example.com
-> The UCP Connection Count is increased to 8 !

Now wait about 60 seconds:
UCP Pool status :     
12:58:19.972: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@359db23
12:58:19.972: Available Pools:  my_ucp_pool
12:58:19.972:   Connection Count : Total : 5 - Available: 5 - Borrowed: 0
12:58:19.972:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
12:58:19.973:   PoolLifeCycle state:  Running
12:58:19.973:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
-> UCP Pool has reduced the Connection Count to 5 from 8 

 

Testing Pool Limits

Settings:
Set Connection Count       :  4  
Press  3x                  : AllocateConnections

UCP Pool status :     
13:00:08.544: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@359db23
13:00:08.544: Available Pools:  my_ucp_pool
13:00:08.544:   Connection Count : Total : 10 - Available: 0 - Borrowed: 10
13:00:08.544:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
13:00:08.544:   PoolLifeCycle state:  Running
13:00:08.544:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
13:00:08.544: Connections in static ArrayList  jsfOpenConnections(): 10
13:00:08.544: jsfOpenConnections(): Connection - Opened:  2   

Exceptions :
13:00:08.531: Error in openConnections() + Already opened Connections: 2
13:00:08.531: Exception occurred while getting connection: oracle.ucp.UniversalConnectionPoolException: 
              All connections in the Universal Connection Pool are in use
13:00:08.531: java.sql.SQLException: Exception occurred while getting connection: oracle.ucp.UniversalConnectionPoolException:
     All connections in the Universal Connection Pool are in use
    at oracle.ucp.util.UCPErrorHandler.newSQLException(UCPErrorHandler.java:479)
    at oracle.ucp.util.UCPErrorHandler.throwSQLException(UCPErrorHandler.java:154)
    at oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:1127)
    at oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:1031)
-> The lastest Allocate Connection request can only allocate 2 connections. 
   After that the get getConnection() fails with above Exception.

 

Testing UCP Purge Operation

UCP Pool status after Purge  :     PurgeUCP

13:04:23.530: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@57e31b7
13:04:23.530: Available Pools:  my_ucp_pool
13:04:23.531:   Connection Count : Total : 0 - Available: 0 - Borrowed: 0
13:04:23.531:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
13:04:23.531:   PoolLifeCycle state:  Running
13:04:23.531:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
13:04:23.531: Connections in static ArrayList after openConnections(): 0
13:04:23.531: Connections remaining in static ArrayList after closeConnections() : 0
13:04:23.531: checkSessionInPool(): Connection - Opened:  0 - Closed: 10       
 -> After a purge pool operation all connections get closed and the pool  
    Total Connection Count is : 0 even MinPoolSize is set to 5 !

Reallocate the connections :
Set Connection Count       :  5  
Press  1x                  : AllocateConnections
Press  1x                  : ReleaseConnections

UCP Pool Status :
13:07:02.775: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@57e31b7
13:07:02.775: Available Pools:  my_ucp_pool
13:07:02.775:   Connection Count : Total : 5 - Available: 5 - Borrowed: 0
13:07:02.775:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
13:07:02.775:   PoolLifeCycle state:  Running
13:07:02.775:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
13:07:02.775: Connections in static ArrayList  jsfCloseConnections(): 0
13:07:02.775: jsfCloseConnections(): Connections Closed:  5    

Testing UCP Refresh Operation

Current Pool Status
13:08:46.268: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@57e31b7
13:08:46.268: Available Pools:  my_ucp_pool
13:08:46.269:   Connection Count : Total : 5 - Available: 5 - Borrowed: 0
13:08:46.269:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
13:08:46.269:   PoolLifeCycle state:  Running
13:08:46.269:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
13:08:46.269: Connections in static ArrayList after openConnections(): 0
13:08:46.269: Connections remaining in static ArrayList after closeConnections() : 0
13:08:46.269: checkSessionInPool(): Connection - Opened:  5 - Closed: 5

Session Info :     
13:08:46.258: Available Connections in UCP POOL: 5
13:08:46.262: Instance Name:bankA_1 - Host: hract21.example.com
13:08:46.264: Instance Name:bankA_2 - Host: hract22.example.com
13:08:46.266: Instance Name:bankA_1 - Host: hract21.example.com
13:08:46.267: Instance Name:bankA_2 - Host: hract22.example.com
13:08:46.268: Instance Name:bankA_1 - Host: hract21.example.com

Press : RefreshUCP
13:10:03.940: Available Connections in UCP POOL: 5
13:10:03.940: Instance Name:bankA_2 - Host: hract22.example.com
13:10:03.942: Instance Name:bankA_2 - Host: hract22.example.com
13:10:03.943: Instance Name:bankA_2 - Host: hract22.example.com
13:10:03.945: Instance Name:bankA_1 - Host: hract21.example.com
13:10:03.945: Instance Name:bankA_2 - Host: hract22.example.com
-> Refresh UCP Pool has closed and recreated the physical Connections 
   The connections point now to different RAC instances.

 

Testing FCF functionality


Current UCP Pool status :     
11:42:07.415: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@44d2df43
11:42:07.415: Available Pools:  my_ucp_pool
11:42:07.416:   Connection Count : Total : 5 - Available: 5 - Borrowed: 0
11:42:07.416:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
11:42:07.416:   PoolLifeCycle state:  Running
11:42:07.416:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
11:42:07.416: Connections in static ArrayList after openConnections(): 0
11:42:07.416: Connections remaining in static ArrayList after closeConnections() : 0
11:42:07.416: checkSessionInPool(): Connection - Opened:  5 - Closed: 5

Session Info :     
11:42:07.313: Available Connections in UCP POOL: 5
11:42:07.317: Instance Name:bankA_2 - Host: hract22.example.com
11:42:07.319: Instance Name:bankA_2 - Host: hract22.example.com
11:42:07.321: Instance Name:bankA_2 - Host: hract22.example.com
11:42:07.413: Instance Name:bankA_3 - Host: hract21.example.com
11:42:07.415: Instance Name:bankA_3 - Host: hract21.example.com
-> All UCP session are  equally distributed on both available RAC instances 

Now stop one of the instances 
[oracle@hract21 ~]$ srvctl stop instance -db banka -n hract22 -o abort

Verify Session Info again  :     
11:44:39.005: Available Connections in UCP POOL: 5
11:44:39.124: Instance Name:bankA_3 - Host: hract21.example.com
11:44:39.127: Instance Name:bankA_3 - Host: hract21.example.com
11:44:39.129: Instance Name:bankA_3 - Host: hract21.example.com
11:44:39.130: Instance Name:bankA_3 - Host: hract21.example.com
11:44:39.132: Instance Name:bankA_3 - Host: hract21.example.com
-> As expected - all UCP sessions are now pointing to the surviving instance.
   Note: We don't need a server roundtrip for this operation - ONS does a great job here ! 
    
FCF Info:
11:44:39.133:  FCF status:  {Apr 11, 2015 11:44 AM SUCCESS      
    Connections:(Available=5 Opened=2 FailedToProcess=0 MarkedDown=0 Closed=2)(Borrowed=0 FailedToProcess=0 MarkedDown=0 Closed=0)}


Restart Instance  and Refresh the pool
[oracle@hract21 ~]$ srvctl start instance -db banka -n hract22

Press : RefreshUCP
11:57:14.914: Available Connections in UCP POOL: 5
11:57:14.915: Instance Name:bankA_2 - Host: hract22.example.com
11:57:14.916: Instance Name:bankA_3 - Host: hract21.example.com
11:57:14.917: Instance Name:bankA_2 - Host: hract22.example.com
11:57:14.918: Instance Name:bankA_3 - Host: hract21.example.com
11:57:14.919: Instance Name:bankA_2 - Host: hract22.example.com
-> All UCP session are now again equally redistributed on both RAC instances 

 

Testing  JNDI

  • The Framework uses ctx.bind() to temporary create a JNDI entry on the fly
  • After ctx.bind() the Framework use ctx.lookup() to create the pooled Datasource
  • Run ctx.lookup() only once and store the created Pooled Datasource in a static variable for re-using.
  • Note: After a JVM reboot the JNDI resource/UCP Pool must be recreated running rebindPool() and lookupPool()
  • The JNDI functions create its own JNDI entry named: java:global/myUcpDs

Complete JAVA Code for JNDI lookup

private static oracle.ucp.jdbc.PoolDataSource pds = null;
   public void lookupPool() throws Exception
      {
        if ( pds != null)
          {
            setPoolStats(Tools.add_hmtl_pre_tag("Pooled Datasource already exist - don't run ctx.lookup() again  "));
            return;
          }    
        cleanAll();
        setPoolStats(Tools.add_hmtl_pre_tag("Testing UPC Pool via JNDI in progress JNDI name: " +  jndiName));
        ctx = new InitialContext();  
        pds = (PoolDataSource)ctx.lookup("java:global/myUcpDs");
        checkAll();
        setPoolStats(getPoolStats() + Tools.add_hmtl_pre_tag("lookupPool(): Pooled Datasource initialized: " + jndiName ));
      }
       
    public void rebindPool() throws Exception
      {
        pds =null;
        cleanAll();                                 
        UniversalConnectionPoolManager ucpMgr = createPoolManager();
        if ( ucpMgr == null)
          {
            setPoolStats(Tools.add_hmtl_pre_tag("Could not create UCP Manager "));
            return;
          }            
        setPoolStats(Tools.add_hmtl_pre_tag("Destroying UCP Pool in progres ..."));
                // We need to destroy the pool first if the pool exist
                // If we recreate the pool without destroying we will get a session leak at the RAC layer
        try
          {    
            ucpMgr.destroyConnectionPool(poolName);
            setPoolStats(getPoolStats() + Tools.add_hmtl_pre_tag("UCP Pool destroyed !"));
          } catch ( Exception e2)         
          {
            setPoolStats(getPoolStats () +Tools.add_hmtl_pre_tag("Exception during delete Pool - [ ignore the error]  "  ));  
                  // genericExp("Execption duringe deleteing pool - If pool does not exists ignore this exception ",  e2);
          }  
        ctx = new InitialContext();
        PoolDataSource lpds = setupPooledDS();
            // ucpMgr.createConnectionPool((UniversalConnectionPoolAdapter)pds);
        ctx.rebind(jndiName, lpds);
        setPoolStats(getPoolStats () +Tools.add_hmtl_pre_tag("JNDI context rebind ok for :  " + jndiName ));  
            // Disable JMX - if needed
             // ucpManager.setJmxEnabled(false);
            // ucpManager.createConnectionPool((UniversalConnectionPoolAdapter)pds);                                                                              
        return;
      }
        
   public  PoolDataSource setupPooledDS() throws Exception
      {
        
        PoolDataSource lpds = oracle.ucp.jdbc.PoolDataSourceFactory.getPoolDataSource();        
         //set the connection properties on the data source and pool properties
        String ONS_CONFIG = "nodes=hract21:6200,hract22:6200,hract23:6200";
        lpds.setONSConfiguration ( ONS_CONFIG);
        lpds.setFastConnectionFailoverEnabled( true);
        lpds.setUser("scott");
        lpds.setPassword("tiger");
        lpds.setURL("jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka");
        lpds.setConnectionFactoryClassName("oracle.jdbc.pool.OracleDataSource"); 
        lpds.setInitialPoolSize(minPoolSize);
        lpds.setMinPoolSize(minPoolSize);
        lpds.setMaxPoolSize(maxPoolSize);
        lpds.setAbandonedConnectionTimeout(abandonedConnectionTimeout);
        lpds.setInactiveConnectionTimeout(inactiveConnectionTimeout);
        lpds.setTimeoutCheckInterval(10);
        lpds.setConnectionPoolName(poolName);
        return lpds;
      } 

JNDI: Use Case I – Destroy Pooled DS and recreate UCP Pool

Destroy UCP Pool :  my_ucp_pool   DestroyUCP         [  but don't run Unbind UCP Pool via JNDI ]    
Lookup UCP Pool via JNDI  :       Lookup
16:49:48.930: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@7ffa742a
16:49:48.930: Available Pools:  my_ucp_pool
16:49:48.930:   Connection Count : Total : 5 - Available: 5 - Borrowed: 0
16:49:48.930:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
16:49:48.930:   PoolLifeCycle state:  Running
16:49:48.930:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
16:49:48.930: Connections in static ArrayList after openConnections(): 0
16:49:48.930: Connections remaining in static ArrayList after closeConnections() : 0
16:49:48.930: checkSessionInPool(): Connection - Opened:  5 - Closed: 5
16:49:48.930: lookupPool(): Pooled Datasource initialized: java:global/myUcpDs

-> After destruction of UCP pool the pool can be re-created by runing lookupPool()
   Note: A destruction of the UCP pool does not delete the JNDI entry.

JNDI: Use Case II – Destropy Pooled DS, Unbind JNDI and recreate JNDI and UCP Pool

Destroy UCP Pool :  my_ucp_pool          DestroyUCP
Unbind JNDI      :  java:global/myUcpDs  JndiUnbindUCP
Lookup UCP Pool via JNDI  fails:         Lookup

16:28:12.673: Exception inside lookupPool() :  JNDI Lookup 
16:28:12.673: myUcpDs -- service jboss.naming.context.java.global.myUcpDs
16:28:12.673: javax.naming.NameNotFoundException: myUcpDs -- service jboss.naming.context.java.global.myUcpDs
    at org.jboss.as.naming.ServiceBasedNamingStore.lookup(ServiceBasedNamingStore.java:104)
    at org.jboss.as.naming.NamingContext.lookup(NamingContext.java:202)
    at org.jboss.as.naming.NamingContext.lookup(NamingContext.java:179)  
    
Solution: 
Rebind the Pooled Datasource :  JndiRebindUCP
16:29:22.214: Destroying UCP Pool in progres ...
16:29:22.214: Exception during delete Pool - [ ignore the error]  
16:29:22.215: JNDI context rebind ok for :  java:global/myUcpDs

Run JNDI Lookup again :                Lookup 
16:29:48.930: Intialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@7ffa742a
16:29:48.930: Available Pools:  my_ucp_pool
16:29:48.930:   Connection Count : Total : 5 - Available: 5 - Borrowed: 0
16:29:48.930:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
16:29:48.930:   PoolLifeCycle state:  Running
16:29:48.930:   InactiveConnectionTimeout: 30 - AbandonedConnectionTimeout: 10
16:29:48.930: Connections in static ArrayList after openConnections(): 0
16:29:48.930: Connections remaining in static ArrayList after closeConnections() : 0
16:29:48.930: checkSessionInPool(): Connection - Opened:  5 - Closed: 5
16:29:48.930: lookupPool(): Pooled Datasource initialized: java:global/myUcpDs
-> After a JVM reboot or after deletion of UPC Pool and JNDI entry the UCP pool must be 
   recreated by calling rebindPool() and lookupPool().

Problem : JNDI lookup fails when calling lookup a 2.nd time

If you re-running the following JNDI code without destryoing the UCP pool first you will get an Exception
    public String lookupPool()
      {  
        cleanAll();
        setPoolStats(Tools.add_hmtl_pre_tag("Testing UPC Pool via JNDI in progress  "));
        genericExp("INFO:  JNDI Lookup doesn't work yet", null);
        try
          {
          ctx = new InitialContext();  
          pds = (PoolDataSource)ctx.lookup("java:global/myUcpDs");
          setPoolStats(getPoolStats() + Tools.add_hmtl_pre_tag("Testing UPC Pool via JNDI - Pooled Datasource initialized "));
          checkAll();
          } catch ( Exception e1)
              {
              genericExp("Exception inside lookupPool() :  JNDI Lookup ", e1);
            
              return "index";
              }
       
        setPoolStats(getPoolStats() + "- JNDI lookup ok  ! ");
        return "index";
      } 


1.st Run ( Note UCP pool was already destroyed )

Instance status :     RAC DB: BANKA
Instance Name:bankA_3 - Host: hract21.example.com
Instance Name:bankA_2 - Host: hract22.example.com
Instance Name:bankA_3 - Session Count 35
Instance Name:bankA_2 - Session Count 35

UCP Pool status :     
15:42:36.773: Initialized Pooled DS: oracle.ucp.jdbc.PoolDataSourceImpl@2daf23a3
15:42:36.773: Available Pools:  my_ucp_pool
15:42:36.773:   Connection Count : Total : 5 - Available: 5 - Borrowed: 0
15:42:36.773:   Pools Size       : Inital: 5 - Min      : 5 - Max     : 10
15:42:36.773:   PoolLifeCycle state:  Running
-> Status: UCP pool was created and started by  JNDI lookup
    
2.nd Run ( Note: UCP pool is already active ! )    
Exceptions :
15:48:09.493: Exception inside lookupPool() :  JNDI Lookup 
15:48:09.493: Unable to start the Universal Connection Pool: oracle.ucp.UniversalConnectionPoolException: 
   Error during pool creation in Universal Connection Pool Manager MBean: oracle.ucp.UniversalConnectionPoolException: 
   Error during pool creation in Universal Connection Pool Manager: oracle.ucp.UniversalConnectionPoolException: 
   Universal Connection Pool already exists in the Universal Connection Pool Manager. 
   Universal Connection Pool cannot be added to the Universal Connection Pool Manager
    at oracle.ucp.util.UCPErrorHandler.newSQLException(UCPErrorHandler.java:479)
    at oracle.ucp.util.UCPErrorHandler.throwSQLException(UCPErrorHandler.java:154)
    at oracle.ucp.jdbc.PoolDataSourceImpl.startPool(PoolDataSourceImpl.java:730)
    at oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:1093)
    at oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:1031)

Instance Status     
15:49:47.032:    RAC DB: BANKA
Instance Name:bankA_2 - Host: hract22.example.com
Instance Name:bankA_3 - Host: hract21.example.com
Instance Name:bankA_2 - Session Count 38
Instance Name:bankA_3 - Session Count 37    
    
-> The 2.nd run leads to a databases session leak
    
WA : Store the Pooled DataSource in a static variable and run lookup only a single time! 

Using XA Datasource with UCP and Wildfly fails with  loader constraint violation

Init XA Datasource:  InitUCPXA
12:20:50.557: Initializing XA UCP Pool in progress ...
12:20:50.561: INFO : Jar File     for XAResource.class:jar:file:/usr/local/wildfly-8.2.0.Final/modules/system/layers/base/javax/transaction/api/main/jboss-transaction-api_1.2_spec-1.0.0.Final.jar!/javax/transaction/xa/XAResource.class
12:20:50.561: INFO : Class Loader for XAResource.class :ModuleClassLoader for Module "javax.transaction.api:main" from local module loader @7fe9a140 (finder: local module finder @4359b25b (roots: /usr/local/wildfly-8.2.0.Final/modules,/usr/local/wildfly-8.2.0.Final/modules/system/layers/base))
12:20:50.784: XA Initializing UCP Pool failed !

Exceptions :
12:20:50.784: Runtime exception in jsfInitPoolXA() : 
12:20:50.785: loader constraint violation: loader (instance of ) previously initiated loading for a different type with name "javax/transaction/xa/XAResource"
12:20:50.787: java.lang.LinkageError: loader constraint violation: loader (instance of ) previously initiated loading for a different type with name "javax/transaction/xa/XAResource"
    at java.lang.Class.getDeclaredMethods0(Native Method)
    at java.lang.Class.privateGetDeclaredMethods(Class.java:2615)
    at java.lang.Class.privateGetPublicMethods(Class.java:2733)
    at java.lang.Class.getMethods(Class.java:1472)
    at sun.misc.ProxyGenerator.generateClassFile(ProxyGenerator.java:426)
    at sun.misc.ProxyGenerator.generateProxyClass(ProxyGenerator.java:323

For Details please check ... 
 Debugging UCP Connection Pool using XA Datasource pointing to a RAC database - http://www.hhutzler.de/blog/debugging-ucp-connection-pool-using-xa-datasource-pointing-to-a-rac-database/

 

Source Code

 JSF code:   index.xhtml      
 Java Code:  UcpPoolBean.java 

JAVADOC

Reference

How to integrate the Oracle JDBC driver as a Wildfly module ?

Purpose of this tutorial

  • Create and test a  RAC datasoure with WildFly jboss-cli.sh command utility
  • Deploy and integrate the Oracle JDBC driver as a Wildfly Module
  • Run a short Web application to display JDBC driver and Oracle Database version  

Deploying the Oracle JDBC Driver as a Wildfly module

Prepare module.xml and copy ojdbc7.jar to its destination
[oracle@wls1 ~]$ ls /usr/local/wildfly-8.2.0.Final/modules/com/oracle/ojdbc/main/
module.xml  ojdbc7.jar

[oracle@wls1 ~]$ cat /usr/local/wildfly-8.2.0.Final/modules/com/oracle/ojdbc/main/module.xml
?xml version="1.0" ?>
<module xmlns="urn:jboss:module:1.1" name="com.oracle.ojdbc">
    <resources>
        <resource-root path="ojdbc7.jar"/>
    </resources>
    <dependencies>
        <module name="javax.api"/>
        <module name="javax.transaction.api"/>
    </dependencies>
</module>

--> Restart Wildfly and your Datasource and verify the Oracle Driver :

[oracle@wls1 WILDFLY]$ $WILDFLY_HOME/bin/jboss-cli.sh --connect  /subsystem=datasources:installed-drivers-list
{
    "outcome" => "success",
    "result" => [
        {
            "driver-name" => "oracle",
            "deployment-name" => undefined,
            "driver-module-name" => "com.oracle.ojdbc",
            "module-slot" => "main",
            "driver-datasource-class-name" => "",
            "driver-xa-datasource-class-name" => "oracle.jdbc.xa.client.OracleXADataSource",
            "driver-class-name" => "oracle.jdbc.OracleDriver",
            "driver-major-version" => 12,
            "driver-minor-version" => 1,
            "jdbc-compliant" => true
        }

Setup RAC datasource by using the RAC SCAN address
[oracle@wls1 WILDFLY]$ cat add_ds.cli
if (outcome != success) of /subsystem=datasources/data-source=myRacDS:read-resource
    data-source add \
        --name=myRacDS \
        --driver-name=oracle \
        --jndi-name=java:jboss/datasources/myRacDS \
        --user-name="scott"\
        --password="tiger"\
        --use-java-context=true \
        --use-ccm=true \
        --min-pool-size=5 \
        --max-pool-size=10 \
        --pool-prefill=true \
        --allocation-retry=1 \
        --prepared-statements-cache-size=32 \
        --share-prepared-statements=true \
        --connection-url="jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka"
end-if

[oracle@wls1 WILDFLY]$ $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=add_ds.cli

Test the connection
[oracle@wls1 WILDFLY]$   $WILDFLY_HOME/bin/jboss-cli.sh --connect   /subsystem=datasources/data-source=myRacDS:test-connection-in-pool
{
    "outcome" => "success",
    "result" => [true]
}

Check DS properties

[oracle@wls1 WILDFLY]$ $WILDFLY_HOME/bin/jboss-cli.sh --connect   /subsystem=datasources/data-source=myRacDS:read-resource
{
    "outcome" => "success",
    "result" => {
        "allocation-retry" => 1,
        "allocation-retry-wait-millis" => undefined,
        "allow-multiple-users" => false,
        "background-validation" => undefined,
        "background-validation-millis" => undefined,
        "blocking-timeout-wait-millis" => undefined,
        "capacity-decrementer-class" => undefined,
        "capacity-decrementer-properties" => undefined,
        "capacity-incrementer-class" => undefined,
        "capacity-incrementer-properties" => undefined,
        "check-valid-connection-sql" => undefined,
        "connection-listener-class" => undefined,
        "connection-listener-property" => undefined,
        "connection-properties" => undefined,
        "connection-url" => "jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka",
        "datasource-class" => undefined,
        "driver-class" => undefined,
        "driver-name" => "oracle",
        "enabled" => true,
        "exception-sorter-class-name" => undefined,
        "exception-sorter-properties" => undefined,
        "flush-strategy" => undefined,
        "idle-timeout-minutes" => undefined,
        "initial-pool-size" => undefined,
        "jndi-name" => "java:jboss/datasources/myRacDS",
        "jta" => true,
        "max-pool-size" => 10,
        "min-pool-size" => 5,
        "new-connection-sql" => undefined,
        "password" => "tiger",
        "pool-prefill" => true,
        "pool-use-strict-min" => undefined,
        "prepared-statements-cache-size" => 32,
        "query-timeout" => undefined,
        "reauth-plugin-class-name" => undefined,
        "reauth-plugin-properties" => undefined,
        "security-domain" => undefined,
        "set-tx-query-timeout" => false,
        "share-prepared-statements" => true,
        "spy" => false,
        "stale-connection-checker-class-name" => undefined,
        "stale-connection-checker-properties" => undefined,
        "track-statements" => "NOWARN",
        "transaction-isolation" => undefined,
        "url-delimiter" => undefined,
        "url-selector-strategy-class-name" => undefined,
        "use-ccm" => true,
        "use-fast-fail" => false,
        "use-java-context" => true,
        "use-try-lock" => undefined,
        "user-name" => "scott",
        "valid-connection-checker-class-name" => undefined,
        "valid-connection-checker-properties" => undefined,
        "validate-on-match" => false,
        "statistics" => {
            "jdbc" => undefined,
            "pool" => undefined
        }
    }
}

If you need to remove the DS run: 
 $WILDFLY_HOME/bin/jboss-cli.sh --connect   /subsystem=datasources/data-source=myRacDS:remove

 

Test  Oracle JDBC driver from a JBOSS WEB application

Run the following JAVA code: 
 try
          {
            String clname= "oracle.jdbc.OracleDriver";
            Class.forName (clname);  
            setJdbcInfo( StackTraceUtil.add_hmtl_pre_tag( "JDBC Driver Check - Loading Driver class ok : " + clname));
            java.util.Properties props = System.getProperties();
            java.util.Enumeration propNames = props.propertyNames();
            setJdbcInfo(getJdbcInfo()  + StackTraceUtil.add_hmtl_pre_tag("JDK Version: " + props.getProperty("java.version")));
            setJdbcInfo(getJdbcInfo() + StackTraceUtil.add_hmtl_pre_tag( "ClassPath  : "  + props.getProperty("java.class.path")));
            Connection c = ds1.getConnection();
            java.sql.DatabaseMetaData md = c.getMetaData();
            setJdbcInfo(getJdbcInfo()  + StackTraceUtil.add_hmtl_pre_tag( "Driver Name             : "+md.getDriverName()));
            setJdbcInfo(getJdbcInfo()  + StackTraceUtil.add_hmtl_pre_tag( "Driver Version          : "+md.getDriverVersion()));
            setJdbcInfo(getJdbcInfo()  + StackTraceUtil.add_hmtl_pre_tag( "Database Product Version: " +md.getDatabaseProductVersion()));
            c.close();
          
          } catch ( Exception e1)
..
Very likely
Class.forName (clname);   throws the following Exceptions  in checkDriver()

oracle.jdbc.OracleDriver from [Module "deployment.WF_JdbcDriverTest.war:main" from Service Module Loader]
java.lang.ClassNotFoundException: oracle.jdbc.OracleDriver from [Module "deployment.WF_JdbcDriverTest.war:main" from Service Module Loader]
    at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:213)
    at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:459)
    at org.jboss.modules.ConcurrentClassLoader.performLoadClassChecked(ConcurrentClassLoader.java:408)
    at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:389)
    at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:134)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:191)
    at DriverTest.DriverTestBean.checkDriver(DriverTestBean.java:54)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at com.sun.el.parser.AstValue.invoke(AstValue.java:292)
    at com.sun.el.MethodExpressionImpl.invoke(MethodExpressionImpl.java:304)
    at com.sun.faces.facelets.el.TagMethodExpression.invoke(TagMethodExpression.java:105

Note if working with Datasources you may see following stack:
Caused by: oracle.ucp.UniversalConnectionPoolException: Error during pool creation in Universal Connection Pool Manager: java.sql.SQLException: Invalid Universal Connection Pool configuration: java.sql.SQLException: Unable to create factory class instance with provided factory class name: java.lang.ClassNotFoundException: oracle.jdbc.pool.OracleDataSource from [Module "deployment.WF_UCPPool.war:main" from Service Module Loader]
    at oracle.ucp.util.UCPErrorHandler.newUniversalConnectionPoolException(UCPErrorHandler.java:359)
    at oracle.ucp.util.UCPErrorHandler.throwUniversalConnectionPoolException(UCPErrorHandler.java:58)
    at oracle.ucp.admin.UniversalConnectionPoolManagerBase.createConnectionPool(UniversalConnectionPoolManagerBase.java:528)
    at UcpPool.UcpPoolBean.rebindPool(UcpPoolBean.java:289)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

Detailed Problem description:

  • Why is Module Loader looking for the JDBC driver ?
  • We expect that Wildfly picks up the Oracle JDBC Driver as we have installed the JDBC Driver as a Module

  Note if have configured the  Oracle JDBC driver as a library in your WAR file the above code works fine .

 

Solution to integrate the Oracle JDBC Driver with Wildfly

Add a dependency to the Oralce JDBC driver module by adding  jboss-deployment-structure.xml 
under your WEB_INF folder:   
<?xml version="1.0" encoding="UTF-8"?>
<!--
To change this license header, choose License Headers in Project Properties.
To change this template file, choose Tools | Templates
and open the template in the editor.
-->

<jboss-deployment-structure>
  <deployment>
    <dependencies>
       <module name="com.oracle.ojdbc" />
    </dependencies>
   </deployment>
</jboss-deployment-structure>

Rerun the test program - ths JSF output should display the following : 

JDBC Driver Check - Loading Driver class ok : oracle.jdbc.OracleDriver
JDK Version: 1.7.0_71
ClassPath  : /usr/local/wildfly-8.2.0.Final/jboss-modules.jar
Driver Name             : Oracle JDBC driver
Driver Version          : 12.1.0.2.0
Database Product Version: Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Advanced Analytics and Real Application Testing options

JSF code : index.xhtml

<?xml version='1.0' encoding='UTF-8' ?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml"
xmlns:h="http://xmlns.jcp.org/jsf/html">
<h:head>
<title>JDBC Driver Test</title>
</h:head>
<h:body>
<h:form>
<h:commandButton id="cBnt1" value="JDBC Driver Check"  action="#{driverTestBean.checkDriver}"></h:commandButton>
<hr color="blue"  size="3" width="90%" align="center"/>
<h:panelGrid columns="6" border="3">
<h:outputText style="color: red"  value="JDBC Driver Status :" />
<h:outputText  id="optxt1"  style="color: blue"  value="#{driverTestBean.jdbcInfo}" escape="false" />
</h:panelGrid>
<hr color="blue"  size="3" width="90%" align="center"/>
<h:outputText style="color: red"  value="Exceptions : "  escape="false"  />
<br/>
<h:outputText  id="optxt2"  style="color: red"  value="#{driverTestBean.exceptInfo}" escape="false" />
</h:form>

</h:body>
</html>

JAVA Code:  DriverTestBean.java

package DriverTest;

import java.io.PrintWriter;
import java.io.StringWriter;
import java.io.Writer;
import java.sql.Connection;
import javax.annotation.Resource;
import javax.faces.bean.ManagedBean;
import javax.faces.bean.SessionScoped;
import javax.sql.DataSource;

/**
 *
 * @author Helmut Hutzler 
 */
 @ManagedBean
 @SessionScoped
public class DriverTestBean
    {
    private String exceptInfo="";
    private String jdbcInfo="  -->  please Press JDBC Driver Check Button";
    @Resource(lookup="java:jboss/datasources/myRacDS")
    private DataSource ds1;
      
    public String getJdbcInfo()
      {
        return jdbcInfo;
      }

    public void setJdbcInfo(String jdbcInfo)
      {
        this.jdbcInfo = jdbcInfo;
      }
     
    public String getExceptInfo()
      {
        return exceptInfo;
      }

    public void setExceptInfo(String exceptInfo)
      {
        this.exceptInfo = exceptInfo;
      }
    public String checkDriver() throws Exception
      {
        try
          {
            String clname= "oracle.jdbc.OracleDriver";
            Class.forName (clname);  
            setJdbcInfo( StackTraceUtil.add_hmtl_pre_tag( "JDBC Driver Check - Loading Driver class ok : " + clname));
            java.util.Properties props = System.getProperties();
            java.util.Enumeration propNames = props.propertyNames();
            setJdbcInfo(getJdbcInfo()  + StackTraceUtil.add_hmtl_pre_tag("JDK Version: " + props.getProperty("java.version")));
            setJdbcInfo(getJdbcInfo() + StackTraceUtil.add_hmtl_pre_tag( "ClassPath  : "  + props.getProperty("java.class.path")));
            Connection c = ds1.getConnection();
            java.sql.DatabaseMetaData md = c.getMetaData();
            setJdbcInfo(getJdbcInfo()  + StackTraceUtil.add_hmtl_pre_tag( "Driver Name             : "+md.getDriverName()));
            setJdbcInfo(getJdbcInfo()  + StackTraceUtil.add_hmtl_pre_tag( "Driver Version          : "+md.getDriverVersion()));
            setJdbcInfo(getJdbcInfo()  + StackTraceUtil.add_hmtl_pre_tag( "Database Product Version: " +md.getDatabaseProductVersion()));
            c.close();
          
          } catch ( Exception e1)
              {
                generic_exp("Error in checkDriver()", e1);
              }
      
       return "index";
      }
    
    public void generic_exp(String ip, Exception e1)
      {
        if ( ip != null)
            setExceptInfo( StackTraceUtil.add_hmtl_pre_tag(ip));
        if ( e1 != null)
          {
            setExceptInfo(getExceptInfo() +  StackTraceUtil.add_hmtl_pre_tag(e1.getMessage()));
            setExceptInfo(getExceptInfo() +  StackTraceUtil.add_hmtl_pre_tag( StackTraceUtil.getStackTrace(e1)));
      
          } 
      }  
    
    }

 class StackTraceUtil 
  {

    public static String getStackTrace(Throwable aThrowable) 
      {
        final Writer result = new StringWriter();
        final PrintWriter printWriter = new PrintWriter(result);
        aThrowable.printStackTrace(printWriter);
        return result.toString();
     }
    
    public static String add_hmtl_pre_tag (String ip)
      {
        String op =  "<pre>"  + ip + "</pre>" ; 
        return op;        
      }      
  }

Reference

WildFLY Commands and Configuration Tasks

Start and stop  Wildfly

Start Wildfly 
$ $WILDFLY_HOME/bin/standalone.sh
=========================================================================
  JBoss Bootstrap Environment
  JBOSS_HOME: /usr/local/wildfly-8.2.0.Final
  JAVA: /usr/java/jdk1.7.0_71/bin/java
  JAVA_OPTS:  -server -Xms64m -Xmx512m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true

Stop WildFly 
$ $WILDFLY_HOME/bin/jboss-cli.sh --connect command=:shutdown
{"outcome" => "success"}

Access Wildfly using localhost and HOSTNAME

If you want to bind to all available IP addresses, then start WILDFLY by : 

% ./bin/standalone.sh -b 0.0.0.0

This should allow to the connect via http://localhost and http://wls1 [ where wls1 is our HOSTNAME ]
$ firefox http://localhost:8180/WFJPA2EL-1.0/
$ firefox http://wls1:8180/WFJPA2EL-1.0/


For permanent solution you can change the bind address in your standalone.xml file:  
    <interfaces>
..       
        <interface name="public">
            <inet-address value="${jboss.bind.address:0.0.0.0}"/>            
        </interface>
  ..      
    </interfaces>

 

Working with simple Objects


Remove a JNDI String object 
[oracle@wls1 JNDI]$  $WILDFLY_HOME/bin/jboss-cli.sh --connect   "/subsystem=naming/binding=java\:global\/mystring/:remove"
[oracle@wls1 JNDI]$  $WILDFLY_HOME/bin/jboss-cli.sh --connect  reload

Create a JNDI String object
[oracle@wls1 JNDI]$ cat  new_jndi.cli
/subsystem=naming/binding=java\:global\/mystring/:add(binding-type=simple,value="My JNDI strored String",type=java.lang.String)
[oracle@wls1 JNDI]$  $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=new_jndi.cli
{"outcome" => "success"}

Verify JNDI view:

[oracle@wls1 JNDI]$  $WILDFLY_HOME/bin/jboss-cli.sh  --connect  "/subsystem=naming:jndi-view"
...
      "java:global" => {
                "mystring" => {
                    "class-name" => "java.lang.String",
                    "value" => "My JNDI strored String"
                },

Setup and verify a RAC datasource by using the RAC SCAN address

Setup RAC datasource by using the RAC SCAN address
[oracle@wls1 WILDFLY]$ cat add_ds.cli
if (outcome != success) of /subsystem=datasources/data-source=myDS:read-resource
    data-source add \
        --name=myDS \
        --driver-name=oracle \
        --jndi-name=java:jboss/datasources/myDS \
        --user-name="scott"\
        --password="tiger"\
        --use-java-context=true \
        --use-ccm=true \
        --min-pool-size=5 \
        --max-pool-size=10 \
        --pool-prefill=true \
        --allocation-retry=1 \
        --prepared-statements-cache-size=32 \
        --share-prepared-statements=true \
        --connection-url="jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka"
end-if

$ $WILDFLY_HOME/bin/jboss-cli.sh --connect --file=add_ds.cli

Test the connection  $WILDFLY_HOME/bin/jboss-cli.sh --connect   /subsystem=datasources/data-source=myRacDS:test-connection-in-pool
{
    "outcome" => "success",
    "result" => [true]
}

Check newly create datasource properties: 
$ $WILDFLY_HOME/bin/jboss-cli.sh --connect   /subsystem=datasources/data-source=myRacDS:read-resource
{
    "outcome" => "success",
    "result" => {
        "allocation-retry" => 1,
        "allocation-retry-wait-millis" => undefined,
        "allow-multiple-users" => false,
        "background-validation" => undefined,
        "background-validation-millis" => undefined,
        "blocking-timeout-wait-millis" => undefined,
        "capacity-decrementer-class" => undefined,
        "capacity-decrementer-properties" => undefined,
        "capacity-incrementer-class" => undefined,
        "capacity-incrementer-properties" => undefined,
        "check-valid-connection-sql" => undefined,
        "connection-listener-class" => undefined,
        "connection-listener-property" => undefined,
        "connection-properties" => undefined,
        "connection-url" => "jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka",
        "datasource-class" => undefined,
        "driver-class" => undefined,
        "driver-name" => "oracle",
        "enabled" => true,
        "exception-sorter-class-name" => undefined,
        "exception-sorter-properties" => undefined,
        "flush-strategy" => undefined,
        "idle-timeout-minutes" => undefined,
        "initial-pool-size" => undefined,
        "jndi-name" => "java:jboss/datasources/myRacDS",
        "jta" => true,
        "max-pool-size" => 10,
        "min-pool-size" => 5,
        "new-connection-sql" => undefined,
        "password" => "tiger",
        "pool-prefill" => true,
        "pool-use-strict-min" => undefined,
        "prepared-statements-cache-size" => 32,
        "query-timeout" => undefined,
        "reauth-plugin-class-name" => undefined,
        "reauth-plugin-properties" => undefined,
        "security-domain" => undefined,
        "set-tx-query-timeout" => false,
        "share-prepared-statements" => true,
        "spy" => false,
        "stale-connection-checker-class-name" => undefined,
        "stale-connection-checker-properties" => undefined,
        "track-statements" => "NOWARN",
        "transaction-isolation" => undefined,
        "url-delimiter" => undefined,
        "url-selector-strategy-class-name" => undefined,
        "use-ccm" => true,
        "use-fast-fail" => false,
        "use-java-context" => true,
        "use-try-lock" => undefined,
        "user-name" => "scott",
        "valid-connection-checker-class-name" => undefined,
        "valid-connection-checker-properties" => undefined,
        "validate-on-match" => false,
        "statistics" => {
            "jdbc" => undefined,
            "pool" => undefined
        }
    }
}

Remove a Datasource

 $WILDFLY_HOME/bin/jboss-cli.sh --connect   /subsystem=datasources/data-source=myRacDS:remove

 

Display installed  JDBC Drivers

$ $WILDFLY_HOME/bin/jboss-cli.sh --connect  /subsystem=datasources:installed-drivers-list
{
    "outcome" => "success",
    "result" => [
        {
            "driver-name" => "oracle",
            "deployment-name" => undefined,
            "driver-module-name" => "com.oracle.ojdbc",
            "module-slot" => "main",
            "driver-datasource-class-name" => "",
            "driver-xa-datasource-class-name" => "oracle.jdbc.xa.client.OracleXADataSource",
            "driver-class-name" => "oracle.jdbc.OracleDriver",
            "driver-major-version" => 12,
            "driver-minor-version" => 1,
            "jdbc-compliant" => true
        }

Change Wildfly JVM parameters  [ Standalone Mode ]

Edit File:   $WILDFLY_HOME/bin/standalone.conf [ Note we add the blue line at the end ! ]
if [ "x$JAVA_OPTS" = "x" ]; then
   JAVA_OPTS="-Xms64m -Xmx512m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true"
   JAVA_OPTS="$JAVA_OPTS -Djboss.modules.system.pkgs=$JBOSS_MODULES_SYSTEM_PKGS -Djava.awt.headless=true"
   JAVA_OPTS="$JAVA_OPTS -Dappdynamics.bciengine.class.lookahead=!*"
   JAVA_OPTS="$JAVA_OPTS -XX:+TraceLoaderConstraints -verbose:class"
else
   echo "JAVA_OPTS already set in environment; overriding default settings with values: $JAVA_OPTS"
fi
--> Restart Wildfly 

With Netbeans Wildfly Integration:  
Services -> Wildfly Application Server -> [RC] Properties -> Platform -> VM Options 
Add your enew parameters  : 
   -Dappdynamics.bciengine.class.lookahead=!* -XX:+TraceLoaderConstraints -verbose:class

After a Wildfly restart you should see :
  JBoss Bootstrap Environment
  JBOSS_HOME: /usr/local/wildfly-8.2.0.Final
  JAVA: /usr/java/latest/bin/java
  JAVA_OPTS:  -Xms128m -Xmx512m  -Dappdynamics.bciengine.class.lookahead=!* -XX:+TraceLoaderConstraints -verbose:class
    -XX:MaxPermSize=256m -server -Dhttp.nonProxyHosts=localhost,127.0.0.1,wls1.example.com -Djava.net.preferIPv4Stack=true 
    -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true

 

Display WildFLY LogFile location

$ $WILDFLY_HOME/bin/jboss-cli.sh --connect  /subsystem=logging/:list-log-files 
{
    "outcome" => "success",
    "result" => [
        {
            "file-name" => "server.log",
            "file-size" => 458152L,
            "last-modified-date" => "2015-03-31T13:15:40.000+0200"
        },
        {
            "file-name" => "server.log.2014-12-24",
            "file-size" => 40595L,
            "last-modified-date" => "2014-12-24T17:40:22.000+0100"
        },

Sample or Standalone Mode : ./standalone/log/server.log

Setup a XA Datasource by using the RAC SCAN address

if (outcome != success) of /subsystem=datasources/xa-data-source=xa_rac12g_banka:read-resource
    xa-data-source add \
        --name=xa_rac12g_banka\
        --driver-name=oracle \
        --jndi-name=java:jboss/datasources/xa_rac12g_banka\
        --user-name="scott"\
        --password="tiger"\
        --use-java-context=true \
        --use-ccm=true \
        --min-pool-size=10 \
        --max-pool-size=100 \
        --pool-prefill=true \
        --check-valid-connection-sql="select 1 from dual" \
        --allocation-retry=1 \
        --prepared-statements-cache-size=32 \
        --share-prepared-statements=true
    /subsystem=datasources/xa-data-source=xa_rac12g_banka/xa-datasource-properties=URL:add(value="jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka")
    reload
end-if

 

Enabling tracing HTTP request with Wildfly

-> jboss-cli Commands  
/subsystem=undertow/configuration=filter/custom-filter=request-dumper:add(class-name=io.undertow.server.handlers.RequestDumpingHandler, module=io.undertow.core)
/subsystem=undertow/server=default-server/host=default-host/filter-ref=request-dumper:add

For Details read:  following Article.

Script to enable HTTP logging :  enable_http_logging.cli
/subsystem=undertow/configuration=filter/custom-filter=request-dumper:add(class-name=io.undertow.server.handlers.RequestDumpingHandler, module=io.undertow.core)
/subsystem=undertow/server=default-server/host=default-host/filter-ref=request-dumper:add

Script to disable HTTP logging : disable_http_logging.cli
/subsystem=undertow/configuration=filter/custom-filter=request-dumper:remove
/subsystem=undertow/server=default-server/host=default-host/filter-ref=request-dumper:remove
:shutdown(restart=true)