Problem with committing in XA mode

Hi Heikki,

I am facing tx timeout problem when committing certain tx in XA mode
using pure postgre jdbc type 4 driver. The tx is issued/started from
within backend deployed on AS BEA Weblogic 10 MP1.
Ive tried the postgresql-jdbc-8.3-603 jdbc driver, the one bundled with
weblogic and also edb jdbc driver.
In all cases, i see this in db server log:
--
2009-01-13 13:37:50 LOG: duration: 0.000 ms parse <unnamed>:
PREPARE TRANSACTION '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-13 13:37:50 LOG: duration: 0.000 ms bind <unnamed>:
PREPARE TRANSACTION '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-13 13:37:50 LOG: duration: 0.000 ms execute <unnamed>:
PREPARE TRANSACTION '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-13 13:37:51 LOG: duration: 0.000 ms parse <unnamed>:
COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-13 13:37:51 LOG: duration: 0.000 ms bind <unnamed>: COMMIT
PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-13 13:37:51 ERROR: prepared transaction with identifier
"48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist
2009-01-13 13:37:51 STATEMENT: COMMIT PREPARED
'48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-13 13:38:51 LOG: duration: 0.000 ms parse <unnamed>:
COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-13 13:38:51 LOG: duration: 0.000 ms bind <unnamed>: COMMIT
PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-13 13:38:51 ERROR: prepared transaction with identifier
"48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" *does not exist*
2009-01-13 13:38:51 STATEMENT: COMMIT PREPARED
'48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
--

and this in weblogic log:

--
SEVERE: BEA1-009A7111759D67A32304; nested exception is:
javax.transaction.SystemException: Timeout during commit processing
java.rmi.RemoteException: BEA1-009A7111759D67A32304; nested
exception is:
javax.transaction.SystemException: Timeout during commit processing
at
weblogic.ejb.container.internal.EJBRuntimeUtils.throwRemoteException(EJBRuntimeUtils.java:101)

at
weblogic.ejb.container.internal.BaseRemoteObject.postInvoke1(BaseRemoteObject.java:645)

at
weblogic.ejb.container.internal.StatelessRemoteObject.postInvoke1(StatelessRemoteObject.java:57)

at
weblogic.ejb.container.internal.BaseRemoteObject.postInvokeTxRetry(BaseRemoteObject.java:427)

--
i.e. weblogic is waiting for the commit and then time-outs.

I've also tried the simple XA example as described in
http://archives.postgresql.org/pgsql-jdbc/2007-06/msg00050.php and it
works lie a charm, the problems are only when weblogic backend is used.

Could this be some XA related postgre jdbc issue?

Regards,

Vlastimil Havranek

--
-------------------------------------------------------------
Vlastimil Havránek
Software Developer
xitee k.s. || www.xitee.com || vlastimil(dot)havranek(at)xitee(dot)com
Phone: office +420 234262342, mobile +420 775366990
-------------------------------------------------------------

Vlastimil Havranek wrote:
> I am facing tx timeout problem when committing certain tx in XA mode
> using pure postgre jdbc type 4 driver. The tx is issued/started from
> within backend deployed on AS BEA Weblogic 10 MP1.
> Ive tried the postgresql-jdbc-8.3-603 jdbc driver, the one bundled with
> weblogic and also edb jdbc driver.
> In all cases, i see this in db server log:
> --
> 2009-01-13 13:37:50 LOG: duration: 0.000 ms parse <unnamed>:
> PREPARE TRANSACTION '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-13 13:37:50 LOG: duration: 0.000 ms bind <unnamed>: PREPARE
> TRANSACTION '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-13 13:37:50 LOG: duration: 0.000 ms execute <unnamed>:
> PREPARE TRANSACTION '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-13 13:37:51 LOG: duration: 0.000 ms parse <unnamed>: COMMIT
> PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-13 13:37:51 LOG: duration: 0.000 ms bind <unnamed>: COMMIT
> PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-13 13:37:51 ERROR: prepared transaction with identifier
> "48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist
> 2009-01-13 13:37:51 STATEMENT: COMMIT PREPARED
> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-13 13:38:51 LOG: duration: 0.000 ms parse <unnamed>: COMMIT
> PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-13 13:38:51 LOG: duration: 0.000 ms bind <unnamed>: COMMIT
> PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-13 13:38:51 ERROR: prepared transaction with identifier
> "48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" *does not exist*
> 2009-01-13 13:38:51 STATEMENT: COMMIT PREPARED
> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

Hmm, that's odd. A PREPARE TRANSACTION is clearly being run, and
followed by a COMMIT PREPARED with the same transaction id, which fails.
This raises two questions:

1. Why does it say the transaction doesn't exist, and
2. why doesn't Weblogic report error when the first COMMIT PREPARED fails?

Is there anything in the PostgreSQL server log? Could you set
log_statement='all' so that we get a trace of the statements from the
server side? (that logs *all* queries to the log, so will generate a lot
of log if the system is busy)

A possible explanation for 2. is that since the transaction was
successfully prepared, the RM should be able to commit it eventually. So
instead of propagating errors in commit, WebLogic just retries.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

Thx a lot for prompt answer, here is a slightly more detailed log:

