Month: May 2015

Using ExecutorService, Callable API to run Multi-threaded JUNIT tests

Overview

  • In this tutorial we use ExecutorService, Callable API  and JUNIT to test your program for thread safty
  • Callable vs Runable
    • Runnable interface is older than Callable, there from JDK 1.0, while Callable is added on Java 5.0.
    • Runnable interface has run() method to define task while Callable interface uses call() method for task definition.
    • run() method does not return any value, it’s return type is void while call method returns value. Callable interface is a generic parameterized interface and Type of value is provided, when instance of Callable implementation is created.
    • Another difference on run and call method is that run method can not throw checked exception, while call method can throw checked exception in Java.

Test case details

  • Assume on of your developer has created the following ThreadCounter class.
  • This class works fine in single threaded Apps but fails if more than 1 Thread is using this Counter

JAVA code : JUnitTest/src/main/java/com/hhu/junittest/ThreadCounter.java

package com.hhu.junittest;

import javax.faces.bean.ManagedBean;
import javax.faces.bean.SessionScoped;

@ManagedBean
@SessionScoped
public class ThreadCounter
    {
    private  int count = 0;
    public final VolatileInt vi = new VolatileInt();    
    
    public ThreadCounter()
      {
      }    
    public ThreadCounter( int count)
      {
        this.count = count;
      }        
    public void setCounter( int count)
      {
        this.count = count;
      }
    public static void main(String[] args)
      {
        System.out.println("Hallo from ThreadCounter Class");
          // TODO code application logic here
        // final VolatileInt vi = new VolatileInt();
        ThreadCounter tc = new ThreadCounter();
        tc.setCounter(100*1000*1000);
        for (int j = 0; j < tc.count; j++)
            tc.testIncrement();
        tc. counterStatus();
      }
    
    public void testIncrement()
      {
        vi.num++;
      }
    
    public int getCounter()
      {
        return vi.num;
      }
    static class VolatileInt 
      {
        volatile int num = 0;
      }
    
    public void counterStatus()
      {
         System.out.printf("Total %,d but was %,d", count, getCounter() );
          if ( count == vi.num   )
                System.out.printf(" - Test : OK \n");
            else
               System.out.printf(" - Test : FAILED \n");
      }   
    }

The single Thread test works fine and returns : 
  Hallo from ThreadCounter Class
  Total 100,000,000 but was 100,000,000 - Test : OK

Test Code for testing thread-safty : JUnitTest/src/test/java/ThreadTest.java

JAVA Code :
import java.util.ArrayList;
import java.util.Collections;
import java.util.List;
import java.util.concurrent.Callable;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import java.util.concurrent.atomic.AtomicInteger;
import com.hhu.junittest.ThreadCounter;

import org.junit.Assert;
import org.junit.Test;
 
