View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000345 | Pgpool-II | Incompatible change | public | 2017-10-03 00:06 | 2017-11-07 10:21 |
| Reporter | juliuszaromskis | Assigned To | t-ishii | ||
| Priority | high | Severity | major | Reproducibility | always |
| Status | resolved | Resolution | open | ||
| Product Version | 3.5.9 | ||||
| Fixed in Version | 3.5.11 | ||||
| Summary | 0000345: pgpool node.js prepared statement | ||||
| Description | This was introduced in 3.5.9 (possibly with erlang changes, idk). When prepared statement is used, application hangs. Works correctly if connected directly to postgres. Using PostgreSQL 9.3.12 and nodejs 6.5.0 Should be easy to reproduce: | ||||
| Steps To Reproduce | npm install pg index.js ``` const pg = require('pg'); const client = new pg.Client({ user: 'user', database: 'db', password: 'passwd', host: 'localhost' }); // connect to our database console.log("trying connect"); client.connect(function (err) { if (err) throw err; console.log("connected"); // any prepared statement really client.query('SELECT name FROM users WHERE id = $1;', [12345], function (err, result) { if (err) throw err; // just print the result to the console console.log(result); // outputs: { name: 'brianc' } // disconnect the client client.end(function (err) { if (err) throw err; }); }); }); ``` | ||||
| Tags | No tags attached. | ||||
|
|
I was wrong, now testing 3.5.8 also has this issue. Just try the latest 3.5.10 to reproduce. |
|
|
I went all the way back to 3.5.6, it work with this version. That mean the incompatible change is probably in 3.5.7. |
|
|
|
|
|
So you have problem even with 3.5.10? If so, please post the pgpool debug log. |
|
|
I don't have the debug log, and there's nothing unusual in log. I have problem with every version starting with 3.5.7. |
|
|
That's unfortunate. I don't have time to set up node.js environment and run your program to reproduce the problem. |
|
|
Right. I'm setting up local test environment to see what's causing this issue. |
|
|
This only happens when there are two backends and master_slave_mode = on. I have debug = 5, and connection loggin etc This is what I see when application hangs: Oct 3 08:46:03 stg-mdb01 pgpool[8313]: [197-1] 2017-10-03 08:46:03: pid 8313: LOG: new connection received Oct 3 08:46:03 stg-mdb01 pgpool[8313]: [197-2] 2017-10-03 08:46:03: pid 8313: DETAIL: connecting host=stg-web03 port=57390 Oct 3 08:46:03 stg-mdb01 pgpool[8313]: [197-3] 2017-10-03 08:46:03: pid 8313: LOCATION: child.c:2154 Oct 3 08:46:03 stg-mdb01 pgpool: 2017-10-03 08:46:03: pid 8313: LOG: new connection received Oct 3 08:46:03 stg-mdb01 pgpool: 2017-10-03 08:46:03: pid 8313: DETAIL: connecting host=stg-web03 port=57390 Oct 3 08:46:03 stg-mdb01 pgpool: 2017-10-03 08:46:03: pid 8313: LOCATION: child.c:2154 This is what I see when master_slave_mode = off Oct 3 08:47:58 stg-mdb01 pgpool[9700]: [5-1] 2017-10-03 08:47:58: pid 9700: LOG: new connection received Oct 3 08:47:58 stg-mdb01 pgpool[9700]: [5-2] 2017-10-03 08:47:58: pid 9700: DETAIL: connecting host=stg-web03 port=58828 Oct 3 08:47:58 stg-mdb01 pgpool[9700]: [5-3] 2017-10-03 08:47:58: pid 9700: LOCATION: child.c:2154 Oct 3 08:47:58 stg-mdb01 pgpool: 2017-10-03 08:47:58: pid 9700: LOG: new connection received Oct 3 08:47:58 stg-mdb01 pgpool: 2017-10-03 08:47:58: pid 9700: DETAIL: connecting host=stg-web03 port=58828 Oct 3 08:47:58 stg-mdb01 pgpool: 2017-10-03 08:47:58: pid 9700: LOCATION: child.c:2154 Oct 3 08:47:58 stg-mdb01 pgpool[9700]: [6-1] 2017-10-03 08:47:58: pid 9700: LOG: statement: DISCARD ALL Oct 3 08:47:58 stg-mdb01 pgpool[9700]: [6-2] 2017-10-03 08:47:58: pid 9700: LOCATION: pool_proto_modules.c:136 Oct 3 08:47:58 stg-mdb01 pgpool: 2017-10-03 08:47:58: pid 9700: LOG: statement: DISCARD ALL Oct 3 08:47:58 stg-mdb01 pgpool: 2017-10-03 08:47:58: pid 9700: LOCATION: pool_proto_modules.c:136 query completes successfully in this case. Can I enable something else for more verbose logging? debug_level = 5 log_error_verbosity = verbose log_connections = on log_hostname = on log_statement = on |
|
|
You want to set: log_min_messages = debug5 |
|
|
My query is this: SELECT name FROM devices WHERE id = $1;" attached associated log |
|
|
Afterwards the PID 17736 seems to hang doing nothing, I've terminated the script after one or two seconds. Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [648-1] 2017-10-03 10:01:43: pid 17736: DEBUG: pool_write: to backend: 0 kind:X Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [648-2] 2017-10-03 10:01:43: pid 17736: LOCATION: pool_stream.c:432 Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [649-1] 2017-10-03 10:01:43: pid 17736: DEBUG: pool_flush_it: flush size: 5 Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [649-2] 2017-10-03 10:01:43: pid 17736: LOCATION: pool_stream.c:609 Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [650-1] 2017-10-03 10:01:43: pid 17736: DEBUG: pool_write: to backend: 1 kind:X Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [650-2] 2017-10-03 10:01:43: pid 17736: LOCATION: pool_stream.c:432 Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [651-1] 2017-10-03 10:01:43: pid 17736: DEBUG: pool_flush_it: flush size: 5 Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [651-2] 2017-10-03 10:01:43: pid 17736: LOCATION: pool_stream.c:609 Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [652-1] 2017-10-03 10:01:43: pid 17736: DEBUG: shmem_exit(-1): 0 callbacks to make Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [652-2] 2017-10-03 10:01:43: pid 17736: LOCATION: elog.c:2563 Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [653-1] 2017-10-03 10:01:43: pid 17736: DEBUG: proc_exit(-1): 0 callbacks to make Oct 3 10:01:43 stg-mdb01 pgpool[17736]: [653-2] 2017-10-03 10:01:43: pid 17736: LOCATION: elog.c:2535 Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: DEBUG: pool_write: to backend: 0 kind:X Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: LOCATION: pool_stream.c:432 Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: DEBUG: pool_flush_it: flush size: 5 Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: LOCATION: pool_stream.c:609 Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: DEBUG: pool_write: to backend: 1 kind:X Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: LOCATION: pool_stream.c:432 Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: DEBUG: pool_flush_it: flush size: 5 Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: LOCATION: pool_stream.c:609 Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: DEBUG: shmem_exit(-1): 0 callbacks to make Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: LOCATION: elog.c:2563 Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: DEBUG: proc_exit(-1): 0 callbacks to make Oct 3 10:01:43 stg-mdb01 pgpool: 2017-10-03 10:01:43: pid 17736: LOCATION: elog.c:2535 |
|
|
adding another sample |
|
|
Thank you for the debug logs. I was busy with customer's work. From the log I see the line: Oct 3 09:59:38 stg-mdb01 pgpool: 2017-10-03 09:59:38: pid 17736: DETAIL: received kind 'E'(45) from frontend then Oct 3 09:59:38 stg-mdb01 pgpool[17736]: [633-2] 2017-10-03 09:59:38: pid 17736: DETAIL: received kind 'H'(48) from frontend The first line shows that node.js client sent an execute request of a prepared statement (more precisely a portal) to pgpool. The second line indicates that it sent a "flush" request which request to send back any response from backend at that point and the client waited for the response. However pgpool also waited for next request or some response from backend without forwarding the flush message to backend. So nothing happend in pgpool. Java applications do not send "flush" after "execute", that's why I missed the case. From 3.5.6 there have been heavy modifications to deal with other bugs. Apparently I have brought in some mistakes which make the case not work any more. Will fix. FYI I attach a test data for "pgproto". |
|
|
Ok, here's a patch trying to fix your problem by continuing to read backend response after receiving a flush message from client. |
|
|
Thank you sir. This seems to fix the issue. I have a mixed environment with Java, PHP, node.js. Will be running version 3.5.10 with patch applied and see how it goes. |
|
|
Thanks for the report. I am looking forward to hearing from you the result in the mixed environment. |
|
|
Hello. I reproduce this issue with pgpool 3.6.6 on Centos 7.4.1708, with node.js I can't reproduce with pgpool 3.6.0, 3.6.1 and 3.6.2. But I can reproduce this issue with pgool 3.6.3 |
|
|
Please try Pgpool-II 3.6.7. The fix is not in 3.6.6. |
|
|
I have updated to Pgpool-II 3.6.7. I can't reproduce this issue. Thanks |
|
|
Glad to hear that! |
|
|
Btw, I've been running the patch for 2 weeks on production and noticed no further issues. |
|
|
Yes, actually 3.6.7 includes exactly the same patch you are using with 3.5.10. Same thing can be said to 3.5.11 as well. |
|
|
May I close this issue? |
|
|
I have received an email that asks my feedback. I am not the first reporter, but in my opinion the issue is resolved and you can close the issue. Thank you t-ishii |
|
|
Thanks. Issue closed. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2017-10-03 00:06 | juliuszaromskis | New Issue | |
| 2017-10-03 00:22 | juliuszaromskis | Note Added: 0001724 | |
| 2017-10-03 00:30 | juliuszaromskis | Note Added: 0001725 | |
| 2017-10-03 00:35 | juliuszaromskis | File Added: pgpool.conf | |
| 2017-10-03 15:39 | t-ishii | Note Added: 0001726 | |
| 2017-10-03 15:46 | t-ishii | Assigned To | => t-ishii |
| 2017-10-03 15:46 | t-ishii | Status | new => feedback |
| 2017-10-03 16:00 | juliuszaromskis | Note Added: 0001728 | |
| 2017-10-03 16:00 | juliuszaromskis | Status | feedback => assigned |
| 2017-10-03 16:13 | t-ishii | Note Added: 0001729 | |
| 2017-10-03 16:23 | juliuszaromskis | Note Added: 0001730 | |
| 2017-10-03 17:52 | juliuszaromskis | Note Added: 0001731 | |
| 2017-10-03 18:04 | t-ishii | Note Added: 0001732 | |
| 2017-10-03 19:04 | juliuszaromskis | File Added: pgpool.log | |
| 2017-10-03 19:04 | juliuszaromskis | Note Added: 0001733 | |
| 2017-10-03 19:16 | juliuszaromskis | Note Added: 0001734 | |
| 2017-10-03 21:35 | juliuszaromskis | File Added: pgpool.log.2 | |
| 2017-10-03 21:35 | juliuszaromskis | Note Added: 0001735 | |
| 2017-10-05 07:52 | t-ishii | File Added: node_js.data | |
| 2017-10-05 07:52 | t-ishii | Note Added: 0001736 | |
| 2017-10-05 07:53 | t-ishii | Note Edited: 0001736 | |
| 2017-10-05 07:56 | t-ishii | Note Edited: 0001736 | |
| 2017-10-05 15:15 | t-ishii | File Added: bug345.diff | |
| 2017-10-05 15:15 | t-ishii | Note Added: 0001738 | |
| 2017-10-05 15:16 | t-ishii | Status | assigned => feedback |
| 2017-10-05 15:52 | juliuszaromskis | Note Added: 0001741 | |
| 2017-10-05 15:52 | juliuszaromskis | Status | feedback => assigned |
| 2017-10-05 16:08 | t-ishii | Note Added: 0001742 | |
| 2017-10-05 16:08 | t-ishii | Status | assigned => feedback |
| 2017-11-03 16:10 | lucasll | Note Added: 0001798 | |
| 2017-11-03 16:15 | t-ishii | Note Added: 0001799 | |
| 2017-11-03 16:43 | lucasll | Note Added: 0001800 | |
| 2017-11-03 16:54 | t-ishii | Note Added: 0001801 | |
| 2017-11-03 22:51 | juliuszaromskis | Note Added: 0001802 | |
| 2017-11-03 22:51 | juliuszaromskis | Status | feedback => assigned |
| 2017-11-04 00:07 | t-ishii | Note Added: 0001803 | |
| 2017-11-04 13:12 | t-ishii | Note Added: 0001804 | |
| 2017-11-06 15:39 | t-ishii | Status | assigned => feedback |
| 2017-11-06 15:39 | t-ishii | Fixed in Version | => 3.5.11 |
| 2017-11-07 06:05 | lucasll | Note Added: 0001805 | |
| 2017-11-07 10:21 | t-ishii | Note Added: 0001808 | |
| 2017-11-07 10:21 | t-ishii | Status | feedback => resolved |