--
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_1: BEGIN
2009-01-15 14:59:55 LOG: execute S_1: BEGIN
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:55 LOG: duration: 0.000 ms parse <unnamed>: SELECT
t0.X, t0.Y FROM TAB_0 t0 WHERE (t0.X = $1 AND t0.Y = $2)
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind <unnamed>: SELECT
t0.X, t0.Y FROM TAB_0 t0 WHERE (t0.X = $1 AND t0.Y = $2)
2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH'
2009-01-15 14:59:55 LOG: execute <unnamed>: SELECT t0.X, t0.Y FROM
TAB_0 t0 WHERE (t0.X = $1 AND t0.Y = $2)
2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH'
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_2: COMMIT
2009-01-15 14:59:55 LOG: execute S_2: COMMIT
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:55 LOG: duration: 0.000 ms parse <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:55 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION
LEVEL
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_1: BEGIN
2009-01-15 14:59:55 LOG: execute S_1: BEGIN
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:55 LOG: duration: 0.000 ms parse <unnamed>: SELECT
t0.* FROM t0 WHERE t0.X=$1 AND t0.Y=$2 FOR UPDATE
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind <unnamed>: SELECT
t0.* FROM t0 WHERE t0.X=$1 AND t0.Y=$2 FOR UPDATE
2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH'
2009-01-15 14:59:55 LOG: execute <unnamed>: SELECT t0.* FROM t0 WHERE
t0.X=$1 AND t0.Y=$2 FOR UPDATE
2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH'
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_1: BEGIN
2009-01-15 14:59:55 LOG: execute S_1: BEGIN
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:55 LOG: duration: 0.000 ms parse <unnamed>: select
count(*) from t0
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind <unnamed>: select
count(*) from t0
2009-01-15 14:59:55 LOG: execute <unnamed>: select count(*) from t0
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_2: COMMIT
2009-01-15 14:59:55 LOG: execute S_2: COMMIT
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_1: BEGIN
2009-01-15 14:59:55 LOG: execute S_1: BEGIN
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:55 LOG: duration: 14.999 ms parse <unnamed>: SELECT
t0.XY, t0.Y FROM TAB_0 t0 WHERE (t0.XY = $1 AND t0.Y = $2)
2009-01-15 14:59:55 LOG: duration: 31.000 ms bind <unnamed>: SELECT
t0.XY, t0.Y FROM TAB_0 t0 WHERE (t0.XY = $1 AND t0.Y = $2)
2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH'
2009-01-15 14:59:55 LOG: execute <unnamed>: SELECT t0.XY, t0.Y FROM
TAB_0 t0 WHERE (t0.XY = $1 AND t0.Y = $2)
2009-01-15 14:59:55 DETAIL: parameters: $1 = 'abcd', $2 = 'EFGH'
2009-01-15 14:59:55 LOG: duration: 32.000 ms
2009-01-15 14:59:55 LOG: duration: 0.000 ms bind S_2: COMMIT
2009-01-15 14:59:55 LOG: execute S_2: COMMIT
2009-01-15 14:59:55 LOG: duration: 0.000 ms
2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: PREPARE
TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE
TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: PREPARE
TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE
TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 LOG: duration: 0.000 ms
2009-01-15 14:59:56 LOG: duration: 0.000 ms
2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT
PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT
PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT
PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT
PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 ERROR: prepared transaction with identifier
"48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist
2009-01-15 14:59:56 STATEMENT: COMMIT PREPARED
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
2009-01-15 14:59:56 LOG: duration: 0.000 ms
2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:56 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION
LEVEL
2009-01-15 14:59:56 LOG: duration: 0.000 ms
2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
2009-01-15 14:59:56 LOG: execute <unnamed>: SHOW TRANSACTION ISOLATION
LEVEL
2009-01-15 14:59:56 LOG: duration: 0.000 ms
--

VH.

Heikki Linnakangas wrote:
> Vlastimil Havranek wrote:
>> I am facing tx timeout problem when committing certain tx in XA mode
>> using pure postgre jdbc type 4 driver. The tx is issued/started from
>> within backend deployed on AS BEA Weblogic 10 MP1.
>> Ive tried the postgresql-jdbc-8.3-603 jdbc driver, the one bundled
>> with weblogic and also edb jdbc driver.
>> In all cases, i see this in db server log:
>> --
>> 2009-01-13 13:37:50 LOG: duration: 0.000 ms parse <unnamed>:
>> PREPARE TRANSACTION
>> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-13 13:37:50 LOG: duration: 0.000 ms bind <unnamed>:
>> PREPARE TRANSACTION
>> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-13 13:37:50 LOG: duration: 0.000 ms execute <unnamed>:
>> PREPARE TRANSACTION
>> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-13 13:37:51 LOG: duration: 0.000 ms parse <unnamed>:
>> COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-13 13:37:51 LOG: duration: 0.000 ms bind <unnamed>:
>> COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-13 13:37:51 ERROR: prepared transaction with identifier
>> "48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist
>> 2009-01-13 13:37:51 STATEMENT: COMMIT PREPARED
>> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-13 13:38:51 LOG: duration: 0.000 ms parse <unnamed>:
>> COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-13 13:38:51 LOG: duration: 0.000 ms bind <unnamed>:
>> COMMIT PREPARED '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-13 13:38:51 ERROR: prepared transaction with identifier
>> "48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" *does not exist*
>> 2009-01-13 13:38:51 STATEMENT: COMMIT PREPARED
>> '48801_AQeOE4t3Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>
> Hmm, that's odd. A PREPARE TRANSACTION is clearly being run, and
> followed by a COMMIT PREPARED with the same transaction id, which
> fails. This raises two questions:
>
> 1. Why does it say the transaction doesn't exist, and
> 2. why doesn't Weblogic report error when the first COMMIT PREPARED
> fails?
>
> Is there anything in the PostgreSQL server log? Could you set
> log_statement='all' so that we get a trace of the statements from the
> server side? (that logs *all* queries to the log, so will generate a
> lot of log if the system is busy)
>
> A possible explanation for 2. is that since the transaction was
> successfully prepared, the RM should be able to commit it eventually.
> So instead of propagating errors in commit, WebLogic just retries.
>

--
-------------------------------------------------------------
Vlastimil Havránek
Software Developer
xitee k.s. || www.xitee.com || vlastimil(dot)havranek(at)xitee(dot)com
Phone: office +420 234262342, mobile +420 775366990
-------------------------------------------------------------

