[pgpool-general: 1307] Re: database detach and I don't understand why

Tatsuo Ishii ishii at postgresql.org
Tue Jan 8 23:58:27 JST 2013


> sorry I forgot about the pgpool archive can't list attachments

Actually the archive allows attachments.

Mail body page:
http://www.pgpool.net/pipermail/pgpool-general/2013-January/001324.html

In the very end of the page you will find a link to the diagram:
http://www.sraoss.jp/pipermail/pgpool-general/attachments/20130108/7132e567/attachment-0001.png
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp

> so here is the link to the diagram
> https://docs.google.com/drawings/d/11_RraiNeDtTJZJO0xSsK2FYbevbfn1BBUAXPAt2mKfM/edit
> 
> 2013/1/8 Flemming Harms <flemming.harms at gmail.com>:
>> I think I might have a theory on what might be wrong.
>>
>> This is related to JBM_MSG_REF record is deleted/committed in multiple
>> threads, and the SQL command has a embedded sub-query that decide if
>> it can delete the message or not.
>>
>> Because it contains a sub-query it will run on each node and might get
>> different result
>>
>> "FROM JBM_MSG WHERE MESSAGE_ID = $1 AND NOT EXISTS (SELECT
>> JBM_MSG_REF.MESSAGE_ID FROM JBM_MSG_REF WHERE JBM_MSG_REF.MESSAGE_ID =
>> $2)"
>>
>> I have tried to illustrate the problem in a diagram what I thinks happens.
>>
>> Could this be the issue or i'm I on a wild goose chase?
>>
>> 2013/1/4 Flemming Harms <flemming.harms at gmail.com>:
>>> thanks for taking time to look into this.
>>>
>>> The "PREPARE TRANSACTION
>>> '131075_MTkxLTdmMDAwMDAxOmUwMDY6NTBkYzllNzU6MjMwNQ==_N2YwMDAwMDE6ZTAwNjo1MGRjOWU3NToyMzBh'
>>> transaction do exists. I cut to much when I was pasting the
>>> information, but you can see the full log here
>>>
>>> jboss-detach-190.sql > http://ubuntuone.com/6Ku56EoHI7FAXAyC1p1prQ
>>> jboss-detach-191.sql > http://ubuntuone.com/0ICbQCiowqDgKe7LglMxSV
>>> pgpool.conf > http://ubuntuone.com/3BhoRnr3ACifYhi2QqSbat
>>> pgppool-191.log > http://ubuntuone.com/1g8ExrevBeRUj92XS5WjyZ
>>>
>>> I have been using the last two days to investigate if jboss is
>>> responsible for rollback a transaction or drop connections. So far
>>> everything looks fine until pgpool decide to degenerate the database.
>>>
>>> If you want I can attach the jboss server.log, you might be able to
>>> get something from it that I'm not?
>>>
>>> Thanks!
>>>
>>> /flemming
>>>
>>>
>>> 2013/1/4 Tatsuo Ishii <ishii at postgresql.org>:
>>>>> Thanks for looking into this!
>>>>>
>>>>> 1) I search through the code and listed all functions for the jboss
>>>>> schema and there is no use of functions
>>>>
>>>> Ok.
>>>>
>>>>> 2) The same goes for triggers
>>>>
>>>> Ok.
>>>>
>>>>> 3) if the JBoss for some reason should disconnect shouldn't I be able
>>>>> to see that in the pgpool log or PostgreSQL log?
>>>>>
>>>>> If you look through the PostgreSQL log you will actual see that all
>>>>> statement are executed in the same order until it degenerate node 1,
>>>>> and I did a diff on the PostgreSQL statement and there is no different
>>>>> until it degenerate.
>>>>>
>>>>> I can't see anything that indicate why it "degenerate" in PostgreSQL log.
>>>>
>>>> I see this line in the log:
>>>>
>>>> 2012-12-27 19:54:18 GMT 25803 20/357 0 LOG:  execute <unnamed>: COMMIT PREPARED '131075_MTkxLTdmMDAwMDAxOmUwMDY6NTBkYzllNzU6MjMwNQ==_N2YwMDAwMDE6ZTAwNjo1MGRjOWU3NToyMzBh'
>>>>
>>>> This is a two phase commit command. Unfortunately I couldn't find any
>>>> corresponding "PREPARE TRANSACTION" and cannot guess what was actually
>>>> committed. Maybe the prepared transaction is related to the
>>>> difference?
>>>> --
>>>> Tatsuo Ishii
>>>> SRA OSS, Inc. Japan
>>>> English: http://www.sraoss.co.jp/index_en.php
>>>> Japanese: http://www.sraoss.co.jp
>>>>
>>>>> SQL for node 1 :(I have truncated the long lines )
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 0 LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 0 LOG:  execute <unnamed>: INSERT
>>>>> INTO JBM_TX (NODE_ID, TRANSACTION_ID, BRANCH_QUAL, FORMAT_ID,
>>>>> GLOBAL_TXID) VALUES($1, $2, $3, $4, $5)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 0 DETAIL:  parameters: $1 =
>>>>> '191', $2 = '3446306904799576068', $3 = '7f000001:e006:50dc9e75:2317',
>>>>> $4 = '131075', $5 = '191-7f000001:e006:50dc9e75:2305'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID,
>>>>> STATE, ORD, PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2,
>>>>> $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2872', $2 = '3446306904799576396', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799576403', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP,
>>>>> PRIORITY, TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7,
>>>>> $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '3446306904799576396', $2 = 'Y', $3 = '0', $4 = '1356638058062', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID,
>>>>> STATE, ORD, PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2,
>>>>> $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576397', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799609172', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP,
>>>>> PRIORITY, TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7,
>>>>> $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '3446306904799576397', $2 = 'Y', $3 = '0', $4 = '1356638058393', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID,
>>>>> STATE, ORD, PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2,
>>>>> $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576397', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799641941', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID,
>>>>> STATE, ORD, PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2,
>>>>> $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576398', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799641942', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP,
>>>>> PRIORITY, TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7,
>>>>> $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '3446306904799576398', $2 = 'Y', $3 = '0', $4 = '1356638058412', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576398', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799641943', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576399', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799674712', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP,
>>>>> PRIORITY, TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7,
>>>>> $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '3446306904799576399', $2 = 'Y', $3 = '0', $4 = '1356638058425', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576399', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799674713', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576400', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799674714', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_6: INSERT
>>>>> INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP, PRIORITY,
>>>>> TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '3446306904799576400', $2 = 'Y', $3 = '0', $4 = '1356638058434', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576400', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799674715', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576401', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799674716', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_6: INSERT
>>>>> INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP, PRIORITY,
>>>>> TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '3446306904799576401', $2 = 'Y', $3 = '0', $4 = '1356638058444', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576401', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799707485', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576402', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799707486', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_6: INSERT
>>>>> INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP, PRIORITY,
>>>>> TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '3446306904799576402', $2 = 'Y', $3 = '0', $4 = '1356638058453', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576402', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799707487', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576403', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799707488', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_6: INSERT
>>>>> INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP, PRIORITY,
>>>>> TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '3446306904799576403', $2 = 'Y', $3 = '0', $4 = '1356638058463', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576403', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799707489', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576404', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799740258', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_6: INSERT
>>>>> INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP, PRIORITY,
>>>>> TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '3446306904799576404', $2 = 'Y', $3 = '0', $4 = '1356638058532', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576404', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799740259', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/167 249453 LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 25803 20/357 0 LOG:  execute <unnamed>: COMMIT
>>>>> PREPARED '131075_MTkxLTdmMDAwMDAxOmUwMDY6NTBkYzllNzU6MjMwNQ==_N2YwMDAwMDE6ZTAwNjo1MGRjOWU3NToyMzBh'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/168 0 LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 26538 23/168 0 LOG:  execute <unnamed>: UPDATE
>>>>> JBM_MSG_REF SET STATE='C', TRANSACTION_ID = NULL WHERE
>>>>> TRANSACTION_ID=$1 AND STATE='+'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/168 0 DETAIL:  parameters: $1 =
>>>>> '3446306904799576068'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/168 249455 LOG:  execute <unnamed>:
>>>>> DELETE FROM JBM_MSG_REF WHERE TRANSACTION_ID=$1 AND STATE='-'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/168 249455 DETAIL:  parameters: $1 =
>>>>> '3446306904799576068'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/168 249455 LOG:  execute <unnamed>:
>>>>> DELETE FROM JBM_TX WHERE NODE_ID = $1 AND TRANSACTION_ID = $2
>>>>> 2012-12-27 19:54:18 GMT 26538 23/168 249455 DETAIL:  parameters: $1 =
>>>>> '191', $2 = '3446306904799576068'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/168 249455 LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 26538 23/169 0 LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 26538 23/169 0 LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 26538 23/170 0 LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 25803 20/358 0 LOG:  statement: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 26538 23/170 0 LOG:  execute <unnamed>: DELETE
>>>>> FROM JBM_MSG_REF WHERE MESSAGE_ID=$1 AND CHANNEL_ID=$2 AND STATE='C'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/170 0 DETAIL:  parameters: $1 =
>>>>> '3446306904799576397', $2 = '2876'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/170 249456 LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 25803 20/358 0 LOG:  statement: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 25803 20/359 0 LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 25803 20/359 0 LOG:  execute <unnamed>: select
>>>>> next_id from sequence_log_msg_attribs for update
>>>>> 2012-12-27 19:54:18 GMT 25803 20/359 249457 LOG:  execute <unnamed>:
>>>>> update sequence_log_msg_attribs set next_id = $1 where next_id = $2
>>>>> 2012-12-27 19:54:18 GMT 25803 20/359 249457 DETAIL:  parameters: $1 =
>>>>> '61691', $2 = '61690'
>>>>> 2012-12-27 19:54:18 GMT 25803 20/359 249457 LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 26537 22/120 0 LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 26537 22/120 0 LOG:  execute <unnamed>: DELETE
>>>>> FROM JBM_MSG_REF WHERE MESSAGE_ID=$1 AND CHANNEL_ID=$2 AND STATE='C'
>>>>> 2012-12-27 19:54:18 GMT 26537 22/120 0 DETAIL:  parameters: $1 =
>>>>> '3446306904799576397', $2 = '2875'
>>>>> 2012-12-27 19:54:18 GMT 26537 22/120 249458 LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 26538 23/171 0 LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 26538 23/171 0 LOG:  execute <unnamed>: DELETE
>>>>> FROM JBM_MSG WHERE MESSAGE_ID = $1 AND NOT EXISTS (SELECT
>>>>> JBM_MSG_REF.MESSAGE_ID FROM JBM_MSG_REF WHERE JBM_MSG_REF.MESSAGE_ID =
>>>>> $2)
>>>>> 2012-12-27 19:54:18 GMT 26538 23/171 0 DETAIL:  parameters: $1 =
>>>>> '3446306904799576397', $2 = '3446306904799576397'
>>>>> 2012-12-27 19:54:18 GMT 26538 23/171 0 DETAIL:  parameters: $1 =
>>>>> '3446306904799576397', $2 = '3446306904799576397'
>>>>> 2012-12-27 19:54:18 GMT 25657 2/0 0 LOG:  unexpected EOF on client connection
>>>>> 2012-12-27 19:54:18 GMT 25658 3/0 0 LOG:  unexpected EOF on client connection
>>>>> 2012-12-27 19:54:18 GMT 28045 25/0 0 LOG:  unexpected EOF on client connection
>>>>> 2012-12-27 19:54:18 GMT 26537 22/0 0 LOG:  could not receive data from
>>>>> client: Connection reset by peer
>>>>>
>>>>> SQL for node 0: (I have truncated the long lines )
>>>>>
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 0LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 0LOG:  execute <unnamed>: INSERT
>>>>> INTO JBM_TX (NODE_ID, TRANSACTION_ID, BRANCH_QUAL, FORMAT_ID,
>>>>> GLOBAL_TXID) VALUES($1, $2, $3, $4, $5)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 0DETAIL:  parameters: $1 = '191',
>>>>> $2 = '3446306904799576068', $3 = '7f000001:e006:50dc9e75:2317', $4 =
>>>>> '131075', $5 = '191-7f000001:e006:50dc9e75:2305'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID,
>>>>> STATE, ORD, PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2,
>>>>> $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2872', $2 = '3446306904799576396', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799576403', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP,
>>>>> PRIORITY, TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7,
>>>>> $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '3446306904799576396', $2 = 'Y', $3 = '0', $4 = '1356638058062', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID,
>>>>> STATE, ORD, PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2,
>>>>> $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576397', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799609172', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP,
>>>>> PRIORITY, TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7,
>>>>> $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '3446306904799576397', $2 = 'Y', $3 = '0', $4 = '1356638058393', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID,
>>>>> STATE, ORD, PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2,
>>>>> $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576397', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799641941', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID,
>>>>> STATE, ORD, PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2,
>>>>> $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576398', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799641942', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP,
>>>>> PRIORITY, TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7,
>>>>> $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '3446306904799576398', $2 = 'Y', $3 = '0', $4 = '1356638058412', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576398', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799641943', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576399', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799674712', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute <unnamed>:
>>>>> INSERT INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP,
>>>>> PRIORITY, TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7,
>>>>> $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '3446306904799576399', $2 = 'Y', $3 = '0', $4 = '1356638058425', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576399', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799674713', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576400', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799674714', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_6: INSERT
>>>>> INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP, PRIORITY,
>>>>> TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '3446306904799576400', $2 = 'Y', $3 = '0', $4 = '1356638058434', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576400', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799674715', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576401', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799674716', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_6: INSERT
>>>>> INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP, PRIORITY,
>>>>> TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '3446306904799576401', $2 = 'Y', $3 = '0', $4 = '1356638058444', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576401', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799707485', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576402', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799707486', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_6: INSERT
>>>>> INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP, PRIORITY,
>>>>> TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '3446306904799576402', $2 = 'Y', $3 = '0', $4 = '1356638058453', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576402', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799707487', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576403', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799707488', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_6: INSERT
>>>>> INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP, PRIORITY,
>>>>> TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '3446306904799576403', $2 = 'Y', $3 = '0', $4 = '1356638058463', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576403', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799707489', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2875', $2 = '3446306904799576404', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799740258', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_6: INSERT
>>>>> INTO JBM_MSG (MESSAGE_ID, RELIABLE, EXPIRATION, TIMESTAMP, PRIORITY,
>>>>> TYPE, HEADERS, PAYLOAD) VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '3446306904799576404', $2 = 'Y', $3 = '0', $4 = '1356638058532', $5 =
>>>>> '4', $6 = '2', $7 = '....' , $8 = '....'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_5: INSERT
>>>>> INTO JBM_MSG_REF (CHANNEL_ID, MESSAGE_ID, TRANSACTION_ID, STATE, ORD,
>>>>> PAGE_ORD, DELIVERY_COUNT, SCHED_DELIVERY) VALUES ($1, $2, $3, $4, $5,
>>>>> $6, $7, $8)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453DETAIL:  parameters: $1 =
>>>>> '2876', $2 = '3446306904799576404', $3 = '3446306904799576068', $4 =
>>>>> '+', $5 = '3446306904799740259', $6 = NULL, $7 = '0', $8 = '0'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/35 249453LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 18558 20/80 0LOG:  execute <unnamed>: COMMIT
>>>>> PREPARED '131075_MTkxLTdmMDAwMDAxOmUwMDY6NTBkYzllNzU6MjMwNQ==_N2YwMDAwMDE6ZTAwNjo1MGRjOWU3NToyMzBh'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/36 0LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 19308 23/36 0LOG:  execute <unnamed>: UPDATE
>>>>> JBM_MSG_REF SET STATE='C', TRANSACTION_ID = NULL WHERE
>>>>> TRANSACTION_ID=$1 AND STATE='+'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/36 0DETAIL:  parameters: $1 =
>>>>> '3446306904799576068'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/36 249455LOG:  execute <unnamed>:
>>>>> DELETE FROM JBM_MSG_REF WHERE TRANSACTION_ID=$1 AND STATE='-'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/36 249455DETAIL:  parameters: $1 =
>>>>> '3446306904799576068'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/36 249455LOG:  execute <unnamed>:
>>>>> DELETE FROM JBM_TX WHERE NODE_ID = $1 AND TRANSACTION_ID = $2
>>>>> 2012-12-27 19:54:18 GMT 19308 23/36 249455DETAIL:  parameters: $1 =
>>>>> '191', $2 = '3446306904799576068'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/36 249455LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 19308 23/37 0LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 19308 23/37 0LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 19308 23/38 0LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 18558 20/81 0LOG:  statement: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 19308 23/38 0LOG:  execute <unnamed>: DELETE
>>>>> FROM JBM_MSG_REF WHERE MESSAGE_ID=$1 AND CHANNEL_ID=$2 AND STATE='C'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/38 0DETAIL:  parameters: $1 =
>>>>> '3446306904799576397', $2 = '2876'
>>>>> 2012-12-27 19:54:18 GMT 19308 23/38 249456LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 18558 20/81 0LOG:  statement: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 18558 20/82 0LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 18558 20/82 0LOG:  execute <unnamed>: select
>>>>> next_id from sequence_log_msg_attribs for update
>>>>> 2012-12-27 19:54:18 GMT 18558 20/82 249457LOG:  execute <unnamed>:
>>>>> update sequence_log_msg_attribs set next_id = $1 where next_id = $2
>>>>> 2012-12-27 19:54:18 GMT 18558 20/82 249457DETAIL:  parameters: $1 =
>>>>> '61691', $2 = '61690'
>>>>> 2012-12-27 19:54:18 GMT 18558 20/82 249457LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 19307 22/70 0LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 19307 22/70 0LOG:  execute <unnamed>: DELETE
>>>>> FROM JBM_MSG_REF WHERE MESSAGE_ID=$1 AND CHANNEL_ID=$2 AND STATE='C'
>>>>> 2012-12-27 19:54:18 GMT 19307 22/70 0DETAIL:  parameters: $1 =
>>>>> '3446306904799576397', $2 = '2875'
>>>>> 2012-12-27 19:54:18 GMT 19307 22/70 249458LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 19308 23/39 0LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 19308 23/39 0LOG:  execute <unnamed>: DELETE
>>>>> FROM JBM_MSG WHERE MESSAGE_ID = $1 AND NOT EXISTS (SELECT
>>>>> JBM_MSG_REF.MESSAGE_ID FROM JBM_MSG_REF WHERE JBM_MSG_REF.MESSAGE_ID =
>>>>> $2)
>>>>> 2012-12-27 19:54:18 GMT 19308 23/39 0DETAIL:  parameters: $1 =
>>>>> '3446306904799576397', $2 = '3446306904799576397'
>>>>> 2012-12-27 19:54:18 GMT 22442 1/124 0LOG:  execute <unnamed>: SET
>>>>> SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL READ COMMITTED
>>>>> 2012-12-27 19:54:18 GMT 22442 1/125 0LOG:  execute <unnamed>: select 1
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0LOG:  execute <unnamed>: select
>>>>> iteminfopa0_.infopanel_item_uuid as infopanel1_99_0_, iteminfopa0_.x
>>>>> as x0_, iteminfopa0_.y as y0_, iteminfopa0_.item_uuid as item4_0_ from
>>>>> itemInfoPanelToPoint iteminfopa0_ where
>>>>> iteminfopa0_.infopanel_item_uuid=$1
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0DETAIL:  parameters: $1 =
>>>>> 'e0005ae7-7285-45a1-88a1-e73e54149485'
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0LOG:  execute <unnamed>: select
>>>>> itempintop0_.pin_item_uuid as pin1_99_0_, itempintop0_.x as x0_,
>>>>> itempintop0_.y as y0_, itempintop0_.item_uuid as item4_0_ from
>>>>> itemPinToPoint itempintop0_ where itempintop0_.pin_item_uuid=$1
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0DETAIL:  parameters: $1 =
>>>>> 'e0005ae7-7285-45a1-88a1-e73e54149485'
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0LOG:  execute <unnamed>: select
>>>>> this_.uuid as uuid100_0_ from placement_service this_
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0LOG:  execute <unnamed>: select
>>>>> this_.uuid as uuid125_0_ from keyword_administration this_
>>>>> 2012-12-27 19:54:18 GMT 22444 2/134 0LOG:  execute <unnamed>: SET
>>>>> SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL READ COMMITTED
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0LOG:  execute <unnamed>: select
>>>>> this_.uuid as uuid501_0_, this_.profile_name as profile2_501_0_ from
>>>>> impact_config_profile this_
>>>>> 2012-12-27 19:54:18 GMT 22444 2/135 0LOG:  execute <unnamed>: select 1
>>>>> 2012-12-27 19:54:18 GMT 22444 2/136 0LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0LOG:  execute <unnamed>: select
>>>>> impactprof0_.impact_profile_id as impact3_501_1_, impactprof0_.uuid as
>>>>> uuid1_, impactprof0_.uuid as uuid500_0_, impactprof0_1_.filter_type as
>>>>> filter2_503_0_, impactprof0_2_.dangerous_temperature as
>>>>> dangerous2_504_0_, impactprof0_2_.critical_temperature as
>>>>> critical3_504_0_, impactprof0_2_.check_redundancy as check4_504_0_,
>>>>> impactprof0_.identifiable_type as identifi2_500_0_ from
>>>>> impact_config_profile_part impactprof0_ left outer join
>>>>> impact_config_alarm_profile_part impactprof0_1_ on
>>>>> impactprof0_.uuid=impactprof0_1_.uuid left outer join
>>>>> impact_config_cooling_profile_part impactprof0_2_ on
>>>>> impactprof0_.uuid=impactprof0_2_.uuid where
>>>>> impactprof0_.impact_profile_id=$1
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0DETAIL:  parameters: $1 =
>>>>> '6aeba475-aba0-4b9b-8fff-6ff264da605f'
>>>>> 2012-12-27 19:54:18 GMT 22444 2/136 0LOG:  execute <unnamed>: DELETE
>>>>> FROM JBM_MSG_REF WHERE MESSAGE_ID=$1 AND CHANNEL_ID=$2 AND STATE='C'
>>>>> 2012-12-27 19:54:18 GMT 22444 2/136 0DETAIL:  parameters: $1 =
>>>>> '3446306904799576396', $2 = '2872'
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0LOG:  execute <unnamed>: select
>>>>> alarmfilte0_.alarm_impact_profile_id as alarm3_500_1_,
>>>>> alarmfilte0_.uuid as uuid1_, alarmfilte0_.uuid as uuid502_0_,
>>>>> alarmfilte0_.description_pattern as descript2_502_0_ from
>>>>> impact_config_alarm_filter_entry alarmfilte0_ where
>>>>> alarmfilte0_.alarm_impact_profile_id=$1
>>>>> 2012-12-27 19:54:18 GMT 22442 1/126 0DETAIL:  parameters: $1 =
>>>>> 'e26f45e2-715e-4465-80bb-ac492c88f880'
>>>>> 2012-12-27 19:54:18 GMT 22444 2/136 249459LOG:  execute S_2: COMMIT
>>>>> 2012-12-27 19:54:18 GMT 22444 2/137 0LOG:  execute S_1: BEGIN
>>>>> 2012-12-27 19:54:18 GMT 22444 2/137 0LOG:  execute <unnamed>: DELETE
>>>>> FROM JBM_MSG WHERE MESSAGE_ID = $1 AND NOT EXISTS (SELECT
>>>>> JBM_MSG_REF.MESSAGE_ID FROM JBM_MSG_REF WHERE JBM_MSG_REF.MESSAGE_ID =
>>>>> $2)
>>>>> 2012-12-27 19:54:18 GMT 22444 2/137 0DETAIL:  parameters: $1 =
>>>>> '3446306904799576396', $2 = '3446306904799576396'
>>>>> 2012-12-27 19:54:18 GMT 22444 2/137 249460LOG:  execute S_2: COMMIT
>>>>>
>>>>> 2013/1/2 Tatsuo Ishii <ishii at postgresql.org>:
>>>>>> Well there some possibilities:
>>>>>>
>>>>>> 1) JBoss uses functions which has side effect(updating tables).
>>>>>>
>>>>>> 2) JBoss uses triggers which updates the table in question.
>>>>>>
>>>>>> 3) the transaction updating the table in question committed on node 1
>>>>>>    but not committed on node 0 for some reason. Maybe the connection
>>>>>>    between JBoss and pgpool between those two commit commands were
>>>>>>    disconnected?
>>>>>>
>>>>>> Anyway, if you carefully look into the PostgreSQL log (I assume
>>>>>> log_statement is on), you may be able find the cause.
>>>>>> --
>>>>>> Tatsuo Ishii
>>>>>> SRA OSS, Inc. Japan
>>>>>> English: http://www.sraoss.co.jp/index_en.php
>>>>>> Japanese: http://www.sraoss.co.jp
>>>>>>
>>>>>>> the different is that node 1 the message in jbm_msg still exist, but
>>>>>>> on node 0 it's deleted. the jbm_msg_ref on both servers are empty.
>>>>>>>
>>>>>>> but I don't understand how that's possible when the jms process
>>>>>>> communicate through the pgpool? and if I read the postgresql logs
>>>>>>> correct for both nodes all SQL statement are executed in the same
>>>>>>> order until it detach.
>>>>>>>
>>>>>>> /Flemming
>>>>>>>
>>>>>>> 2012/12/31 Tatsuo Ishii <ishii at postgresql.org>:
>>>>>>>>> Hello,
>>>>>>>>>
>>>>>>>>> We have been using pgpool2 for sometime now and been happy with it,
>>>>>>>>> but lately it suddenly start to detach the database on one of the
>>>>>>>>> nodes on 2 node cluster. I have been investigated this for a while and
>>>>>>>>> I can't understand why pgpool2 thinks is should detach.
>>>>>>>>>
>>>>>>>>> We are using pgpool version 3.0.4-1 with postgresql version
>>>>>>>>> 8.4.8-0squeeze2 our application server is JBossAS 5 including (jboss
>>>>>>>>> messaging 1.4.8-SP2). The application server only communicate through
>>>>>>>>> pgpool so we are sure that no other processes are working around
>>>>>>>>> pgpool
>>>>>>>>>
>>>>>>>>> We are pretty sure the databases are not different from the beginning
>>>>>>>>> and it's new records that are created. We post 3 messages on 2
>>>>>>>>> different jms queues and 3 clients that consumes the messages. When
>>>>>>>>> jboss messaging component want to remove the messages because it
>>>>>>>>> delivered to all the clients, pgpool detach the database because it
>>>>>>>>> get a different response from node 1 when it want to delete the
>>>>>>>>> message.... which I don't understand how that's possible
>>>>>>>>>
>>>>>>>>> I really will appreciate some help to understand what is going on and
>>>>>>>>> why it detach the database
>>>>>>>>>
>>>>>>>>> Thanks!
>>>>>>>>>
>>>>>>>>> br,
>>>>>>>>> Flemming
>>>>>>>>>
>>>>>>>>> the log_line_prefix = '%t %p %v %x' for the postgresql
>>>>>>>>>
>>>>>>>>> You can find the log files by following the links below for pgpool2
>>>>>>>>> debug log and postgresql log from both servers
>>>>>>>>>
>>>>>>>>> jboss-detach-190.sql(postgresql log) >
>>>>>>>>> http://ubuntuone.com/6Ku56EoHI7FAXAyC1p1prQ
>>>>>>>>> jboss-detach-191.sql(postgresql log) >
>>>>>>>>> http://ubuntuone.com/0ICbQCiowqDgKe7LglMxSV
>>>>>>>>> pgpool.conf > http://ubuntuone.com/3BhoRnr3ACifYhi2QqSbat
>>>>>>>>> pgppool-191-log  > http://ubuntuone.com/1g8ExrevBeRUj92XS5WjyZ7
>>>>>>>>
>>>>>>>> From the log, the cause of the detach was this:
>>>>>>>>
>>>>>>>> Dec 27 19:54:18 SWDEV035 pgpool: 2012-12-27 19:54:18 ERROR: pid 18412: pgpool detected difference of the number of inserted, updated or deleted tuples. Possible last query was: "DELETE FROM JBM_MSG WHERE MESSAGE_ID = $1 AND NOT EXISTS (SELECT JBM_MSG_REF.MESSAGE_ID FROM JBM_MSG_REF WHERE JBM_MSG_REF.MESSAGE_ID = $2)"
>>>>>>>> Dec 27 19:54:18 SWDEV035 pgpool: 2012-12-27 19:54:18 LOG:   pid 18412: CommandComplete: Number of affected tuples are: 0 1
>>>>>>>>
>>>>>>>> As you said, it seems your node 0 DB did not have a raw satisfied the
>>>>>>>> WHERE clause, while your node 1 had one row which satisfied it at that
>>>>>>>> time. I suggest to check tables used by JBoss right after failover to
>>>>>>>> see there's difference in table's data.
>>>>>>>> --
>>>>>>>> Tatsuo Ishii
>>>>>>>> SRA OSS, Inc. Japan
>>>>>>>> English: http://www.sraoss.co.jp/index_en.php
>>>>>>>> Japanese: http://www.sraoss.co.jp
>>>>>>> _______________________________________________
>>>>>>> pgpool-general mailing list
>>>>>>> pgpool-general at pgpool.net
>>>>>>> http://www.pgpool.net/mailman/listinfo/pgpool-general
> _______________________________________________
> pgpool-general mailing list
> pgpool-general at pgpool.net
> http://www.pgpool.net/mailman/listinfo/pgpool-general


More information about the pgpool-general mailing list