public class ThreadTest
  {
    
    /*
     static class VolatileInt 
      {
        volatile int num = 0;
      }
    */
    private void test(final int threadCount, boolean atomicTest ) throws InterruptedException, ExecutionException 
      {
        final boolean atomicTestf = atomicTest;        
       // final VolatileInt vi = new VolatileInt();          // This test fails for threadCount > 1
        final AtomicInteger num = new AtomicInteger();     // This test works for any threadCount value
        
        final int count = 100 *1000*1000;
        
        final ThreadCounter tc = new ThreadCounter(100*1000*1000);
            // Create an Anonymous Innner Class with a Callable Object
            // Use Callable  object so we get some results back from our thread test
        Callable<String> task = new Callable<String>() 
          {
            @Override
            public String call() 
              {
                for (int j = 0; j < count; j += threadCount)
                  {
                    if (atomicTestf)
                        num.incrementAndGet();
                    else 
                      //  vi.num++;
                      tc.testIncrement();
                  }       
                return "atomicTest: " + atomicTestf + " - Leaving Thread:  " + Thread.currentThread().getName() +
                   " - nThreads: "  + threadCount; 
              }                
          };
           // As we want to run the same Callable Objects on all threads use:  Collections.nCopies   
           // Collections.nCopies returns an immutable list consisting of n copies of the specified object. 
           // Note the newly allocated data object contains only a single reference to the data object.
        List<Callable<String>> tasks = Collections.nCopies(threadCount, task);
           //Get ExecutorService from Executors utility class, thread pool size is threadCount 
        ExecutorService executorService = Executors.newFixedThreadPool(threadCount);
           // The invokeAll() method invokes all of the Callable objects you pass to it in the collection passed as parameter. 
           // The invokeAll() returns a list of Future objects via which you can obtain the results of the executions of each Callable.
        List<Future<String>> futures = executorService.invokeAll(tasks);
           // create new and empty String ArrayList
        List<String> resultList = new ArrayList<String>(futures.size());
        // Check for exceptions - our Futures are returning  String Objects
        for (Future<String> future : futures) 
          {
            // Throws an exception if an exception was thrown by the task.
            resultList.add(future.get());
          }
        // Note the future.get() blocks until we get some return value
        // At this stage all tasks are finished - either with an Exception or be a regular method return
        // Validate the final Thread Counter status        
        if (atomicTest)
          {
            System.out.printf("With %,d threads should total %,d but was %,d",
                threadCount , count, num.intValue() ); 
             if ( count == num.intValue()   )
                System.out.printf(" - Test : OK \n");
            else
               System.out.printf(" - Test : FAILED \n");
            Assert.assertEquals(count,num.intValue());
          }
        else
          {
            System.out.printf("With %,d threads should total %,d but was %,d",
                threadCount , count,  tc.getCounter()  ); 
            if ( count == tc.getCounter()  )
                System.out.printf(" - Test : OK \n");
            else
               System.out.printf(" - Test : FAILED \n"); 
            Assert.assertEquals(count,  tc.getCounter());
          }
           // Display the results 
        for ( int i = 0; i<resultList.size(); i++)
            System.out.println(resultList.get(i) );
      }
 
    @Test
    public void test01() throws InterruptedException, ExecutionException 
      {
        test(1,false);
      }
 
    @Test
    public void test02() throws InterruptedException, ExecutionException 
      {
        test(2,false);
      } 
 
    @Test
    public void test04() throws InterruptedException, ExecutionException 
      {
        test(4,false);
      }
 
    @Test
    public void test08() throws InterruptedException, ExecutionException 
      {
        test(8,false);
      }
 
    @Test
    public void test16() throws InterruptedException, ExecutionException 
      {
        test(8,true);    
   } 
 }

Test results

[oracle@wls1 JUnitTest]$ mvn test
-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running ThreadTest
With 1 threads should total 100,000,000 but was 100,000,000 - Test : OK 
atomicTest: false - Leaving Thread:  pool-1-thread-1 - nThreads: 1
With 2 threads should total 100,000,000 but was 74,553,473 - Test : FAILED 
With 4 threads should total 100,000,000 but was 40,718,556 - Test : FAILED 
With 8 threads should total 100,000,000 but was 23,405,246 - Test : FAILED 
With 8 threads should total 100,000,000 but was 100,000,000 - Test : OK 
atomicTest: true - Leaving Thread:  pool-5-thread-1 - nThreads: 8
atomicTest: true - Leaving Thread:  pool-5-thread-2 - nThreads: 8
atomicTest: true - Leaving Thread:  pool-5-thread-3 - nThreads: 8
atomicTest: true - Leaving Thread:  pool-5-thread-4 - nThreads: 8
atomicTest: true - Leaving Thread:  pool-5-thread-5 - nThreads: 8
atomicTest: true - Leaving Thread:  pool-5-thread-6 - nThreads: 8
atomicTest: true - Leaving Thread:  pool-5-thread-7 - nThreads: 8
atomicTest: true - Leaving Thread:  pool-5-thread-8 - nThreads: 8
Tests run: 5, Failures: 3, Errors: 0, Skipped: 0, Time elapsed: 2.253 sec <<< FAILURE!