Vlastimil Havranek wrote:
> Thx a lot for prompt answer, here is a slightly more detailed log:
>
> --
> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: PREPARE
> TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE
> TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
> 2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION
> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: PREPARE
> TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE
> TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION
> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-15 14:59:56 LOG: duration: 0.000 ms
> 2009-01-15 14:59:56 LOG: duration: 0.000 ms
> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT
> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT
> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
> 2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED
> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT
> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT
> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED
> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> 2009-01-15 14:59:56 ERROR: prepared transaction with identifier
> "48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist
> 2009-01-15 14:59:56 STATEMENT: COMMIT PREPARED
> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

Hmm, it looks like the server is getting a COMMIT, followed by two
PREPARE TRANSACTION commands in a row:

BEGIN
...
COMMIT
PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

I presume there's multiple backends issuing these commands concurrently,
otherwise both PREPARE TRANSACTION commands should fail with "there is
no transaction in progress" warning.

One theory is that the 2nd PREPARE TRANSACTION *is* failing, and gives a
WARNING, but we're not seeing that in any of the logs. I don't know why
that might happen, but I notice that we don't have a check for that case
in the JDBC driver's prepare() method, so the application server would
think that the transaction prepare succeeded.

Please make sure you have log_min_messages set to "warning" (or lower,
e.g "notice") and try again. Also, %c would be very helpful in
log_line_prefix, so that we could tell apart actions of different
backends in the log.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

Here is the log with the settings zou have suggested:

--
database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_A SID:496f4f4d.454 16:12:09.578 LOG: execute S_1: BEGIN
database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms
parse <unnamed>: select count(*) from t0
database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms bind
<unnamed>: select count(*) from t0
database_A SID:496f4f4d.454 16:12:09.578 LOG: execute <unnamed>:
select count(*) from t0
database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms bind
S_2: COMMIT
database_A SID:496f4f4d.454 16:12:09.578 LOG: execute S_2: COMMIT
database_A SID:496f4f4d.454 16:12:09.578 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.593 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_A SID:496f4f4d.454 16:12:09.593 LOG: execute S_1: BEGIN
database_A SID:496f4f4d.454 16:12:09.593 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.593 LOG: duration: 0.000 ms
parse <unnamed>: SELECT SOME_SEQ.nextval FROM dual
database_A SID:496f4f4d.454 16:12:09.593 LOG: duration: 0.000 ms bind
<unnamed>: SELECT SOME_SEQ.nextval FROM dual
database_A SID:496f4f4d.454 16:12:09.593 LOG: execute <unnamed>:
SELECT SOME_SEQ.nextval FROM dual
database_A SID:496f4f4d.454 16:12:09.593 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.609 LOG: duration: 0.000 ms bind
S_2: COMMIT
database_A SID:496f4f4d.454 16:12:09.609 LOG: execute S_2: COMMIT
database_A SID:496f4f4d.454 16:12:09.609 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.609 LOG: duration: 0.000 ms
parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:09.609 LOG: duration: 0.000 ms bind
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:09.609 LOG: execute <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:09.609 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.625 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_A SID:496f4f4d.454 16:12:09.625 LOG: execute S_1: BEGIN
database_A SID:496f4f4d.454 16:12:09.625 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.625 LOG: duration: 0.000 ms
parse <unnamed>: SOME SELECT
database_A SID:496f4f4d.454 16:12:09.625 LOG: duration: 0.000 ms bind
<unnamed>: SOME SELECT
database_A SID:496f4f4d.454 16:12:09.625 LOG: execute <unnamed>: SOME
SELECT
database_A SID:496f4f4d.454 16:12:09.625 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.656 LOG: duration: 0.000 ms
parse <unnamed>: SOME SELECT
database_A SID:496f4f4d.454 16:12:09.656 LOG: duration: 0.000 ms bind
<unnamed>: SOME SELECT
database_A SID:496f4f4d.454 16:12:09.656 DETAIL: parameters: $1 = '1234'
database_A SID:496f4f4d.454 16:12:09.656 LOG: execute <unnamed>: SOME
SELECT
database_A SID:496f4f4d.454 16:12:09.656 DETAIL: parameters: $1 = '1234'
database_A SID:496f4f4d.454 16:12:09.656 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.671 LOG: duration: 0.000 ms bind
S_2: COMMIT
database_A SID:496f4f4d.454 16:12:09.671 LOG: execute S_2: COMMIT
database_A SID:496f4f4d.454 16:12:09.671 LOG: duration: 0.000 ms
database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_A SID:496f4ed6.200 16:12:09.671 LOG: execute S_1: BEGIN
database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms
database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms
parse <unnamed>: select count(*) from t0
database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms bind
<unnamed>: select count(*) from t0
database_A SID:496f4ed6.200 16:12:09.671 LOG: execute <unnamed>:
select count(*) from t0
database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms
database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms bind
S_2: COMMIT
database_A SID:496f4ed6.200 16:12:09.671 LOG: execute S_2: COMMIT
database_A SID:496f4ed6.200 16:12:09.671 LOG: duration: 0.000 ms
database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_A SID:496f4ed6.200 16:12:09.687 LOG: execute S_1: BEGIN
database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms
database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms
parse <unnamed>: SOME UPDATE
database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms bind
<unnamed>: SOME UPDATE
database_A SID:496f4ed6.200 16:12:09.687 DETAIL: parameters: $1 = 'a',
$2 = '1234', $3 = '2008-01-01 00:00:00'
database_A SID:496f4ed6.200 16:12:09.687 LOG: execute <unnamed>: SOME
UPDATE
database_A SID:496f4ed6.200 16:12:09.687 DETAIL: parameters: $1 = 'A',
$2 = '1234', $3 = '2008-01-01 00:00:00'
database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms
database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms bind
S_2: COMMIT
database_A SID:496f4ed6.200 16:12:09.687 LOG: execute S_2: COMMIT
database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms
database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms
parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms bind
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4ed6.200 16:12:09.687 LOG: execute <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
database_A SID:496f4ed6.200 16:12:09.687 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:09.703 LOG: duration: 0.000 ms
parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:09.703 LOG: duration: 0.000 ms bind
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:09.703 LOG: execute <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:09.703 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:10.062 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_A SID:496f4f4d.454 16:12:10.062 LOG: execute S_1: BEGIN
database_A SID:496f4f4d.454 16:12:10.062 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:10.062 LOG: duration: 0.000 ms
parse <unnamed>: SOME SELECT
database_A SID:496f4f4d.454 16:12:10.062 LOG: duration: 0.000 ms bind
<unnamed>: SOME SELECT
database_A SID:496f4f4d.454 16:12:10.062 LOG: execute <unnamed>: SOME
SELECT
database_A SID:496f4f4d.454 16:12:10.062 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:10.171 LOG: duration: 0.000 ms bind
S_2: COMMIT
database_A SID:496f4f4d.454 16:12:10.171 LOG: execute S_2: COMMIT
database_A SID:496f4f4d.454 16:12:10.171 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:10.171 LOG: duration: 0.000 ms
parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:10.171 LOG: duration: 0.000 ms bind
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:10.171 LOG: execute <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:10.171 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_A SID:496f4f4d.454 16:12:27.531 LOG: execute S_1: BEGIN
database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms
parse <unnamed>: select count(*) from t0
database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms bind
<unnamed>: select count(*) from t0
database_A SID:496f4f4d.454 16:12:27.531 LOG: execute <unnamed>:
select count(*) from t0
database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms bind
S_2: COMMIT
database_A SID:496f4f4d.454 16:12:27.531 LOG: execute S_2: COMMIT
database_A SID:496f4f4d.454 16:12:27.531 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:27.546 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_A SID:496f4f4d.454 16:12:27.546 LOG: execute S_1: BEGIN
database_A SID:496f4f4d.454 16:12:27.546 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:27.546 LOG: duration: 0.000 ms
parse <unnamed>: SOME SELECT
database_A SID:496f4f4d.454 16:12:27.546 LOG: duration: 0.000 ms bind
<unnamed>: SOME SELECT
database_A SID:496f4f4d.454 16:12:27.546 DETAIL: parameters: $1 =
'abcd', $2 = 'EFGH'
database_A SID:496f4f4d.454 16:12:27.546 LOG: execute <unnamed>: SOME
SELECT
database_A SID:496f4f4d.454 16:12:27.546 DETAIL: parameters: $1 =
'abcd', $2 = 'EFGH'
database_A SID:496f4f4d.454 16:12:27.546 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:27.578 LOG: duration: 0.000 ms bind
S_2: COMMIT
database_A SID:496f4f4d.454 16:12:27.578 LOG: execute S_2: COMMIT
database_A SID:496f4f4d.454 16:12:27.578 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:27.578 LOG: duration: 0.000 ms
parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:27.578 LOG: duration: 0.000 ms bind
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:27.578 LOG: execute <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:27.578 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:27.625 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_A SID:496f4f4d.454 16:12:27.625 LOG: execute S_1: BEGIN
database_A SID:496f4f4d.454 16:12:27.625 LOG: duration: 0.000 ms
database_A SID:496f4f4d.454 16:12:27.625 LOG: duration: 0.000 ms
parse <unnamed>: SOME SELECT FOR UPDATE
database_A SID:496f4f4d.454 16:12:27.625 LOG: duration: 0.000 ms bind
<unnamed>: SOME SELECT FOR UPDATE
database_A SID:496f4f4d.454 16:12:27.625 DETAIL: parameters: $1 =
'abcd', $2 = 'EFGH'
database_A SID:496f4f4d.454 16:12:27.625 LOG: execute <unnamed>: SOME
SELECT FOR UPDATE
database_A SID:496f4f4d.454 16:12:27.625 DETAIL: parameters: $1 =
'abcd', $2 = 'EFGH'
database_A SID:496f4f4d.454 16:12:27.625 LOG: duration: 0.000 ms

