Thread: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Achilleas Mantzios
Date:
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();
"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
seein 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
I dont think that the usage of XA connections are critical for our case, so i can live with local connections (although
iguess
i have a lot of garbage data since the above setup was deployed some 2 years ago.... imagine if i were selling open
sourceto some bank)
Any thoughts as to where the problem might reside? The jboss camp or the pgsql-jdbc camp?
--
Achilleas Mantzios
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Heikki Linnakangas
Date:
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();
>
> "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,
isee 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.
--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Achilleas Mantzios
Date:
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
theproblem.
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
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Heikki Linnakangas
Date:
Achilleas Mantzios wrote: > 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. If you can set logLevel to DEBUG (ie. loglevel=2 in connection string), run the code, and send over the logs, that would help a lot. From that we should see what exactly is the sequence of XA commands the JDBC driver is receiving from JBoss. -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Achilleas Mantzios
Date:
Στις Wednesday 03 March 2010 10:54:53 ο/η Heikki Linnakangas έγραψε:
> Achilleas Mantzios wrote:
> > 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.
>
> If you can set logLevel to DEBUG (ie. loglevel=2 in connection string),
> run the code, and send over the logs, that would help a lot. From that
> we should see what exactly is the sequence of XA commands the JDBC
> driver is receiving from JBoss.
>
As loglevel configuration property to org.postgresql.ds.common.BaseDataSource is not supported in the lastest driver,
i made this patch (i attach it) against postgresql-jdbc-8.4-701.src, also i set in jboss
<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">xxxx</xa-datasource-property>
<xa-datasource-property name="Compatible">8.2</xa-datasource-property>
<xa-datasource-property name="Loglevel">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>
But i dont see anything spectacular comming out of PostgreSQL logs.
in postgresql.conf I have set
client_min_messages = debug5
log_min_messages = debug5
however playing with <xa-datasource-property name="Loglevel"></xa-datasource-property> does not seem to change a thing.
Am i missing something?
> --
> Heikki Linnakangas
> EnterpriseDB http://www.enterprisedb.com
>
--
Achilleas Mantzios
Attachment
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Heikki Linnakangas
Date:
Achilleas Mantzios wrote:
> Στις Wednesday 03 March 2010 10:54:53 ο/η Heikki Linnakangas έγραψε:
>> Achilleas Mantzios wrote:
>>> 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.
>> If you can set logLevel to DEBUG (ie. loglevel=2 in connection string),
>> run the code, and send over the logs, that would help a lot. From that
>> we should see what exactly is the sequence of XA commands the JDBC
>> driver is receiving from JBoss.
>
> As loglevel configuration property to org.postgresql.ds.common.BaseDataSource is not supported in the lastest
driver,
> i made this patch (i attach it) against postgresql-jdbc-8.4-701.src, also i set in jboss
>
> <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">xxxx</xa-datasource-property>
> <xa-datasource-property name="Compatible">8.2</xa-datasource-property>
> <xa-datasource-property name="Loglevel">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>
>
> But i dont see anything spectacular comming out of PostgreSQL logs.
> in postgresql.conf I have set
> client_min_messages = debug5
> log_min_messages = debug5
The extra logs should go somewhere in the client side, in one of the
jboss log files. If you can't find it, you can do something like this in
the application to redirect it to a file:
java.io.Writer output = new
java.io.FileWriter("/tmp/postgresql-jdbc.debug.txt", true);
java.sql.DriverManager.setLogWriter(new
java.io.PrintWriter(output,true));
> however playing with <xa-datasource-property name="Loglevel"></xa-datasource-property> does not seem to change a
thing.
> Am i missing something?
Not sure why that's not working, but here's one way of setting loglevel:
1. Create file "org/postgresql/driverconfig.properties" with line
"loglevel=2" in it:
echo "loglevel=2" > org/postgresql/driverconfig.properties
2. Add file to the driver jar:
jar uvf postgresql.jar org/postgresql/driverconfig.properties
--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Achilleas Mantzios
Date:
Thanx
Here are the logs:
call to the ejb
=========
2010-03-03 12:47:57,177 INFO [STDOUT] 12:47:57.177 (2) XAResource 1291479: starting transaction xid = < 131075, 26,
24,1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 >
2010-03-03 12:47:57,181 INFO [STDOUT] 12:47:57.180 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@dd0f87,maxRows=0, fetchSize=0, flags=1
2010-03-03 12:47:57,184 INFO [STDOUT] 12:47:57.183 (2) FE=> Parse(stmt=S_1,query="BEGIN",oids={})
2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.184 (2) FE=> Bind(stmt=S_1,portal=null)
2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.185 (2) FE=> Execute(portal=null,limit=0)
2010-03-03 12:47:57,186 INFO [STDOUT] 12:47:57.186 (2) FE=> Parse(stmt=null,query="select apptblidval,colname from
statuswhere assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by
apptblidval",oids={1043,23,1043,1043,1043})
2010-03-03 12:47:57,188 INFO [STDOUT] 12:47:57.187 (2) FE=>
Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>)
2010-03-03 12:47:57,189 INFO [STDOUT] 12:47:57.189 (2) FE=> Describe(portal=null)
2010-03-03 12:47:57,190 INFO [STDOUT] 12:47:57.190 (2) FE=> Execute(portal=null,limit=0)
2010-03-03 12:47:57,192 INFO [STDOUT] 12:47:57.192 (2) FE=> Sync
2010-03-03 12:47:57,199 INFO [STDOUT] 12:47:57.199 (2) <=BE ParseComplete [S_1]
2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE BindComplete [null]
2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE CommandStatus(BEGIN)
2010-03-03 12:47:57,201 INFO [STDOUT] 12:47:57.201 (2) <=BE ParseComplete [null]
2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.201 (2) <=BE BindComplete [null]
2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.202 (2) <=BE RowDescription(2)
2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE CommandStatus(SELECT)
2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE ReadyForQuery(T)
2010-03-03 12:47:57,206 INFO [STDOUT] 12:47:57.204 (2) XAResource 1291479: ending transaction xid = < 131075, 26, 24,
1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34>
2010-03-03 12:47:57,211 INFO [STDOUT] 12:47:57.211 (2) XAResource 1291479: committing xid = < 131075, 26, 24,
1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34> (one phase)
2010-03-03 12:47:57,217 INFO [STDOUT] 12:47:57.217 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1a9b034,maxRows=0, fetchSize=0, flags=22
2010-03-03 12:47:57,225 INFO [STDOUT] 12:47:57.225 (2) FE=> Parse(stmt=S_2,query="COMMIT",oids={})
2010-03-03 12:47:57,227 INFO [STDOUT] 12:47:57.227 (2) FE=> Bind(stmt=S_2,portal=null)
2010-03-03 12:47:57,229 INFO [STDOUT] 12:47:57.228 (2) FE=> Execute(portal=null,limit=1)
2010-03-03 12:47:57,237 INFO [STDOUT] 12:47:57.237 (2) FE=> Sync
2010-03-03 12:47:57,246 INFO [STDOUT] 12:47:57.246 (2) <=BE ParseComplete [S_2]
2010-03-03 12:47:57,248 INFO [STDOUT] 12:47:57.248 (2) <=BE BindComplete [null]
2010-03-03 12:47:57,250 INFO [STDOUT] 12:47:57.250 (2) <=BE CommandStatus(COMMIT)
2010-03-03 12:47:57,251 INFO [STDOUT] 12:47:57.251 (2) <=BE ReadyForQuery(I)
call to the java block - the one with con.setAutocommit(false) - (as we see below its fine the very first time)
=================================================================
2010-03-03 12:49:31,892 INFO [STDOUT] 12:49:31.892 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@19331eb,maxRows=0, fetchSize=0, flags=1
2010-03-03 12:49:31,893 INFO [STDOUT] 12:49:31.893 (2) FE=> Bind(stmt=S_1,portal=null)
2010-03-03 12:49:31,895 INFO [STDOUT] 12:49:31.895 (2) FE=> Execute(portal=null,limit=0)
2010-03-03 12:49:31,896 INFO [STDOUT] 12:49:31.895 (2) FE=> Parse(stmt=null,query="select now()",oids={})
2010-03-03 12:49:31,897 INFO [STDOUT] 12:49:31.897 (2) FE=> Bind(stmt=null,portal=null)
2010-03-03 12:49:31,898 INFO [STDOUT] 12:49:31.898 (2) FE=> Describe(portal=null)
2010-03-03 12:49:31,899 INFO [STDOUT] 12:49:31.899 (2) FE=> Execute(portal=null,limit=0)
2010-03-03 12:49:31,901 INFO [STDOUT] 12:49:31.901 (2) FE=> Sync
2010-03-03 12:49:31,903 INFO [STDOUT] 12:49:31.902 (2) <=BE BindComplete [null]
2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE CommandStatus(BEGIN)
2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE ParseComplete [null]
2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE BindComplete [null]
2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE RowDescription(1)
2010-03-03 12:49:31,906 INFO [STDOUT] 12:49:31.906 (2) <=BE DataRow
2010-03-03 12:49:31,907 INFO [STDOUT] 12:49:31.907 (2) <=BE CommandStatus(SELECT)
2010-03-03 12:49:31,908 INFO [STDOUT] 12:49:31.908 (2) <=BE ReadyForQuery(T)
2010-03-03 12:49:31,909 INFO [STDOUT] 12:49:31.909 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1d7ce63,maxRows=0, fetchSize=0, flags=22
2010-03-03 12:49:31,910 INFO [STDOUT] 12:49:31.910 (2) FE=> Bind(stmt=S_2,portal=null)
2010-03-03 12:49:31,911 INFO [STDOUT] 12:49:31.911 (2) FE=> Execute(portal=null,limit=1)
2010-03-03 12:49:31,913 INFO [STDOUT] 12:49:31.912 (2) FE=> Sync
2010-03-03 12:49:31,915 INFO [STDOUT] 12:49:31.915 (2) <=BE BindComplete [null]
2010-03-03 12:49:31,916 INFO [STDOUT] 12:49:31.916 (2) <=BE CommandStatus(COMMIT)
2010-03-03 12:49:31,917 INFO [STDOUT] 12:49:31.917 (2) <=BE ReadyForQuery(I)
call to the ejb (again - 2nd time)
====================
2010-03-03 12:50:24,246 INFO [STDOUT] 12:50:24.245 (2) XAResource 1291479: starting transaction xid = < 131075, 26,
24,1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e >
2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.247 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@a06e8d,maxRows=0, fetchSize=0, flags=1
2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.248 (2) FE=> Bind(stmt=S_1,portal=null)
2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Execute(portal=null,limit=0)
2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Parse(stmt=null,query="select apptblidval,colname from
statuswhere assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by
apptblidval",oids={1043,23,1043,1043,1043})
2010-03-03 12:50:24,250 INFO [STDOUT] 12:50:24.250 (2) FE=>
Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>)
2010-03-03 12:50:24,251 INFO [STDOUT] 12:50:24.251 (2) FE=> Describe(portal=null)
2010-03-03 12:50:24,252 INFO [STDOUT] 12:50:24.252 (2) FE=> Execute(portal=null,limit=0)
2010-03-03 12:50:24,253 INFO [STDOUT] 12:50:24.252 (2) FE=> Sync
2010-03-03 12:50:24,255 INFO [STDOUT] 12:50:24.255 (2) <=BE BindComplete [null]
2010-03-03 12:50:24,256 INFO [STDOUT] 12:50:24.256 (2) <=BE CommandStatus(BEGIN)
2010-03-03 12:50:24,257 INFO [STDOUT] 12:50:24.257 (2) <=BE ParseComplete [null]
2010-03-03 12:50:24,258 INFO [STDOUT] 12:50:24.258 (2) <=BE BindComplete [null]
2010-03-03 12:50:24,260 INFO [STDOUT] 12:50:24.260 (2) <=BE RowDescription(2)
2010-03-03 12:50:24,261 INFO [STDOUT] 12:50:24.261 (2) <=BE CommandStatus(SELECT)
2010-03-03 12:50:24,262 INFO [STDOUT] 12:50:24.262 (2) <=BE ReadyForQuery(T)
2010-03-03 12:50:24,263 INFO [STDOUT] 12:50:24.262 (2) XAResource 1291479: ending transaction xid = < 131075, 26, 24,
1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e>
2010-03-03 12:50:24,264 INFO [STDOUT] 12:50:24.263 (2) XAResource 1291479: committing xid = < 131075, 26, 24,
1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e> (one phase)
2010-03-03 12:50:24,265 INFO [STDOUT] 12:50:24.265 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1217fef,maxRows=0, fetchSize=0, flags=22
2010-03-03 12:50:24,266 INFO [STDOUT] 12:50:24.266 (2) FE=> Bind(stmt=S_2,portal=null)
2010-03-03 12:50:24,267 INFO [STDOUT] 12:50:24.267 (2) FE=> Execute(portal=null,limit=1)
2010-03-03 12:50:24,269 INFO [STDOUT] 12:50:24.269 (2) FE=> Sync
2010-03-03 12:50:24,272 INFO [STDOUT] 12:50:24.272 (2) <=BE BindComplete [null]
2010-03-03 12:50:24,273 INFO [STDOUT] 12:50:24.273 (2) <=BE CommandStatus(COMMIT)
2010-03-03 12:50:24,274 INFO [STDOUT] 12:50:24.274 (2) <=BE ReadyForQuery(I)
call to the java block - the one with con.setAutocommit(false) - again - 2nd time - this time we have a problem
=================================================================
2010-03-03 12:51:30,426 INFO [STDOUT] 12:51:30.426 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@13b64eb,maxRows=0, fetchSize=0, flags=17
2010-03-03 12:51:30,427 INFO [STDOUT] 12:51:30.427 (2) FE=> Parse(stmt=null,query="select now()",oids={})
2010-03-03 12:51:30,428 INFO [STDOUT] 12:51:30.428 (2) FE=> Bind(stmt=null,portal=null)
2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Describe(portal=null)
2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Execute(portal=null,limit=0)
2010-03-03 12:51:30,430 INFO [STDOUT] 12:51:30.430 (2) FE=> Sync
2010-03-03 12:51:30,433 INFO [STDOUT] 12:51:30.433 (2) <=BE ParseComplete [null]
2010-03-03 12:51:30,434 INFO [STDOUT] 12:51:30.434 (2) <=BE BindComplete [null]
2010-03-03 12:51:30,435 INFO [STDOUT] 12:51:30.435 (2) <=BE RowDescription(1)
2010-03-03 12:51:30,436 INFO [STDOUT] 12:51:30.436 (2) <=BE DataRow
2010-03-03 12:51:30,437 INFO [STDOUT] 12:51:30.437 (2) <=BE CommandStatus(SELECT)
2010-03-03 12:51:30,440 INFO [STDOUT] 12:51:30.440 (2) <=BE ReadyForQuery(I)
call to a java block with con.setAutocommit(true)
==============================
2010-03-03 12:55:42,028 INFO [STDOUT] 12:55:42.028 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@18526aa,maxRows=0, fetchSize=0, flags=17
2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.028 (2) FE=> Parse(stmt=null,query="select now()",oids={})
2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.029 (2) FE=> Bind(stmt=null,portal=null)
2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Describe(portal=null)
2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Execute(portal=null,limit=0)
2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Sync
2010-03-03 12:55:42,032 INFO [STDOUT] 12:55:42.032 (2) <=BE ParseComplete [null]
2010-03-03 12:55:42,033 INFO [STDOUT] 12:55:42.033 (2) <=BE BindComplete [null]
2010-03-03 12:55:42,034 INFO [STDOUT] 12:55:42.034 (2) <=BE RowDescription(1)
2010-03-03 12:55:42,035 INFO [STDOUT] 12:55:42.035 (2) <=BE DataRow
2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.035 (2) <=BE CommandStatus(SELECT)
2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.036 (2) <=BE ReadyForQuery(I)
call to the java block - the one with con.setAutocommit(false) - again - 3rd time - this time its ok again
==============================================================
2010-03-03 12:56:51,374 INFO [STDOUT] 12:56:51.374 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@14a5594,maxRows=0, fetchSize=0, flags=1
2010-03-03 12:56:51,378 INFO [STDOUT] 12:56:51.378 (2) FE=> Bind(stmt=S_1,portal=null)
2010-03-03 12:56:51,380 INFO [STDOUT] 12:56:51.380 (2) FE=> Execute(portal=null,limit=0)
2010-03-03 12:56:51,385 INFO [STDOUT] 12:56:51.385 (2) FE=> Parse(stmt=null,query="select now()",oids={})
2010-03-03 12:56:51,387 INFO [STDOUT] 12:56:51.387 (2) FE=> Bind(stmt=null,portal=null)
2010-03-03 12:56:51,388 INFO [STDOUT] 12:56:51.388 (2) FE=> Describe(portal=null)
2010-03-03 12:56:51,390 INFO [STDOUT] 12:56:51.390 (2) FE=> Execute(portal=null,limit=0)
2010-03-03 12:56:51,391 INFO [STDOUT] 12:56:51.391 (2) FE=> Sync
2010-03-03 12:56:51,393 INFO [STDOUT] 12:56:51.393 (2) <=BE BindComplete [null]
2010-03-03 12:56:51,395 INFO [STDOUT] 12:56:51.395 (2) <=BE CommandStatus(BEGIN)
2010-03-03 12:56:51,397 INFO [STDOUT] 12:56:51.397 (2) <=BE ParseComplete [null]
2010-03-03 12:56:51,398 INFO [STDOUT] 12:56:51.398 (2) <=BE BindComplete [null]
2010-03-03 12:56:51,399 INFO [STDOUT] 12:56:51.399 (2) <=BE RowDescription(1)
2010-03-03 12:56:51,400 INFO [STDOUT] 12:56:51.400 (2) <=BE DataRow
2010-03-03 12:56:51,402 INFO [STDOUT] 12:56:51.402 (2) <=BE CommandStatus(SELECT)
2010-03-03 12:56:51,404 INFO [STDOUT] 12:56:51.404 (2) <=BE ReadyForQuery(T)
2010-03-03 12:56:51,406 INFO [STDOUT] 12:56:51.406 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@13d3f62,maxRows=0, fetchSize=0, flags=22
2010-03-03 12:56:51,409 INFO [STDOUT] 12:56:51.409 (2) FE=> Bind(stmt=S_2,portal=null)
2010-03-03 12:56:51,411 INFO [STDOUT] 12:56:51.411 (2) FE=> Execute(portal=null,limit=1)
2010-03-03 12:56:51,413 INFO [STDOUT] 12:56:51.413 (2) FE=> Sync
2010-03-03 12:56:51,417 INFO [STDOUT] 12:56:51.417 (2) <=BE BindComplete [null]
2010-03-03 12:56:51,419 INFO [STDOUT] 12:56:51.418 (2) <=BE CommandStatus(COMMIT)
2010-03-03 12:56:51,421 INFO [STDOUT] 12:56:51.421 (2) <=BE ReadyForQuery(I)
Στις Wednesday 03 March 2010 12:30:37 ο/η Heikki Linnakangas έγραψε:
> Achilleas Mantzios wrote:
> > Στις Wednesday 03 March 2010 10:54:53 ο/η Heikki Linnakangas έγραψε:
> >> Achilleas Mantzios wrote:
> >>> 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.
> >> If you can set logLevel to DEBUG (ie. loglevel=2 in connection string),
> >> run the code, and send over the logs, that would help a lot. From that
> >> we should see what exactly is the sequence of XA commands the JDBC
> >> driver is receiving from JBoss.
> >
> > As loglevel configuration property to org.postgresql.ds.common.BaseDataSource is not supported in the lastest
driver,
> > i made this patch (i attach it) against postgresql-jdbc-8.4-701.src, also i set in jboss
> >
> > <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">xxxx</xa-datasource-property>
> > <xa-datasource-property name="Compatible">8.2</xa-datasource-property>
> > <xa-datasource-property name="Loglevel">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>
> >
> > But i dont see anything spectacular comming out of PostgreSQL logs.
> > in postgresql.conf I have set
> > client_min_messages = debug5
> > log_min_messages = debug5
>
> The extra logs should go somewhere in the client side, in one of the
> jboss log files. If you can't find it, you can do something like this in
> the application to redirect it to a file:
>
> java.io.Writer output = new
> java.io.FileWriter("/tmp/postgresql-jdbc.debug.txt", true);
> java.sql.DriverManager.setLogWriter(new
> java.io.PrintWriter(output,true));
>
>
> > however playing with <xa-datasource-property name="Loglevel"></xa-datasource-property> does not seem to change a
thing.
> > Am i missing something?
>
> Not sure why that's not working, but here's one way of setting loglevel:
>
> 1. Create file "org/postgresql/driverconfig.properties" with line
> "loglevel=2" in it:
> echo "loglevel=2" > org/postgresql/driverconfig.properties
> 2. Add file to the driver jar:
> jar uvf postgresql.jar org/postgresql/driverconfig.properties
>
> --
> Heikki Linnakangas
> EnterpriseDB http://www.enterprisedb.com
>
--
Achilleas Mantzios
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Heikki Linnakangas
Date:
Thanks!
I tried to reproduce that with the attached test program. It's doing
essentially the same thing you did, right? The program works fine here,
producing a log identical to what you sent, except that I'm not seeing
the incorrect behavior you're seeing; the INSERT in the 2nd java block
is wrapped with BEGIN/COMMIT just like the 1st one.
I don't understand why we're seeing different behavior with what should
be the same sequence of calls as far as the driver is concerned. Can you
try the attached patch, rerun the test case, and send over the logs
again? The patch adds some logging to see all the setAutoCommit() and
commit/rollback calls, maybe that sheds some light on this.
BTW, you are using a recent version of the driver, right? There was some
fixes to setAutoCommit() and XA interactions a few years ago.
Achilleas Mantzios wrote:
> Thanx
> Here are the logs:
>
> call to the ejb
> =========
> 2010-03-03 12:47:57,177 INFO [STDOUT] 12:47:57.177 (2) XAResource 1291479: starting transaction xid = < 131075, 26,
24,1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 >
> 2010-03-03 12:47:57,181 INFO [STDOUT] 12:47:57.180 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@dd0f87,maxRows=0, fetchSize=0, flags=1
> 2010-03-03 12:47:57,184 INFO [STDOUT] 12:47:57.183 (2) FE=> Parse(stmt=S_1,query="BEGIN",oids={})
> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.184 (2) FE=> Bind(stmt=S_1,portal=null)
> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.185 (2) FE=> Execute(portal=null,limit=0)
> 2010-03-03 12:47:57,186 INFO [STDOUT] 12:47:57.186 (2) FE=> Parse(stmt=null,query="select apptblidval,colname from
statuswhere assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by
apptblidval",oids={1043,23,1043,1043,1043})
> 2010-03-03 12:47:57,188 INFO [STDOUT] 12:47:57.187 (2) FE=>
Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>)
> 2010-03-03 12:47:57,189 INFO [STDOUT] 12:47:57.189 (2) FE=> Describe(portal=null)
> 2010-03-03 12:47:57,190 INFO [STDOUT] 12:47:57.190 (2) FE=> Execute(portal=null,limit=0)
> 2010-03-03 12:47:57,192 INFO [STDOUT] 12:47:57.192 (2) FE=> Sync
> 2010-03-03 12:47:57,199 INFO [STDOUT] 12:47:57.199 (2) <=BE ParseComplete [S_1]
> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE BindComplete [null]
> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE CommandStatus(BEGIN)
> 2010-03-03 12:47:57,201 INFO [STDOUT] 12:47:57.201 (2) <=BE ParseComplete [null]
> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.201 (2) <=BE BindComplete [null]
> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.202 (2) <=BE RowDescription(2)
> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE CommandStatus(SELECT)
> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE ReadyForQuery(T)
> 2010-03-03 12:47:57,206 INFO [STDOUT] 12:47:57.204 (2) XAResource 1291479: ending transaction xid = < 131075, 26,
24,1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 >
> 2010-03-03 12:47:57,211 INFO [STDOUT] 12:47:57.211 (2) XAResource 1291479: committing xid = < 131075, 26, 24,
1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34> (one phase)
> 2010-03-03 12:47:57,217 INFO [STDOUT] 12:47:57.217 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1a9b034,maxRows=0, fetchSize=0, flags=22
> 2010-03-03 12:47:57,225 INFO [STDOUT] 12:47:57.225 (2) FE=> Parse(stmt=S_2,query="COMMIT",oids={})
> 2010-03-03 12:47:57,227 INFO [STDOUT] 12:47:57.227 (2) FE=> Bind(stmt=S_2,portal=null)
> 2010-03-03 12:47:57,229 INFO [STDOUT] 12:47:57.228 (2) FE=> Execute(portal=null,limit=1)
> 2010-03-03 12:47:57,237 INFO [STDOUT] 12:47:57.237 (2) FE=> Sync
> 2010-03-03 12:47:57,246 INFO [STDOUT] 12:47:57.246 (2) <=BE ParseComplete [S_2]
> 2010-03-03 12:47:57,248 INFO [STDOUT] 12:47:57.248 (2) <=BE BindComplete [null]
> 2010-03-03 12:47:57,250 INFO [STDOUT] 12:47:57.250 (2) <=BE CommandStatus(COMMIT)
> 2010-03-03 12:47:57,251 INFO [STDOUT] 12:47:57.251 (2) <=BE ReadyForQuery(I)
>
>
> call to the java block - the one with con.setAutocommit(false) - (as we see below its fine the very first time)
> =================================================================
> 2010-03-03 12:49:31,892 INFO [STDOUT] 12:49:31.892 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@19331eb,maxRows=0, fetchSize=0, flags=1
> 2010-03-03 12:49:31,893 INFO [STDOUT] 12:49:31.893 (2) FE=> Bind(stmt=S_1,portal=null)
> 2010-03-03 12:49:31,895 INFO [STDOUT] 12:49:31.895 (2) FE=> Execute(portal=null,limit=0)
> 2010-03-03 12:49:31,896 INFO [STDOUT] 12:49:31.895 (2) FE=> Parse(stmt=null,query="select now()",oids={})
> 2010-03-03 12:49:31,897 INFO [STDOUT] 12:49:31.897 (2) FE=> Bind(stmt=null,portal=null)
> 2010-03-03 12:49:31,898 INFO [STDOUT] 12:49:31.898 (2) FE=> Describe(portal=null)
> 2010-03-03 12:49:31,899 INFO [STDOUT] 12:49:31.899 (2) FE=> Execute(portal=null,limit=0)
> 2010-03-03 12:49:31,901 INFO [STDOUT] 12:49:31.901 (2) FE=> Sync
> 2010-03-03 12:49:31,903 INFO [STDOUT] 12:49:31.902 (2) <=BE BindComplete [null]
> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE CommandStatus(BEGIN)
> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE ParseComplete [null]
> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE BindComplete [null]
> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE RowDescription(1)
> 2010-03-03 12:49:31,906 INFO [STDOUT] 12:49:31.906 (2) <=BE DataRow
> 2010-03-03 12:49:31,907 INFO [STDOUT] 12:49:31.907 (2) <=BE CommandStatus(SELECT)
> 2010-03-03 12:49:31,908 INFO [STDOUT] 12:49:31.908 (2) <=BE ReadyForQuery(T)
> 2010-03-03 12:49:31,909 INFO [STDOUT] 12:49:31.909 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1d7ce63,maxRows=0, fetchSize=0, flags=22
> 2010-03-03 12:49:31,910 INFO [STDOUT] 12:49:31.910 (2) FE=> Bind(stmt=S_2,portal=null)
> 2010-03-03 12:49:31,911 INFO [STDOUT] 12:49:31.911 (2) FE=> Execute(portal=null,limit=1)
> 2010-03-03 12:49:31,913 INFO [STDOUT] 12:49:31.912 (2) FE=> Sync
> 2010-03-03 12:49:31,915 INFO [STDOUT] 12:49:31.915 (2) <=BE BindComplete [null]
> 2010-03-03 12:49:31,916 INFO [STDOUT] 12:49:31.916 (2) <=BE CommandStatus(COMMIT)
> 2010-03-03 12:49:31,917 INFO [STDOUT] 12:49:31.917 (2) <=BE ReadyForQuery(I)
>
> call to the ejb (again - 2nd time)
> ====================
> 2010-03-03 12:50:24,246 INFO [STDOUT] 12:50:24.245 (2) XAResource 1291479: starting transaction xid = < 131075, 26,
24,1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e >
> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.247 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@a06e8d,maxRows=0, fetchSize=0, flags=1
> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.248 (2) FE=> Bind(stmt=S_1,portal=null)
> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Execute(portal=null,limit=0)
> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Parse(stmt=null,query="select apptblidval,colname from
statuswhere assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by
apptblidval",oids={1043,23,1043,1043,1043})
> 2010-03-03 12:50:24,250 INFO [STDOUT] 12:50:24.250 (2) FE=>
Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>)
> 2010-03-03 12:50:24,251 INFO [STDOUT] 12:50:24.251 (2) FE=> Describe(portal=null)
> 2010-03-03 12:50:24,252 INFO [STDOUT] 12:50:24.252 (2) FE=> Execute(portal=null,limit=0)
> 2010-03-03 12:50:24,253 INFO [STDOUT] 12:50:24.252 (2) FE=> Sync
> 2010-03-03 12:50:24,255 INFO [STDOUT] 12:50:24.255 (2) <=BE BindComplete [null]
> 2010-03-03 12:50:24,256 INFO [STDOUT] 12:50:24.256 (2) <=BE CommandStatus(BEGIN)
> 2010-03-03 12:50:24,257 INFO [STDOUT] 12:50:24.257 (2) <=BE ParseComplete [null]
> 2010-03-03 12:50:24,258 INFO [STDOUT] 12:50:24.258 (2) <=BE BindComplete [null]
> 2010-03-03 12:50:24,260 INFO [STDOUT] 12:50:24.260 (2) <=BE RowDescription(2)
> 2010-03-03 12:50:24,261 INFO [STDOUT] 12:50:24.261 (2) <=BE CommandStatus(SELECT)
> 2010-03-03 12:50:24,262 INFO [STDOUT] 12:50:24.262 (2) <=BE ReadyForQuery(T)
> 2010-03-03 12:50:24,263 INFO [STDOUT] 12:50:24.262 (2) XAResource 1291479: ending transaction xid = < 131075, 26,
24,1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e >
> 2010-03-03 12:50:24,264 INFO [STDOUT] 12:50:24.263 (2) XAResource 1291479: committing xid = < 131075, 26, 24,
1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e> (one phase)
> 2010-03-03 12:50:24,265 INFO [STDOUT] 12:50:24.265 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1217fef,maxRows=0, fetchSize=0, flags=22
> 2010-03-03 12:50:24,266 INFO [STDOUT] 12:50:24.266 (2) FE=> Bind(stmt=S_2,portal=null)
> 2010-03-03 12:50:24,267 INFO [STDOUT] 12:50:24.267 (2) FE=> Execute(portal=null,limit=1)
> 2010-03-03 12:50:24,269 INFO [STDOUT] 12:50:24.269 (2) FE=> Sync
> 2010-03-03 12:50:24,272 INFO [STDOUT] 12:50:24.272 (2) <=BE BindComplete [null]
> 2010-03-03 12:50:24,273 INFO [STDOUT] 12:50:24.273 (2) <=BE CommandStatus(COMMIT)
> 2010-03-03 12:50:24,274 INFO [STDOUT] 12:50:24.274 (2) <=BE ReadyForQuery(I)
>
> call to the java block - the one with con.setAutocommit(false) - again - 2nd time - this time we have a problem
> =================================================================
> 2010-03-03 12:51:30,426 INFO [STDOUT] 12:51:30.426 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@13b64eb,maxRows=0, fetchSize=0, flags=17
> 2010-03-03 12:51:30,427 INFO [STDOUT] 12:51:30.427 (2) FE=> Parse(stmt=null,query="select now()",oids={})
> 2010-03-03 12:51:30,428 INFO [STDOUT] 12:51:30.428 (2) FE=> Bind(stmt=null,portal=null)
> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Describe(portal=null)
> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Execute(portal=null,limit=0)
> 2010-03-03 12:51:30,430 INFO [STDOUT] 12:51:30.430 (2) FE=> Sync
> 2010-03-03 12:51:30,433 INFO [STDOUT] 12:51:30.433 (2) <=BE ParseComplete [null]
> 2010-03-03 12:51:30,434 INFO [STDOUT] 12:51:30.434 (2) <=BE BindComplete [null]
> 2010-03-03 12:51:30,435 INFO [STDOUT] 12:51:30.435 (2) <=BE RowDescription(1)
> 2010-03-03 12:51:30,436 INFO [STDOUT] 12:51:30.436 (2) <=BE DataRow
> 2010-03-03 12:51:30,437 INFO [STDOUT] 12:51:30.437 (2) <=BE CommandStatus(SELECT)
> 2010-03-03 12:51:30,440 INFO [STDOUT] 12:51:30.440 (2) <=BE ReadyForQuery(I)
>
> call to a java block with con.setAutocommit(true)
> ==============================
> 2010-03-03 12:55:42,028 INFO [STDOUT] 12:55:42.028 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@18526aa,maxRows=0, fetchSize=0, flags=17
> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.028 (2) FE=> Parse(stmt=null,query="select now()",oids={})
> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.029 (2) FE=> Bind(stmt=null,portal=null)
> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Describe(portal=null)
> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Execute(portal=null,limit=0)
> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Sync
> 2010-03-03 12:55:42,032 INFO [STDOUT] 12:55:42.032 (2) <=BE ParseComplete [null]
> 2010-03-03 12:55:42,033 INFO [STDOUT] 12:55:42.033 (2) <=BE BindComplete [null]
> 2010-03-03 12:55:42,034 INFO [STDOUT] 12:55:42.034 (2) <=BE RowDescription(1)
> 2010-03-03 12:55:42,035 INFO [STDOUT] 12:55:42.035 (2) <=BE DataRow
> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.035 (2) <=BE CommandStatus(SELECT)
> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.036 (2) <=BE ReadyForQuery(I)
>
> call to the java block - the one with con.setAutocommit(false) - again - 3rd time - this time its ok again
> ==============================================================
> 2010-03-03 12:56:51,374 INFO [STDOUT] 12:56:51.374 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@14a5594,maxRows=0, fetchSize=0, flags=1
> 2010-03-03 12:56:51,378 INFO [STDOUT] 12:56:51.378 (2) FE=> Bind(stmt=S_1,portal=null)
> 2010-03-03 12:56:51,380 INFO [STDOUT] 12:56:51.380 (2) FE=> Execute(portal=null,limit=0)
> 2010-03-03 12:56:51,385 INFO [STDOUT] 12:56:51.385 (2) FE=> Parse(stmt=null,query="select now()",oids={})
> 2010-03-03 12:56:51,387 INFO [STDOUT] 12:56:51.387 (2) FE=> Bind(stmt=null,portal=null)
> 2010-03-03 12:56:51,388 INFO [STDOUT] 12:56:51.388 (2) FE=> Describe(portal=null)
> 2010-03-03 12:56:51,390 INFO [STDOUT] 12:56:51.390 (2) FE=> Execute(portal=null,limit=0)
> 2010-03-03 12:56:51,391 INFO [STDOUT] 12:56:51.391 (2) FE=> Sync
> 2010-03-03 12:56:51,393 INFO [STDOUT] 12:56:51.393 (2) <=BE BindComplete [null]
> 2010-03-03 12:56:51,395 INFO [STDOUT] 12:56:51.395 (2) <=BE CommandStatus(BEGIN)
> 2010-03-03 12:56:51,397 INFO [STDOUT] 12:56:51.397 (2) <=BE ParseComplete [null]
> 2010-03-03 12:56:51,398 INFO [STDOUT] 12:56:51.398 (2) <=BE BindComplete [null]
> 2010-03-03 12:56:51,399 INFO [STDOUT] 12:56:51.399 (2) <=BE RowDescription(1)
> 2010-03-03 12:56:51,400 INFO [STDOUT] 12:56:51.400 (2) <=BE DataRow
> 2010-03-03 12:56:51,402 INFO [STDOUT] 12:56:51.402 (2) <=BE CommandStatus(SELECT)
> 2010-03-03 12:56:51,404 INFO [STDOUT] 12:56:51.404 (2) <=BE ReadyForQuery(T)
> 2010-03-03 12:56:51,406 INFO [STDOUT] 12:56:51.406 (2) simple execute,
handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@13d3f62,maxRows=0, fetchSize=0, flags=22
> 2010-03-03 12:56:51,409 INFO [STDOUT] 12:56:51.409 (2) FE=> Bind(stmt=S_2,portal=null)
> 2010-03-03 12:56:51,411 INFO [STDOUT] 12:56:51.411 (2) FE=> Execute(portal=null,limit=1)
> 2010-03-03 12:56:51,413 INFO [STDOUT] 12:56:51.413 (2) FE=> Sync
> 2010-03-03 12:56:51,417 INFO [STDOUT] 12:56:51.417 (2) <=BE BindComplete [null]
> 2010-03-03 12:56:51,419 INFO [STDOUT] 12:56:51.418 (2) <=BE CommandStatus(COMMIT)
> 2010-03-03 12:56:51,421 INFO [STDOUT] 12:56:51.421 (2) <=BE ReadyForQuery(I)
>
> Στις Wednesday 03 March 2010 12:30:37 ο/η Heikki Linnakangas έγραψε:
>> Achilleas Mantzios wrote:
>>> Στις Wednesday 03 March 2010 10:54:53 ο/η Heikki Linnakangas έγραψε:
>>>> Achilleas Mantzios wrote:
>>>>> 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.
>>>> If you can set logLevel to DEBUG (ie. loglevel=2 in connection string),
>>>> run the code, and send over the logs, that would help a lot. From that
>>>> we should see what exactly is the sequence of XA commands the JDBC
>>>> driver is receiving from JBoss.
>>> As loglevel configuration property to org.postgresql.ds.common.BaseDataSource is not supported in the lastest
driver,
>>> i made this patch (i attach it) against postgresql-jdbc-8.4-701.src, also i set in jboss
>>>
>>> <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">xxxx</xa-datasource-property>
>>> <xa-datasource-property name="Compatible">8.2</xa-datasource-property>
>>> <xa-datasource-property name="Loglevel">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>
>>>
>>> But i dont see anything spectacular comming out of PostgreSQL logs.
>>> in postgresql.conf I have set
>>> client_min_messages = debug5
>>> log_min_messages = debug5
>> The extra logs should go somewhere in the client side, in one of the
>> jboss log files. If you can't find it, you can do something like this in
>> the application to redirect it to a file:
>>
>> java.io.Writer output = new
>> java.io.FileWriter("/tmp/postgresql-jdbc.debug.txt", true);
>> java.sql.DriverManager.setLogWriter(new
>> java.io.PrintWriter(output,true));
>>
>>
>>> however playing with <xa-datasource-property name="Loglevel"></xa-datasource-property> does not seem to change a
thing.
>>> Am i missing something?
>> Not sure why that's not working, but here's one way of setting loglevel:
>>
>> 1. Create file "org/postgresql/driverconfig.properties" with line
>> "loglevel=2" in it:
>> echo "loglevel=2" > org/postgresql/driverconfig.properties
>> 2. Add file to the driver jar:
>> jar uvf postgresql.jar org/postgresql/driverconfig.properties
>>
>> --
>> Heikki Linnakangas
>> EnterpriseDB http://www.enterprisedb.com
>>
>
>
>
--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com
import java.sql.Connection;
import java.sql.Statement;
import java.util.Arrays;
import java.util.Random;
import javax.sql.XAConnection;
import javax.transaction.xa.XAResource;
import javax.transaction.xa.Xid;
import org.postgresql.xa.PGXAConnection;
import org.postgresql.xa.PGXADataSource;
public class XATest3 {
/**
* @param args
*/
public static void main(String[] args) {
PGXADataSource dataSource = new PGXADataSource();
dataSource.setDatabaseName("postgres");
dataSource.setUser("postgres");
dataSource.setServerName("localhost");
try {
XAConnection connection = dataSource.getXAConnection();
System.out.println("Connected!");
XAResource resource = connection.getXAResource();
CustomXid identifier = new CustomXid(10);
// Apparently the application server gets the connection
// handle once and reuses it because there was no
// trace of getConnection() calls in the log.
Connection jdbcConnection = connection.getConnection();
// TM
resource.start(identifier, XAResource.TMNOFLAGS);
// application, EJB call
Statement statement = jdbcConnection.createStatement();
String sql = "INSERT INTO foo values ('ejb')";
statement.executeUpdate(sql);
// TM
resource.end(identifier, XAResource.TMSUCCESS);
resource.commit(identifier, true);
// application, java block
jdbcConnection.setAutoCommit(false);
statement = jdbcConnection.createStatement();
sql = "INSERT INTO foo values ('javablock, autocommit off')";
statement.executeUpdate(sql);
jdbcConnection.commit();
// TM
resource.start(identifier, XAResource.TMNOFLAGS);
// application, EJB call
statement = jdbcConnection.createStatement();
sql = "INSERT INTO foo values ('ejb again')";
statement.executeUpdate(sql);
// TM
resource.end(identifier, XAResource.TMSUCCESS);
resource.commit(identifier, true);
// application, 2nd java block
jdbcConnection.setAutoCommit(false);
statement = jdbcConnection.createStatement();
sql = "INSERT INTO foo values ('javablock, autocommit still off')";
statement.executeUpdate(sql);
jdbcConnection.commit();
} catch(Throwable tw)
{
tw.printStackTrace();
}
}
static class CustomXid implements Xid {
private static Random rand = new Random(System.currentTimeMillis());
byte[] gtrid = new byte[Xid.MAXGTRIDSIZE];
byte[] bqual = new byte[Xid.MAXBQUALSIZE];
CustomXid(int i)
{
rand.nextBytes(gtrid);
gtrid[0] = (byte)i;
gtrid[1] = (byte)i;
gtrid[2] = (byte)i;
gtrid[3] = (byte)i;
gtrid[4] = (byte)i;
bqual[0] = 4;
bqual[1] = 5;
bqual[2] = 6;
}
public int getFormatId() {
return 0;
}
public byte[] getGlobalTransactionId() {
return gtrid;
}
public byte[] getBranchQualifier() {
return bqual;
}
public boolean equals(Object o) {
Xid other = (Xid)o;
if (other.getFormatId() != this.getFormatId())
return false;
if (!Arrays.equals(other.getBranchQualifier(), this.getBranchQualifier()))
return false;
if (!Arrays.equals(other.getGlobalTransactionId(), this.getGlobalTransactionId()))
return false;
return true;
}
}
}
Index: org/postgresql/ds/jdbc23/AbstractJdbc23PooledConnection.java
===================================================================
RCS file: /cvsroot/jdbc/pgjdbc/org/postgresql/ds/jdbc23/AbstractJdbc23PooledConnection.java,v
retrieving revision 1.6
diff -u -r1.6 AbstractJdbc23PooledConnection.java
--- org/postgresql/ds/jdbc23/AbstractJdbc23PooledConnection.java 15 Jan 2009 04:18:03 -0000 1.6
+++ org/postgresql/ds/jdbc23/AbstractJdbc23PooledConnection.java 3 Mar 2010 12:23:17 -0000
@@ -263,6 +263,8 @@
public Object invoke(Object proxy, Method method, Object[] args)
throws Throwable
{
+ ((org.postgresql.core.BaseConnection)con).getLogger().debug("invoke: " + method.getName());
+
// From Object
if (method.getDeclaringClass().getName().equals("java.lang.Object"))
{
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Achilleas Mantzios
Date:
Your test case worked as you described. I send you an ear app which you can deploy in a jboss-4.2.x, Postgresql must be defined as <jndi-name>pgsql</jndi-name> in xa-datasource inside jboss's deploy dir. You can go to the app by hitting: http://localhost/xabug and looking at the directions there. Again, thanx for caring, and lets see if you can figure smth out off this. Στις Wednesday 03 March 2010 14:25:20 ο/η Heikki Linnakangas έγραψε: > Thanks! > > I tried to reproduce that with the attached test program. It's doing > essentially the same thing you did, right? The program works fine here, > producing a log identical to what you sent, except that I'm not seeing > the incorrect behavior you're seeing; the INSERT in the 2nd java block > is wrapped with BEGIN/COMMIT just like the 1st one. > > I don't understand why we're seeing different behavior with what should > be the same sequence of calls as far as the driver is concerned. Can you > try the attached patch, rerun the test case, and send over the logs > again? The patch adds some logging to see all the setAutoCommit() and > commit/rollback calls, maybe that sheds some light on this. > > BTW, you are using a recent version of the driver, right? There was some > fixes to setAutoCommit() and XA interactions a few years ago. > > Achilleas Mantzios wrote: > > Thanx > > Here are the logs: > > > > call to the ejb > > ========= > > 2010-03-03 12:47:57,177 INFO [STDOUT] 12:47:57.177 (2) XAResource 1291479: starting transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 > > > 2010-03-03 12:47:57,181 INFO [STDOUT] 12:47:57.180 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@dd0f87,maxRows=0, fetchSize=0, flags=1 > > 2010-03-03 12:47:57,184 INFO [STDOUT] 12:47:57.183 (2) FE=> Parse(stmt=S_1,query="BEGIN",oids={}) > > 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.184 (2) FE=> Bind(stmt=S_1,portal=null) > > 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.185 (2) FE=> Execute(portal=null,limit=0) > > 2010-03-03 12:47:57,186 INFO [STDOUT] 12:47:57.186 (2) FE=> Parse(stmt=null,query="select apptblidval,colname fromstatus where assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by apptblidval",oids={1043,23,1043,1043,1043}) > > 2010-03-03 12:47:57,188 INFO [STDOUT] 12:47:57.187 (2) FE=> Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>) > > 2010-03-03 12:47:57,189 INFO [STDOUT] 12:47:57.189 (2) FE=> Describe(portal=null) > > 2010-03-03 12:47:57,190 INFO [STDOUT] 12:47:57.190 (2) FE=> Execute(portal=null,limit=0) > > 2010-03-03 12:47:57,192 INFO [STDOUT] 12:47:57.192 (2) FE=> Sync > > 2010-03-03 12:47:57,199 INFO [STDOUT] 12:47:57.199 (2) <=BE ParseComplete [S_1] > > 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE BindComplete [null] > > 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE CommandStatus(BEGIN) > > 2010-03-03 12:47:57,201 INFO [STDOUT] 12:47:57.201 (2) <=BE ParseComplete [null] > > 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.201 (2) <=BE BindComplete [null] > > 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.202 (2) <=BE RowDescription(2) > > 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE CommandStatus(SELECT) > > 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE ReadyForQuery(T) > > 2010-03-03 12:47:57,206 INFO [STDOUT] 12:47:57.204 (2) XAResource 1291479: ending transaction xid = < 131075, 26, 24,1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 > > > 2010-03-03 12:47:57,211 INFO [STDOUT] 12:47:57.211 (2) XAResource 1291479: committing xid = < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34> (one phase) > > 2010-03-03 12:47:57,217 INFO [STDOUT] 12:47:57.217 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1a9b034,maxRows=0, fetchSize=0, flags=22 > > 2010-03-03 12:47:57,225 INFO [STDOUT] 12:47:57.225 (2) FE=> Parse(stmt=S_2,query="COMMIT",oids={}) > > 2010-03-03 12:47:57,227 INFO [STDOUT] 12:47:57.227 (2) FE=> Bind(stmt=S_2,portal=null) > > 2010-03-03 12:47:57,229 INFO [STDOUT] 12:47:57.228 (2) FE=> Execute(portal=null,limit=1) > > 2010-03-03 12:47:57,237 INFO [STDOUT] 12:47:57.237 (2) FE=> Sync > > 2010-03-03 12:47:57,246 INFO [STDOUT] 12:47:57.246 (2) <=BE ParseComplete [S_2] > > 2010-03-03 12:47:57,248 INFO [STDOUT] 12:47:57.248 (2) <=BE BindComplete [null] > > 2010-03-03 12:47:57,250 INFO [STDOUT] 12:47:57.250 (2) <=BE CommandStatus(COMMIT) > > 2010-03-03 12:47:57,251 INFO [STDOUT] 12:47:57.251 (2) <=BE ReadyForQuery(I) > > > > > > call to the java block - the one with con.setAutocommit(false) - (as we see below its fine the very first time) > > ================================================================= > > 2010-03-03 12:49:31,892 INFO [STDOUT] 12:49:31.892 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@19331eb,maxRows=0, fetchSize=0, flags=1 > > 2010-03-03 12:49:31,893 INFO [STDOUT] 12:49:31.893 (2) FE=> Bind(stmt=S_1,portal=null) > > 2010-03-03 12:49:31,895 INFO [STDOUT] 12:49:31.895 (2) FE=> Execute(portal=null,limit=0) > > 2010-03-03 12:49:31,896 INFO [STDOUT] 12:49:31.895 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > > 2010-03-03 12:49:31,897 INFO [STDOUT] 12:49:31.897 (2) FE=> Bind(stmt=null,portal=null) > > 2010-03-03 12:49:31,898 INFO [STDOUT] 12:49:31.898 (2) FE=> Describe(portal=null) > > 2010-03-03 12:49:31,899 INFO [STDOUT] 12:49:31.899 (2) FE=> Execute(portal=null,limit=0) > > 2010-03-03 12:49:31,901 INFO [STDOUT] 12:49:31.901 (2) FE=> Sync > > 2010-03-03 12:49:31,903 INFO [STDOUT] 12:49:31.902 (2) <=BE BindComplete [null] > > 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE CommandStatus(BEGIN) > > 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE ParseComplete [null] > > 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE BindComplete [null] > > 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE RowDescription(1) > > 2010-03-03 12:49:31,906 INFO [STDOUT] 12:49:31.906 (2) <=BE DataRow > > 2010-03-03 12:49:31,907 INFO [STDOUT] 12:49:31.907 (2) <=BE CommandStatus(SELECT) > > 2010-03-03 12:49:31,908 INFO [STDOUT] 12:49:31.908 (2) <=BE ReadyForQuery(T) > > 2010-03-03 12:49:31,909 INFO [STDOUT] 12:49:31.909 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1d7ce63,maxRows=0, fetchSize=0, flags=22 > > 2010-03-03 12:49:31,910 INFO [STDOUT] 12:49:31.910 (2) FE=> Bind(stmt=S_2,portal=null) > > 2010-03-03 12:49:31,911 INFO [STDOUT] 12:49:31.911 (2) FE=> Execute(portal=null,limit=1) > > 2010-03-03 12:49:31,913 INFO [STDOUT] 12:49:31.912 (2) FE=> Sync > > 2010-03-03 12:49:31,915 INFO [STDOUT] 12:49:31.915 (2) <=BE BindComplete [null] > > 2010-03-03 12:49:31,916 INFO [STDOUT] 12:49:31.916 (2) <=BE CommandStatus(COMMIT) > > 2010-03-03 12:49:31,917 INFO [STDOUT] 12:49:31.917 (2) <=BE ReadyForQuery(I) > > > > call to the ejb (again - 2nd time) > > ==================== > > 2010-03-03 12:50:24,246 INFO [STDOUT] 12:50:24.245 (2) XAResource 1291479: starting transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e > > > 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.247 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@a06e8d,maxRows=0, fetchSize=0, flags=1 > > 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.248 (2) FE=> Bind(stmt=S_1,portal=null) > > 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Execute(portal=null,limit=0) > > 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Parse(stmt=null,query="select apptblidval,colname fromstatus where assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by apptblidval",oids={1043,23,1043,1043,1043}) > > 2010-03-03 12:50:24,250 INFO [STDOUT] 12:50:24.250 (2) FE=> Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>) > > 2010-03-03 12:50:24,251 INFO [STDOUT] 12:50:24.251 (2) FE=> Describe(portal=null) > > 2010-03-03 12:50:24,252 INFO [STDOUT] 12:50:24.252 (2) FE=> Execute(portal=null,limit=0) > > 2010-03-03 12:50:24,253 INFO [STDOUT] 12:50:24.252 (2) FE=> Sync > > 2010-03-03 12:50:24,255 INFO [STDOUT] 12:50:24.255 (2) <=BE BindComplete [null] > > 2010-03-03 12:50:24,256 INFO [STDOUT] 12:50:24.256 (2) <=BE CommandStatus(BEGIN) > > 2010-03-03 12:50:24,257 INFO [STDOUT] 12:50:24.257 (2) <=BE ParseComplete [null] > > 2010-03-03 12:50:24,258 INFO [STDOUT] 12:50:24.258 (2) <=BE BindComplete [null] > > 2010-03-03 12:50:24,260 INFO [STDOUT] 12:50:24.260 (2) <=BE RowDescription(2) > > 2010-03-03 12:50:24,261 INFO [STDOUT] 12:50:24.261 (2) <=BE CommandStatus(SELECT) > > 2010-03-03 12:50:24,262 INFO [STDOUT] 12:50:24.262 (2) <=BE ReadyForQuery(T) > > 2010-03-03 12:50:24,263 INFO [STDOUT] 12:50:24.262 (2) XAResource 1291479: ending transaction xid = < 131075, 26, 24,1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e > > > 2010-03-03 12:50:24,264 INFO [STDOUT] 12:50:24.263 (2) XAResource 1291479: committing xid = < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e> (one phase) > > 2010-03-03 12:50:24,265 INFO [STDOUT] 12:50:24.265 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1217fef,maxRows=0, fetchSize=0, flags=22 > > 2010-03-03 12:50:24,266 INFO [STDOUT] 12:50:24.266 (2) FE=> Bind(stmt=S_2,portal=null) > > 2010-03-03 12:50:24,267 INFO [STDOUT] 12:50:24.267 (2) FE=> Execute(portal=null,limit=1) > > 2010-03-03 12:50:24,269 INFO [STDOUT] 12:50:24.269 (2) FE=> Sync > > 2010-03-03 12:50:24,272 INFO [STDOUT] 12:50:24.272 (2) <=BE BindComplete [null] > > 2010-03-03 12:50:24,273 INFO [STDOUT] 12:50:24.273 (2) <=BE CommandStatus(COMMIT) > > 2010-03-03 12:50:24,274 INFO [STDOUT] 12:50:24.274 (2) <=BE ReadyForQuery(I) > > > > call to the java block - the one with con.setAutocommit(false) - again - 2nd time - this time we have a problem > > ================================================================= > > 2010-03-03 12:51:30,426 INFO [STDOUT] 12:51:30.426 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@13b64eb,maxRows=0, fetchSize=0, flags=17 > > 2010-03-03 12:51:30,427 INFO [STDOUT] 12:51:30.427 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > > 2010-03-03 12:51:30,428 INFO [STDOUT] 12:51:30.428 (2) FE=> Bind(stmt=null,portal=null) > > 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Describe(portal=null) > > 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Execute(portal=null,limit=0) > > 2010-03-03 12:51:30,430 INFO [STDOUT] 12:51:30.430 (2) FE=> Sync > > 2010-03-03 12:51:30,433 INFO [STDOUT] 12:51:30.433 (2) <=BE ParseComplete [null] > > 2010-03-03 12:51:30,434 INFO [STDOUT] 12:51:30.434 (2) <=BE BindComplete [null] > > 2010-03-03 12:51:30,435 INFO [STDOUT] 12:51:30.435 (2) <=BE RowDescription(1) > > 2010-03-03 12:51:30,436 INFO [STDOUT] 12:51:30.436 (2) <=BE DataRow > > 2010-03-03 12:51:30,437 INFO [STDOUT] 12:51:30.437 (2) <=BE CommandStatus(SELECT) > > 2010-03-03 12:51:30,440 INFO [STDOUT] 12:51:30.440 (2) <=BE ReadyForQuery(I) > > > > call to a java block with con.setAutocommit(true) > > ============================== > > 2010-03-03 12:55:42,028 INFO [STDOUT] 12:55:42.028 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@18526aa,maxRows=0, fetchSize=0, flags=17 > > 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.028 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > > 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.029 (2) FE=> Bind(stmt=null,portal=null) > > 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Describe(portal=null) > > 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Execute(portal=null,limit=0) > > 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Sync > > 2010-03-03 12:55:42,032 INFO [STDOUT] 12:55:42.032 (2) <=BE ParseComplete [null] > > 2010-03-03 12:55:42,033 INFO [STDOUT] 12:55:42.033 (2) <=BE BindComplete [null] > > 2010-03-03 12:55:42,034 INFO [STDOUT] 12:55:42.034 (2) <=BE RowDescription(1) > > 2010-03-03 12:55:42,035 INFO [STDOUT] 12:55:42.035 (2) <=BE DataRow > > 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.035 (2) <=BE CommandStatus(SELECT) > > 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.036 (2) <=BE ReadyForQuery(I) > > > > call to the java block - the one with con.setAutocommit(false) - again - 3rd time - this time its ok again > > ============================================================== > > 2010-03-03 12:56:51,374 INFO [STDOUT] 12:56:51.374 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@14a5594,maxRows=0, fetchSize=0, flags=1 > > 2010-03-03 12:56:51,378 INFO [STDOUT] 12:56:51.378 (2) FE=> Bind(stmt=S_1,portal=null) > > 2010-03-03 12:56:51,380 INFO [STDOUT] 12:56:51.380 (2) FE=> Execute(portal=null,limit=0) > > 2010-03-03 12:56:51,385 INFO [STDOUT] 12:56:51.385 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > > 2010-03-03 12:56:51,387 INFO [STDOUT] 12:56:51.387 (2) FE=> Bind(stmt=null,portal=null) > > 2010-03-03 12:56:51,388 INFO [STDOUT] 12:56:51.388 (2) FE=> Describe(portal=null) > > 2010-03-03 12:56:51,390 INFO [STDOUT] 12:56:51.390 (2) FE=> Execute(portal=null,limit=0) > > 2010-03-03 12:56:51,391 INFO [STDOUT] 12:56:51.391 (2) FE=> Sync > > 2010-03-03 12:56:51,393 INFO [STDOUT] 12:56:51.393 (2) <=BE BindComplete [null] > > 2010-03-03 12:56:51,395 INFO [STDOUT] 12:56:51.395 (2) <=BE CommandStatus(BEGIN) > > 2010-03-03 12:56:51,397 INFO [STDOUT] 12:56:51.397 (2) <=BE ParseComplete [null] > > 2010-03-03 12:56:51,398 INFO [STDOUT] 12:56:51.398 (2) <=BE BindComplete [null] > > 2010-03-03 12:56:51,399 INFO [STDOUT] 12:56:51.399 (2) <=BE RowDescription(1) > > 2010-03-03 12:56:51,400 INFO [STDOUT] 12:56:51.400 (2) <=BE DataRow > > 2010-03-03 12:56:51,402 INFO [STDOUT] 12:56:51.402 (2) <=BE CommandStatus(SELECT) > > 2010-03-03 12:56:51,404 INFO [STDOUT] 12:56:51.404 (2) <=BE ReadyForQuery(T) > > 2010-03-03 12:56:51,406 INFO [STDOUT] 12:56:51.406 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@13d3f62,maxRows=0, fetchSize=0, flags=22 > > 2010-03-03 12:56:51,409 INFO [STDOUT] 12:56:51.409 (2) FE=> Bind(stmt=S_2,portal=null) > > 2010-03-03 12:56:51,411 INFO [STDOUT] 12:56:51.411 (2) FE=> Execute(portal=null,limit=1) > > 2010-03-03 12:56:51,413 INFO [STDOUT] 12:56:51.413 (2) FE=> Sync > > 2010-03-03 12:56:51,417 INFO [STDOUT] 12:56:51.417 (2) <=BE BindComplete [null] > > 2010-03-03 12:56:51,419 INFO [STDOUT] 12:56:51.418 (2) <=BE CommandStatus(COMMIT) > > 2010-03-03 12:56:51,421 INFO [STDOUT] 12:56:51.421 (2) <=BE ReadyForQuery(I) > > > > Στις Wednesday 03 March 2010 12:30:37 ο/η Heikki Linnakangas έγραψε: > >> Achilleas Mantzios wrote: > >>> Στις Wednesday 03 March 2010 10:54:53 ο/η Heikki Linnakangas έγραψε: > >>>> Achilleas Mantzios wrote: > >>>>> 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. > >>>> If you can set logLevel to DEBUG (ie. loglevel=2 in connection string), > >>>> run the code, and send over the logs, that would help a lot. From that > >>>> we should see what exactly is the sequence of XA commands the JDBC > >>>> driver is receiving from JBoss. > >>> As loglevel configuration property to org.postgresql.ds.common.BaseDataSource is not supported in the lastest driver, > >>> i made this patch (i attach it) against postgresql-jdbc-8.4-701.src, also i set in jboss > >>> > >>> <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">xxxx</xa-datasource-property> > >>> <xa-datasource-property name="Compatible">8.2</xa-datasource-property> > >>> <xa-datasource-property name="Loglevel">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> > >>> > >>> But i dont see anything spectacular comming out of PostgreSQL logs. > >>> in postgresql.conf I have set > >>> client_min_messages = debug5 > >>> log_min_messages = debug5 > >> The extra logs should go somewhere in the client side, in one of the > >> jboss log files. If you can't find it, you can do something like this in > >> the application to redirect it to a file: > >> > >> java.io.Writer output = new > >> java.io.FileWriter("/tmp/postgresql-jdbc.debug.txt", true); > >> java.sql.DriverManager.setLogWriter(new > >> java.io.PrintWriter(output,true)); > >> > >> > >>> however playing with <xa-datasource-property name="Loglevel"></xa-datasource-property> does not seem to change a thing. > >>> Am i missing something? > >> Not sure why that's not working, but here's one way of setting loglevel: > >> > >> 1. Create file "org/postgresql/driverconfig.properties" with line > >> "loglevel=2" in it: > >> echo "loglevel=2" > org/postgresql/driverconfig.properties > >> 2. Add file to the driver jar: > >> jar uvf postgresql.jar org/postgresql/driverconfig.properties > >> > >> -- > >> Heikki Linnakangas > >> EnterpriseDB http://www.enterprisedb.com > >> > > > > > > > > -- Achilleas Mantzios
Attachment
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Achilleas Mantzios
Date:
Thanx a lot! Good job! btw what an evil coincidence, we have been haunted by this for nearly 2 years now. Στις Wednesday 03 March 2010 21:43:41 ο/η Heikki Linnakangas έγραψε: > Okay, thanks, I see what's going on now. > > There's two things contributing to this: > > * When you call setAutoCommit(false) on a connection acquired from a > PGXAConnection, in a local transaction, and subsequently use the > connection for XA transaction, the driver puts the connection back into > autocommit mode. Looking at the JDBC spec, I don't think the driver > should be doing that; when the XA transaction ends, autocommit mode > should be restored to whatever it was before. > > * Even though you explicitly call setAutoCommit(false) in the 2nd > invocation of the java block, JBoss intercepts the call and turns it > into a no-op, because it remembers that setAutoCommit(false) was already > called on the connection in the first invocation of that. But the driver > turned on autocommit mode behind its back, so the connection is in fact > in autocommit mode even though JBoss thinks it's not, and despite the > application explicitly called setAutoCommit(false). > > Sometimes I want to punch the designers of the JTA API in the face, it's > unnecessarily complicated with all those interactions between local and > XA transactions, sharing connections between transactions, transaction > suspend/resume etc. But it is what it is and we have to live with it :-(. > > Attached is a patch to fix the issue by remembering the autocommit > status of the connection when an XA transaction is started and to > restore it after it ends (fix-jboss-autocommit-issue-2.patch). > > While we're at it, the other attached patch includes the changes from > the first patch, plus some sanity checks. It throws an error if you call > setAutoCommit/commit/rollback/setSavePoint in an XA transaction. That's > forbidden according to the JDBC spec, but we haven't enforced it before > (the behavior is not well-defined if you do it). It also throws an error > if you call XAResource.commit(..., true) (ie. COMMIT PREPARED) using a > connection that's being used for a local transaction. That currently > silently commits the local transaction, which is bad. It adds another > layer of reflection the calls on Connection objects, but that shouldn't > be that performance critical, correctness is much more important. > > Attached is also a stand-alone test case exhibiting the same sequence of > calls that JBoss produced in this scenario, so that we have that > archived for future reference. > > Achilleas Mantzios wrote: > > Your test case worked as you described. > > I send you an ear app which you can deploy in a jboss-4.2.x, Postgresql must be defined as <jndi-name>pgsql</jndi-name> > > in xa-datasource inside jboss's deploy dir. > > You can go to the app by hitting: http://localhost/xabug and looking at the directions there. > > > > Again, thanx for caring, and lets see if you can figure smth out off this. > > > > Στις Wednesday 03 March 2010 14:25:20 ο/η Heikki Linnakangas έγραψε: > >> Thanks! > >> > >> I tried to reproduce that with the attached test program. It's doing > >> essentially the same thing you did, right? The program works fine here, > >> producing a log identical to what you sent, except that I'm not seeing > >> the incorrect behavior you're seeing; the INSERT in the 2nd java block > >> is wrapped with BEGIN/COMMIT just like the 1st one. > >> > >> I don't understand why we're seeing different behavior with what should > >> be the same sequence of calls as far as the driver is concerned. Can you > >> try the attached patch, rerun the test case, and send over the logs > >> again? The patch adds some logging to see all the setAutoCommit() and > >> commit/rollback calls, maybe that sheds some light on this. > >> > >> BTW, you are using a recent version of the driver, right? There was some > >> fixes to setAutoCommit() and XA interactions a few years ago. > >> > >> Achilleas Mantzios wrote: > >>> Thanx > >>> Here are the logs: > >>> > >>> call to the ejb > >>> ========= > >>> 2010-03-03 12:47:57,177 INFO [STDOUT] 12:47:57.177 (2) XAResource 1291479: starting transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 > > >>> 2010-03-03 12:47:57,181 INFO [STDOUT] 12:47:57.180 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@dd0f87,maxRows=0, fetchSize=0, flags=1 > >>> 2010-03-03 12:47:57,184 INFO [STDOUT] 12:47:57.183 (2) FE=> Parse(stmt=S_1,query="BEGIN",oids={}) > >>> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.184 (2) FE=> Bind(stmt=S_1,portal=null) > >>> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.185 (2) FE=> Execute(portal=null,limit=0) > >>> 2010-03-03 12:47:57,186 INFO [STDOUT] 12:47:57.186 (2) FE=> Parse(stmt=null,query="select apptblidval,colname fromstatus where assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by apptblidval",oids={1043,23,1043,1043,1043}) > >>> 2010-03-03 12:47:57,188 INFO [STDOUT] 12:47:57.187 (2) FE=> Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>) > >>> 2010-03-03 12:47:57,189 INFO [STDOUT] 12:47:57.189 (2) FE=> Describe(portal=null) > >>> 2010-03-03 12:47:57,190 INFO [STDOUT] 12:47:57.190 (2) FE=> Execute(portal=null,limit=0) > >>> 2010-03-03 12:47:57,192 INFO [STDOUT] 12:47:57.192 (2) FE=> Sync > >>> 2010-03-03 12:47:57,199 INFO [STDOUT] 12:47:57.199 (2) <=BE ParseComplete [S_1] > >>> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE CommandStatus(BEGIN) > >>> 2010-03-03 12:47:57,201 INFO [STDOUT] 12:47:57.201 (2) <=BE ParseComplete [null] > >>> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.201 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.202 (2) <=BE RowDescription(2) > >>> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE CommandStatus(SELECT) > >>> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE ReadyForQuery(T) > >>> 2010-03-03 12:47:57,206 INFO [STDOUT] 12:47:57.204 (2) XAResource 1291479: ending transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 > > >>> 2010-03-03 12:47:57,211 INFO [STDOUT] 12:47:57.211 (2) XAResource 1291479: committing xid = < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34> (one phase) > >>> 2010-03-03 12:47:57,217 INFO [STDOUT] 12:47:57.217 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1a9b034,maxRows=0, fetchSize=0, flags=22 > >>> 2010-03-03 12:47:57,225 INFO [STDOUT] 12:47:57.225 (2) FE=> Parse(stmt=S_2,query="COMMIT",oids={}) > >>> 2010-03-03 12:47:57,227 INFO [STDOUT] 12:47:57.227 (2) FE=> Bind(stmt=S_2,portal=null) > >>> 2010-03-03 12:47:57,229 INFO [STDOUT] 12:47:57.228 (2) FE=> Execute(portal=null,limit=1) > >>> 2010-03-03 12:47:57,237 INFO [STDOUT] 12:47:57.237 (2) FE=> Sync > >>> 2010-03-03 12:47:57,246 INFO [STDOUT] 12:47:57.246 (2) <=BE ParseComplete [S_2] > >>> 2010-03-03 12:47:57,248 INFO [STDOUT] 12:47:57.248 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:47:57,250 INFO [STDOUT] 12:47:57.250 (2) <=BE CommandStatus(COMMIT) > >>> 2010-03-03 12:47:57,251 INFO [STDOUT] 12:47:57.251 (2) <=BE ReadyForQuery(I) > >>> > >>> > >>> call to the java block - the one with con.setAutocommit(false) - (as we see below its fine the very first time) > >>> ================================================================= > >>> 2010-03-03 12:49:31,892 INFO [STDOUT] 12:49:31.892 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@19331eb,maxRows=0, fetchSize=0, flags=1 > >>> 2010-03-03 12:49:31,893 INFO [STDOUT] 12:49:31.893 (2) FE=> Bind(stmt=S_1,portal=null) > >>> 2010-03-03 12:49:31,895 INFO [STDOUT] 12:49:31.895 (2) FE=> Execute(portal=null,limit=0) > >>> 2010-03-03 12:49:31,896 INFO [STDOUT] 12:49:31.895 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > >>> 2010-03-03 12:49:31,897 INFO [STDOUT] 12:49:31.897 (2) FE=> Bind(stmt=null,portal=null) > >>> 2010-03-03 12:49:31,898 INFO [STDOUT] 12:49:31.898 (2) FE=> Describe(portal=null) > >>> 2010-03-03 12:49:31,899 INFO [STDOUT] 12:49:31.899 (2) FE=> Execute(portal=null,limit=0) > >>> 2010-03-03 12:49:31,901 INFO [STDOUT] 12:49:31.901 (2) FE=> Sync > >>> 2010-03-03 12:49:31,903 INFO [STDOUT] 12:49:31.902 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE CommandStatus(BEGIN) > >>> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE ParseComplete [null] > >>> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE RowDescription(1) > >>> 2010-03-03 12:49:31,906 INFO [STDOUT] 12:49:31.906 (2) <=BE DataRow > >>> 2010-03-03 12:49:31,907 INFO [STDOUT] 12:49:31.907 (2) <=BE CommandStatus(SELECT) > >>> 2010-03-03 12:49:31,908 INFO [STDOUT] 12:49:31.908 (2) <=BE ReadyForQuery(T) > >>> 2010-03-03 12:49:31,909 INFO [STDOUT] 12:49:31.909 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1d7ce63,maxRows=0, fetchSize=0, flags=22 > >>> 2010-03-03 12:49:31,910 INFO [STDOUT] 12:49:31.910 (2) FE=> Bind(stmt=S_2,portal=null) > >>> 2010-03-03 12:49:31,911 INFO [STDOUT] 12:49:31.911 (2) FE=> Execute(portal=null,limit=1) > >>> 2010-03-03 12:49:31,913 INFO [STDOUT] 12:49:31.912 (2) FE=> Sync > >>> 2010-03-03 12:49:31,915 INFO [STDOUT] 12:49:31.915 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:49:31,916 INFO [STDOUT] 12:49:31.916 (2) <=BE CommandStatus(COMMIT) > >>> 2010-03-03 12:49:31,917 INFO [STDOUT] 12:49:31.917 (2) <=BE ReadyForQuery(I) > >>> > >>> call to the ejb (again - 2nd time) > >>> ==================== > >>> 2010-03-03 12:50:24,246 INFO [STDOUT] 12:50:24.245 (2) XAResource 1291479: starting transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e > > >>> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.247 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@a06e8d,maxRows=0, fetchSize=0, flags=1 > >>> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.248 (2) FE=> Bind(stmt=S_1,portal=null) > >>> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Execute(portal=null,limit=0) > >>> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Parse(stmt=null,query="select apptblidval,colname fromstatus where assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by apptblidval",oids={1043,23,1043,1043,1043}) > >>> 2010-03-03 12:50:24,250 INFO [STDOUT] 12:50:24.250 (2) FE=> Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>) > >>> 2010-03-03 12:50:24,251 INFO [STDOUT] 12:50:24.251 (2) FE=> Describe(portal=null) > >>> 2010-03-03 12:50:24,252 INFO [STDOUT] 12:50:24.252 (2) FE=> Execute(portal=null,limit=0) > >>> 2010-03-03 12:50:24,253 INFO [STDOUT] 12:50:24.252 (2) FE=> Sync > >>> 2010-03-03 12:50:24,255 INFO [STDOUT] 12:50:24.255 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:50:24,256 INFO [STDOUT] 12:50:24.256 (2) <=BE CommandStatus(BEGIN) > >>> 2010-03-03 12:50:24,257 INFO [STDOUT] 12:50:24.257 (2) <=BE ParseComplete [null] > >>> 2010-03-03 12:50:24,258 INFO [STDOUT] 12:50:24.258 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:50:24,260 INFO [STDOUT] 12:50:24.260 (2) <=BE RowDescription(2) > >>> 2010-03-03 12:50:24,261 INFO [STDOUT] 12:50:24.261 (2) <=BE CommandStatus(SELECT) > >>> 2010-03-03 12:50:24,262 INFO [STDOUT] 12:50:24.262 (2) <=BE ReadyForQuery(T) > >>> 2010-03-03 12:50:24,263 INFO [STDOUT] 12:50:24.262 (2) XAResource 1291479: ending transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e > > >>> 2010-03-03 12:50:24,264 INFO [STDOUT] 12:50:24.263 (2) XAResource 1291479: committing xid = < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e> (one phase) > >>> 2010-03-03 12:50:24,265 INFO [STDOUT] 12:50:24.265 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1217fef,maxRows=0, fetchSize=0, flags=22 > >>> 2010-03-03 12:50:24,266 INFO [STDOUT] 12:50:24.266 (2) FE=> Bind(stmt=S_2,portal=null) > >>> 2010-03-03 12:50:24,267 INFO [STDOUT] 12:50:24.267 (2) FE=> Execute(portal=null,limit=1) > >>> 2010-03-03 12:50:24,269 INFO [STDOUT] 12:50:24.269 (2) FE=> Sync > >>> 2010-03-03 12:50:24,272 INFO [STDOUT] 12:50:24.272 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:50:24,273 INFO [STDOUT] 12:50:24.273 (2) <=BE CommandStatus(COMMIT) > >>> 2010-03-03 12:50:24,274 INFO [STDOUT] 12:50:24.274 (2) <=BE ReadyForQuery(I) > >>> > >>> call to the java block - the one with con.setAutocommit(false) - again - 2nd time - this time we have a problem > >>> ================================================================= > >>> 2010-03-03 12:51:30,426 INFO [STDOUT] 12:51:30.426 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@13b64eb,maxRows=0, fetchSize=0, flags=17 > >>> 2010-03-03 12:51:30,427 INFO [STDOUT] 12:51:30.427 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > >>> 2010-03-03 12:51:30,428 INFO [STDOUT] 12:51:30.428 (2) FE=> Bind(stmt=null,portal=null) > >>> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Describe(portal=null) > >>> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Execute(portal=null,limit=0) > >>> 2010-03-03 12:51:30,430 INFO [STDOUT] 12:51:30.430 (2) FE=> Sync > >>> 2010-03-03 12:51:30,433 INFO [STDOUT] 12:51:30.433 (2) <=BE ParseComplete [null] > >>> 2010-03-03 12:51:30,434 INFO [STDOUT] 12:51:30.434 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:51:30,435 INFO [STDOUT] 12:51:30.435 (2) <=BE RowDescription(1) > >>> 2010-03-03 12:51:30,436 INFO [STDOUT] 12:51:30.436 (2) <=BE DataRow > >>> 2010-03-03 12:51:30,437 INFO [STDOUT] 12:51:30.437 (2) <=BE CommandStatus(SELECT) > >>> 2010-03-03 12:51:30,440 INFO [STDOUT] 12:51:30.440 (2) <=BE ReadyForQuery(I) > >>> > >>> call to a java block with con.setAutocommit(true) > >>> ============================== > >>> 2010-03-03 12:55:42,028 INFO [STDOUT] 12:55:42.028 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@18526aa,maxRows=0, fetchSize=0, flags=17 > >>> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.028 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > >>> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.029 (2) FE=> Bind(stmt=null,portal=null) > >>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Describe(portal=null) > >>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Execute(portal=null,limit=0) > >>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Sync > >>> 2010-03-03 12:55:42,032 INFO [STDOUT] 12:55:42.032 (2) <=BE ParseComplete [null] > >>> 2010-03-03 12:55:42,033 INFO [STDOUT] 12:55:42.033 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:55:42,034 INFO [STDOUT] 12:55:42.034 (2) <=BE RowDescription(1) > >>> 2010-03-03 12:55:42,035 INFO [STDOUT] 12:55:42.035 (2) <=BE DataRow > >>> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.035 (2) <=BE CommandStatus(SELECT) > >>> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.036 (2) <=BE ReadyForQuery(I) > >>> > >>> call to the java block - the one with con.setAutocommit(false) - again - 3rd time - this time its ok again > >>> ============================================================== > >>> 2010-03-03 12:56:51,374 INFO [STDOUT] 12:56:51.374 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@14a5594,maxRows=0, fetchSize=0, flags=1 > >>> 2010-03-03 12:56:51,378 INFO [STDOUT] 12:56:51.378 (2) FE=> Bind(stmt=S_1,portal=null) > >>> 2010-03-03 12:56:51,380 INFO [STDOUT] 12:56:51.380 (2) FE=> Execute(portal=null,limit=0) > >>> 2010-03-03 12:56:51,385 INFO [STDOUT] 12:56:51.385 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > >>> 2010-03-03 12:56:51,387 INFO [STDOUT] 12:56:51.387 (2) FE=> Bind(stmt=null,portal=null) > >>> 2010-03-03 12:56:51,388 INFO [STDOUT] 12:56:51.388 (2) FE=> Describe(portal=null) > >>> 2010-03-03 12:56:51,390 INFO [STDOUT] 12:56:51.390 (2) FE=> Execute(portal=null,limit=0) > >>> 2010-03-03 12:56:51,391 INFO [STDOUT] 12:56:51.391 (2) FE=> Sync > >>> 2010-03-03 12:56:51,393 INFO [STDOUT] 12:56:51.393 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:56:51,395 INFO [STDOUT] 12:56:51.395 (2) <=BE CommandStatus(BEGIN) > >>> 2010-03-03 12:56:51,397 INFO [STDOUT] 12:56:51.397 (2) <=BE ParseComplete [null] > >>> 2010-03-03 12:56:51,398 INFO [STDOUT] 12:56:51.398 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:56:51,399 INFO [STDOUT] 12:56:51.399 (2) <=BE RowDescription(1) > >>> 2010-03-03 12:56:51,400 INFO [STDOUT] 12:56:51.400 (2) <=BE DataRow > >>> 2010-03-03 12:56:51,402 INFO [STDOUT] 12:56:51.402 (2) <=BE CommandStatus(SELECT) > >>> 2010-03-03 12:56:51,404 INFO [STDOUT] 12:56:51.404 (2) <=BE ReadyForQuery(T) > >>> 2010-03-03 12:56:51,406 INFO [STDOUT] 12:56:51.406 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@13d3f62,maxRows=0, fetchSize=0, flags=22 > >>> 2010-03-03 12:56:51,409 INFO [STDOUT] 12:56:51.409 (2) FE=> Bind(stmt=S_2,portal=null) > >>> 2010-03-03 12:56:51,411 INFO [STDOUT] 12:56:51.411 (2) FE=> Execute(portal=null,limit=1) > >>> 2010-03-03 12:56:51,413 INFO [STDOUT] 12:56:51.413 (2) FE=> Sync > >>> 2010-03-03 12:56:51,417 INFO [STDOUT] 12:56:51.417 (2) <=BE BindComplete [null] > >>> 2010-03-03 12:56:51,419 INFO [STDOUT] 12:56:51.418 (2) <=BE CommandStatus(COMMIT) > >>> 2010-03-03 12:56:51,421 INFO [STDOUT] 12:56:51.421 (2) <=BE ReadyForQuery(I) > >>> > >>> Στις Wednesday 03 March 2010 12:30:37 ο/η Heikki Linnakangas έγραψε: > >>>> Achilleas Mantzios wrote: > >>>>> Στις Wednesday 03 March 2010 10:54:53 ο/η Heikki Linnakangas έγραψε: > >>>>>> Achilleas Mantzios wrote: > >>>>>>> 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. > >>>>>> If you can set logLevel to DEBUG (ie. loglevel=2 in connection string), > >>>>>> run the code, and send over the logs, that would help a lot. From that > >>>>>> we should see what exactly is the sequence of XA commands the JDBC > >>>>>> driver is receiving from JBoss. > >>>>> As loglevel configuration property to org.postgresql.ds.common.BaseDataSource is not supported in the lastest driver, > >>>>> i made this patch (i attach it) against postgresql-jdbc-8.4-701.src, also i set in jboss > >>>>> > >>>>> <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">xxxx</xa-datasource-property> > >>>>> <xa-datasource-property name="Compatible">8.2</xa-datasource-property> > >>>>> <xa-datasource-property name="Loglevel">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> > >>>>> > >>>>> But i dont see anything spectacular comming out of PostgreSQL logs. > >>>>> in postgresql.conf I have set > >>>>> client_min_messages = debug5 > >>>>> log_min_messages = debug5 > >>>> The extra logs should go somewhere in the client side, in one of the > >>>> jboss log files. If you can't find it, you can do something like this in > >>>> the application to redirect it to a file: > >>>> > >>>> java.io.Writer output = new > >>>> java.io.FileWriter("/tmp/postgresql-jdbc.debug.txt", true); > >>>> java.sql.DriverManager.setLogWriter(new > >>>> java.io.PrintWriter(output,true)); > >>>> > >>>> > >>>>> however playing with <xa-datasource-property name="Loglevel"></xa-datasource-property> does not seem to change athing. > >>>>> Am i missing something? > >>>> Not sure why that's not working, but here's one way of setting loglevel: > >>>> > >>>> 1. Create file "org/postgresql/driverconfig.properties" with line > >>>> "loglevel=2" in it: > >>>> echo "loglevel=2" > org/postgresql/driverconfig.properties > >>>> 2. Add file to the driver jar: > >>>> jar uvf postgresql.jar org/postgresql/driverconfig.properties > >>>> > >>>> -- > >>>> Heikki Linnakangas > >>>> EnterpriseDB http://www.enterprisedb.com > >>>> > >>> > >>> > >> > > > > > > > > -- Achilleas Mantzios
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Heikki Linnakangas
Date:
I don't think these patches were ever committed. At least the smaller one of them should be, this is a pretty scary bug because of the interaction with JBoss. And the bigger patch adds sanity checks that would be nice to have, maybe not for back-branches but for HEAD. Heikki Linnakangas wrote: > Okay, thanks, I see what's going on now. > > There's two things contributing to this: > > * When you call setAutoCommit(false) on a connection acquired from a > PGXAConnection, in a local transaction, and subsequently use the > connection for XA transaction, the driver puts the connection back into > autocommit mode. Looking at the JDBC spec, I don't think the driver > should be doing that; when the XA transaction ends, autocommit mode > should be restored to whatever it was before. > > * Even though you explicitly call setAutoCommit(false) in the 2nd > invocation of the java block, JBoss intercepts the call and turns it > into a no-op, because it remembers that setAutoCommit(false) was already > called on the connection in the first invocation of that. But the driver > turned on autocommit mode behind its back, so the connection is in fact > in autocommit mode even though JBoss thinks it's not, and despite the > application explicitly called setAutoCommit(false). > > Sometimes I want to punch the designers of the JTA API in the face, it's > unnecessarily complicated with all those interactions between local and > XA transactions, sharing connections between transactions, transaction > suspend/resume etc. But it is what it is and we have to live with it :-(. > > Attached is a patch to fix the issue by remembering the autocommit > status of the connection when an XA transaction is started and to > restore it after it ends (fix-jboss-autocommit-issue-2.patch). > > While we're at it, the other attached patch includes the changes from > the first patch, plus some sanity checks. It throws an error if you call > setAutoCommit/commit/rollback/setSavePoint in an XA transaction. That's > forbidden according to the JDBC spec, but we haven't enforced it before > (the behavior is not well-defined if you do it). It also throws an error > if you call XAResource.commit(..., true) (ie. COMMIT PREPARED) using a > connection that's being used for a local transaction. That currently > silently commits the local transaction, which is bad. It adds another > layer of reflection the calls on Connection objects, but that shouldn't > be that performance critical, correctness is much more important. > > Attached is also a stand-alone test case exhibiting the same sequence of > calls that JBoss produced in this scenario, so that we have that > archived for future reference. > > Achilleas Mantzios wrote: >> Your test case worked as you described. >> I send you an ear app which you can deploy in a jboss-4.2.x, Postgresql must be defined as <jndi-name>pgsql</jndi-name> >> in xa-datasource inside jboss's deploy dir. >> You can go to the app by hitting: http://localhost/xabug and looking at the directions there. >> >> Again, thanx for caring, and lets see if you can figure smth out off this. >> >> Στις Wednesday 03 March 2010 14:25:20 ο/η Heikki Linnakangas έγραψε: >>> Thanks! >>> >>> I tried to reproduce that with the attached test program. It's doing >>> essentially the same thing you did, right? The program works fine here, >>> producing a log identical to what you sent, except that I'm not seeing >>> the incorrect behavior you're seeing; the INSERT in the 2nd java block >>> is wrapped with BEGIN/COMMIT just like the 1st one. >>> >>> I don't understand why we're seeing different behavior with what should >>> be the same sequence of calls as far as the driver is concerned. Can you >>> try the attached patch, rerun the test case, and send over the logs >>> again? The patch adds some logging to see all the setAutoCommit() and >>> commit/rollback calls, maybe that sheds some light on this. >>> >>> BTW, you are using a recent version of the driver, right? There was some >>> fixes to setAutoCommit() and XA interactions a few years ago. >>> >>> Achilleas Mantzios wrote: >>>> Thanx >>>> Here are the logs: >>>> >>>> call to the ejb >>>> ========= >>>> 2010-03-03 12:47:57,177 INFO [STDOUT] 12:47:57.177 (2) XAResource 1291479: starting transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 > >>>> 2010-03-03 12:47:57,181 INFO [STDOUT] 12:47:57.180 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@dd0f87,maxRows=0, fetchSize=0, flags=1 >>>> 2010-03-03 12:47:57,184 INFO [STDOUT] 12:47:57.183 (2) FE=> Parse(stmt=S_1,query="BEGIN",oids={}) >>>> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.184 (2) FE=> Bind(stmt=S_1,portal=null) >>>> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.185 (2) FE=> Execute(portal=null,limit=0) >>>> 2010-03-03 12:47:57,186 INFO [STDOUT] 12:47:57.186 (2) FE=> Parse(stmt=null,query="select apptblidval,colname fromstatus where assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by apptblidval",oids={1043,23,1043,1043,1043}) >>>> 2010-03-03 12:47:57,188 INFO [STDOUT] 12:47:57.187 (2) FE=> Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>) >>>> 2010-03-03 12:47:57,189 INFO [STDOUT] 12:47:57.189 (2) FE=> Describe(portal=null) >>>> 2010-03-03 12:47:57,190 INFO [STDOUT] 12:47:57.190 (2) FE=> Execute(portal=null,limit=0) >>>> 2010-03-03 12:47:57,192 INFO [STDOUT] 12:47:57.192 (2) FE=> Sync >>>> 2010-03-03 12:47:57,199 INFO [STDOUT] 12:47:57.199 (2) <=BE ParseComplete [S_1] >>>> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE CommandStatus(BEGIN) >>>> 2010-03-03 12:47:57,201 INFO [STDOUT] 12:47:57.201 (2) <=BE ParseComplete [null] >>>> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.201 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.202 (2) <=BE RowDescription(2) >>>> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE CommandStatus(SELECT) >>>> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE ReadyForQuery(T) >>>> 2010-03-03 12:47:57,206 INFO [STDOUT] 12:47:57.204 (2) XAResource 1291479: ending transaction xid = < 131075, 26, 24,1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 > >>>> 2010-03-03 12:47:57,211 INFO [STDOUT] 12:47:57.211 (2) XAResource 1291479: committing xid = < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34> (one phase) >>>> 2010-03-03 12:47:57,217 INFO [STDOUT] 12:47:57.217 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1a9b034,maxRows=0, fetchSize=0, flags=22 >>>> 2010-03-03 12:47:57,225 INFO [STDOUT] 12:47:57.225 (2) FE=> Parse(stmt=S_2,query="COMMIT",oids={}) >>>> 2010-03-03 12:47:57,227 INFO [STDOUT] 12:47:57.227 (2) FE=> Bind(stmt=S_2,portal=null) >>>> 2010-03-03 12:47:57,229 INFO [STDOUT] 12:47:57.228 (2) FE=> Execute(portal=null,limit=1) >>>> 2010-03-03 12:47:57,237 INFO [STDOUT] 12:47:57.237 (2) FE=> Sync >>>> 2010-03-03 12:47:57,246 INFO [STDOUT] 12:47:57.246 (2) <=BE ParseComplete [S_2] >>>> 2010-03-03 12:47:57,248 INFO [STDOUT] 12:47:57.248 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:47:57,250 INFO [STDOUT] 12:47:57.250 (2) <=BE CommandStatus(COMMIT) >>>> 2010-03-03 12:47:57,251 INFO [STDOUT] 12:47:57.251 (2) <=BE ReadyForQuery(I) >>>> >>>> >>>> call to the java block - the one with con.setAutocommit(false) - (as we see below its fine the very first time) >>>> ================================================================= >>>> 2010-03-03 12:49:31,892 INFO [STDOUT] 12:49:31.892 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@19331eb,maxRows=0, fetchSize=0, flags=1 >>>> 2010-03-03 12:49:31,893 INFO [STDOUT] 12:49:31.893 (2) FE=> Bind(stmt=S_1,portal=null) >>>> 2010-03-03 12:49:31,895 INFO [STDOUT] 12:49:31.895 (2) FE=> Execute(portal=null,limit=0) >>>> 2010-03-03 12:49:31,896 INFO [STDOUT] 12:49:31.895 (2) FE=> Parse(stmt=null,query="select now()",oids={}) >>>> 2010-03-03 12:49:31,897 INFO [STDOUT] 12:49:31.897 (2) FE=> Bind(stmt=null,portal=null) >>>> 2010-03-03 12:49:31,898 INFO [STDOUT] 12:49:31.898 (2) FE=> Describe(portal=null) >>>> 2010-03-03 12:49:31,899 INFO [STDOUT] 12:49:31.899 (2) FE=> Execute(portal=null,limit=0) >>>> 2010-03-03 12:49:31,901 INFO [STDOUT] 12:49:31.901 (2) FE=> Sync >>>> 2010-03-03 12:49:31,903 INFO [STDOUT] 12:49:31.902 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE CommandStatus(BEGIN) >>>> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE ParseComplete [null] >>>> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE RowDescription(1) >>>> 2010-03-03 12:49:31,906 INFO [STDOUT] 12:49:31.906 (2) <=BE DataRow >>>> 2010-03-03 12:49:31,907 INFO [STDOUT] 12:49:31.907 (2) <=BE CommandStatus(SELECT) >>>> 2010-03-03 12:49:31,908 INFO [STDOUT] 12:49:31.908 (2) <=BE ReadyForQuery(T) >>>> 2010-03-03 12:49:31,909 INFO [STDOUT] 12:49:31.909 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1d7ce63,maxRows=0, fetchSize=0, flags=22 >>>> 2010-03-03 12:49:31,910 INFO [STDOUT] 12:49:31.910 (2) FE=> Bind(stmt=S_2,portal=null) >>>> 2010-03-03 12:49:31,911 INFO [STDOUT] 12:49:31.911 (2) FE=> Execute(portal=null,limit=1) >>>> 2010-03-03 12:49:31,913 INFO [STDOUT] 12:49:31.912 (2) FE=> Sync >>>> 2010-03-03 12:49:31,915 INFO [STDOUT] 12:49:31.915 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:49:31,916 INFO [STDOUT] 12:49:31.916 (2) <=BE CommandStatus(COMMIT) >>>> 2010-03-03 12:49:31,917 INFO [STDOUT] 12:49:31.917 (2) <=BE ReadyForQuery(I) >>>> >>>> call to the ejb (again - 2nd time) >>>> ==================== >>>> 2010-03-03 12:50:24,246 INFO [STDOUT] 12:50:24.245 (2) XAResource 1291479: starting transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e > >>>> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.247 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@a06e8d,maxRows=0, fetchSize=0, flags=1 >>>> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.248 (2) FE=> Bind(stmt=S_1,portal=null) >>>> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Execute(portal=null,limit=0) >>>> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Parse(stmt=null,query="select apptblidval,colname fromstatus where assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by apptblidval",oids={1043,23,1043,1043,1043}) >>>> 2010-03-03 12:50:24,250 INFO [STDOUT] 12:50:24.250 (2) FE=> Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>) >>>> 2010-03-03 12:50:24,251 INFO [STDOUT] 12:50:24.251 (2) FE=> Describe(portal=null) >>>> 2010-03-03 12:50:24,252 INFO [STDOUT] 12:50:24.252 (2) FE=> Execute(portal=null,limit=0) >>>> 2010-03-03 12:50:24,253 INFO [STDOUT] 12:50:24.252 (2) FE=> Sync >>>> 2010-03-03 12:50:24,255 INFO [STDOUT] 12:50:24.255 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:50:24,256 INFO [STDOUT] 12:50:24.256 (2) <=BE CommandStatus(BEGIN) >>>> 2010-03-03 12:50:24,257 INFO [STDOUT] 12:50:24.257 (2) <=BE ParseComplete [null] >>>> 2010-03-03 12:50:24,258 INFO [STDOUT] 12:50:24.258 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:50:24,260 INFO [STDOUT] 12:50:24.260 (2) <=BE RowDescription(2) >>>> 2010-03-03 12:50:24,261 INFO [STDOUT] 12:50:24.261 (2) <=BE CommandStatus(SELECT) >>>> 2010-03-03 12:50:24,262 INFO [STDOUT] 12:50:24.262 (2) <=BE ReadyForQuery(T) >>>> 2010-03-03 12:50:24,263 INFO [STDOUT] 12:50:24.262 (2) XAResource 1291479: ending transaction xid = < 131075, 26, 24,1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e > >>>> 2010-03-03 12:50:24,264 INFO [STDOUT] 12:50:24.263 (2) XAResource 1291479: committing xid = < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e> (one phase) >>>> 2010-03-03 12:50:24,265 INFO [STDOUT] 12:50:24.265 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1217fef,maxRows=0, fetchSize=0, flags=22 >>>> 2010-03-03 12:50:24,266 INFO [STDOUT] 12:50:24.266 (2) FE=> Bind(stmt=S_2,portal=null) >>>> 2010-03-03 12:50:24,267 INFO [STDOUT] 12:50:24.267 (2) FE=> Execute(portal=null,limit=1) >>>> 2010-03-03 12:50:24,269 INFO [STDOUT] 12:50:24.269 (2) FE=> Sync >>>> 2010-03-03 12:50:24,272 INFO [STDOUT] 12:50:24.272 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:50:24,273 INFO [STDOUT] 12:50:24.273 (2) <=BE CommandStatus(COMMIT) >>>> 2010-03-03 12:50:24,274 INFO [STDOUT] 12:50:24.274 (2) <=BE ReadyForQuery(I) >>>> >>>> call to the java block - the one with con.setAutocommit(false) - again - 2nd time - this time we have a problem >>>> ================================================================= >>>> 2010-03-03 12:51:30,426 INFO [STDOUT] 12:51:30.426 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@13b64eb,maxRows=0, fetchSize=0, flags=17 >>>> 2010-03-03 12:51:30,427 INFO [STDOUT] 12:51:30.427 (2) FE=> Parse(stmt=null,query="select now()",oids={}) >>>> 2010-03-03 12:51:30,428 INFO [STDOUT] 12:51:30.428 (2) FE=> Bind(stmt=null,portal=null) >>>> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Describe(portal=null) >>>> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Execute(portal=null,limit=0) >>>> 2010-03-03 12:51:30,430 INFO [STDOUT] 12:51:30.430 (2) FE=> Sync >>>> 2010-03-03 12:51:30,433 INFO [STDOUT] 12:51:30.433 (2) <=BE ParseComplete [null] >>>> 2010-03-03 12:51:30,434 INFO [STDOUT] 12:51:30.434 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:51:30,435 INFO [STDOUT] 12:51:30.435 (2) <=BE RowDescription(1) >>>> 2010-03-03 12:51:30,436 INFO [STDOUT] 12:51:30.436 (2) <=BE DataRow >>>> 2010-03-03 12:51:30,437 INFO [STDOUT] 12:51:30.437 (2) <=BE CommandStatus(SELECT) >>>> 2010-03-03 12:51:30,440 INFO [STDOUT] 12:51:30.440 (2) <=BE ReadyForQuery(I) >>>> >>>> call to a java block with con.setAutocommit(true) >>>> ============================== >>>> 2010-03-03 12:55:42,028 INFO [STDOUT] 12:55:42.028 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@18526aa,maxRows=0, fetchSize=0, flags=17 >>>> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.028 (2) FE=> Parse(stmt=null,query="select now()",oids={}) >>>> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.029 (2) FE=> Bind(stmt=null,portal=null) >>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Describe(portal=null) >>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Execute(portal=null,limit=0) >>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Sync >>>> 2010-03-03 12:55:42,032 INFO [STDOUT] 12:55:42.032 (2) <=BE ParseComplete [null] >>>> 2010-03-03 12:55:42,033 INFO [STDOUT] 12:55:42.033 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:55:42,034 INFO [STDOUT] 12:55:42.034 (2) <=BE RowDescription(1) >>>> 2010-03-03 12:55:42,035 INFO [STDOUT] 12:55:42.035 (2) <=BE DataRow >>>> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.035 (2) <=BE CommandStatus(SELECT) >>>> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.036 (2) <=BE ReadyForQuery(I) >>>> >>>> call to the java block - the one with con.setAutocommit(false) - again - 3rd time - this time its ok again >>>> ============================================================== >>>> 2010-03-03 12:56:51,374 INFO [STDOUT] 12:56:51.374 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@14a5594,maxRows=0, fetchSize=0, flags=1 >>>> 2010-03-03 12:56:51,378 INFO [STDOUT] 12:56:51.378 (2) FE=> Bind(stmt=S_1,portal=null) >>>> 2010-03-03 12:56:51,380 INFO [STDOUT] 12:56:51.380 (2) FE=> Execute(portal=null,limit=0) >>>> 2010-03-03 12:56:51,385 INFO [STDOUT] 12:56:51.385 (2) FE=> Parse(stmt=null,query="select now()",oids={}) >>>> 2010-03-03 12:56:51,387 INFO [STDOUT] 12:56:51.387 (2) FE=> Bind(stmt=null,portal=null) >>>> 2010-03-03 12:56:51,388 INFO [STDOUT] 12:56:51.388 (2) FE=> Describe(portal=null) >>>> 2010-03-03 12:56:51,390 INFO [STDOUT] 12:56:51.390 (2) FE=> Execute(portal=null,limit=0) >>>> 2010-03-03 12:56:51,391 INFO [STDOUT] 12:56:51.391 (2) FE=> Sync >>>> 2010-03-03 12:56:51,393 INFO [STDOUT] 12:56:51.393 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:56:51,395 INFO [STDOUT] 12:56:51.395 (2) <=BE CommandStatus(BEGIN) >>>> 2010-03-03 12:56:51,397 INFO [STDOUT] 12:56:51.397 (2) <=BE ParseComplete [null] >>>> 2010-03-03 12:56:51,398 INFO [STDOUT] 12:56:51.398 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:56:51,399 INFO [STDOUT] 12:56:51.399 (2) <=BE RowDescription(1) >>>> 2010-03-03 12:56:51,400 INFO [STDOUT] 12:56:51.400 (2) <=BE DataRow >>>> 2010-03-03 12:56:51,402 INFO [STDOUT] 12:56:51.402 (2) <=BE CommandStatus(SELECT) >>>> 2010-03-03 12:56:51,404 INFO [STDOUT] 12:56:51.404 (2) <=BE ReadyForQuery(T) >>>> 2010-03-03 12:56:51,406 INFO [STDOUT] 12:56:51.406 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@13d3f62,maxRows=0, fetchSize=0, flags=22 >>>> 2010-03-03 12:56:51,409 INFO [STDOUT] 12:56:51.409 (2) FE=> Bind(stmt=S_2,portal=null) >>>> 2010-03-03 12:56:51,411 INFO [STDOUT] 12:56:51.411 (2) FE=> Execute(portal=null,limit=1) >>>> 2010-03-03 12:56:51,413 INFO [STDOUT] 12:56:51.413 (2) FE=> Sync >>>> 2010-03-03 12:56:51,417 INFO [STDOUT] 12:56:51.417 (2) <=BE BindComplete [null] >>>> 2010-03-03 12:56:51,419 INFO [STDOUT] 12:56:51.418 (2) <=BE CommandStatus(COMMIT) >>>> 2010-03-03 12:56:51,421 INFO [STDOUT] 12:56:51.421 (2) <=BE ReadyForQuery(I) >>>> >>>> Στις Wednesday 03 March 2010 12:30:37 ο/η Heikki Linnakangas έγραψε: >>>>> Achilleas Mantzios wrote: >>>>>> Στις Wednesday 03 March 2010 10:54:53 ο/η Heikki Linnakangas έγραψε: >>>>>>> Achilleas Mantzios wrote: >>>>>>>> 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. >>>>>>> If you can set logLevel to DEBUG (ie. loglevel=2 in connection string), >>>>>>> run the code, and send over the logs, that would help a lot. From that >>>>>>> we should see what exactly is the sequence of XA commands the JDBC >>>>>>> driver is receiving from JBoss. >>>>>> As loglevel configuration property to org.postgresql.ds.common.BaseDataSource is not supported in the lastest driver, >>>>>> i made this patch (i attach it) against postgresql-jdbc-8.4-701.src, also i set in jboss >>>>>> >>>>>> <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">xxxx</xa-datasource-property> >>>>>> <xa-datasource-property name="Compatible">8.2</xa-datasource-property> >>>>>> <xa-datasource-property name="Loglevel">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> >>>>>> >>>>>> But i dont see anything spectacular comming out of PostgreSQL logs. >>>>>> in postgresql.conf I have set >>>>>> client_min_messages = debug5 >>>>>> log_min_messages = debug5 >>>>> The extra logs should go somewhere in the client side, in one of the >>>>> jboss log files. If you can't find it, you can do something like this in >>>>> the application to redirect it to a file: >>>>> >>>>> java.io.Writer output = new >>>>> java.io.FileWriter("/tmp/postgresql-jdbc.debug.txt", true); >>>>> java.sql.DriverManager.setLogWriter(new >>>>> java.io.PrintWriter(output,true)); >>>>> >>>>> >>>>>> however playing with <xa-datasource-property name="Loglevel"></xa-datasource-property> does not seem to change a thing. >>>>>> Am i missing something? >>>>> Not sure why that's not working, but here's one way of setting loglevel: >>>>> >>>>> 1. Create file "org/postgresql/driverconfig.properties" with line >>>>> "loglevel=2" in it: >>>>> echo "loglevel=2" > org/postgresql/driverconfig.properties >>>>> 2. Add file to the driver jar: >>>>> jar uvf postgresql.jar org/postgresql/driverconfig.properties >>>>> >>>>> -- >>>>> Heikki Linnakangas >>>>> EnterpriseDB http://www.enterprisedb.com >>>>> >>>> >> >> > > -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Achilleas Mantzios
Date:
Στις Friday 23 April 2010 20:15:15 ο/η Heikki Linnakangas έγραψε: > I don't think these patches were ever committed. At least the smaller > one of them should be, this is a pretty scary bug because of the > interaction with JBoss. And the bigger patch adds sanity checks that > would be nice to have, maybe not for back-branches but for HEAD. > I second the above. In our case, we were haunted by this bug for many years it seems. Practically, this bug, under certain circumstances, made the whole JDBC xaction framework, simply useless, since it behaved like having set autocommit to on, even if *explicitly* set to off. I just want to say that Heikki's patch works very well, since the early March when it was applied. > Heikki Linnakangas wrote: > > Okay, thanks, I see what's going on now. > > > > There's two things contributing to this: > > > > * When you call setAutoCommit(false) on a connection acquired from a > > PGXAConnection, in a local transaction, and subsequently use the > > connection for XA transaction, the driver puts the connection back into > > autocommit mode. Looking at the JDBC spec, I don't think the driver > > should be doing that; when the XA transaction ends, autocommit mode > > should be restored to whatever it was before. > > > > * Even though you explicitly call setAutoCommit(false) in the 2nd > > invocation of the java block, JBoss intercepts the call and turns it > > into a no-op, because it remembers that setAutoCommit(false) was already > > called on the connection in the first invocation of that. But the driver > > turned on autocommit mode behind its back, so the connection is in fact > > in autocommit mode even though JBoss thinks it's not, and despite the > > application explicitly called setAutoCommit(false). > > > > Sometimes I want to punch the designers of the JTA API in the face, it's > > unnecessarily complicated with all those interactions between local and > > XA transactions, sharing connections between transactions, transaction > > suspend/resume etc. But it is what it is and we have to live with it :-(. > > > > Attached is a patch to fix the issue by remembering the autocommit > > status of the connection when an XA transaction is started and to > > restore it after it ends (fix-jboss-autocommit-issue-2.patch). > > > > While we're at it, the other attached patch includes the changes from > > the first patch, plus some sanity checks. It throws an error if you call > > setAutoCommit/commit/rollback/setSavePoint in an XA transaction. That's > > forbidden according to the JDBC spec, but we haven't enforced it before > > (the behavior is not well-defined if you do it). It also throws an error > > if you call XAResource.commit(..., true) (ie. COMMIT PREPARED) using a > > connection that's being used for a local transaction. That currently > > silently commits the local transaction, which is bad. It adds another > > layer of reflection the calls on Connection objects, but that shouldn't > > be that performance critical, correctness is much more important. > > > > Attached is also a stand-alone test case exhibiting the same sequence of > > calls that JBoss produced in this scenario, so that we have that > > archived for future reference. > > > > Achilleas Mantzios wrote: > >> Your test case worked as you described. > >> I send you an ear app which you can deploy in a jboss-4.2.x, Postgresql must be defined as <jndi-name>pgsql</jndi-name> > >> in xa-datasource inside jboss's deploy dir. > >> You can go to the app by hitting: http://localhost/xabug and looking at the directions there. > >> > >> Again, thanx for caring, and lets see if you can figure smth out off this. > >> > >> Στις Wednesday 03 March 2010 14:25:20 ο/η Heikki Linnakangas έγραψε: > >>> Thanks! > >>> > >>> I tried to reproduce that with the attached test program. It's doing > >>> essentially the same thing you did, right? The program works fine here, > >>> producing a log identical to what you sent, except that I'm not seeing > >>> the incorrect behavior you're seeing; the INSERT in the 2nd java block > >>> is wrapped with BEGIN/COMMIT just like the 1st one. > >>> > >>> I don't understand why we're seeing different behavior with what should > >>> be the same sequence of calls as far as the driver is concerned. Can you > >>> try the attached patch, rerun the test case, and send over the logs > >>> again? The patch adds some logging to see all the setAutoCommit() and > >>> commit/rollback calls, maybe that sheds some light on this. > >>> > >>> BTW, you are using a recent version of the driver, right? There was some > >>> fixes to setAutoCommit() and XA interactions a few years ago. > >>> > >>> Achilleas Mantzios wrote: > >>>> Thanx > >>>> Here are the logs: > >>>> > >>>> call to the ejb > >>>> ========= > >>>> 2010-03-03 12:47:57,177 INFO [STDOUT] 12:47:57.177 (2) XAResource 1291479: starting transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 > > >>>> 2010-03-03 12:47:57,181 INFO [STDOUT] 12:47:57.180 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@dd0f87,maxRows=0, fetchSize=0, flags=1 > >>>> 2010-03-03 12:47:57,184 INFO [STDOUT] 12:47:57.183 (2) FE=> Parse(stmt=S_1,query="BEGIN",oids={}) > >>>> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.184 (2) FE=> Bind(stmt=S_1,portal=null) > >>>> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.185 (2) FE=> Execute(portal=null,limit=0) > >>>> 2010-03-03 12:47:57,186 INFO [STDOUT] 12:47:57.186 (2) FE=> Parse(stmt=null,query="select apptblidval,colname fromstatus where assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by apptblidval",oids={1043,23,1043,1043,1043}) > >>>> 2010-03-03 12:47:57,188 INFO [STDOUT] 12:47:57.187 (2) FE=> Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>) > >>>> 2010-03-03 12:47:57,189 INFO [STDOUT] 12:47:57.189 (2) FE=> Describe(portal=null) > >>>> 2010-03-03 12:47:57,190 INFO [STDOUT] 12:47:57.190 (2) FE=> Execute(portal=null,limit=0) > >>>> 2010-03-03 12:47:57,192 INFO [STDOUT] 12:47:57.192 (2) FE=> Sync > >>>> 2010-03-03 12:47:57,199 INFO [STDOUT] 12:47:57.199 (2) <=BE ParseComplete [S_1] > >>>> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE CommandStatus(BEGIN) > >>>> 2010-03-03 12:47:57,201 INFO [STDOUT] 12:47:57.201 (2) <=BE ParseComplete [null] > >>>> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.201 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.202 (2) <=BE RowDescription(2) > >>>> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE CommandStatus(SELECT) > >>>> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE ReadyForQuery(T) > >>>> 2010-03-03 12:47:57,206 INFO [STDOUT] 12:47:57.204 (2) XAResource 1291479: ending transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 > > >>>> 2010-03-03 12:47:57,211 INFO [STDOUT] 12:47:57.211 (2) XAResource 1291479: committing xid = < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34> (one phase) > >>>> 2010-03-03 12:47:57,217 INFO [STDOUT] 12:47:57.217 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1a9b034,maxRows=0, fetchSize=0, flags=22 > >>>> 2010-03-03 12:47:57,225 INFO [STDOUT] 12:47:57.225 (2) FE=> Parse(stmt=S_2,query="COMMIT",oids={}) > >>>> 2010-03-03 12:47:57,227 INFO [STDOUT] 12:47:57.227 (2) FE=> Bind(stmt=S_2,portal=null) > >>>> 2010-03-03 12:47:57,229 INFO [STDOUT] 12:47:57.228 (2) FE=> Execute(portal=null,limit=1) > >>>> 2010-03-03 12:47:57,237 INFO [STDOUT] 12:47:57.237 (2) FE=> Sync > >>>> 2010-03-03 12:47:57,246 INFO [STDOUT] 12:47:57.246 (2) <=BE ParseComplete [S_2] > >>>> 2010-03-03 12:47:57,248 INFO [STDOUT] 12:47:57.248 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:47:57,250 INFO [STDOUT] 12:47:57.250 (2) <=BE CommandStatus(COMMIT) > >>>> 2010-03-03 12:47:57,251 INFO [STDOUT] 12:47:57.251 (2) <=BE ReadyForQuery(I) > >>>> > >>>> > >>>> call to the java block - the one with con.setAutocommit(false) - (as we see below its fine the very first time) > >>>> ================================================================= > >>>> 2010-03-03 12:49:31,892 INFO [STDOUT] 12:49:31.892 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@19331eb,maxRows=0, fetchSize=0, flags=1 > >>>> 2010-03-03 12:49:31,893 INFO [STDOUT] 12:49:31.893 (2) FE=> Bind(stmt=S_1,portal=null) > >>>> 2010-03-03 12:49:31,895 INFO [STDOUT] 12:49:31.895 (2) FE=> Execute(portal=null,limit=0) > >>>> 2010-03-03 12:49:31,896 INFO [STDOUT] 12:49:31.895 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > >>>> 2010-03-03 12:49:31,897 INFO [STDOUT] 12:49:31.897 (2) FE=> Bind(stmt=null,portal=null) > >>>> 2010-03-03 12:49:31,898 INFO [STDOUT] 12:49:31.898 (2) FE=> Describe(portal=null) > >>>> 2010-03-03 12:49:31,899 INFO [STDOUT] 12:49:31.899 (2) FE=> Execute(portal=null,limit=0) > >>>> 2010-03-03 12:49:31,901 INFO [STDOUT] 12:49:31.901 (2) FE=> Sync > >>>> 2010-03-03 12:49:31,903 INFO [STDOUT] 12:49:31.902 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE CommandStatus(BEGIN) > >>>> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE ParseComplete [null] > >>>> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE RowDescription(1) > >>>> 2010-03-03 12:49:31,906 INFO [STDOUT] 12:49:31.906 (2) <=BE DataRow > >>>> 2010-03-03 12:49:31,907 INFO [STDOUT] 12:49:31.907 (2) <=BE CommandStatus(SELECT) > >>>> 2010-03-03 12:49:31,908 INFO [STDOUT] 12:49:31.908 (2) <=BE ReadyForQuery(T) > >>>> 2010-03-03 12:49:31,909 INFO [STDOUT] 12:49:31.909 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1d7ce63,maxRows=0, fetchSize=0, flags=22 > >>>> 2010-03-03 12:49:31,910 INFO [STDOUT] 12:49:31.910 (2) FE=> Bind(stmt=S_2,portal=null) > >>>> 2010-03-03 12:49:31,911 INFO [STDOUT] 12:49:31.911 (2) FE=> Execute(portal=null,limit=1) > >>>> 2010-03-03 12:49:31,913 INFO [STDOUT] 12:49:31.912 (2) FE=> Sync > >>>> 2010-03-03 12:49:31,915 INFO [STDOUT] 12:49:31.915 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:49:31,916 INFO [STDOUT] 12:49:31.916 (2) <=BE CommandStatus(COMMIT) > >>>> 2010-03-03 12:49:31,917 INFO [STDOUT] 12:49:31.917 (2) <=BE ReadyForQuery(I) > >>>> > >>>> call to the ejb (again - 2nd time) > >>>> ==================== > >>>> 2010-03-03 12:50:24,246 INFO [STDOUT] 12:50:24.245 (2) XAResource 1291479: starting transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e > > >>>> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.247 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@a06e8d,maxRows=0, fetchSize=0, flags=1 > >>>> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.248 (2) FE=> Bind(stmt=S_1,portal=null) > >>>> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Execute(portal=null,limit=0) > >>>> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Parse(stmt=null,query="select apptblidval,colname fromstatus where assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by apptblidval",oids={1043,23,1043,1043,1043}) > >>>> 2010-03-03 12:50:24,250 INFO [STDOUT] 12:50:24.250 (2) FE=> Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>) > >>>> 2010-03-03 12:50:24,251 INFO [STDOUT] 12:50:24.251 (2) FE=> Describe(portal=null) > >>>> 2010-03-03 12:50:24,252 INFO [STDOUT] 12:50:24.252 (2) FE=> Execute(portal=null,limit=0) > >>>> 2010-03-03 12:50:24,253 INFO [STDOUT] 12:50:24.252 (2) FE=> Sync > >>>> 2010-03-03 12:50:24,255 INFO [STDOUT] 12:50:24.255 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:50:24,256 INFO [STDOUT] 12:50:24.256 (2) <=BE CommandStatus(BEGIN) > >>>> 2010-03-03 12:50:24,257 INFO [STDOUT] 12:50:24.257 (2) <=BE ParseComplete [null] > >>>> 2010-03-03 12:50:24,258 INFO [STDOUT] 12:50:24.258 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:50:24,260 INFO [STDOUT] 12:50:24.260 (2) <=BE RowDescription(2) > >>>> 2010-03-03 12:50:24,261 INFO [STDOUT] 12:50:24.261 (2) <=BE CommandStatus(SELECT) > >>>> 2010-03-03 12:50:24,262 INFO [STDOUT] 12:50:24.262 (2) <=BE ReadyForQuery(T) > >>>> 2010-03-03 12:50:24,263 INFO [STDOUT] 12:50:24.262 (2) XAResource 1291479: ending transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e > > >>>> 2010-03-03 12:50:24,264 INFO [STDOUT] 12:50:24.263 (2) XAResource 1291479: committing xid = < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e> (one phase) > >>>> 2010-03-03 12:50:24,265 INFO [STDOUT] 12:50:24.265 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1217fef,maxRows=0, fetchSize=0, flags=22 > >>>> 2010-03-03 12:50:24,266 INFO [STDOUT] 12:50:24.266 (2) FE=> Bind(stmt=S_2,portal=null) > >>>> 2010-03-03 12:50:24,267 INFO [STDOUT] 12:50:24.267 (2) FE=> Execute(portal=null,limit=1) > >>>> 2010-03-03 12:50:24,269 INFO [STDOUT] 12:50:24.269 (2) FE=> Sync > >>>> 2010-03-03 12:50:24,272 INFO [STDOUT] 12:50:24.272 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:50:24,273 INFO [STDOUT] 12:50:24.273 (2) <=BE CommandStatus(COMMIT) > >>>> 2010-03-03 12:50:24,274 INFO [STDOUT] 12:50:24.274 (2) <=BE ReadyForQuery(I) > >>>> > >>>> call to the java block - the one with con.setAutocommit(false) - again - 2nd time - this time we have a problem > >>>> ================================================================= > >>>> 2010-03-03 12:51:30,426 INFO [STDOUT] 12:51:30.426 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@13b64eb,maxRows=0, fetchSize=0, flags=17 > >>>> 2010-03-03 12:51:30,427 INFO [STDOUT] 12:51:30.427 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > >>>> 2010-03-03 12:51:30,428 INFO [STDOUT] 12:51:30.428 (2) FE=> Bind(stmt=null,portal=null) > >>>> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Describe(portal=null) > >>>> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Execute(portal=null,limit=0) > >>>> 2010-03-03 12:51:30,430 INFO [STDOUT] 12:51:30.430 (2) FE=> Sync > >>>> 2010-03-03 12:51:30,433 INFO [STDOUT] 12:51:30.433 (2) <=BE ParseComplete [null] > >>>> 2010-03-03 12:51:30,434 INFO [STDOUT] 12:51:30.434 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:51:30,435 INFO [STDOUT] 12:51:30.435 (2) <=BE RowDescription(1) > >>>> 2010-03-03 12:51:30,436 INFO [STDOUT] 12:51:30.436 (2) <=BE DataRow > >>>> 2010-03-03 12:51:30,437 INFO [STDOUT] 12:51:30.437 (2) <=BE CommandStatus(SELECT) > >>>> 2010-03-03 12:51:30,440 INFO [STDOUT] 12:51:30.440 (2) <=BE ReadyForQuery(I) > >>>> > >>>> call to a java block with con.setAutocommit(true) > >>>> ============================== > >>>> 2010-03-03 12:55:42,028 INFO [STDOUT] 12:55:42.028 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@18526aa,maxRows=0, fetchSize=0, flags=17 > >>>> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.028 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > >>>> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.029 (2) FE=> Bind(stmt=null,portal=null) > >>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Describe(portal=null) > >>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Execute(portal=null,limit=0) > >>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Sync > >>>> 2010-03-03 12:55:42,032 INFO [STDOUT] 12:55:42.032 (2) <=BE ParseComplete [null] > >>>> 2010-03-03 12:55:42,033 INFO [STDOUT] 12:55:42.033 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:55:42,034 INFO [STDOUT] 12:55:42.034 (2) <=BE RowDescription(1) > >>>> 2010-03-03 12:55:42,035 INFO [STDOUT] 12:55:42.035 (2) <=BE DataRow > >>>> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.035 (2) <=BE CommandStatus(SELECT) > >>>> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.036 (2) <=BE ReadyForQuery(I) > >>>> > >>>> call to the java block - the one with con.setAutocommit(false) - again - 3rd time - this time its ok again > >>>> ============================================================== > >>>> 2010-03-03 12:56:51,374 INFO [STDOUT] 12:56:51.374 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@14a5594,maxRows=0, fetchSize=0, flags=1 > >>>> 2010-03-03 12:56:51,378 INFO [STDOUT] 12:56:51.378 (2) FE=> Bind(stmt=S_1,portal=null) > >>>> 2010-03-03 12:56:51,380 INFO [STDOUT] 12:56:51.380 (2) FE=> Execute(portal=null,limit=0) > >>>> 2010-03-03 12:56:51,385 INFO [STDOUT] 12:56:51.385 (2) FE=> Parse(stmt=null,query="select now()",oids={}) > >>>> 2010-03-03 12:56:51,387 INFO [STDOUT] 12:56:51.387 (2) FE=> Bind(stmt=null,portal=null) > >>>> 2010-03-03 12:56:51,388 INFO [STDOUT] 12:56:51.388 (2) FE=> Describe(portal=null) > >>>> 2010-03-03 12:56:51,390 INFO [STDOUT] 12:56:51.390 (2) FE=> Execute(portal=null,limit=0) > >>>> 2010-03-03 12:56:51,391 INFO [STDOUT] 12:56:51.391 (2) FE=> Sync > >>>> 2010-03-03 12:56:51,393 INFO [STDOUT] 12:56:51.393 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:56:51,395 INFO [STDOUT] 12:56:51.395 (2) <=BE CommandStatus(BEGIN) > >>>> 2010-03-03 12:56:51,397 INFO [STDOUT] 12:56:51.397 (2) <=BE ParseComplete [null] > >>>> 2010-03-03 12:56:51,398 INFO [STDOUT] 12:56:51.398 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:56:51,399 INFO [STDOUT] 12:56:51.399 (2) <=BE RowDescription(1) > >>>> 2010-03-03 12:56:51,400 INFO [STDOUT] 12:56:51.400 (2) <=BE DataRow > >>>> 2010-03-03 12:56:51,402 INFO [STDOUT] 12:56:51.402 (2) <=BE CommandStatus(SELECT) > >>>> 2010-03-03 12:56:51,404 INFO [STDOUT] 12:56:51.404 (2) <=BE ReadyForQuery(T) > >>>> 2010-03-03 12:56:51,406 INFO [STDOUT] 12:56:51.406 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@13d3f62,maxRows=0, fetchSize=0, flags=22 > >>>> 2010-03-03 12:56:51,409 INFO [STDOUT] 12:56:51.409 (2) FE=> Bind(stmt=S_2,portal=null) > >>>> 2010-03-03 12:56:51,411 INFO [STDOUT] 12:56:51.411 (2) FE=> Execute(portal=null,limit=1) > >>>> 2010-03-03 12:56:51,413 INFO [STDOUT] 12:56:51.413 (2) FE=> Sync > >>>> 2010-03-03 12:56:51,417 INFO [STDOUT] 12:56:51.417 (2) <=BE BindComplete [null] > >>>> 2010-03-03 12:56:51,419 INFO [STDOUT] 12:56:51.418 (2) <=BE CommandStatus(COMMIT) > >>>> 2010-03-03 12:56:51,421 INFO [STDOUT] 12:56:51.421 (2) <=BE ReadyForQuery(I) > >>>> > >>>> Στις Wednesday 03 March 2010 12:30:37 ο/η Heikki Linnakangas έγραψε: > >>>>> Achilleas Mantzios wrote: > >>>>>> Στις Wednesday 03 March 2010 10:54:53 ο/η Heikki Linnakangas έγραψε: > >>>>>>> Achilleas Mantzios wrote: > >>>>>>>> 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. > >>>>>>> If you can set logLevel to DEBUG (ie. loglevel=2 in connection string), > >>>>>>> run the code, and send over the logs, that would help a lot. From that > >>>>>>> we should see what exactly is the sequence of XA commands the JDBC > >>>>>>> driver is receiving from JBoss. > >>>>>> As loglevel configuration property to org.postgresql.ds.common.BaseDataSource is not supported in the lastest driver, > >>>>>> i made this patch (i attach it) against postgresql-jdbc-8.4-701.src, also i set in jboss > >>>>>> > >>>>>> <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">xxxx</xa-datasource-property> > >>>>>> <xa-datasource-property name="Compatible">8.2</xa-datasource-property> > >>>>>> <xa-datasource-property name="Loglevel">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> > >>>>>> > >>>>>> But i dont see anything spectacular comming out of PostgreSQL logs. > >>>>>> in postgresql.conf I have set > >>>>>> client_min_messages = debug5 > >>>>>> log_min_messages = debug5 > >>>>> The extra logs should go somewhere in the client side, in one of the > >>>>> jboss log files. If you can't find it, you can do something like this in > >>>>> the application to redirect it to a file: > >>>>> > >>>>> java.io.Writer output = new > >>>>> java.io.FileWriter("/tmp/postgresql-jdbc.debug.txt", true); > >>>>> java.sql.DriverManager.setLogWriter(new > >>>>> java.io.PrintWriter(output,true)); > >>>>> > >>>>> > >>>>>> however playing with <xa-datasource-property name="Loglevel"></xa-datasource-property> does not seem to change athing. > >>>>>> Am i missing something? > >>>>> Not sure why that's not working, but here's one way of setting loglevel: > >>>>> > >>>>> 1. Create file "org/postgresql/driverconfig.properties" with line > >>>>> "loglevel=2" in it: > >>>>> echo "loglevel=2" > org/postgresql/driverconfig.properties > >>>>> 2. Add file to the driver jar: > >>>>> jar uvf postgresql.jar org/postgresql/driverconfig.properties > >>>>> > >>>>> -- > >>>>> Heikki Linnakangas > >>>>> EnterpriseDB http://www.enterprisedb.com > >>>>> > >>>> > >> > >> > > > > > > > -- > Heikki Linnakangas > EnterpriseDB http://www.enterprisedb.com > -- Achilleas Mantzios
Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar
From
Kris Jurka
Date:
Applied. Kris Jurka On Fri, 23 Apr 2010, Heikki Linnakangas wrote: > I don't think these patches were ever committed. At least the smaller > one of them should be, this is a pretty scary bug because of the > interaction with JBoss. And the bigger patch adds sanity checks that > would be nice to have, maybe not for back-branches but for HEAD. > > Heikki Linnakangas wrote: >> Okay, thanks, I see what's going on now. >> >> There's two things contributing to this: >> >> * When you call setAutoCommit(false) on a connection acquired from a >> PGXAConnection, in a local transaction, and subsequently use the >> connection for XA transaction, the driver puts the connection back into >> autocommit mode. Looking at the JDBC spec, I don't think the driver >> should be doing that; when the XA transaction ends, autocommit mode >> should be restored to whatever it was before. >> >> * Even though you explicitly call setAutoCommit(false) in the 2nd >> invocation of the java block, JBoss intercepts the call and turns it >> into a no-op, because it remembers that setAutoCommit(false) was already >> called on the connection in the first invocation of that. But the driver >> turned on autocommit mode behind its back, so the connection is in fact >> in autocommit mode even though JBoss thinks it's not, and despite the >> application explicitly called setAutoCommit(false). >> >> Sometimes I want to punch the designers of the JTA API in the face, it's >> unnecessarily complicated with all those interactions between local and >> XA transactions, sharing connections between transactions, transaction >> suspend/resume etc. But it is what it is and we have to live with it :-(. >> >> Attached is a patch to fix the issue by remembering the autocommit >> status of the connection when an XA transaction is started and to >> restore it after it ends (fix-jboss-autocommit-issue-2.patch). >> >> While we're at it, the other attached patch includes the changes from >> the first patch, plus some sanity checks. It throws an error if you call >> setAutoCommit/commit/rollback/setSavePoint in an XA transaction. That's >> forbidden according to the JDBC spec, but we haven't enforced it before >> (the behavior is not well-defined if you do it). It also throws an error >> if you call XAResource.commit(..., true) (ie. COMMIT PREPARED) using a >> connection that's being used for a local transaction. That currently >> silently commits the local transaction, which is bad. It adds another >> layer of reflection the calls on Connection objects, but that shouldn't >> be that performance critical, correctness is much more important. >> >> Attached is also a stand-alone test case exhibiting the same sequence of >> calls that JBoss produced in this scenario, so that we have that >> archived for future reference. >> >> Achilleas Mantzios wrote: >>> Your test case worked as you described. >>> I send you an ear app which you can deploy in a jboss-4.2.x, Postgresql must be defined as <jndi-name>pgsql</jndi-name> >>> in xa-datasource inside jboss's deploy dir. >>> You can go to the app by hitting: http://localhost/xabug and looking at the directions there. >>> >>> Again, thanx for caring, and lets see if you can figure smth out off this. >>> >>> ???? Wednesday 03 March 2010 14:25:20 ?/? Heikki Linnakangas ??????: >>>> Thanks! >>>> >>>> I tried to reproduce that with the attached test program. It's doing >>>> essentially the same thing you did, right? The program works fine here, >>>> producing a log identical to what you sent, except that I'm not seeing >>>> the incorrect behavior you're seeing; the INSERT in the 2nd java block >>>> is wrapped with BEGIN/COMMIT just like the 1st one. >>>> >>>> I don't understand why we're seeing different behavior with what should >>>> be the same sequence of calls as far as the driver is concerned. Can you >>>> try the attached patch, rerun the test case, and send over the logs >>>> again? The patch adds some logging to see all the setAutoCommit() and >>>> commit/rollback calls, maybe that sheds some light on this. >>>> >>>> BTW, you are using a recent version of the driver, right? There was some >>>> fixes to setAutoCommit() and XA interactions a few years ago. >>>> >>>> Achilleas Mantzios wrote: >>>>> Thanx >>>>> Here are the logs: >>>>> >>>>> call to the ejb >>>>> ========= >>>>> 2010-03-03 12:47:57,177 INFO [STDOUT] 12:47:57.177 (2) XAResource 1291479: starting transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 > >>>>> 2010-03-03 12:47:57,181 INFO [STDOUT] 12:47:57.180 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@dd0f87,maxRows=0, fetchSize=0, flags=1 >>>>> 2010-03-03 12:47:57,184 INFO [STDOUT] 12:47:57.183 (2) FE=> Parse(stmt=S_1,query="BEGIN",oids={}) >>>>> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.184 (2) FE=> Bind(stmt=S_1,portal=null) >>>>> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.185 (2) FE=> Execute(portal=null,limit=0) >>>>> 2010-03-03 12:47:57,186 INFO [STDOUT] 12:47:57.186 (2) FE=> Parse(stmt=null,query="select apptblidval,colname fromstatus where assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by apptblidval",oids={1043,23,1043,1043,1043}) >>>>> 2010-03-03 12:47:57,188 INFO [STDOUT] 12:47:57.187 (2) FE=> Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>) >>>>> 2010-03-03 12:47:57,189 INFO [STDOUT] 12:47:57.189 (2) FE=> Describe(portal=null) >>>>> 2010-03-03 12:47:57,190 INFO [STDOUT] 12:47:57.190 (2) FE=> Execute(portal=null,limit=0) >>>>> 2010-03-03 12:47:57,192 INFO [STDOUT] 12:47:57.192 (2) FE=> Sync >>>>> 2010-03-03 12:47:57,199 INFO [STDOUT] 12:47:57.199 (2) <=BE ParseComplete [S_1] >>>>> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=BE CommandStatus(BEGIN) >>>>> 2010-03-03 12:47:57,201 INFO [STDOUT] 12:47:57.201 (2) <=BE ParseComplete [null] >>>>> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.201 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.202 (2) <=BE RowDescription(2) >>>>> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE CommandStatus(SELECT) >>>>> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=BE ReadyForQuery(T) >>>>> 2010-03-03 12:47:57,206 INFO [STDOUT] 12:47:57.204 (2) XAResource 1291479: ending transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34 > >>>>> 2010-03-03 12:47:57,211 INFO [STDOUT] 12:47:57.211 (2) XAResource 1291479: committing xid = < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:32a09c8d8:d10e:4b8e3e06:34> (one phase) >>>>> 2010-03-03 12:47:57,217 INFO [STDOUT] 12:47:57.217 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1a9b034,maxRows=0, fetchSize=0, flags=22 >>>>> 2010-03-03 12:47:57,225 INFO [STDOUT] 12:47:57.225 (2) FE=> Parse(stmt=S_2,query="COMMIT",oids={}) >>>>> 2010-03-03 12:47:57,227 INFO [STDOUT] 12:47:57.227 (2) FE=> Bind(stmt=S_2,portal=null) >>>>> 2010-03-03 12:47:57,229 INFO [STDOUT] 12:47:57.228 (2) FE=> Execute(portal=null,limit=1) >>>>> 2010-03-03 12:47:57,237 INFO [STDOUT] 12:47:57.237 (2) FE=> Sync >>>>> 2010-03-03 12:47:57,246 INFO [STDOUT] 12:47:57.246 (2) <=BE ParseComplete [S_2] >>>>> 2010-03-03 12:47:57,248 INFO [STDOUT] 12:47:57.248 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:47:57,250 INFO [STDOUT] 12:47:57.250 (2) <=BE CommandStatus(COMMIT) >>>>> 2010-03-03 12:47:57,251 INFO [STDOUT] 12:47:57.251 (2) <=BE ReadyForQuery(I) >>>>> >>>>> >>>>> call to the java block - the one with con.setAutocommit(false) - (as we see below its fine the very first time) >>>>> ================================================================= >>>>> 2010-03-03 12:49:31,892 INFO [STDOUT] 12:49:31.892 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@19331eb,maxRows=0, fetchSize=0, flags=1 >>>>> 2010-03-03 12:49:31,893 INFO [STDOUT] 12:49:31.893 (2) FE=> Bind(stmt=S_1,portal=null) >>>>> 2010-03-03 12:49:31,895 INFO [STDOUT] 12:49:31.895 (2) FE=> Execute(portal=null,limit=0) >>>>> 2010-03-03 12:49:31,896 INFO [STDOUT] 12:49:31.895 (2) FE=> Parse(stmt=null,query="select now()",oids={}) >>>>> 2010-03-03 12:49:31,897 INFO [STDOUT] 12:49:31.897 (2) FE=> Bind(stmt=null,portal=null) >>>>> 2010-03-03 12:49:31,898 INFO [STDOUT] 12:49:31.898 (2) FE=> Describe(portal=null) >>>>> 2010-03-03 12:49:31,899 INFO [STDOUT] 12:49:31.899 (2) FE=> Execute(portal=null,limit=0) >>>>> 2010-03-03 12:49:31,901 INFO [STDOUT] 12:49:31.901 (2) FE=> Sync >>>>> 2010-03-03 12:49:31,903 INFO [STDOUT] 12:49:31.902 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE CommandStatus(BEGIN) >>>>> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=BE ParseComplete [null] >>>>> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=BE RowDescription(1) >>>>> 2010-03-03 12:49:31,906 INFO [STDOUT] 12:49:31.906 (2) <=BE DataRow >>>>> 2010-03-03 12:49:31,907 INFO [STDOUT] 12:49:31.907 (2) <=BE CommandStatus(SELECT) >>>>> 2010-03-03 12:49:31,908 INFO [STDOUT] 12:49:31.908 (2) <=BE ReadyForQuery(T) >>>>> 2010-03-03 12:49:31,909 INFO [STDOUT] 12:49:31.909 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1d7ce63,maxRows=0, fetchSize=0, flags=22 >>>>> 2010-03-03 12:49:31,910 INFO [STDOUT] 12:49:31.910 (2) FE=> Bind(stmt=S_2,portal=null) >>>>> 2010-03-03 12:49:31,911 INFO [STDOUT] 12:49:31.911 (2) FE=> Execute(portal=null,limit=1) >>>>> 2010-03-03 12:49:31,913 INFO [STDOUT] 12:49:31.912 (2) FE=> Sync >>>>> 2010-03-03 12:49:31,915 INFO [STDOUT] 12:49:31.915 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:49:31,916 INFO [STDOUT] 12:49:31.916 (2) <=BE CommandStatus(COMMIT) >>>>> 2010-03-03 12:49:31,917 INFO [STDOUT] 12:49:31.917 (2) <=BE ReadyForQuery(I) >>>>> >>>>> call to the ejb (again - 2nd time) >>>>> ==================== >>>>> 2010-03-03 12:50:24,246 INFO [STDOUT] 12:50:24.245 (2) XAResource 1291479: starting transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e > >>>>> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.247 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@a06e8d,maxRows=0, fetchSize=0, flags=1 >>>>> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.248 (2) FE=> Bind(stmt=S_1,portal=null) >>>>> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Execute(portal=null,limit=0) >>>>> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=> Parse(stmt=null,query="select apptblidval,colname fromstatus where assettable=$1 and assetidval=$2 and appname=$3 and apptblname=$4 and status=$5 and isvalid order by apptblidval",oids={1043,23,1043,1043,1043}) >>>>> 2010-03-03 12:50:24,250 INFO [STDOUT] 12:50:24.250 (2) FE=> Bind(stmt=null,portal=null,$1=<'mariner'>,$2=<'14173'>,$3=<'Crew'>,$4=<'marinercourses'>,$5=<'warn'>) >>>>> 2010-03-03 12:50:24,251 INFO [STDOUT] 12:50:24.251 (2) FE=> Describe(portal=null) >>>>> 2010-03-03 12:50:24,252 INFO [STDOUT] 12:50:24.252 (2) FE=> Execute(portal=null,limit=0) >>>>> 2010-03-03 12:50:24,253 INFO [STDOUT] 12:50:24.252 (2) FE=> Sync >>>>> 2010-03-03 12:50:24,255 INFO [STDOUT] 12:50:24.255 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:50:24,256 INFO [STDOUT] 12:50:24.256 (2) <=BE CommandStatus(BEGIN) >>>>> 2010-03-03 12:50:24,257 INFO [STDOUT] 12:50:24.257 (2) <=BE ParseComplete [null] >>>>> 2010-03-03 12:50:24,258 INFO [STDOUT] 12:50:24.258 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:50:24,260 INFO [STDOUT] 12:50:24.260 (2) <=BE RowDescription(2) >>>>> 2010-03-03 12:50:24,261 INFO [STDOUT] 12:50:24.261 (2) <=BE CommandStatus(SELECT) >>>>> 2010-03-03 12:50:24,262 INFO [STDOUT] 12:50:24.262 (2) <=BE ReadyForQuery(T) >>>>> 2010-03-03 12:50:24,263 INFO [STDOUT] 12:50:24.262 (2) XAResource 1291479: ending transaction xid = < 131075, 26,24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e > >>>>> 2010-03-03 12:50:24,264 INFO [STDOUT] 12:50:24.263 (2) XAResource 1291479: committing xid = < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:3ca09c8d8:d10e:4b8e3e06:3e> (one phase) >>>>> 2010-03-03 12:50:24,265 INFO [STDOUT] 12:50:24.265 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@1217fef,maxRows=0, fetchSize=0, flags=22 >>>>> 2010-03-03 12:50:24,266 INFO [STDOUT] 12:50:24.266 (2) FE=> Bind(stmt=S_2,portal=null) >>>>> 2010-03-03 12:50:24,267 INFO [STDOUT] 12:50:24.267 (2) FE=> Execute(portal=null,limit=1) >>>>> 2010-03-03 12:50:24,269 INFO [STDOUT] 12:50:24.269 (2) FE=> Sync >>>>> 2010-03-03 12:50:24,272 INFO [STDOUT] 12:50:24.272 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:50:24,273 INFO [STDOUT] 12:50:24.273 (2) <=BE CommandStatus(COMMIT) >>>>> 2010-03-03 12:50:24,274 INFO [STDOUT] 12:50:24.274 (2) <=BE ReadyForQuery(I) >>>>> >>>>> call to the java block - the one with con.setAutocommit(false) - again - 2nd time - this time we have a problem >>>>> ================================================================= >>>>> 2010-03-03 12:51:30,426 INFO [STDOUT] 12:51:30.426 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@13b64eb,maxRows=0, fetchSize=0, flags=17 >>>>> 2010-03-03 12:51:30,427 INFO [STDOUT] 12:51:30.427 (2) FE=> Parse(stmt=null,query="select now()",oids={}) >>>>> 2010-03-03 12:51:30,428 INFO [STDOUT] 12:51:30.428 (2) FE=> Bind(stmt=null,portal=null) >>>>> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Describe(portal=null) >>>>> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=> Execute(portal=null,limit=0) >>>>> 2010-03-03 12:51:30,430 INFO [STDOUT] 12:51:30.430 (2) FE=> Sync >>>>> 2010-03-03 12:51:30,433 INFO [STDOUT] 12:51:30.433 (2) <=BE ParseComplete [null] >>>>> 2010-03-03 12:51:30,434 INFO [STDOUT] 12:51:30.434 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:51:30,435 INFO [STDOUT] 12:51:30.435 (2) <=BE RowDescription(1) >>>>> 2010-03-03 12:51:30,436 INFO [STDOUT] 12:51:30.436 (2) <=BE DataRow >>>>> 2010-03-03 12:51:30,437 INFO [STDOUT] 12:51:30.437 (2) <=BE CommandStatus(SELECT) >>>>> 2010-03-03 12:51:30,440 INFO [STDOUT] 12:51:30.440 (2) <=BE ReadyForQuery(I) >>>>> >>>>> call to a java block with con.setAutocommit(true) >>>>> ============================== >>>>> 2010-03-03 12:55:42,028 INFO [STDOUT] 12:55:42.028 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@18526aa,maxRows=0, fetchSize=0, flags=17 >>>>> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.028 (2) FE=> Parse(stmt=null,query="select now()",oids={}) >>>>> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.029 (2) FE=> Bind(stmt=null,portal=null) >>>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Describe(portal=null) >>>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Execute(portal=null,limit=0) >>>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=> Sync >>>>> 2010-03-03 12:55:42,032 INFO [STDOUT] 12:55:42.032 (2) <=BE ParseComplete [null] >>>>> 2010-03-03 12:55:42,033 INFO [STDOUT] 12:55:42.033 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:55:42,034 INFO [STDOUT] 12:55:42.034 (2) <=BE RowDescription(1) >>>>> 2010-03-03 12:55:42,035 INFO [STDOUT] 12:55:42.035 (2) <=BE DataRow >>>>> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.035 (2) <=BE CommandStatus(SELECT) >>>>> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.036 (2) <=BE ReadyForQuery(I) >>>>> >>>>> call to the java block - the one with con.setAutocommit(false) - again - 3rd time - this time its ok again >>>>> ============================================================== >>>>> 2010-03-03 12:56:51,374 INFO [STDOUT] 12:56:51.374 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler@14a5594,maxRows=0, fetchSize=0, flags=1 >>>>> 2010-03-03 12:56:51,378 INFO [STDOUT] 12:56:51.378 (2) FE=> Bind(stmt=S_1,portal=null) >>>>> 2010-03-03 12:56:51,380 INFO [STDOUT] 12:56:51.380 (2) FE=> Execute(portal=null,limit=0) >>>>> 2010-03-03 12:56:51,385 INFO [STDOUT] 12:56:51.385 (2) FE=> Parse(stmt=null,query="select now()",oids={}) >>>>> 2010-03-03 12:56:51,387 INFO [STDOUT] 12:56:51.387 (2) FE=> Bind(stmt=null,portal=null) >>>>> 2010-03-03 12:56:51,388 INFO [STDOUT] 12:56:51.388 (2) FE=> Describe(portal=null) >>>>> 2010-03-03 12:56:51,390 INFO [STDOUT] 12:56:51.390 (2) FE=> Execute(portal=null,limit=0) >>>>> 2010-03-03 12:56:51,391 INFO [STDOUT] 12:56:51.391 (2) FE=> Sync >>>>> 2010-03-03 12:56:51,393 INFO [STDOUT] 12:56:51.393 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:56:51,395 INFO [STDOUT] 12:56:51.395 (2) <=BE CommandStatus(BEGIN) >>>>> 2010-03-03 12:56:51,397 INFO [STDOUT] 12:56:51.397 (2) <=BE ParseComplete [null] >>>>> 2010-03-03 12:56:51,398 INFO [STDOUT] 12:56:51.398 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:56:51,399 INFO [STDOUT] 12:56:51.399 (2) <=BE RowDescription(1) >>>>> 2010-03-03 12:56:51,400 INFO [STDOUT] 12:56:51.400 (2) <=BE DataRow >>>>> 2010-03-03 12:56:51,402 INFO [STDOUT] 12:56:51.402 (2) <=BE CommandStatus(SELECT) >>>>> 2010-03-03 12:56:51,404 INFO [STDOUT] 12:56:51.404 (2) <=BE ReadyForQuery(T) >>>>> 2010-03-03 12:56:51,406 INFO [STDOUT] 12:56:51.406 (2) simple execute, handler=org.postgresql.jdbc2.AbstractJdbc2Connection$TransactionCommandHandler@13d3f62,maxRows=0, fetchSize=0, flags=22 >>>>> 2010-03-03 12:56:51,409 INFO [STDOUT] 12:56:51.409 (2) FE=> Bind(stmt=S_2,portal=null) >>>>> 2010-03-03 12:56:51,411 INFO [STDOUT] 12:56:51.411 (2) FE=> Execute(portal=null,limit=1) >>>>> 2010-03-03 12:56:51,413 INFO [STDOUT] 12:56:51.413 (2) FE=> Sync >>>>> 2010-03-03 12:56:51,417 INFO [STDOUT] 12:56:51.417 (2) <=BE BindComplete [null] >>>>> 2010-03-03 12:56:51,419 INFO [STDOUT] 12:56:51.418 (2) <=BE CommandStatus(COMMIT) >>>>> 2010-03-03 12:56:51,421 INFO [STDOUT] 12:56:51.421 (2) <=BE ReadyForQuery(I) >>>>> >>>>> ???? Wednesday 03 March 2010 12:30:37 ?/? Heikki Linnakangas ??????: >>>>>> Achilleas Mantzios wrote: >>>>>>> ???? Wednesday 03 March 2010 10:54:53 ?/? Heikki Linnakangas ??????: >>>>>>>> Achilleas Mantzios wrote: >>>>>>>>> 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. >>>>>>>> If you can set logLevel to DEBUG (ie. loglevel=2 in connection string), >>>>>>>> run the code, and send over the logs, that would help a lot. From that >>>>>>>> we should see what exactly is the sequence of XA commands the JDBC >>>>>>>> driver is receiving from JBoss. >>>>>>> As loglevel configuration property to org.postgresql.ds.common.BaseDataSource is not supported in the lastest driver, >>>>>>> i made this patch (i attach it) against postgresql-jdbc-8.4-701.src, also i set in jboss >>>>>>> >>>>>>> <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">xxxx</xa-datasource-property> >>>>>>> <xa-datasource-property name="Compatible">8.2</xa-datasource-property> >>>>>>> <xa-datasource-property name="Loglevel">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> >>>>>>> >>>>>>> But i dont see anything spectacular comming out of PostgreSQL logs.. >>>>>>> in postgresql.conf I have set >>>>>>> client_min_messages = debug5 >>>>>>> log_min_messages = debug5 >>>>>> The extra logs should go somewhere in the client side, in one of the >>>>>> jboss log files. If you can't find it, you can do something like this in >>>>>> the application to redirect it to a file: >>>>>> >>>>>> java.io.Writer output = new >>>>>> java.io.FileWriter("/tmp/postgresql-jdbc.debug.txt", true); >>>>>> java.sql.DriverManager.setLogWriter(new >>>>>> java.io.PrintWriter(output,true)); >>>>>> >>>>>> >>>>>>> however playing with <xa-datasource-property name="Loglevel"></xa-datasource-property> does not seem to change athing. >>>>>>> Am i missing something? >>>>>> Not sure why that's not working, but here's one way of setting loglevel: >>>>>> >>>>>> 1. Create file "org/postgresql/driverconfig.properties" with line >>>>>> "loglevel=2" in it: >>>>>> echo "loglevel=2" > org/postgresql/driverconfig.properties >>>>>> 2. Add file to the driver jar: >>>>>> jar uvf postgresql.jar org/postgresql/driverconfig.properties >>>>>> >>>>>> -- >>>>>> Heikki Linnakangas >>>>>> EnterpriseDB http://www.enterprisedb.com >>>>>> >>>>> >>> >>> >> >> > > > -- > Heikki Linnakangas > EnterpriseDB http://www.enterprisedb.com > > -- > Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-jdbc >