Results :
Failed tests:   
  test02(ThreadTest): expected:<100000000> but was:<74553473>
  test04(ThreadTest): expected:<100000000> but was:<40718556>
  test08(ThreadTest): expected:<100000000> but was:<23405246>
Tests run: 5, Failures: 3, Errors: 0, Skipped: 0

Some comments on above test results

  • test01 works as we use only a single Thread
  • test02, test04, test08 fails if using 2,4 or 8 Threads and if using volatile int as ThreadCounter
  • test08 works even for 8 Threads if using AtomicInteger() instead of volatile int as ThreadCounter
  • test08 with AtomicInteger() returns a String object for each Thread by using our Future objects

 

Reference

What is the best way to implement a thread-safe Integer Counter ?

Overview and Key Facts

  • You may take into account the following JAVA features
    • Using a static volatile int like  :  volatile int num = 0;            –>  NOT WORKING
    • Use a synchronized method  
    • Using AtomicInteger         like  :  final AtomicInteger num = new AtomicInteger();
  • The Java volatile keyword guarantees visibility of changes to variables across threads
  • Using volatile is not enough to create thread safe code
   Lets assume we have 2 threads incrementing a global volatile int as our Thread Counter
     Thread 1 could read a shared counter variable with the value 20 into its CPU cache, increment it to 21
     Thread 2 could read a shared counter variable with the value 20 into its CPU cache, increment it to 21
     Thread 1 writes Thread Counter value [ which is 21 ] to main memory
     Thread 2 writes Thread Counter value [ which is 21 ] to main memory
   Despite we have incremented our Counter 2x the counter value increases only by 1 !
   This problem can occur as the ++ operator is not thread safe !
  • AtomicInteger uses combination of volatile & CAS for thread-safe implementation of Integer Counter.
  • AtomicInteger class stores its value field in a volatile variable, thus it is a decorator over the traditional volatile variable
  • AtomicInteger provides unique non-blocking mechanism for updating the value after requiring the hardware level support for CAS (compare and set).
  • Syncronized access is using locks and therefore slower than CAS method used by AtomicInteger

 

JAVA test case : IncrementNotThreadSafeMain.java

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;

public class IncrementNotThreadSafeMain {
  public static void main(String... args) throws InterruptedException {
    for (int nThreads = 1; nThreads <= 64; nThreads *= 2)
      doThreadSafeTest(nThreads);
  }

  static class VolatileInt {
    volatile int num = 0;
  }

  private static void doThreadSafeTest(final int nThreads) throws InterruptedException {
    final int count = 100 * 1000 * 1000;

    ExecutorService es = Executors.newFixedThreadPool(nThreads);
    final VolatileInt vi = new VolatileInt();
    System.out.printf("--- Testing with Volatile --- ");
    for (int i = 0; i < nThreads; i++)
      es.submit(new Runnable() {
        public void run() {
          for (int j = 0; j < count; j += nThreads)
             vi.num++;
        }
      });
    es.shutdown();
    es.awaitTermination(1, TimeUnit.MINUTES);
    assert es.isTerminated();
    System.out.printf("With %,d threads should total %,d but was %,d%n", nThreads, count, vi.num /*num.longValue()*/);
    
    System.out.printf("--- Testing AtomicInteger --- ");
    es = Executors.newFixedThreadPool(nThreads);
    final AtomicInteger num = new AtomicInteger();
    for (int i = 0; i < nThreads; i++)
      es.submit(new Runnable() {
        public void run() {
          for (int j = 0; j < count; j += nThreads)
              num.incrementAndGet();
        }
      });
    es.shutdown();
    es.awaitTermination(1, TimeUnit.MINUTES);
    assert es.isTerminated();
    System.out.printf("With %,d threads should total %,d but was %,d%n", nThreads, count, num.longValue() );   
  }
}

