View Issue Details

IDProjectCategoryView StatusLast Update
0000169Pgpool-IIBugpublic2016-03-07 11:26
Reportertest11Assigned Tot-ishii 
PriorityurgentSeveritymajorReproducibilityalways
Status resolvedResolutionopen 
Product Version 
Target VersionFixed in Version 
Summary0000169: 3.5.0 issues with php-pdo/2 - constraint violation version
Descriptionthis 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 Reproducephp -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 Information2016-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
TagsNo tags attached.

Activities

t-ishii

2016-03-04 19:52

developer   ~0000673

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?

test11

2016-03-05 01:27

reporter   ~0000674

Ok, i've tested it with 4 different kind of errors (42P01,42601,23502,23505) - everything seems to work as expected.

Thank you again.

t-ishii

2016-03-07 11:25

developer   ~0000675

Thanks for the feedback!

Issue History

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