Received: from maia.hub.org (unknown [200.46.204.183])
	by mail.postgresql.org (Postfix) with ESMTP id 0EBEE6337DD
	for <pgsql-jdbc-postgresql.org@mail.postgresql.org>;
	Wed,  3 Mar 2010 04:35:30 -0400 (AST)
Received: from mail.postgresql.org ([200.46.204.86])
	by maia.hub.org (mx1.hub.org [200.46.204.183]) (amavisd-maia,
	port 10024) with ESMTP id 69016-01 for
	<pgsql-jdbc-postgresql.org@mail.postgresql.org>;
	Wed,  3 Mar 2010 08:35:19 +0000 (UTC)
X-Greylist: from auto-whitelisted by SQLgrey-1.7.6
Received: from smadev.internal.net (host3.dynacom.ondsl.gr [62.103.35.211])
	by mail.postgresql.org (Postfix) with ESMTP id C2EF663259B
	for <pgsql-jdbc@postgresql.org>; Wed,  3 Mar 2010 04:35:18 -0400 (AST)
Received: from smadev.internal.net (localhost [127.0.0.1])
	by smadev.internal.net (8.14.2/8.14.2) with ESMTP id o238Z5E9036697;
	Wed, 3 Mar 2010 10:35:05 +0200 (EET)
	(envelope-from achill@matrix.gatewaynet.com)
Received: from localhost (localhost [[UNIX: localhost]])
	by smadev.internal.net (8.14.2/8.14.2/Submit) id o238Yi0S036687;
	Wed, 3 Mar 2010 10:34:44 +0200 (EET)
	(envelope-from achill@matrix.gatewaynet.com)
From: Achilleas Mantzios <achill@matrix.gatewaynet.com>
Organization: Dynacom Tankers Mgmt
To: pgsql-jdbc@postgresql.org
Subject: Re: Very Dangerous bug in XA connection pooling and SL EJBs with
	jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
Date: Wed, 3 Mar 2010 10:34:43 +0200
User-Agent: KMail/1.9.7
Cc: Heikki Linnakangas <heikki.linnakangas@enterprisedb.com>,
	jboss-user@lists.jboss.org
References: <201003011731.15724.achill@matrix.gatewaynet.com>
	<201003021629.07368.achill@matrix.gatewaynet.com>
	<4B8D6561.3040902@enterprisedb.com>
In-Reply-To: <4B8D6561.3040902@enterprisedb.com>
MIME-Version: 1.0
Content-Type: text/plain;
  charset="utf-8"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: inline
Message-Id: <201003031034.44077.achill@matrix.gatewaynet.com>
X-Virus-Scanned: Maia Mailguard 1.0.1
X-Spam-Status: No, hits=-0.74 tagged_above=-10 required=5 tests=BAYES_20=-0.74
X-Spam-Level: 
X-Archive-Number: 201003/7
X-Sequence-Number: 20347

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

