Received: from maia.hub.org (unknown [200.46.208.211]) by mail.postgresql.org (Postfix) with ESMTP id 1655E6331C8 for ; Fri, 23 Apr 2010 14:15:44 -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 57017-05 for ; Fri, 23 Apr 2010 17:15:31 +0000 (UTC) X-Greylist: domain auto-whitelisted by SQLgrey-1.7.6 Received: from exprod7og107.obsmtp.com (exprod7og107.obsmtp.com [64.18.2.167]) by mail.postgresql.org (Postfix) with SMTP id CE19463316B for ; Fri, 23 Apr 2010 14:15:31 -0300 (ADT) Received: from source ([209.85.219.227]) by exprod7ob107.postini.com ([64.18.6.12]) with SMTP ID DSNKS9HVsj55K3ltHIZVtND8uGGecc4f8lqM@postini.com; Fri, 23 Apr 2010 10:15:31 PDT Received: by ewy27 with SMTP id 27so3197772ewy.30 for ; Fri, 23 Apr 2010 10:15:26 -0700 (PDT) Received: by 10.213.60.138 with SMTP id p10mr70085ebh.35.1272042925725; Fri, 23 Apr 2010 10:15:25 -0700 (PDT) Received: from [192.168.1.117] (dsl-hkibrasgw2-ff67c300-165.dhcp.inet.fi [88.195.103.165]) by mx.google.com with ESMTPS id 15sm461031ewy.8.2010.04.23.10.15.24 (version=TLSv1/SSLv3 cipher=RC4-MD5); Fri, 23 Apr 2010 10:15:24 -0700 (PDT) Message-ID: <4BD1D5A3.6090100@enterprisedb.com> Date: Fri, 23 Apr 2010 20:15:15 +0300 From: Heikki Linnakangas Organization: EnterpriseDB User-Agent: Mozilla-Thunderbird 2.0.0.22 (X11/20090706) MIME-Version: 1.0 To: pgsql-jdbc@postgresql.org CC: Achilleas Mantzios Subject: Re: Very Dangerous bug in XA connection pooling and SL EJBs with jboss-4.2.3 & latest postgresql-8.4-701.jdbc3.jar References: <201003011731.15724.achill@matrix.gatewaynet.com> <201003031257.31670.achill@matrix.gatewaynet.com> <4B8E5530.5040901@enterprisedb.com> <201003031753.04467.achill@matrix.gatewaynet.com> <4B8EBBED.80605@enterprisedb.com> In-Reply-To: <4B8EBBED.80605@enterprisedb.com> Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-0.647 tagged_above=-10 required=5 tests=AWL=-1.447, BAYES_50=0.8 X-Spam-Level: X-Archive-Number: 201004/63 X-Sequence-Number: 20474 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 pgsql >> 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 from status 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 from status 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 >>>>>> >>>>>> >>>>>> >>>>>> 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. >>>>>> 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 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