Received: from maia.hub.org (unknown [200.46.208.211]) by mail.postgresql.org (Postfix) with ESMTP id 85282632FCC for ; Mon, 26 Apr 2010 08:49:37 -0300 (ADT) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.208.211]) (amavisd-maia, port 10024) with ESMTP id 58838-05 for ; Mon, 26 Apr 2010 11:49:19 +0000 (UTC) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from smadev.internal.net (host3.dynacom.ondsl.gr [62.103.35.211]) by mail.postgresql.org (Postfix) with ESMTP id 00A0C632BD7 for ; Mon, 26 Apr 2010 08:49:24 -0300 (ADT) Received: from smadev.internal.net (localhost [127.0.0.1]) by smadev.internal.net (8.14.2/8.14.2) with ESMTP id o3QBnDvg092816; Mon, 26 Apr 2010 14:49:13 +0300 (EEST) (envelope-from achill@matrix.gatewaynet.com) Received: from localhost (localhost [[UNIX: localhost]]) by smadev.internal.net (8.14.2/8.14.2/Submit) id o3QBnCVI092815; Mon, 26 Apr 2010 14:49:12 +0300 (EEST) (envelope-from achill@matrix.gatewaynet.com) From: Achilleas Mantzios Organization: Dynacom Tankers Mgmt To: pgsql-jdbc@postgresql.org Subject: Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar Date: Mon, 26 Apr 2010 13:49:12 +0200 User-Agent: KMail/1.9.7 Cc: Heikki Linnakangas References: <201003011731.15724.achill@matrix.gatewaynet.com> <4B8EBBED.80605@enterprisedb.com> <4BD1D5A3.6090100@enterprisedb.com> In-Reply-To: <4BD1D5A3.6090100@enterprisedb.com> MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable Content-Disposition: inline Message-Id: <201004261449.12786.achill@matrix.gatewaynet.com> X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-0.466 tagged_above=-10 required=5 tests=AWL=-1.266, BAYES_50=0.8 X-Spam-Level: X-Archive-Number: 201004/64 X-Sequence-Number: 20475 =CE=A3=CF=84=CE=B9=CF=82 Friday 23 April 2010 20:15:15 =CE=BF/=CE=B7 Heikki= Linnakangas =CE=AD=CE=B3=CF=81=CE=B1=CF=88=CE=B5: > 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. >=20 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 autocom= mit to on, even if *explicitly* set to off. I just want to say that Heikki's patch works very well, since the early Mar= ch when it was applied. > Heikki Linnakangas wrote: > > Okay, thanks, I see what's going on now. > >=20 > > There's two things contributing to this: > >=20 > > * 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. > >=20 > > * 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). > >=20 > > 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 :-= (. > >=20 > > 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). > >=20 > > 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. > >=20 > > 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. > >=20 > > 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, Postgresq= l must be defined as pgsql=20 > >> in xa-datasource inside jboss's deploy dir. > >> You can go to the app by hitting: http://localhost/xabug and looking a= t the directions there. > >> > >> Again, thanx for caring, and lets see if you can figure smth out off t= his. > >> > >> =CE=A3=CF=84=CE=B9=CF=82 Wednesday 03 March 2010 14:25:20 =CE=BF/=CE= =B7 Heikki Linnakangas =CE=AD=CE=B3=CF=81=CE=B1=CF=88=CE=B5: > >>> 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 her= e, > >>> 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 shou= ld > >>> 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 s= ome > >>> fixes to setAutoCommit() and XA interactions a few years ago. > >>> > >>> Achilleas Mantzios wrote: > >>>> Thanx > >>>> Here are the logs: > >>>> > >>>> call to the ejb > >>>> =3D=3D=3D=3D=3D=3D=3D=3D=3D > >>>> 2010-03-03 12:47:57,177 INFO [STDOUT] 12:47:57.177 (2) XAResource 1= 291479: starting transaction xid =3D < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3= e06:32a09c8d8:d10e:4b8e3e06:34 > > >>>> 2010-03-03 12:47:57,181 INFO [STDOUT] 12:47:57.180 (2) simple execu= te, handler=3Dorg.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHa= ndler@dd0f87, maxRows=3D0, fetchSize=3D0, flags=3D1 > >>>> 2010-03-03 12:47:57,184 INFO [STDOUT] 12:47:57.183 (2) FE=3D> Pars= e(stmt=3DS_1,query=3D"BEGIN",oids=3D{}) > >>>> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.184 (2) FE=3D> Bind= (stmt=3DS_1,portal=3Dnull) > >>>> 2010-03-03 12:47:57,185 INFO [STDOUT] 12:47:57.185 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D0) > >>>> 2010-03-03 12:47:57,186 INFO [STDOUT] 12:47:57.186 (2) FE=3D> Pars= e(stmt=3Dnull,query=3D"select apptblidval,colname from status where assetta= ble=3D$1 and assetidval=3D$2 and appname=3D$3 and apptblname=3D$4 and statu= s=3D$5 and isvalid order by apptblidval",oids=3D{1043,23,1043,1043,1043}) > >>>> 2010-03-03 12:47:57,188 INFO [STDOUT] 12:47:57.187 (2) FE=3D> Bind= (stmt=3Dnull,portal=3Dnull,$1=3D<'mariner'>,$2=3D<'14173'>,$3=3D<'Crew'>,$4= =3D<'marinercourses'>,$5=3D<'warn'>) > >>>> 2010-03-03 12:47:57,189 INFO [STDOUT] 12:47:57.189 (2) FE=3D> Desc= ribe(portal=3Dnull) > >>>> 2010-03-03 12:47:57,190 INFO [STDOUT] 12:47:57.190 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D0) > >>>> 2010-03-03 12:47:57,192 INFO [STDOUT] 12:47:57.192 (2) FE=3D> Sync > >>>> 2010-03-03 12:47:57,199 INFO [STDOUT] 12:47:57.199 (2) <=3DBE Pars= eComplete [S_1] > >>>> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:47:57,200 INFO [STDOUT] 12:47:57.200 (2) <=3DBE Comm= andStatus(BEGIN) > >>>> 2010-03-03 12:47:57,201 INFO [STDOUT] 12:47:57.201 (2) <=3DBE Pars= eComplete [null] > >>>> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.201 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:47:57,202 INFO [STDOUT] 12:47:57.202 (2) <=3DBE RowD= escription(2) > >>>> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=3DBE Comm= andStatus(SELECT) > >>>> 2010-03-03 12:47:57,203 INFO [STDOUT] 12:47:57.203 (2) <=3DBE Read= yForQuery(T) > >>>> 2010-03-03 12:47:57,206 INFO [STDOUT] 12:47:57.204 (2) XAResource 1= 291479: ending transaction xid =3D < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e0= 6:32a09c8d8:d10e:4b8e3e06:34 > > >>>> 2010-03-03 12:47:57,211 INFO [STDOUT] 12:47:57.211 (2) XAResource 1= 291479: committing xid =3D < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:32a09c= 8d8:d10e:4b8e3e06:34 > (one phase) > >>>> 2010-03-03 12:47:57,217 INFO [STDOUT] 12:47:57.217 (2) simple execu= te, handler=3Dorg.postgresql.jdbc2.AbstractJdbc2Connection$TransactionComma= ndHandler@1a9b034, maxRows=3D0, fetchSize=3D0, flags=3D22 > >>>> 2010-03-03 12:47:57,225 INFO [STDOUT] 12:47:57.225 (2) FE=3D> Pars= e(stmt=3DS_2,query=3D"COMMIT",oids=3D{}) > >>>> 2010-03-03 12:47:57,227 INFO [STDOUT] 12:47:57.227 (2) FE=3D> Bind= (stmt=3DS_2,portal=3Dnull) > >>>> 2010-03-03 12:47:57,229 INFO [STDOUT] 12:47:57.228 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D1) > >>>> 2010-03-03 12:47:57,237 INFO [STDOUT] 12:47:57.237 (2) FE=3D> Sync > >>>> 2010-03-03 12:47:57,246 INFO [STDOUT] 12:47:57.246 (2) <=3DBE Pars= eComplete [S_2] > >>>> 2010-03-03 12:47:57,248 INFO [STDOUT] 12:47:57.248 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:47:57,250 INFO [STDOUT] 12:47:57.250 (2) <=3DBE Comm= andStatus(COMMIT) > >>>> 2010-03-03 12:47:57,251 INFO [STDOUT] 12:47:57.251 (2) <=3DBE Read= yForQuery(I) > >>>> > >>>> > >>>> call to the java block - the one with con.setAutocommit(false) - (as= we see below its fine the very first time) > >>>> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > >>>> 2010-03-03 12:49:31,892 INFO [STDOUT] 12:49:31.892 (2) simple execu= te, handler=3Dorg.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHa= ndler@19331eb, maxRows=3D0, fetchSize=3D0, flags=3D1 > >>>> 2010-03-03 12:49:31,893 INFO [STDOUT] 12:49:31.893 (2) FE=3D> Bind= (stmt=3DS_1,portal=3Dnull) > >>>> 2010-03-03 12:49:31,895 INFO [STDOUT] 12:49:31.895 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D0) > >>>> 2010-03-03 12:49:31,896 INFO [STDOUT] 12:49:31.895 (2) FE=3D> Pars= e(stmt=3Dnull,query=3D"select now()",oids=3D{}) > >>>> 2010-03-03 12:49:31,897 INFO [STDOUT] 12:49:31.897 (2) FE=3D> Bind= (stmt=3Dnull,portal=3Dnull) > >>>> 2010-03-03 12:49:31,898 INFO [STDOUT] 12:49:31.898 (2) FE=3D> Desc= ribe(portal=3Dnull) > >>>> 2010-03-03 12:49:31,899 INFO [STDOUT] 12:49:31.899 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D0) > >>>> 2010-03-03 12:49:31,901 INFO [STDOUT] 12:49:31.901 (2) FE=3D> Sync > >>>> 2010-03-03 12:49:31,903 INFO [STDOUT] 12:49:31.902 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=3DBE Comm= andStatus(BEGIN) > >>>> 2010-03-03 12:49:31,904 INFO [STDOUT] 12:49:31.904 (2) <=3DBE Pars= eComplete [null] > >>>> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:49:31,905 INFO [STDOUT] 12:49:31.905 (2) <=3DBE RowD= escription(1) > >>>> 2010-03-03 12:49:31,906 INFO [STDOUT] 12:49:31.906 (2) <=3DBE Data= Row > >>>> 2010-03-03 12:49:31,907 INFO [STDOUT] 12:49:31.907 (2) <=3DBE Comm= andStatus(SELECT) > >>>> 2010-03-03 12:49:31,908 INFO [STDOUT] 12:49:31.908 (2) <=3DBE Read= yForQuery(T) > >>>> 2010-03-03 12:49:31,909 INFO [STDOUT] 12:49:31.909 (2) simple execu= te, handler=3Dorg.postgresql.jdbc2.AbstractJdbc2Connection$TransactionComma= ndHandler@1d7ce63, maxRows=3D0, fetchSize=3D0, flags=3D22 > >>>> 2010-03-03 12:49:31,910 INFO [STDOUT] 12:49:31.910 (2) FE=3D> Bind= (stmt=3DS_2,portal=3Dnull) > >>>> 2010-03-03 12:49:31,911 INFO [STDOUT] 12:49:31.911 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D1) > >>>> 2010-03-03 12:49:31,913 INFO [STDOUT] 12:49:31.912 (2) FE=3D> Sync > >>>> 2010-03-03 12:49:31,915 INFO [STDOUT] 12:49:31.915 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:49:31,916 INFO [STDOUT] 12:49:31.916 (2) <=3DBE Comm= andStatus(COMMIT) > >>>> 2010-03-03 12:49:31,917 INFO [STDOUT] 12:49:31.917 (2) <=3DBE Read= yForQuery(I) > >>>> > >>>> call to the ejb (again - 2nd time) > >>>> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > >>>> 2010-03-03 12:50:24,246 INFO [STDOUT] 12:50:24.245 (2) XAResource 1= 291479: starting transaction xid =3D < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3= e06:3ca09c8d8:d10e:4b8e3e06:3e > > >>>> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.247 (2) simple execu= te, handler=3Dorg.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHa= ndler@a06e8d, maxRows=3D0, fetchSize=3D0, flags=3D1 > >>>> 2010-03-03 12:50:24,248 INFO [STDOUT] 12:50:24.248 (2) FE=3D> Bind= (stmt=3DS_1,portal=3Dnull) > >>>> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D0) > >>>> 2010-03-03 12:50:24,249 INFO [STDOUT] 12:50:24.249 (2) FE=3D> Pars= e(stmt=3Dnull,query=3D"select apptblidval,colname from status where assetta= ble=3D$1 and assetidval=3D$2 and appname=3D$3 and apptblname=3D$4 and statu= s=3D$5 and isvalid order by apptblidval",oids=3D{1043,23,1043,1043,1043}) > >>>> 2010-03-03 12:50:24,250 INFO [STDOUT] 12:50:24.250 (2) FE=3D> Bind= (stmt=3Dnull,portal=3Dnull,$1=3D<'mariner'>,$2=3D<'14173'>,$3=3D<'Crew'>,$4= =3D<'marinercourses'>,$5=3D<'warn'>) > >>>> 2010-03-03 12:50:24,251 INFO [STDOUT] 12:50:24.251 (2) FE=3D> Desc= ribe(portal=3Dnull) > >>>> 2010-03-03 12:50:24,252 INFO [STDOUT] 12:50:24.252 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D0) > >>>> 2010-03-03 12:50:24,253 INFO [STDOUT] 12:50:24.252 (2) FE=3D> Sync > >>>> 2010-03-03 12:50:24,255 INFO [STDOUT] 12:50:24.255 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:50:24,256 INFO [STDOUT] 12:50:24.256 (2) <=3DBE Comm= andStatus(BEGIN) > >>>> 2010-03-03 12:50:24,257 INFO [STDOUT] 12:50:24.257 (2) <=3DBE Pars= eComplete [null] > >>>> 2010-03-03 12:50:24,258 INFO [STDOUT] 12:50:24.258 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:50:24,260 INFO [STDOUT] 12:50:24.260 (2) <=3DBE RowD= escription(2) > >>>> 2010-03-03 12:50:24,261 INFO [STDOUT] 12:50:24.261 (2) <=3DBE Comm= andStatus(SELECT) > >>>> 2010-03-03 12:50:24,262 INFO [STDOUT] 12:50:24.262 (2) <=3DBE Read= yForQuery(T) > >>>> 2010-03-03 12:50:24,263 INFO [STDOUT] 12:50:24.262 (2) XAResource 1= 291479: ending transaction xid =3D < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e0= 6:3ca09c8d8:d10e:4b8e3e06:3e > > >>>> 2010-03-03 12:50:24,264 INFO [STDOUT] 12:50:24.263 (2) XAResource 1= 291479: committing xid =3D < 131075, 26, 24, 1-a09c8d8:d10e:4b8e3e06:3ca09c= 8d8:d10e:4b8e3e06:3e > (one phase) > >>>> 2010-03-03 12:50:24,265 INFO [STDOUT] 12:50:24.265 (2) simple execu= te, handler=3Dorg.postgresql.jdbc2.AbstractJdbc2Connection$TransactionComma= ndHandler@1217fef, maxRows=3D0, fetchSize=3D0, flags=3D22 > >>>> 2010-03-03 12:50:24,266 INFO [STDOUT] 12:50:24.266 (2) FE=3D> Bind= (stmt=3DS_2,portal=3Dnull) > >>>> 2010-03-03 12:50:24,267 INFO [STDOUT] 12:50:24.267 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D1) > >>>> 2010-03-03 12:50:24,269 INFO [STDOUT] 12:50:24.269 (2) FE=3D> Sync > >>>> 2010-03-03 12:50:24,272 INFO [STDOUT] 12:50:24.272 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:50:24,273 INFO [STDOUT] 12:50:24.273 (2) <=3DBE Comm= andStatus(COMMIT) > >>>> 2010-03-03 12:50:24,274 INFO [STDOUT] 12:50:24.274 (2) <=3DBE Read= yForQuery(I) > >>>> > >>>> call to the java block - the one with con.setAutocommit(false) - aga= in - 2nd time - this time we have a problem > >>>> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > >>>> 2010-03-03 12:51:30,426 INFO [STDOUT] 12:51:30.426 (2) simple execu= te, handler=3Dorg.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHa= ndler@13b64eb, maxRows=3D0, fetchSize=3D0, flags=3D17 > >>>> 2010-03-03 12:51:30,427 INFO [STDOUT] 12:51:30.427 (2) FE=3D> Pars= e(stmt=3Dnull,query=3D"select now()",oids=3D{}) > >>>> 2010-03-03 12:51:30,428 INFO [STDOUT] 12:51:30.428 (2) FE=3D> Bind= (stmt=3Dnull,portal=3Dnull) > >>>> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=3D> Desc= ribe(portal=3Dnull) > >>>> 2010-03-03 12:51:30,429 INFO [STDOUT] 12:51:30.429 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D0) > >>>> 2010-03-03 12:51:30,430 INFO [STDOUT] 12:51:30.430 (2) FE=3D> Sync > >>>> 2010-03-03 12:51:30,433 INFO [STDOUT] 12:51:30.433 (2) <=3DBE Pars= eComplete [null] > >>>> 2010-03-03 12:51:30,434 INFO [STDOUT] 12:51:30.434 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:51:30,435 INFO [STDOUT] 12:51:30.435 (2) <=3DBE RowD= escription(1) > >>>> 2010-03-03 12:51:30,436 INFO [STDOUT] 12:51:30.436 (2) <=3DBE Data= Row > >>>> 2010-03-03 12:51:30,437 INFO [STDOUT] 12:51:30.437 (2) <=3DBE Comm= andStatus(SELECT) > >>>> 2010-03-03 12:51:30,440 INFO [STDOUT] 12:51:30.440 (2) <=3DBE Read= yForQuery(I) > >>>> > >>>> call to a java block with con.setAutocommit(true) > >>>> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D > >>>> 2010-03-03 12:55:42,028 INFO [STDOUT] 12:55:42.028 (2) simple execu= te, handler=3Dorg.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHa= ndler@18526aa, maxRows=3D0, fetchSize=3D0, flags=3D17 > >>>> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.028 (2) FE=3D> Pars= e(stmt=3Dnull,query=3D"select now()",oids=3D{}) > >>>> 2010-03-03 12:55:42,029 INFO [STDOUT] 12:55:42.029 (2) FE=3D> Bind= (stmt=3Dnull,portal=3Dnull) > >>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=3D> Desc= ribe(portal=3Dnull) > >>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D0) > >>>> 2010-03-03 12:55:42,030 INFO [STDOUT] 12:55:42.030 (2) FE=3D> Sync > >>>> 2010-03-03 12:55:42,032 INFO [STDOUT] 12:55:42.032 (2) <=3DBE Pars= eComplete [null] > >>>> 2010-03-03 12:55:42,033 INFO [STDOUT] 12:55:42.033 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:55:42,034 INFO [STDOUT] 12:55:42.034 (2) <=3DBE RowD= escription(1) > >>>> 2010-03-03 12:55:42,035 INFO [STDOUT] 12:55:42.035 (2) <=3DBE Data= Row > >>>> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.035 (2) <=3DBE Comm= andStatus(SELECT) > >>>> 2010-03-03 12:55:42,036 INFO [STDOUT] 12:55:42.036 (2) <=3DBE Read= yForQuery(I) > >>>> > >>>> call to the java block - the one with con.setAutocommit(false) - aga= in - 3rd time - this time its ok again > >>>> =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > >>>> 2010-03-03 12:56:51,374 INFO [STDOUT] 12:56:51.374 (2) simple execu= te, handler=3Dorg.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHa= ndler@14a5594, maxRows=3D0, fetchSize=3D0, flags=3D1 > >>>> 2010-03-03 12:56:51,378 INFO [STDOUT] 12:56:51.378 (2) FE=3D> Bind= (stmt=3DS_1,portal=3Dnull) > >>>> 2010-03-03 12:56:51,380 INFO [STDOUT] 12:56:51.380 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D0) > >>>> 2010-03-03 12:56:51,385 INFO [STDOUT] 12:56:51.385 (2) FE=3D> Pars= e(stmt=3Dnull,query=3D"select now()",oids=3D{}) > >>>> 2010-03-03 12:56:51,387 INFO [STDOUT] 12:56:51.387 (2) FE=3D> Bind= (stmt=3Dnull,portal=3Dnull) > >>>> 2010-03-03 12:56:51,388 INFO [STDOUT] 12:56:51.388 (2) FE=3D> Desc= ribe(portal=3Dnull) > >>>> 2010-03-03 12:56:51,390 INFO [STDOUT] 12:56:51.390 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D0) > >>>> 2010-03-03 12:56:51,391 INFO [STDOUT] 12:56:51.391 (2) FE=3D> Sync > >>>> 2010-03-03 12:56:51,393 INFO [STDOUT] 12:56:51.393 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:56:51,395 INFO [STDOUT] 12:56:51.395 (2) <=3DBE Comm= andStatus(BEGIN) > >>>> 2010-03-03 12:56:51,397 INFO [STDOUT] 12:56:51.397 (2) <=3DBE Pars= eComplete [null] > >>>> 2010-03-03 12:56:51,398 INFO [STDOUT] 12:56:51.398 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:56:51,399 INFO [STDOUT] 12:56:51.399 (2) <=3DBE RowD= escription(1) > >>>> 2010-03-03 12:56:51,400 INFO [STDOUT] 12:56:51.400 (2) <=3DBE Data= Row > >>>> 2010-03-03 12:56:51,402 INFO [STDOUT] 12:56:51.402 (2) <=3DBE Comm= andStatus(SELECT) > >>>> 2010-03-03 12:56:51,404 INFO [STDOUT] 12:56:51.404 (2) <=3DBE Read= yForQuery(T) > >>>> 2010-03-03 12:56:51,406 INFO [STDOUT] 12:56:51.406 (2) simple execu= te, handler=3Dorg.postgresql.jdbc2.AbstractJdbc2Connection$TransactionComma= ndHandler@13d3f62, maxRows=3D0, fetchSize=3D0, flags=3D22 > >>>> 2010-03-03 12:56:51,409 INFO [STDOUT] 12:56:51.409 (2) FE=3D> Bind= (stmt=3DS_2,portal=3Dnull) > >>>> 2010-03-03 12:56:51,411 INFO [STDOUT] 12:56:51.411 (2) FE=3D> Exec= ute(portal=3Dnull,limit=3D1) > >>>> 2010-03-03 12:56:51,413 INFO [STDOUT] 12:56:51.413 (2) FE=3D> Sync > >>>> 2010-03-03 12:56:51,417 INFO [STDOUT] 12:56:51.417 (2) <=3DBE Bind= Complete [null] > >>>> 2010-03-03 12:56:51,419 INFO [STDOUT] 12:56:51.418 (2) <=3DBE Comm= andStatus(COMMIT) > >>>> 2010-03-03 12:56:51,421 INFO [STDOUT] 12:56:51.421 (2) <=3DBE Read= yForQuery(I) > >>>> > >>>> =CE=A3=CF=84=CE=B9=CF=82 Wednesday 03 March 2010 12:30:37 =CE=BF/=CE= =B7 Heikki Linnakangas =CE=AD=CE=B3=CF=81=CE=B1=CF=88=CE=B5: > >>>>> Achilleas Mantzios wrote: > >>>>>> =CE=A3=CF=84=CE=B9=CF=82 Wednesday 03 March 2010 10:54:53 =CE=BF/= =CE=B7 Heikki Linnakangas =CE=AD=CE=B3=CF=81=CE=B1=CF=88=CE=B5: > >>>>>>> Achilleas Mantzios wrote: > >>>>>>>> i'll try to make a test case, but i think now there is enuf mate= rial for anyone to make his own case, > >>>>>>>> please ask whatever i may have missed, and thank you for your at= tention. > >>>>>>> If you can set logLevel to DEBUG (ie. loglevel=3D2 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.Bas= eDataSource is not supported in the lastest driver,=20 > >>>>>> i made this patch (i attach it) against postgresql-jdbc-8.4-701.sr= c, also i set in jboss=20 > >>>>>> > >>>>>> > >>>>>> > >>>>>> pgsql > >>>>>> true > >>>>>> org.postgresql.xa.PGXADataSource > >>>>>> localhost > >>>>>> 5432 > >>>>>> dynacom > >>>>>> postgres > >>>>>> xxxx > >>>>>> 8.2 > >>>>>> 2 > >>>>>> > >>>>>> 1 > >>>>>> 2 > >>>>>> > >>>>>> PostgreSQL 8.0 > >>>>>> > >>>>>> > >>>>>> > >>>>>> > >>>>>> But i dont see anything spectacular comming out of PostgreSQL logs= =2E=20 > >>>>>> in postgresql.conf I have set=20 > >>>>>> client_min_messages =3D debug5 > >>>>>> log_min_messages =3D 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 th= is in > >>>>> the application to redirect it to a file: > >>>>> > >>>>> java.io.Writer output =3D new > >>>>> java.io.FileWriter("/tmp/postgresql-jdbc.debug.txt", true); > >>>>> java.sql.DriverManager.setLogWriter(new > >>>>> java.io.PrintWriter(output,true)); > >>>>> > >>>>> > >>>>>> however playing with 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 logl= evel: > >>>>> > >>>>> 1. Create file "org/postgresql/driverconfig.properties" with line > >>>>> "loglevel=3D2" in it: > >>>>> echo "loglevel=3D2" > org/postgresql/driverconfig.properties > >>>>> 2. Add file to the driver jar: > >>>>> jar uvf postgresql.jar org/postgresql/driverconfig.properties > >>>>> > >>>>> --=20 > >>>>> Heikki Linnakangas > >>>>> EnterpriseDB http://www.enterprisedb.com > >>>>> > >>>> > >> > >> > >=20 > >=20 >=20 >=20 > --=20 > Heikki Linnakangas > EnterpriseDB http://www.enterprisedb.com >=20 =2D-=20 Achilleas Mantzios