Re: Problem with committing in XA mode - Mailing list pgsql-jdbc

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