Re: Problem with committing in XA mode

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