View Issue Details

IDProjectCategoryView StatusLast Update
0000345pgpool-IIIncompatible changepublic2017-11-07 10:21
ReporterjuliuszaromskisAssigned Tot-ishii 
PriorityhighSeveritymajorReproducibilityalways
Status resolvedResolutionopen 
Product Version3.5.9 
Target VersionFixed in Version3.5.11 
Summary0000345: pgpool node.js prepared statement
DescriptionThis 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 Reproducenpm 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;
    });
  });
});
```
TagsNo tags attached.

Activities

juliuszaromskis

2017-10-03 00:22

reporter   ~0001724

I was wrong, now testing 3.5.8 also has this issue. Just try the latest 3.5.10 to reproduce.

juliuszaromskis

2017-10-03 00:30

reporter   ~0001725

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.

juliuszaromskis

2017-10-03 00:35

reporter  

pgpool.conf (27,543 bytes)

t-ishii

2017-10-03 15:39

developer   ~0001726

So you have problem even with 3.5.10? If so, please post the pgpool debug log.

juliuszaromskis

2017-10-03 16:00

reporter   ~0001728

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.

t-ishii

2017-10-03 16:13

developer   ~0001729

That's unfortunate. I don't have time to set up node.js environment and run your program to reproduce the problem.

juliuszaromskis

2017-10-03 16:23

reporter   ~0001730

Right. I'm setting up local test environment to see what's causing this issue.

juliuszaromskis

2017-10-03 17:52

reporter   ~0001731

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

t-ishii

2017-10-03 18:04

developer   ~0001732

You want to set:
log_min_messages = debug5

juliuszaromskis

2017-10-03 19:04

reporter   ~0001733

My query is this: SELECT name FROM devices WHERE id = $1;"

attached associated log

pgpool.log (259,757 bytes)

juliuszaromskis

2017-10-03 19:16

reporter   ~0001734

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

juliuszaromskis

2017-10-03 21:35

reporter   ~0001735

adding another sample

pgpool.log.2 (92,468 bytes)

t-ishii

2017-10-05 07:52

developer   ~0001736

Last edited: 2017-10-05 07:56

View 3 revisions

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".



node_js.data (138 bytes)

t-ishii

2017-10-05 15:15

developer   ~0001738

Ok, here's a patch trying to fix your problem by continuing to read backend response after receiving a flush message from client.

bug345.diff (648 bytes)
diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index 97ed6c9..4de769d 100644
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -2457,7 +2457,11 @@ POOL_STATUS ProcessFrontendResponse(POOL_CONNECTION *frontend,
 				}
 				status = SimpleForwardToBackend(fkind, frontend, backend, len, contents);
 
-				if (pool_is_doing_extended_query_message())
+				/*
+				 * After flush message received, extended query mode should be
+				 * continued.
+				 */
+				if (fkind != 'H' && pool_is_doing_extended_query_message())
 				{
 					pool_unset_doing_extended_query_message();
 				}
bug345.diff (648 bytes)

juliuszaromskis

2017-10-05 15:52

reporter   ~0001741

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.

t-ishii

2017-10-05 16:08

developer   ~0001742

Thanks for the report. I am looking forward to hearing from you the result in the mixed environment.

lucasll

2017-11-03 16:10

reporter   ~0001798

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

t-ishii

2017-11-03 16:15

developer   ~0001799

Please try Pgpool-II 3.6.7. The fix is not in 3.6.6.

lucasll

2017-11-03 16:43

reporter   ~0001800

I have updated to Pgpool-II 3.6.7. I can't reproduce this issue.
Thanks

t-ishii

2017-11-03 16:54

developer   ~0001801

Glad to hear that!

juliuszaromskis

2017-11-03 22:51

reporter   ~0001802

Btw, I've been running the patch for 2 weeks on production and noticed no further issues.

t-ishii

2017-11-04 00:07

developer   ~0001803

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.

t-ishii

2017-11-04 13:12

developer   ~0001804

May I close this issue?

lucasll

2017-11-07 06:05

reporter   ~0001805

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

t-ishii

2017-11-07 10:21

developer   ~0001808

Thanks. Issue closed.

Issue History

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 View Revisions
2017-10-05 07:56 t-ishii Note Edited: 0001736 View Revisions
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