[pgpool-general: 1304] Re: database detach and I don't understand why
Flemming Harms
flemming.harms at gmail.com
Tue Jan 8 21:42:44 JST 2013
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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: pgpool-replication-save-with-jboss-jms.png
Type: image/png
Size: 68940 bytes
Desc: not available
URL: <http://www.sraoss.jp/pipermail/pgpool-general/attachments/20130108/7132e567/attachment-0001.png>
More information about the pgpool-general
mailing list