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

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