database_B SID:496f4ed7.e04 16:12:27.859 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_B SID:496f4ed7.e04 16:12:27.859 LOG: execute S_1: BEGIN
database_B SID:496f4ed7.e04 16:12:27.859 LOG: duration: 0.000 ms
database_B SID:496f4ed7.e04 16:12:27.859 LOG: duration: 0.000 ms
parse <unnamed>: select count(*) from t0
database_B SID:496f4ed7.e04 16:12:27.859 LOG: duration: 0.000 ms bind
<unnamed>: select count(*) from t0
database_B SID:496f4ed7.e04 16:12:27.859 LOG: execute <unnamed>:
select count(*) from t0
database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 15.999 ms
database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 0.000 ms bind
S_2: COMMIT
database_B SID:496f4ed7.e04 16:12:27.875 LOG: execute S_2: COMMIT
database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 0.000 ms
database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 0.000 ms bind
S_1: BEGIN
database_B SID:496f4ed7.e04 16:12:27.875 LOG: execute S_1: BEGIN
database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 0.000 ms
database_B SID:496f4ed7.e04 16:12:27.875 LOG: duration: 0.000 ms
parse <unnamed>: SOME SELECT
database_B SID:496f4ed7.e04 16:12:27.890 LOG: duration: 14.999 ms
bind <unnamed>: SOME SELECT
database_B SID:496f4ed7.e04 16:12:27.890 DETAIL: parameters: $1 =
'abcd', $2 = 'EFGH'
database_B SID:496f4ed7.e04 16:12:27.890 LOG: execute <unnamed>: SOME
SELECT FOR UPDATE
database_B SID:496f4ed7.e04 16:12:27.890 DETAIL: parameters: $1 =
'abcd', $2 = 'EFGH'
database_B SID:496f4ed7.e04 16:12:27.890 LOG: duration: 0.000 ms