Running above Code
$  java  IncrementNotThreadSafeMain
--- Testing with Volatile --- With 1 threads should total 100,000,000 but was 100,000,000
--- Testing AtomicInteger --- With 1 threads should total 100,000,000 but was 100,000,000
--- Testing with Volatile --- With 2 threads should total 100,000,000 but was 54,089,900
--- Testing AtomicInteger --- With 2 threads should total 100,000,000 but was 100,000,000
--- Testing with Volatile --- With 4 threads should total 100,000,000 but was 44,019,787
--- Testing AtomicInteger --- With 4 threads should total 100,000,000 but was 100,000,000
--- Testing with Volatile --- With 8 threads should total 100,000,000 but was 24,731,449
--- Testing AtomicInteger --- With 8 threads should total 100,000,000 but was 100,000,000
--- Testing with Volatile --- With 16 threads should total 100,000,000 but was 28,908,662
--- Testing AtomicInteger --- With 16 threads should total 100,000,000 but was 100,000,000
--- Testing with Volatile --- With 32 threads should total 100,000,000 but was 37,063,611
--- Testing AtomicInteger --- With 32 threads should total 100,000,000 but was 100,000,000
--- Testing with Volatile --- With 64 threads should total 100,000,000 but was 79,022,174
--- Testing AtomicInteger --- With 64 threads should total 100,000,000 but was 100,000,000

--> All Volatile tests with more then 2 Threads are failing !

Reference

Using Eclipselink as a Persistence Provider in a Netbeans/Wildfly project for JTA transaction

Project Versions

 EclipseLink Version: 2.5.2 - [ EclipseLink 2.5.2 == JPA 2.1] 
 JBDC Driver Name             : Oracle JDBC driver
 JDBC Driver Version          : 12.1.0.2.0
 Database Version             : 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
 Database Name and Instances  : DB Name:  BANKA
                                1. Instance Name: bankA_2 - Host: hract21.example.com
                                2. Instance Name: bankA_1 - Host: hract22.example.com
 Netbeans Version             : 8.0.2
 Wildfly Version              : 8.2
 Entity Manger Type           : Application Managed
 Transaction Type             : JTA

Setup EclipseLink as a Wildfly Module

Check modules/system/layers/base/org/eclipse/persistence/main directory
oracle@wls1 main]$ pwd
/usr/local/wildfly-8.2.0.Final/modules/system/layers/base/org/eclipse/persistence/main

Copy eclipselink-2.5.2.jar from MAVEN repository  to modules/system/layers/base/org/eclipse/persistence/main
[oracle@wls1 main]$ ls
eclipselink-2.5.2.jar  jipijapa-eclipselink-1.0.1.Final.jar  module.xml
 
Add  eclipselink-2.5.2.jar to module.xml in  modules/system/layers/base/org/eclipse/persistence/main
[oracle@wls1 main]$ cat  module.xml
<module xmlns="urn:jboss:module:1.3" name="org.eclipse.persistence">
    <resources>
        <resource-root path="jipijapa-eclipselink-1.0.1.Final.jar"/>
        <resource-root path="eclipselink-2.5.2.jar"/>
    </resources>
    <dependencies>
        <module name="asm.asm"/>
        <module name="javax.api"/>
        <module name="javax.annotation.api"/>
        <module name="javax.enterprise.api"/>
        <module name="javax.persistence.api"/>
        <module name="javax.transaction.api"/>
        <module name="javax.validation.api"/>
        <module name="javax.xml.bind.api"/>
        <module name="org.antlr"/>
        <module name="org.apache.commons.collections"/>
        <module name="org.dom4j"/>
        <module name="org.javassist"/>
        <module name="org.jboss.as.jpa.spi"/>
        <module name="org.jboss.logging"/>
        <module name="org.jboss.vfs"/>
    </dependencies>

