View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000169 | Pgpool-II | Bug | public | 2016-03-03 16:36 | 2016-03-07 11:26 |
| Reporter | test11 | Assigned To | t-ishii | ||
| Priority | urgent | Severity | major | Reproducibility | always |
| Status | resolved | Resolution | open | ||
| Summary | 0000169: 3.5.0 issues with php-pdo/2 - constraint violation version | ||||
| Description | this is somehow connected to http://www.pgpool.net/mantisbt/view.php?id=168, but i can not reopen it. running a quety, that triggers a constraint violation error, agains the patched/unpatched versions, will hangup the PHP/PDO client. Raw php client works fine, and 3.4 is not affected. Note the line "query context 0x10b2bc0 is still used 2 times." in the error log | ||||
| Steps To Reproduce | php -r '$p = new PDO("pgsql:host=127.0.0.1 port=5432 dbname=test","postgres","your pw");$s=$p->prepare("insert into groups(id) values (1)");$s->execute();var_dump($s->errorInfo());' or any other query that should return constraint violation errors like "duplicate key value violates unique constraint" or "null value in column "name" violates not-null constraint" | ||||
| Additional Information | 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'P'(50) from frontend 2016-03-03 08:24:51: pid 16271: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: Parse: statement name <pdo_stmt_00000001> 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: decide where to send the queries 2016-03-03 08:24:51: pid 16271: DETAIL: destination = 0 for query= "insert into groups(id) values (1)" 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-03 08:24:51: pid 16271: DEBUG: pool_write: to backend: kind:P 2016-03-03 08:24:51: pid 16271: DEBUG: called by pool_add_sent_message: sent message: address: 10b07f0 kind: P name: =pdo_stmt_00000001= 2016-03-03 08:24:51: pid 16271: DEBUG: session context: unsetting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: processing frontend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'S'(53) from frontend 2016-03-03 08:24:51: pid 16271: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: pool_write: to backend: kind:S 2016-03-03 08:24:51: pid 16271: DEBUG: pool_read: read 11 bytes from backend 0 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: master node id: 0 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: backend:0 of 3 kind = '1' 2016-03-03 08:24:51: pid 16271: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1 2016-03-03 08:24:51: pid 16271: DEBUG: processing backend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind '1'(31) from backend 2016-03-03 08:24:51: pid 16271: DEBUG: called by pool_add_sent_message: sent message: address: 10b07f0 kind: P name: =pdo_stmt_00000001= 2016-03-03 08:24:51: pid 16271: DEBUG: adding sent message to list 2016-03-03 08:24:51: pid 16271: DETAIL: adding exactly same message is prohibited 2016-03-03 08:24:51: pid 16271: DEBUG: SimpleForwardToFrontend: packet:1 length:0 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting command success. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: master node id: 0 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: backend:0 of 3 kind = 'Z' 2016-03-03 08:24:51: pid 16271: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1 2016-03-03 08:24:51: pid 16271: DEBUG: processing backend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'Z'(5a) from backend 2016-03-03 08:24:51: pid 16271: DEBUG: processing backend response 2016-03-03 08:24:51: pid 16271: DETAIL: Ready For Query received 2016-03-03 08:24:51: pid 16271: DEBUG: reading message length 2016-03-03 08:24:51: pid 16271: DETAIL: slot: 0 length: 5 2016-03-03 08:24:51: pid 16271: DEBUG: processing ReadyForQuery 2016-03-03 08:24:51: pid 16271: DETAIL: transaction state 'I'(49) 2016-03-03 08:24:51: pid 16271: DEBUG: session context: unsetting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: processing frontend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'B'(42) from frontend 2016-03-03 08:24:51: pid 16271: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: Bind: waiting for master completing the query 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-03 08:24:51: pid 16271: DEBUG: pool_write: to backend: kind:B 2016-03-03 08:24:51: pid 16271: DEBUG: session context: unsetting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: called by pool_add_sent_message: sent message: address: 10b08c0 kind: B name: == 2016-03-03 08:24:51: pid 16271: DEBUG: processing frontend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'D'(44) from frontend 2016-03-03 08:24:51: pid 16271: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: Describe: waiting for master completing the query 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-03 08:24:51: pid 16271: DEBUG: pool_write: to backend: kind:D 2016-03-03 08:24:51: pid 16271: DEBUG: session context: unsetting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: processing frontend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'E'(45) from frontend 2016-03-03 08:24:51: pid 16271: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: pool_send_and_wait: pool_set_sync_map: 0 2016-03-03 08:24:51: pid 16271: DEBUG: pool_write: to backend: kind:E 2016-03-03 08:24:51: pid 16271: DEBUG: session context: unsetting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: processing frontend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'S'(53) from frontend 2016-03-03 08:24:51: pid 16271: DEBUG: session context: clearing doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting doing extended query messaging. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: pool_write: to backend: kind:S 2016-03-03 08:24:51: pid 16271: DEBUG: pool_read: read 178 bytes from backend 0 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: master node id: 0 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: backend:0 of 3 kind = '2' 2016-03-03 08:24:51: pid 16271: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1 2016-03-03 08:24:51: pid 16271: DEBUG: processing backend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind '2'(32) from backend 2016-03-03 08:24:51: pid 16271: DEBUG: called by pool_add_sent_message: sent message: address: 10b08c0 kind: B name: == 2016-03-03 08:24:51: pid 16271: DEBUG: adding sent message to list 2016-03-03 08:24:51: pid 16271: DETAIL: adding exactly same message is prohibited 2016-03-03 08:24:51: pid 16271: DEBUG: SimpleForwardToFrontend: packet:2 length:0 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting command success. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: master node id: 0 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: backend:0 of 3 kind = 'n' 2016-03-03 08:24:51: pid 16271: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1 2016-03-03 08:24:51: pid 16271: DEBUG: processing backend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'n'(6e) from backend 2016-03-03 08:24:51: pid 16271: DEBUG: SimpleForwardToFrontend: packet:n length:0 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: master node id: 0 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: backend:0 of 3 kind = 'E' 2016-03-03 08:24:51: pid 16271: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1 2016-03-03 08:24:51: pid 16271: DEBUG: processing backend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'E'(45) from backend 2016-03-03 08:24:51: pid 16271: DEBUG: SimpleForwardToFrontend: packet:E length:163 2016-03-03 08:24:51: pid 16271: DEBUG: session context: clearing transaction isolation. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting ignore till sync. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: unsetting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: pool_read: read 6 bytes from backend 0 2016-03-03 08:24:51: pid 16271: DEBUG: detect error: kind: Z 2016-03-03 08:24:51: pid 16271: DEBUG: detect error: kind: Z 2016-03-03 08:24:51: pid 16271: DEBUG: detect error: kind: Z 2016-03-03 08:24:51: pid 16271: DEBUG: pool_use_sync_map: set use sync map: 0 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: master node id: 0 2016-03-03 08:24:51: pid 16271: DEBUG: reading backend data packet kind 2016-03-03 08:24:51: pid 16271: DETAIL: backend:0 of 3 kind = 'Z' 2016-03-03 08:24:51: pid 16271: DEBUG: read_kind_from_backend max_count:1.000000 num_executed_nodes:1 2016-03-03 08:24:51: pid 16271: DEBUG: processing backend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'Z'(5a) from backend 2016-03-03 08:24:51: pid 16271: DEBUG: processing backend response 2016-03-03 08:24:51: pid 16271: DETAIL: Ready For Query received 2016-03-03 08:24:51: pid 16271: DEBUG: pool_use_sync_map: set use sync map: 0 2016-03-03 08:24:51: pid 16271: DEBUG: pool_use_sync_map: set use sync map: 0 2016-03-03 08:24:51: pid 16271: DEBUG: pool_use_sync_map: set use sync map: 0 2016-03-03 08:24:51: pid 16271: DEBUG: reading message length 2016-03-03 08:24:51: pid 16271: DETAIL: slot: 0 length: 5 2016-03-03 08:24:51: pid 16271: DEBUG: processing ReadyForQuery 2016-03-03 08:24:51: pid 16271: DETAIL: transaction state 'I'(49) 2016-03-03 08:24:51: pid 16271: DEBUG: processing frontend response 2016-03-03 08:24:51: pid 16271: DETAIL: received kind 'Q'(51) from frontend 2016-03-03 08:24:51: pid 16271: DEBUG: session context: setting query in progress. DONE 2016-03-03 08:24:51: pid 16271: DEBUG: session context: unsetting query in progress. DONE 2016-03-03 08:24:55: pid 16271: ERROR: unable to read data from frontend 2016-03-03 08:24:55: pid 16271: DETAIL: EOF encountered with frontend 2016-03-03 08:24:55: pid 16271: DEBUG: session context: unsetting query in progress. DONE 2016-03-03 08:24:55: pid 16271: DEBUG: called by pool_sent_message_destroy: sent message: address: 10b07f0 kind: P name: =pdo_stmt_00000001= 2016-03-03 08:24:55: pid 16271: DEBUG: checking if query context can be safely destroyed 2016-03-03 08:24:55: pid 16271: DETAIL: query context 0x10b2bc0 is still used 2 times. query:"insert into groups(id) values (1)" 2016-03-03 08:24:55: pid 16271: DEBUG: called by pool_sent_message_destroy: sent message: address: 10b08c0 kind: B name: == 2016-03-03 08:24:55: pid 16271: DEBUG: session context: unsetting query in progress. DONE 2016-03-03 08:24:55: pid 16271: DEBUG: pool_write: to backend: kind:X 2016-03-03 08:24:55: pid 16271: DEBUG: pool_write: to backend: kind:X 2016-03-03 08:24:55: pid 16271: DEBUG: pool_write: to backend: kind:X | ||||
| Tags | No tags attached. | ||||
|
|
Thanks for the report. It seems pgpool-II remembers that it has received an error message from backend for too long. Thus it does not process the subsequent query (DEALLOCATE) and hangs there. I have pushed fix to master and 3.5 stable tree. http://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=67ac541d879b9a96353216b793ce954088e5ff06 Could you please try it out? |
|
|
Ok, i've tested it with 4 different kind of errors (42P01,42601,23502,23505) - everything seems to work as expected. Thank you again. |
|
|
Thanks for the feedback! |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2016-03-03 16:36 | test11 | New Issue | |
| 2016-03-03 17:28 | t-ishii | Assigned To | => t-ishii |
| 2016-03-03 17:28 | t-ishii | Status | new => assigned |
| 2016-03-04 19:52 | t-ishii | Note Added: 0000673 | |
| 2016-03-04 19:52 | t-ishii | Status | assigned => feedback |
| 2016-03-05 01:27 | test11 | Note Added: 0000674 | |
| 2016-03-05 01:27 | test11 | Status | feedback => assigned |
| 2016-03-07 11:25 | t-ishii | Note Added: 0000675 | |
| 2016-03-07 11:26 | t-ishii | Status | assigned => resolved |