database_A SID:496f4f4d.454 16:12:27.937 LOG: duration: 0.000 ms bind
S_2: COMMIT
database_A SID:496f4f4d.454 16:12:27.937 LOG: execute S_2: COMMIT
database_A SID:496f4f4d.454 16:12:27.937 LOG: duration: 0.000 ms

database_B SID:496f4ed7.e04 16:12:27.953 LOG: duration: 0.000 ms
parse <unnamed>: PREPARE TRANSACTION
'48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'

database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms
parse <unnamed>: PREPARE TRANSACTION
'48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms bind
<unnamed>: PREPARE TRANSACTION
'48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

database_B SID:496f4ed7.e04 16:12:27.953 LOG: duration: 0.000 ms bind
<unnamed>: PREPARE TRANSACTION
'48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'

database_A SID:496f4f4d.454 16:12:27.953 LOG: execute <unnamed>:
PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
database_B SID:496f4ed7.e04 16:12:27.953 LOG: execute <unnamed>:
PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms

database_B SID:496f4ed7.e04 16:12:27.968 LOG: duration: 14.999 ms

database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms
parse <unnamed>: COMMIT PREPARED
'48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms bind
<unnamed>: COMMIT PREPARED
'48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

database_B SID:496f4ed7.e04 16:12:28.000 LOG: duration: 0.000 ms
parse <unnamed>: COMMIT PREPARED
'48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'

database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>:
COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

database_B SID:496f4ed7.e04 16:12:28.000 LOG: duration: 0.000 ms bind
<unnamed>: COMMIT PREPARED
'48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'

database_A SID:496f4f4d.454 16:12:28.000 ERROR: prepared transaction
with identifier "48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU="
does not exist
database_A SID:496f4f4d.454 16:12:28.000 STATEMENT: COMMIT PREPARED
'48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

database_B SID:496f4ed7.e04 16:12:28.000 LOG: execute <unnamed>:
COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'

database_A SID:496f4f4d.454 16:12:28.015 LOG: duration: 0.000 ms
parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:28.015 LOG: duration: 0.000 ms bind
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:28.015 LOG: execute <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:28.015 LOG: duration: 0.000 ms

database_B SID:496f4ed7.e04 16:12:28.015 LOG: duration: 14.999 ms
database_B SID:496f4ed7.e04 16:12:28.015 LOG: duration: 0.000 ms
parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_B SID:496f4ed7.e04 16:12:28.015 LOG: duration: 0.000 ms bind
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_B SID:496f4ed7.e04 16:12:28.015 LOG: execute <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
database_B SID:496f4ed7.e04 16:12:28.015 LOG: duration: 0.000 ms

database_A SID:496f4f4d.454 16:12:29.421 LOG: duration: 0.000 ms
parse <unnamed>: COMMIT PREPARED
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

database_B SID:496f4ed7.e04 16:12:29.421 LOG: duration: 0.000 ms
parse <unnamed>: COMMIT PREPARED
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'

database_A SID:496f4f4d.454 16:12:29.421 LOG: duration: 0.000 ms bind
<unnamed>: COMMIT PREPARED
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

database_B SID:496f4ed7.e04 16:12:29.421 LOG: duration: 0.000 ms bind
<unnamed>: COMMIT PREPARED
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'

database_A SID:496f4f4d.454 16:12:29.421 LOG: execute <unnamed>:
COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

database_B SID:496f4ed7.e04 16:12:29.421 LOG: execute <unnamed>:
COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'

database_A SID:496f4f4d.454 16:12:29.421 ERROR: prepared transaction
with identifier "48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU="
does not exist
database_A SID:496f4f4d.454 16:12:29.421 STATEMENT: COMMIT PREPARED
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

database_B SID:496f4ed7.e04 16:12:29.421 ERROR: prepared transaction
with identifier "48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt"
does not exist
database_B SID:496f4ed7.e04 16:12:29.421 STATEMENT: COMMIT PREPARED
'48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
database_B SID:496f4ed7.e04 16:12:29.421 LOG: duration: 0.000 ms
parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_B SID:496f4ed7.e04 16:12:29.421 LOG: duration: 0.000 ms bind
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_B SID:496f4ed7.e04 16:12:29.421 LOG: execute <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL

database_A SID:496f4f4d.454 16:12:29.421 LOG: duration: 0.000 ms
parse <unnamed>: SHOW TRANSACTION ISOLATION LEVEL

database_B SID:496f4ed7.e04 16:12:29.421 LOG: duration: 0.000 ms

database_A SID:496f4f4d.454 16:12:29.421 LOG: duration: 0.000 ms bind
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:29.421 LOG: execute <unnamed>: SHOW
TRANSACTION ISOLATION LEVEL
database_A SID:496f4f4d.454 16:12:29.421 LOG: duration: 0.000 ms
--

Thx in advance,

Regards

VH

Heikki Linnakangas wrote:
> Vlastimil Havranek wrote:
>> Thx a lot for prompt answer, here is a slightly more detailed log:
>>
>> --
>> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>:
>> PREPARE TRANSACTION
>> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
>> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE
>> TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
>> 2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION
>> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
>> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>:
>> PREPARE TRANSACTION
>> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: PREPARE
>> TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-15 14:59:56 LOG: execute <unnamed>: PREPARE TRANSACTION
>> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-15 14:59:56 LOG: duration: 0.000 ms
>> 2009-01-15 14:59:56 LOG: duration: 0.000 ms
>> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT
>> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
>> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT
>> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
>> 2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED
>> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
>> 2009-01-15 14:59:56 LOG: duration: 0.000 ms parse <unnamed>: COMMIT
>> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-15 14:59:56 LOG: duration: 0.000 ms bind <unnamed>: COMMIT
>> PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-15 14:59:56 LOG: execute <unnamed>: COMMIT PREPARED
>> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> 2009-01-15 14:59:56 ERROR: prepared transaction with identifier
>> "48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist
>> 2009-01-15 14:59:56 STATEMENT: COMMIT PREPARED
>> '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>
> Hmm, it looks like the server is getting a COMMIT, followed by two
> PREPARE TRANSACTION commands in a row:
>
> BEGIN
> ...
> COMMIT
> PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> PREPARE TRANSACTION '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>
> I presume there's multiple backends issuing these commands
> concurrently, otherwise both PREPARE TRANSACTION commands should fail
> with "there is no transaction in progress" warning.
>
> One theory is that the 2nd PREPARE TRANSACTION *is* failing, and gives
> a WARNING, but we're not seeing that in any of the logs. I don't know
> why that might happen, but I notice that we don't have a check for
> that case in the JDBC driver's prepare() method, so the application
> server would think that the transaction prepare succeeded.
>
> Please make sure you have log_min_messages set to "warning" (or lower,
> e.g "notice") and try again. Also, %c would be very helpful in
> log_line_prefix, so that we could tell apart actions of different
> backends in the log.
>