Configure  your pom.xml

  • Remove the hibernate reference and add the EclipseLink reference
As we provided the EclipseLink Jar as a Wildlfly module add : <scope>provided</scope>

        <dependency>
            <groupId>org.eclipse.persistence</groupId>
            <artifactId>eclipselink</artifactId>
            <version>2.5.2</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>org.eclipse.persistence</groupId>
            <artifactId>org.eclipse.persistence.jpa.modelgen.processor</artifactId>
            <version>2.5.2</version>
            <scope>provided</scope>
        </dependency>

Create a new Netbeans project

Create new Maven project : Maven -> Web Application 
Add JSF support          : Properties -> Add Framework -> JSF 2.2 
Source Package -> New  -> Entity Class from Database 
Add New File -> Persistence -> Entity Class from Database 
-> Select Datasource:
 Host : ract2-scan.grid12c.example.com 
 Port : 1521/banka
 URL  : jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka

-> Select table : EMP2
Select ; 
x Generate Named Query Annotations for Persistent Fields
x Generate JAXB Annotations
x Create Persistence Unit

Create persistence.xml 
New File -> Persistence -> Create new Persistence Unit 
-> Select Datasource: ..
x Use Java Transaction API


A working persistence.xml sample may look like :

<?xml version="1.0" encoding="UTF-8"?>
<!-- <persistence xmlns="http://java.sun.com/xml/ns/persistence"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://java.sun.com/xml/ns/persistence
http://java.sun.com/xml/ns/persistence/persistence_2_0.xsd"
version="2.0"> -->
<persistence version="2.1" xmlns="http://xmlns.jcp.org/xml/ns/persistence" 
  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" 
  xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence http://xmlns.jcp.org/xml/ns/persistence/persistence_2_1.xsd">
  <persistence-unit name="jpaPU" transaction-type="JTA">
    <provider>org.eclipse.persistence.jpa.PersistenceProvider</provider>
    <jta-data-source>java:/jboss/datasources/myRacDS</jta-data-source>
    <jar-file>MyFirstRACPU.jar</jar-file>
    <class>com.hhu.wfjpa2el.Emp2</class>
    <class>com.hhu.wfjpa2el.Logemp2</class>
    <exclude-unlisted-classes>true</exclude-unlisted-classes>
    <properties>
      <property name="eclipselink.logging.level" value="FINEST"/>
      <property name="eclipselink.cache.shared.default" value="false"/>
    </properties>
  </persistence-unit>
</persistence>
  • JTA is used and the datasoruce name is : java:/jboss/datasources/myRacDS
  • org.eclipse.persistence.jpa.PersistenceProvider is the Persistence Provider
  • The perstistence Unit name is jpaPU [ this is used by our JAVA code ]

JAVA Code to create a thread safe access to the Entity Manager

  •   Persistence.createEntityManagerFactory(“jpaPU“) must match  <persistence-unit name=”jpaPU” transaction-type=”JTA“>
  •  <class>com.hhu.wfjpa2el.Logemp2</class>  must match the  Classes we have  created by using Netbeans menu option : Create Entity Class from Database
  • For the Entity Manger access we use the “ThreadLocal Pattern”
 

 static 
      {
        emf = Persistence.createEntityManagerFactory("jpaPU");
        threadLocal = new ThreadLocal<EntityManager>();        
      }
    
    
    public static EntityManager getEntityManager() 
      {
        EntityManager em = threadLocal.get();

        if (em == null) 
          {
          // setRunTimeInfo(getRunTimeInfo() + Tools.add_hmtl_pre_tag("Creating Entity Manager ! "  ));
            logger.info("Creating Entity Manager Factory ..." );
            em = emf.createEntityManager();
            // set your flush mode here
            threadLocal.set(em);
          }
        return em;
      }
    
    
    public static void closeEntityManager() 
      {
        EntityManager em = threadLocal.get();
        if (em != null) 
          {
            logger.info("Closing Entity Manager" );
            em.close();
            threadLocal.set(null);
           }
     }
    
