Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar

Sorry i forgot one line, the one which calls the EJB method, see below

Στις Tuesday 02 March 2010 21:22:09 ο/η Heikki Linnakangas έγραψε:
> Achilleas Mantzios wrote:
> > Introduction
> > ========
> > This bug has the potential effect of xactions which under certain condition should rollback, to behave
> > as if autocommit is true.
> > The workaround is to use local-tx-datasource with the standard driver org.postgresql.Driver instead of
> > xa-datasource with org.postgresql.xa.PGXADataSource.
> >
> > The description below is with FreeBSD diablo-1.5 , but its exactly the same with SLES 10 SP1 and 1.5.0_15.
> >
> > configuration
> > ==============
> > server/default/deploy/postgres-xa-ds.xml
> > -------------------------------------------------------------------
> > <datasources>
> > <xa-datasource>
> > <jndi-name>pgsql</jndi-name>
> >
> > <use-java-context>true</use-java-context>
> >
> > <xa-datasource-class>org.postgresql.xa.PGXADataSource</xa-datasource-class>
> > <xa-datasource-property name="ServerName">localhost</xa-datasource-property>
> > <xa-datasource-property name="PortNumber">5432</xa-datasource-property>
> > <xa-datasource-property name="DatabaseName">dynacom</xa-datasource-property>
> >
> > <xa-datasource-property name="User">postgres</xa-datasource-property>
> > <xa-datasource-property name="Password">xxxxx</xa-datasource-property>
> > <xa-datasource-property name="Compatible">8.2</xa-datasource-property>
> >
> > <track-connection-by-tx/>
> > <min-pool-size>1</min-pool-size>
> > <max-pool-size>2</max-pool-size>
> >
> > <metadata>
> > <type-mapping>PostgreSQL 8.0</type-mapping>
> > </metadata>
> > </xa-datasource>
> > </datasources>
> >
> > Description
> > ========
> > Consider the following test case:
> > This code is executed:
> > StatusHome sthome = (StatusHome) ic.lookup("java:comp/env/ejb/Status");
> > Status stat = sthome.create();
(missed line) actual call to the EJB:
Collection warns = stat.getCrewCoursesWarns(14173);

> >
> > "Status" is a SL Session EJB, which is defined to run with @ejb.transaction type = "Required"
> > Whenever the above is executed, i see in pgsql log:
> >
> > postgres [23247] 2010-03-02 16:04:09.377 EET line:8 LOG: execute S_1: BEGIN
> > postgres [23247] 2010-03-02 16:04:09.378 EET line:9 LOG: execute <unnamed>: select ....
> > postgres [23247] 2010-03-02 16:04:09.380 EET line:11 LOG: execute S_2: COMMIT
> >
> > which is correct behaviour. Then the following code (lets name it sql_xact) is executed:
> > sql_xact:
> > try {
> > DataSource ds = (javax.sql.DataSource) ic.lookup("java:comp/env/jdbc/DynacomDB");
> > con = ds.getConnection();
> > con.setAutoCommit(false);
> > st = con.prepareStatement("select now();");
> > rs = st.executeQuery();
> > rs.close();
> > st.close();
> > con.commit();
> > }
> > catch (Exception e) {
> > out.println("<BR>\n");
> > out.println("Error: " + e.getMessage());
> > con.rollback();
> > e.printStackTrace();
> > }
> > finally {
> > if (con != null) con.close();
> > }
> >
> > If the above is executed on the same postgresql backend and immediately after the previous (EJB call) block of code, i see in pgsql log:
> >
> > postgres [23247] 2010-03-02 16:07:24.088 EET line:24 LOG: execute <unnamed>: select now()
> >
> > which means no begin-commit/rollback block. at this point a xaction supposed to rollback, is semi-commited.
> > Now, If however, i execute this block of code:
> >
> > try {
> > DataSource ds = (javax.sql.DataSource) ic.lookup("java:comp/env/jdbc/DynacomDB");
> > con = ds.getConnection();
> > con.setAutoCommit(true);
> >
> > st = con.prepareStatement("select now();");
> > rs = st.executeQuery();
> > rs.close();
> > st.close();
> >
> > }
> > catch (Exception e) {
> > out.println("<BR>\n");
> > out.println("Error: " + e.getMessage());
> > e.printStackTrace();
> > }
> > finally {
> > if (con != null) con.close();
> > }
> >
> > and then sql_xact code again, then the connection gets back to normal, pgsql log looking like:
> > postgres [23247] 2010-03-02 16:11:57.729 EET line:39 LOG: execute S_1: BEGIN
> > postgres [23247] 2010-03-02 16:11:57.729 EET line:40 LOG: execute <unnamed>: select now()
> > postgres [23247] 2010-03-02 16:11:57.730 EET line:41 LOG: execute S_2: COMMIT
>
> > Any thoughts as to where the problem might reside? The jboss camp or the pgsql-jdbc camp?
>
> Hard to tell. Can you make a complete reproducable test case and send
> that over? It's a bit hard to see what exactly is going on without that.
>
> And/or if you could set logLevel property to DEBUG, and send the full
> log produced when you run the test test case with that, that might help.
>

Making a complete ready-to-run reproducible test case is equally hard, it nearly took me almost 1.5 days to identify the problem.
In the first email i failed to properly describe the problem.
So i'll try to:
- describe the problem (see below)
- build a complete test case (i cannot promise that)

The problem appears under the following assumptions:
1) the jboss connection pool is based on org.postgresql.xa.PGXADataSource
2) the problem is demonstrated *on the same* backend, so minimizing <max-pool-size>1</max-pool-size>
will guarantee the problem will show up, otherwise the output becomes more random, (and in my real life case with 50 connections
completely chaotic)
3) an SL Session EJB (lets name it Status) with
<container-transaction >
<method >
<ejb-name>Status</ejb-name>
<method-name>*</method-name>
</method>
<trans-attribute>Required</trans-attribute>
</container-transaction>
4) the following sequence occures:
a) a call to a method (involving some SQL e.g. select) of the EJB above
b) a call to a block similar to

try {
DataSource ds = (javax.sql.DataSource) ic.lookup("java:comp/env/jdbc/DynacomDB");
con = ds.getConnection();
con.setAutoCommit(false);
st = con.prepareStatement("........");
int rc = st.executeUpdate();
st.close();
st = con.prepareStatement("........");
rc = st.executeUpdate();
st.close();
...... other statements....
// if some of those statements throw an Exception
// the rest should be skipped and program control transfered
// to the catch block, where rollback is called
con.commit();
}
catch (Exception e) {
out.println("<BR>\n");
out.println("Error: " + e.getMessage());
con.rollback();
e.printStackTrace();
}
finally {
if (con != null) con.close();
}

However, under the described conditions (right after the call to the EJB) the above session IS NOT initiated with a BEGIN!!,
making it effectively be equivalent as if we had set : con.setAutoCommit(true), which means that in a case of an Exception
all statements in the above block till the Exception occures will be committed.

Now, if on the same connection, someone executes another java code block with con.setAutoCommit(true), then the connection
somehow appears back to normal so that if we execute the previous problematic java block again,
then everything seems fine and the pgsql session is indeed initiated with a BEGIN statement.

i'll try to make a test case, but i think now there is enuf material for anyone to make his own case,
please ask whatever i may have missed, and thank you for your attention.

> --
> Heikki Linnakangas
> EnterpriseDB http://www.enterprisedb.com
>

--
Achilleas Mantzios