=CE=A3=CF=84=CE=B9=CF=82 Tuesday 02 March 2010 21:22:09 =CE=BF/=CE=B7 Heikk=
i Linnakangas =CE=AD=CE=B3=CF=81=CE=B1=CF=88=CE=B5:
> Achilleas Mantzios wrote:
> > Introduction
> > =3D=3D=3D=3D=3D=3D=3D=3D
> > This bug has the potential effect of xactions which under certain condi=
tion should rollback, to behave
> > as if autocommit is true.
> > The workaround is to use local-tx-datasource with the standard driver o=
rg.postgresql.Driver instead of=20
> > xa-datasource with org.postgresql.xa.PGXADataSource.
> >=20
> > The description below is with FreeBSD diablo-1.5 , but its exactly the =
same with SLES 10 SP1 and 1.5.0_15.
> >=20
> > configuration
> > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
> > server/default/deploy/postgres-xa-ds.xml
> > -------------------------------------------------------------------
> > <datasources>
> >    <xa-datasource>
> >      <jndi-name>pgsql</jndi-name>
> >=20
> >      <use-java-context>true</use-java-context>
> >=20
> >      <xa-datasource-class>org.postgresql.xa.PGXADataSource</xa-datasour=
ce-class>
> >      <xa-datasource-property name=3D"ServerName">localhost</xa-datasour=
ce-property>
> >      <xa-datasource-property name=3D"PortNumber">5432</xa-datasource-pr=
operty>
> >      <xa-datasource-property name=3D"DatabaseName">dynacom</xa-datasour=
ce-property>
> >=20
> >      <xa-datasource-property name=3D"User">postgres</xa-datasource-prop=
erty>
> >      <xa-datasource-property name=3D"Password">xxxxx</xa-datasource-pro=
perty>
> >      <xa-datasource-property name=3D"Compatible">8.2</xa-datasource-pro=
perty>
> >=20
> >      <track-connection-by-tx/>
> >     <min-pool-size>1</min-pool-size>
> >      <max-pool-size>2</max-pool-size>
> >=20
> >      <metadata>
> >          <type-mapping>PostgreSQL 8.0</type-mapping>
> >      </metadata>
> >    </xa-datasource>
> > </datasources>
> >=20
> > Description
> > =3D=3D=3D=3D=3D=3D=3D=3D
> > Consider the following test case:
> > This code is executed:
> > 	StatusHome sthome =3D (StatusHome) ic.lookup("java:comp/env/ejb/Status=
");
> > 	Status stat =3D sthome.create();
(missed line) actual call to the EJB:
Collection warns =3D stat.getCrewCoursesWarns(14173);

> >=20
> > "Status" is a SL Session EJB, which is defined to run with @ejb.transac=
tion type =3D "Required"
> > Whenever the above is executed, i see in pgsql log:
> >=20
> > 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 <unna=
med>: select ....
> > postgres [23247] 2010-03-02 16:04:09.380 EET line:11 LOG:  execute S_2:=
 COMMIT
> >=20
> > which is correct behaviour. Then the following code (lets name it sql_x=
act) is executed:
> > sql_xact:
> > try {
> > 	DataSource ds =3D (javax.sql.DataSource) ic.lookup("java:comp/env/jdbc=
/DynacomDB");  =20
> > 	con =3D ds.getConnection();
> > 	con.setAutoCommit(false);
> > 	st =3D con.prepareStatement("select now();");
> > 	rs =3D 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 !=3D null) con.close();
> > }
> >=20
> > 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:
> >=20
> > postgres [23247] 2010-03-02 16:07:24.088 EET line:24 LOG:  execute <unn=
amed>: select now()
> >=20
> > which means no begin-commit/rollback block. at this point a xaction sup=
posed to rollback, is semi-commited.
> > Now, If however, i execute this block of code:
> >=20
> > try {
> >     DataSource ds =3D (javax.sql.DataSource) ic.lookup("java:comp/env/j=
dbc/DynacomDB");  =20
> >     con =3D ds.getConnection();
> >     con.setAutoCommit(true);
> >    =20
> >     st =3D con.prepareStatement("select now();");
> > 	rs =3D st.executeQuery();
> > 	rs.close();
> > 	st.close();
> >=20
> > }
> > catch (Exception e) {
> >     out.println("<BR>\n");
> >     out.println("Error: " + e.getMessage());
> >     e.printStackTrace();
> > }
> > finally {
> >     if (con !=3D null) con.close();
> > }
> >=20
> > 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 <unn=
amed>: select now()
> > postgres [23247] 2010-03-02 16:11:57.730 EET line:41 LOG:  execute S_2:=
 COMMIT
>=20
> > Any thoughts as to where the problem might reside? The jboss camp or th=
e pgsql-jdbc camp?
>=20
> 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.
>=20
> 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.
>=20

Making a complete ready-to-run reproducible test case is equally hard, it n=
early 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:
=2D describe the problem (see below)
=2D 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-po=
ol-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=20
<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=20

try {
 	DataSource ds =3D (javax.sql.DataSource) ic.lookup("java:comp/env/jdbc/Dy=
nacomDB");  =20
 	con =3D ds.getConnection();
 	con.setAutoCommit(false);
 	st =3D con.prepareStatement("........");
	int rc =3D st.executeUpdate();
 	st.close();
	st =3D con.prepareStatement("........");
	rc =3D 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 !=3D null) con.close();
 }

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

Now, if on the same connection, someone executes another java code block wi=
th con.setAutoCommit(true), then the connection
somehow appears back to normal so that if we execute the previous problemat=
ic java block again,=20
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 an=
yone to make his own case,
please ask whatever i may have missed, and thank you for your attention.

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



=2D-=20
Achilleas Mantzios