Note for each request you have to open and close the Entity Manager 
   ..
   em=getEntityManager();
   ..
   closeEntityManager();
   ..

A more Complete Code fragment

public String addEntity()  
      {
        EntityManager em;
        String methodName = "addEntity()";
        short eno= getEmpno();
        cleanall();
        try
          {    
            setRunTimeInfo("Calling "  + methodName + "in progress - ID: " + eno + " - useJoinTransaction : " + isUseJoinTransaction() );          
            Emp2 e =  new Emp2(eno);
            e.setEname("Helmut");
            e.setJob("Progr.");
            e.setSal(new BigDecimal(1000.0));
            setRunTimeInfo("Requesting Entity Manager.. ");
            em=getEntityManager();
            ut.begin();
            em.joinTransaction();
            setRunTimeInfo("Running em.persists() ... ");           
            em.persist(e);
            setRunTimeInfo("Running em.flush() ... ");
            em.flush();
            setRunTimeInfo("Running ut.commit() ... ");
            ut.commit();
            setRunTimeInfo("Closing  Entity Manager.. !");
            setRunTimeInfo("Leaving " + methodName + " without Exceptions !");                   
            }            
          catch ( Throwable t1)
          {            
            jpa_exception(t1, methodName);
          }            
        closeEntityManager();
        setRunTimeInfo("Leaving "  +  methodName + " - Entity manager  closed !\n");
        return "index";
      }

The related Server.log File shoud look like :

