[pgpool-general: 1305] Re: database detach and I don't understand why
Flemming Harms
flemming.harms at gmail.com
Tue Jan 8 23:03:13 JST 2013
sorry I forgot about the pgpool archive can't list attachments
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
More information about the pgpool-general
mailing list