--
-------------------------------------------------------------
Vlastimil Havránek
Software Developer
xitee k.s. || www.xitee.com || vlastimil(dot)havranek(at)xitee(dot)com
Phone: office +420 234262342, mobile +420 775366990
-------------------------------------------------------------

Vlastimil Havranek <vlastimil(dot)havranek(at)xitee(dot)com> writes:
> Here is the log with the settings zou have suggested:

[ extracted... ]

> database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms
> parse <unnamed>: PREPARE TRANSACTION
> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms bind
> <unnamed>: PREPARE TRANSACTION
> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> database_A SID:496f4f4d.454 16:12:27.953 LOG: execute <unnamed>:
> PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms
> database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms
> parse <unnamed>: COMMIT PREPARED
> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms bind
> <unnamed>: COMMIT PREPARED
> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>:
> COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> database_A SID:496f4f4d.454 16:12:28.000 ERROR: prepared transaction
> with identifier "48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU="
> does not exist

Well, this clearly shows the same GID being committed twice --- and by
the same session, so my early thoughts about a race condition are out.

So either Weblogic is broken, or there's a bug in the JDBC driver that
somehow causes this, or we've misread the spec and should allow this.

regards, tom lane

Tom Lane wrote:
> Vlastimil Havranek <vlastimil(dot)havranek(at)xitee(dot)com> writes:
>> Here is the log with the settings zou have suggested:
>
> [ extracted... ]
>
>> database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms
>> parse <unnamed>: PREPARE TRANSACTION
>> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms bind
>> <unnamed>: PREPARE TRANSACTION
>> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> database_A SID:496f4f4d.454 16:12:27.953 LOG: execute <unnamed>:
>> PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> database_A SID:496f4f4d.454 16:12:27.953 LOG: duration: 0.000 ms
>> database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms
>> parse <unnamed>: COMMIT PREPARED
>> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> database_A SID:496f4f4d.454 16:12:28.000 LOG: duration: 0.000 ms bind
>> <unnamed>: COMMIT PREPARED
>> '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>:
>> COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
>> database_A SID:496f4f4d.454 16:12:28.000 ERROR: prepared transaction
>> with identifier "48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU="
>> does not exist
>
> Well, this clearly shows the same GID being committed twice --- and by
> the same session, so my early thoughts about a race condition are out.
>
> So either Weblogic is broken, or there's a bug in the JDBC driver that
> somehow causes this, or we've misread the spec and should allow this.

No, you misread the log. There's a parse, bind, and execute for COMMIT
PREPARED for that GID, but only once.

Here's a reduced log with a lot of lines removed to make the problem
obvious:

> database_A SID:496f4f4d.454 16:12:27.625 LOG: execute S_1: BEGIN
> database_A SID:496f4f4d.454 16:12:27.625 LOG: execute <unnamed>: SOME SELECT FOR UPDATE
> database_A SID:496f4f4d.454 16:12:27.937 LOG: execute S_2: COMMIT
(so far so good)
> database_A SID:496f4f4d.454 16:12:27.953 LOG: execute <unnamed>: PREPARE TRANSACTION '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> database_A SID:496f4f4d.454 16:12:28.000 ERROR: prepared transaction with identifier "48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU=" does not exist
> database_A SID:496f4f4d.454 16:12:28.000 STATEMENT: COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='

It's trying to PREPARE a TRANSACTION right after regular 1-phase COMMIT.
You should get a "WARNING: there is no transaction in progress", and
rollback; I'm not sure why we're not seeing that in the log. Vlastimil,
did you check the log_min_messages setting? If you run "PREPARE
TRANSACTION 'foo'" manually, without a BEGIN, do you get that warning
both on the screen and in the log?

Now, why we're getting those commands from the JDBC driver, I don't
know. I concur that either WebLogic is broken, or there's a bug in the
JDBC driver.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

Heikki Linnakangas <heikki(dot)linnakangas(at)enterprisedb(dot)com> writes:
> No, you misread the log. There's a parse, bind, and execute for COMMIT
> PREPARED for that GID, but only once.

Better read it again.

regards, tom lane

Tom Lane wrote:
> Heikki Linnakangas <heikki(dot)linnakangas(at)enterprisedb(dot)com> writes:
>> No, you misread the log. There's a parse, bind, and execute for COMMIT
>> PREPARED for that GID, but only once.
>
> Better read it again.

grep "COMMIT PREPARED" /tmp/a | grep execute

database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>:
COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
database_B SID:496f4ed7.e04 16:12:28.000 LOG: execute <unnamed>:
COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
database_A SID:496f4f4d.454 16:12:29.421 LOG: execute <unnamed>:
COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
database_B SID:496f4ed7.e04 16:12:29.421 LOG: execute <unnamed>:
COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'

Those are four different GIDs.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

Hi Heikki,
yes the log_min_messages is set to notice. I've just rechecked it.

Vlastimil Havranek

Vl.