2015-05-20 18:38:23,361 INFO  [org.eclipse.persistence] (default task-5) EclipseLink, version: Eclipse Persistence Services - 2.5.2.v20140319-9ad6abd
2015-05-20 18:38:23,496 INFO  [org.eclipse.persistence.connection] (default task-5) connecting(DatabaseLogin(
2015-05-20 18:38:23,497 INFO  [org.eclipse.persistence.connection] (default task-5) Connected: jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka
2015-05-20 18:38:23,497 INFO  [org.eclipse.persistence.connection] (default task-5) connecting(DatabaseLogin(
2015-05-20 18:38:23,497 INFO  [org.eclipse.persistence.connection] (default task-5) Connected: jdbc:oracle:thin:@ract2-scan.grid12c.example.com:1521/banka
2015-05-20 18:38:23,653 INFO  [org.eclipse.persistence.connection] (default task-5) vfs:/usr/local/wildfly-8.2.0.Final/standalone/deployments/t-1.0.war/WEB-INF/classes/_jpaPU login successful

Using ServletContextListener and JNDI to run a clean Web Application shutdown

Key Facts and Overview

  • ServletContextListener runs contextInitialized() during a deployment operation
  • ServletContextListener runs contextDestroyed() during a un-deployment operation
  • This allows to cleanup or initialize certain objects factories, loggers, ..
  • Without a clean shutdown you may encounter following Exception during redeployment of a WEB applications
     12:54:21.020 Object: com.hhu.wfjpa2el.Emp2[ empno=9997 ] is not a known entity type.
     12:54:21.020 java.lang.IllegalArgumentException: Object: com.hhu.wfjpa2el.Emp2[ empno=9997 ] is not a known entity type.
         at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.registerNewObjectForPersist(UnitOfWorkImpl.java:4228)
         at org.eclipse.persistence.internal.jpa.EntityManagerImpl.persist(EntityManagerImpl.java:496)
         at com.hhu.wfjpa2el.JPATestBean.runJPA(JPATestBean.java:137)
         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  • To solve this reboot your Webserver or shutdown() the Entity Manager Factory

JAVA Code

  • JPATestBean() constructor stores/binds a object reference of the current  JPATestBean() reference via JNDI
  • shutdown() is invoked by  ServletContextListener function contextDestroyed() and stops the Entity Manager Factory.
  • ServletContextListener is using JNDI lookup to get the object reference
JPATestBean.java  
public JPATestBean() throws Exception
      {
        ctx = new InitialContext();
        ctx.rebind(jndiName, this);  
        logger.info("Constructor JPATestBean()  called and bound to JNDI !");
      }
 
 static 
      {
        emf = Persistence.createEntityManagerFactory("jpaELPU");
        threadLocal = new ThreadLocal<EntityManager>();       
      }
 public void shutdown()
      {
        logger.info("\nWeb Application shutdown ..." );
        closeEntityManager();
        logger.info("Closing Entitiy Manager Factory ..." );
        emf.close();
        emf=null; 
        System.gc();
        logger.info("Leaving Web Application shutdown" );
      }
...

Implementing ServletContextListener 
  -  contextDestroyed() uses JNDI lookup to read an object reference from our  JPATestBean() instance
  -  contextDestroyed() invokes shutdown methode to run a clean application shutdown

web.xml entry
./src/main/webapp/WEB-INF/web.xml
..
  <listener>
        <listener-class>com.hhu.wfjpa2el.ServletContextListenerImpl</listener-class>
    </listener>


Java Code for ServletContextListener
package com.hhu.wfjpa2el;

import javax.naming.InitialContext;
import javax.naming.NamingException;
import javax.servlet.ServletContextEvent;
import javax.servlet.ServletContextListener;
import org.slf4j.LoggerFactory;

public class ServletContextListenerImpl implements ServletContextListener 
  {
    final static org.slf4j.Logger logger = LoggerFactory.getLogger(ServletContextListenerImpl.class);
    private JPATestBean jtb;    
    private final String jndiName = "java:global/myJPATestBean";
    private InitialContext ctx;
    
    @Override
    public void contextInitialized(ServletContextEvent arg) {
        logger.info("+++ ServletContextListener : contextInitialized - no action \n");
 
    }

    @Override
    public void contextDestroyed(ServletContextEvent arg) 
     {
        System.out.println("+++ ServletContextListener: running contextDestroyed()....");
        try
          {
            ctx = new InitialContext();
            jtb = (JPATestBean)ctx.lookup(jndiName);
            jtb.shutdown();
            logger.info("+++ ServletContextListener:  Leaving contextDestroyed() without Exception\n");
          } catch (NamingException ex)
          {
            //Logger.getLogger(ServletContextListenerImpl.class.getName()).log(Level.SEVERE, null, ex);
            logger.error("+++ Error in contextDestroyed()\n" + ex);
          }
     }
}

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

Remove a Wildfly Transaction from LOG-STORE

Overview

You may need to run these commands under following circumstances:

  • you are running a test system and testing UserTransaction API
  •  you have dropped some objects ( database , table ) and you don’t care about this XA transactions
  • your DBA has manually committed or rolled back a XA transaction  be running : COMMIT FORCE ‘Local_TranID’ or ROLLBACK FORCE  ‘Local_TranID’ via sqlplus
  • In any case be careful when running this commands as this could logically corrupt your production system very easily  !

 

Setup and Commands

List PREPARED transactions: 
[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:682bf87e:55433e74:127

Try to List JNDI resources 
[standalone@localhost:9990 /]  /subsystem=transactions/log-store=log-store/transactions=0\:ffffc0a805c9\:682bf87e\:55433e74\:127:read_resource
{
    "outcome" => "failed",
    "failure-description" => "JBAS014884: No operation named 'read_resource' exists at address [
    (\"subsystem\" => \"transactions\"),
    (\"log-store\" => \"log-store\"),
    (\"transactions\" => \"0:ffffc0a805c9:682bf87e:55433e74:127\")
]",
    "rolled-back" => true
}

Finally delete the transaction and verify transaction status  
[standalone@localhost:9990 /]  /subsystem=transactions/log-store=log-store/transactions=0\:ffffc0a805c9\:682bf87e\:55433e74\:127:delete
{"outcome" => "success"}

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

Reference: