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:
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
>>>
>>> <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
>>
>
>
>