Heikki Linnakangas wrote:
> Tom Lane wrote:
>> Heikki Linnakangas <heikki(dot)linnakangas(at)enterprisedb(dot)com> writes:
>>> No, you misread the log. There's a parse, bind, and execute for
>>> COMMIT PREPARED for that GID, but only once.
>>
>> Better read it again.
>
> grep "COMMIT PREPARED" /tmp/a | grep execute
>
> database_A SID:496f4f4d.454 16:12:28.000 LOG: execute <unnamed>:
> COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> database_B SID:496f4ed7.e04 16:12:28.000 LOG: execute <unnamed>:
> COMMIT PREPARED '48801_AOiMyUwnZ6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
> database_A SID:496f4f4d.454 16:12:29.421 LOG: execute <unnamed>:
> COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU0xpdmU='
> database_B SID:496f4ed7.e04 16:12:29.421 LOG: execute <unnamed>:
> COMMIT PREPARED '48801_AF7jVNS8Z6MjBA==_Q3ZoYXZyYW5la2pkYmNEU1BhcmFt'
>
> Those are four different GIDs.
>

--
-------------------------------------------------------------
Vlastimil Havránek
Software Developer
xitee k.s. || www.xitee.com || vlastimil(dot)havranek(at)xitee(dot)com
Phone: office +420 234262342, mobile +420 775366990
-------------------------------------------------------------

Vlastimil Havranek wrote:
> yes the log_min_messages is set to notice. I've just rechecked it.

Ok, thanks.

One theory is that WebLogic, or your application code, is calling
setAutoCommit on the XA connection. I can reproduce a similar error with
a stand-alone test case by doing that:

XAConnection xaconn1 = ds.getXAConnection();
XAResource xares1 = xaconn1.getXAResource();
Connection conn1 = xaconn1.getConnection();

xares1.start(initxid, XAResource.TMNOFLAGS);
Statement stmt = conn1.createStatement();
stmt.executeUpdate("INSERT INTO foo VALUES (1234)");
// 1. conn1.setAutoCommit(true);
xares1.end(initxid, XAResource.TMSUCCESS);
// 2. conn1.setAutoCommit(true);
xares1.prepare(initxid);
xares1.commit(initxid, false);

Uncommenting either of the commented lines will cause a similar error as
you're seeing. Since the end() call is made by WebLogic, the 1st case
would be an explicit setAutoCommit call in your application. You don't
have one, do you? That's forbidden by the JTA spec.

The 2nd call would be a call made by WebLogic. We've seen WebLogic do
strange call patterns before (see
http://archives.postgresql.org/pgsql-jdbc/2006-10/msg00011.php), so I
wouldn't be surprised if it was doing that. It's allowed by the JTA
spec, but not by the PostgreSQL driver because we don't support
transaction interleaving. We could try modifying the driver to tolerate
it like the aforementioned "end then join" case, by not passing the
setAutoCommit call immediately to the underlying connection object, but
delay it until prepare-call. Whether that would work depends on what
else the application server is trying to do with the connection between
end and prepare.

Calling commit or rollback at those points will also trigger the same
error. JTA spec also forbids setSavePoint, but I'm not sure if that
would actually be a problem for PostgreSQL.

There's some options in WebLogic to dumb-down the interaction with the
JDBC XA driver, see
http://edocs.bea.com/wls/docs100/ConsoleHelp/pagehelp/JDBCjdbcdatasourcesjdbcdatasourceconfigtransactiontitle.html.
At least "Keep Connection Open On Release" is required for PostgreSQL
driver, and setting the other settings marked with "Use this setting to
work around specific problems with JDBC XA drivers" might help too.
Please make sure you have those set.

Now, it would be very good if we threw an error immediately at the
offending call, regardless of whether it's allowed by JTA or not. I've
been trying to figure out how to do that. We could create a proxy for
the Connection object handed to the application in PGXAConnection, and
throw an error if you call one of those functions while an
XA-transaction is open. That would be fairly simple, but wouldn't catch
the pattern:

start(xid)
// do stuff in XA transaction
executeUpdate("UPDATE ...");
end(xid)
// do stuff outside the XA transaction
executeUpdate("UPDATE ...");
prepare(xid);

It would be better than nothing, but it would be even better if we could
catch all the cases we can't handle properly. If we could inject a proxy
to check that at lower level, around QueryExecutor, it would be more
robust, but I don't see any easy way to do that.

Another check that we really ought to do is to check the command tag
that PREPARE TRANSACTION returns. If it returns ROLLBACK, the driver
should throw an error. I'll write a patch for that.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

Hi,
regarding the autocommit, we do not use it in our application, we use
the EJBs mostly with CMP, some with BMP, which are accessing several dbs
via XA driver.
The EJB on which it gets stuck runs with CMP.

Ive found that weblogic provides some monitoring of tx, the tx was there
in state 'comitting' but both force local and force global commit failed
with xaexception: someDataSource: null.

Ive tried all the XA related data source settings, but it didnt help.

So maybe if you could modify the driver to tolerate the strange WL XA
pattern, then I would try that one out.

Anyway, thx for your great cooperation,

Vlastimil Havranek

Heikki Linnakangas wrote:
> Vlastimil Havranek wrote:
>> yes the log_min_messages is set to notice. I've just rechecked it.
>
> Ok, thanks.
>
> One theory is that WebLogic, or your application code, is calling
> setAutoCommit on the XA connection. I can reproduce a similar error
> with a stand-alone test case by doing that:
>
> XAConnection xaconn1 = ds.getXAConnection();
> XAResource xares1 = xaconn1.getXAResource();
> Connection conn1 = xaconn1.getConnection();
>
> xares1.start(initxid, XAResource.TMNOFLAGS);
> Statement stmt = conn1.createStatement();
> stmt.executeUpdate("INSERT INTO foo VALUES (1234)");
> // 1. conn1.setAutoCommit(true);
> xares1.end(initxid, XAResource.TMSUCCESS);
> // 2. conn1.setAutoCommit(true);
> xares1.prepare(initxid);
> xares1.commit(initxid, false);
>
> Uncommenting either of the commented lines will cause a similar error
> as you're seeing. Since the end() call is made by WebLogic, the 1st
> case would be an explicit setAutoCommit call in your application. You
> don't have one, do you? That's forbidden by the JTA spec.
>
> The 2nd call would be a call made by WebLogic. We've seen WebLogic do
> strange call patterns before (see
> http://archives.postgresql.org/pgsql-jdbc/2006-10/msg00011.php), so I
> wouldn't be surprised if it was doing that. It's allowed by the JTA
> spec, but not by the PostgreSQL driver because we don't support
> transaction interleaving. We could try modifying the driver to
> tolerate it like the aforementioned "end then join" case, by not
> passing the setAutoCommit call immediately to the underlying
> connection object, but delay it until prepare-call. Whether that would
> work depends on what else the application server is trying to do with
> the connection between end and prepare.
>
> Calling commit or rollback at those points will also trigger the same
> error. JTA spec also forbids setSavePoint, but I'm not sure if that
> would actually be a problem for PostgreSQL.
>
> There's some options in WebLogic to dumb-down the interaction with the
> JDBC XA driver, see
> http://edocs.bea.com/wls/docs100/ConsoleHelp/pagehelp/JDBCjdbcdatasourcesjdbcdatasourceconfigtransactiontitle.html.
> At least "Keep Connection Open On Release" is required for PostgreSQL
> driver, and setting the other settings marked with "Use this setting
> to work around specific problems with JDBC XA drivers" might help too.
> Please make sure you have those set.
>
>
> Now, it would be very good if we threw an error immediately at the
> offending call, regardless of whether it's allowed by JTA or not. I've
> been trying to figure out how to do that. We could create a proxy for
> the Connection object handed to the application in PGXAConnection, and
> throw an error if you call one of those functions while an
> XA-transaction is open. That would be fairly simple, but wouldn't
> catch the pattern:
>
> start(xid)
> // do stuff in XA transaction
> executeUpdate("UPDATE ...");
> end(xid)
> // do stuff outside the XA transaction
> executeUpdate("UPDATE ...");
> prepare(xid);
>
> It would be better than nothing, but it would be even better if we
> could catch all the cases we can't handle properly. If we could inject
> a proxy to check that at lower level, around QueryExecutor, it would
> be more robust, but I don't see any easy way to do that.
>
>
> Another check that we really ought to do is to check the command tag
> that PREPARE TRANSACTION returns. If it returns ROLLBACK, the driver
> should throw an error. I'll write a patch for that.
>

--
-------------------------------------------------------------
Vlastimil Havránek
Software Developer
xitee k.s. || www.xitee.com || vlastimil(dot)havranek(at)xitee(dot)com
Phone: office +420 234262342, mobile +420 775366990
-------------------------------------------------------------

Hi,
Ive just tried the patched driver and at first look it seems to have
solved the issue! I will check the logs and do more tests tomorow.

VH

Heikki Linnakangas wrote:
> Vlastimil Havranek wrote:
>> Hi,
>> regarding the autocommit, we do not use it in our application, we use
>> the EJBs mostly with CMP, some with BMP, which are accessing several
>> dbs via XA driver.
>> The EJB on which it gets stuck runs with CMP.
>>
>> Ive found that weblogic provides some monitoring of tx, the tx was
>> there in state 'comitting' but both force local and force global
>> commit failed with xaexception: someDataSource: null.
>>
>> Ive tried all the XA related data source settings, but it didnt help.
>>
>> So maybe if you could modify the driver to tolerate the strange WL XA
>> pattern, then I would try that one out.
>>
>> Anyway, thx for your great cooperation,
>
> Ok, here's a patch to tighten up the XA state handling in the driver,
> in two different ways:
> 1. More cases of illegal (per JTA spec) calls and calls we can't
> handle because of lack of transaction interleaving are explicitly
> checked for, and an error is thrown.
> 2. The returned command tag of PREPARE TRANSACTION/COMMIT
> PREPARED/ROLLBACK PREPARED are checked, and an exception is thrown if
> it's not what was expected.
>
> This makes the XA part of the driver much more robust.
>
> Vlastimil, can you try what this patch does to your test case? It
> won't solve your problem, but you should get a more descriptive error
> message, showing more clearly what WebLogic is doing. Then we can
> hopefully see if there's something we can do in the driver to make it
> work.
>
> I can send you a patched postgresql.jar offlist. If you need one, just
> drop me a note.
>

--
-------------------------------------------------------------
Vlastimil Havránek
Software Developer
xitee k.s. || www.xitee.com || vlastimil(dot)havranek(at)xitee(dot)com
Phone: office +420 234262342, mobile +420 775366990
-------------------------------------------------------------

Vlastimil Havranek wrote:
> Ive just tried the patched driver and at first look it seems to have
> solved the issue! I will check the logs and do more tests tomorow.

Huh, that's odd. It really shouldn't have solved it! It should've just
given a different error message.

--
Heikki Linnakangas
EnterpriseDB http://www.enterprisedb.com

It has not solve the issue completely, but really made it appear less
often.
Currently we are preparing to start using jboss, so I will leave the
issue to the community now.

Thx for your help anyway,

Vl.

Heikki Linnakangas wrote:
> Vlastimil Havranek wrote:
>> Ive just tried the patched driver and at first look it seems to have
>> solved the issue! I will check the logs and do more tests tomorow.
>
> Huh, that's odd. It really shouldn't have solved it! It should've just
> given a different error message.
>

--
-------------------------------------------------------------
Vlastimil Havránek
Software Developer
xitee k.s. || www.xitee.com || vlastimil(dot)havranek(at)xitee(dot)com
Phone: office +420 234262342, mobile +420 775366990
-------------------------------------------------------------