[pgpool-general: 1281] Re: database detach and I don't understand why
Flemming Harms
flemming.harms at gmail.com
Fri Jan 4 22:59:57 JST 2013
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