Connection to PGPool-II Fails to return results

[mbell8903]

So I ran into an issue that I'm not totally sure how to fix. We are using PGPool-II to do all of our communication to the DB since we have a handful of services connecting. That being said I know pg has connection pooling built in by default, but our configurations demand that all services go through PGPool-II. Anyways the issue I'm seeing is that if I connect to the postgres instance directly, everything works well, but if i attempt to connect thought PGPool-II the callback in client.query never gets called. Here is my code:

 getKeyData : function (key, cb) {
                pg.connect(config.connectionInfo.db.connectionString, function(err, client, done) {
                        if (err) {
                                done();
                                console.error('Failed to fetch client from PostgreSQL connection pool'.red, err);
                                return cb("Failed to fetch client from postgreSQL connection pool");
                        } else {
                                var sql = "SELECT key FROM y WHERE LOWER(key) = LOWER($1) LIMIT 1",
                                        params = [key];

                                if (config.connectionInfo.debug) {
                                        console.log(util.inspect({ query: sql, params: params }, { colors: true }));
                                }

                                client.query(sql, params, function (err, results) {
                                        done();
                                        if (err) {
                                                console.error('Failed to execute query "'.red + colors.green(sql) + '"'.red, err);
                                                return cb('Failed to execute query: ' + err);
                                        } else {
                                                if (results.rows.length > 0) {
                                                        return cb(null, results.rows[0].key);
                                                } else {
                                                        return cb();
                                                }
                                        }
                                });
                        }
                });
        }

Connection string: 'pg://username:pass@localhost:9999/db'

I looked at the PGPool-II logs and have the following:

2014-01-24 15:55:17 DEBUG: pid 28012: I am 28012 accept fd 5
2014-01-24 15:55:17 LOG: pid 28012: connection received: host=127.0.0.1 port=37038
2014-01-24 15:55:17 DEBUG: pid 28012: Protocol Major: 3 Minor: 0 database: ******* user: *******
2014-01-24 15:55:17 DEBUG: pid 28012: do_child: connection exists but startup packet length is not identical
2014-01-24 15:55:17 DEBUG: pid 28012: new_connection: connecting 0 backend
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length: slot: 0 length: 12
2014-01-24 15:55:17 DEBUG: pid 28012: pool_do_auth: auth kind:5
2014-01-24 15:55:17 DEBUG: pid 28012: trying md5 authentication
2014-01-24 15:55:17 DEBUG: pid 28012: DB node id: 0 salt: 91a28b4c
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length2: master slot: 0 length: 28
2014-01-24 15:55:17 DEBUG: pid 28012: 0 th backend: name: client_encoding value: 'utf-8'
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length2: master slot: 0 length: 23
2014-01-24 15:55:17 DEBUG: pid 28012: 0 th backend: name: DateStyle value: ISO, MDY
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length2: master slot: 0 length: 25
2014-01-24 15:55:17 DEBUG: pid 28012: 0 th backend: name: integer_datetimes value: on
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length2: master slot: 0 length: 27
2014-01-24 15:55:17 DEBUG: pid 28012: 0 th backend: name: IntervalStyle value: postgres
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length2: master slot: 0 length: 21
2014-01-24 15:55:17 DEBUG: pid 28012: 0 th backend: name: is_superuser value: off
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length2: master slot: 0 length: 25
2014-01-24 15:55:17 DEBUG: pid 28012: 0 th backend: name: server_encoding value: UTF8
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length2: master slot: 0 length: 26
2014-01-24 15:55:17 DEBUG: pid 28012: 0 th backend: name: server_version value: 8.4.13
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length2: master slot: 0 length: 33
2014-01-24 15:55:17 DEBUG: pid 28012: 0 th backend: name: session_authorization value: *******
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length2: master slot: 0 length: 36
2014-01-24 15:55:17 DEBUG: pid 28012: 0 th backend: name: standard_conforming_strings value: off
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length2: master slot: 0 length: 17
2014-01-24 15:55:17 DEBUG: pid 28012: 0 th backend: name: TimeZone value: UTC
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length: slot: 0 length: 12
2014-01-24 15:55:17 DEBUG: pid 28012: pool_do_auth: cp->info[i]:0x2ad60b540000 pid:17747
2014-01-24 15:55:17 DEBUG: pid 28012: pool_send_auth_ok: send pid 17747 to frontend
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_query_in_progress: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_command_success: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_writing_transaction: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_failed_transaction: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_transaction_isolation: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_skip_reading_from_backends: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_ignore_till_sync: done
2014-01-24 15:55:17 DEBUG: pid 28012: read_kind_from_backend: read kind from 0 th backend Z NUM_BACKENDS: 1
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessBackendResponse: kind from backend: Z
2014-01-24 15:55:17 DEBUG: pid 28012: pool_read_message_length: slot: 0 length: 5
2014-01-24 15:55:17 DEBUG: pid 28012: ReadyForQuery: transaction state:
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessFrontendResponse: kind from frontend P(50)
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_doing_extended_query_message: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_doing_extended_query_message: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_query_in_progress: done
2014-01-24 15:55:17 DEBUG: pid 28012: Parse: statement name <>
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_query_in_progress: done
2014-01-24 15:55:17 LOG: pid 28012: DB node id: 0 backend pid: 17747 statement: Parse: SELECT key FROM y WHERE LOWER(key) = LOWER($1) LIMIT 1
2014-01-24 15:55:17 DEBUG: pid 28012: wait_for_query_response: waiting for backend 0 completing the query
2014-01-24 15:55:17 DEBUG: pid 28012: read_kind_from_backend: read kind from 0 th backend 1 NUM_BACKENDS: 1
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessBackendResponse: kind from backend: 1
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_command_success: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_query_in_progress: done
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessFrontendResponse: kind from frontend B(42)
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_doing_extended_query_message: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_doing_extended_query_message: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_query_in_progress: done
2014-01-24 15:55:17 DEBUG: pid 28012: Bind: waiting for master completing the query
2014-01-24 15:55:17 LOG: pid 28012: DB node id: 0 backend pid: 17747 statement: B message
2014-01-24 15:55:17 DEBUG: pid 28012: wait_for_query_response: waiting for backend 0 completing the query
2014-01-24 15:55:17 DEBUG: pid 28012: read_kind_from_backend: read kind from 0 th backend 2 NUM_BACKENDS: 1
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessBackendResponse: kind from backend: 2
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_command_success: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_query_in_progress: done
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessFrontendResponse: kind from frontend D(44)
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_doing_extended_query_message: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_doing_extended_query_message: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_query_in_progress: done
2014-01-24 15:55:17 DEBUG: pid 28012: Describe: waiting for master completing the query
2014-01-24 15:55:17 LOG: pid 28012: DB node id: 0 backend pid: 17747 statement: D message
2014-01-24 15:55:17 DEBUG: pid 28012: wait_for_query_response: waiting for backend 0 completing the query
2014-01-24 15:55:17 DEBUG: pid 28012: read_kind_from_backend: read kind from 0 th backend T NUM_BACKENDS: 1
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessBackendResponse: kind from backend: T
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_query_in_progress: done
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessFrontendResponse: kind from frontend E(45)
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_doing_extended_query_message: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_doing_extended_query_message: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_query_in_progress: done
2014-01-24 15:55:17 DEBUG: pid 28012: Execute: portal name <>
2014-01-24 15:55:17 DEBUG: pid 28012: Execute: query: SELECT key FROM y WHERE LOWER(key) = LOWER($1) LIMIT 1
2014-01-24 15:55:17 LOG: pid 28012: DB node id: 0 backend pid: 17747 statement: Execute: SELECT key FROM y WHERE LOWER(key) = LOWER($1) LIMIT 1
2014-01-24 15:55:17 DEBUG: pid 28012: wait_for_query_response: waiting for backend 0 completing the query
2014-01-24 15:55:17 DEBUG: pid 28012: read_kind_from_backend: read kind from 0 th backend D NUM_BACKENDS: 1
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessBackendResponse: kind from backend: D
2014-01-24 15:55:17 DEBUG: pid 28012: read_kind_from_backend: read kind from 0 th backend C NUM_BACKENDS: 1
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessBackendResponse: kind from backend: C
2014-01-24 15:55:17 DEBUG: pid 28012: pool_set_command_success: done
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_query_in_progress: done
2014-01-24 15:55:17 DEBUG: pid 28012: ProcessFrontendResponse: kind from frontend H(48)
2014-01-24 15:55:17 DEBUG: pid 28012: pool_unset_doing_extended_query_message: done'

As you can see its executing the query and processing the response from the backend. Also all of the other python based services i have running around seem to use PGPool-II just fine.

Any ideas as to why this would be happening?

[brianc]

Very strange! I unfortunately don't have any experience with using PGPool-II - I am guessing someone else does & hopefully they'll weigh in on this issue soon. The exact same code works without PGPool-II? I might need to do some binary sniffing on that one.

Are you using native or pure javascript bindings? If JavaScript bindings, One thing that might help is if you add this to your code & run a single query:

pg.connect(function(err, client, done) {
   //dump out the parsed binary messages
   client.connection.on('message', console.log.bind(console))
   client.query('SELECT NOW()', function() {
       console.log('done')
    })
})

Then maybe paste me what that says?

[mbell8903]

OK... I have some more info on this issue. I tried your code and it worked perfectly fine, so i did more finagling and tried my code with the 'SELECT NOW() AS now' and that seemed to come back OK, then i tried removing the parameters and voila! It worked! So it has to do with the parameters. If i change the code:

var sql = "SELECT key FROM y WHERE LOWER(key) = LOWER($1) LIMIT 1",
params = [key];

To the following:

var sql = "SELECT key FROM y WHERE LOWER(key) = LOWER('" + key + "') LIMIT 1",
params = [];

It works perfectly fine. Unfortunately this doesn't help with SQL injection, and I'm not sure why parameters dont work. So the next thing i did was use your chunk of code with my query and parameters. A message came back but the callback was never fired and 'done' was never printed out. Here is the output and code:

{ name: 'parseComplete', length: 4 }
{ name: 'bindComplete', length: 4 }
{ name: 'rowDescription',
length: 32,
fieldCount: 1,
fields:
[ { name: 'key',
tableID: 92954,
columnID: 1,
dataTypeID: 1043,
dataTypeSize: -1,
dataTypeModifier: 36,
format: 'text' } ] }
{ name: 'dataRow',
length: 1,
fieldCount: undefined,
fields: [ 'abcdefghijklmnopqrstuvwxyz1234567890' ] }
{ name: 'commandComplete', length: 11, text: 'SELECT' }

Here is the modified code:

pg.connect(config.connectionInfo.db.connectionString, function(err, client, done) {
//dump out the parsed binary messages
client.connection.on('message', console.log.bind(console))
client.query('SELECT key FROM y WHERE LOWER(key) = LOWER($1) LIMIT 1', ['abcdefghijklmnopqrstuvwxyz1234567890'], function() {
console.log('done')
})
})

So this confirms that the callback never gets fired if you send parameters in a query to pgpool-II.

Any ideas?

[brianc]

Those messages look correct; however, the last message is missing. After sending a commandComplete the backend waits for a sync message from the front-end and then should receive a readyForQuery message signaling the query is processed completely & the backend can accept another one on this connection. I'm pretty dang sure node-postgres is sending the sync message to the back-end or all queries everywhere would never work. The question is does this message get lost in PGPool-II? That seems like the most likely result. Do any of the devs on that project know how to debug it a bit more?

[mbell8903]

I'll try and get the devs over there involved. It may take some time as i cant seem to get a login for their bug tracker, but where there is a will there is a way. =)

[yaronn]

@mbell8903 were you able to solve this? also - what version of pgpool do you use? I think that the issue might be related to specific pgpool versions (maybe regression).

[yaronn]

@brianc - I see that JDBC has similar issues and people were able to work around it by placing protocolVersion=2 in the JDBC URL which tells the Postgres JDBC driver not to use server side prepared statements. Is there a way to do this in pg?

[brianc]

@yaronn hi! Yeah, actually you can disable server side prepared statements "automatically" by sending queries without any parameters...

client.query('SELECT NOW()') //<--- does not use server side prepared statements
client.query('SELECT $1::date', [new Date()]) //<--- does use server side prepared statements
client.query('SELECT ' + JSON.stringify(new Date()) + '::date') //<--- does not use server sized prepared statements

Do the escaping yourself in your code (be careful for sql injection) by using some of the techniques we discussed in this issue

[yaronn]

Thanks @brianc. Queries with no Params do work. However this is a big
application with some security concerns and it will be hard to have
concatenated sql as the main solution. Any information I can ask the
pgpool team that will help you understand what is going here? Though they
are not very responsive so if there is something we can try ourselves it is
best. Our operations team and dba insist on pgpool as best solution for
postgress high availability based on their jdbc experience.

Appreciate your help on this do far!
On Mar 25, 2014 7:44 PM, "Brian C" notifications@github.com wrote:

@yaronn https://github.com/yaronn hi! Yeah, actually you can disable
server side prepared statements "automatically" by sending queries without
any parameters...

client.query('SELECT NOW()') //<--- does not use server side prepared statementsclient.query('SELECT $1::date', [new Date()]) //<--- does use server side prepared statementsclient.query('SELECT ' + JSON.stringify(new Date()) + '::date') //<--- does not use server sized prepared statements

Do the escaping yourself in your code (be careful for sql injection) by
using some of the techniques we discussed in this issuehttps://github.com//issues/539

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/513#issuecomment-38596914
.

[yaronn]

Good news - downgrading pg-pool from 3.3.2. to 3.3.1 seem to work well with parameterized queries. Doing more testing now.

[IronBridge]

Hi Yaron...Any luck with with your testing? I'm experiencing similar issues.

[yaronn]

Hi @IronBridge . We were able to get everything sort of working but still struggle to get it to production quality. downgrading to 3.3.1 solved the issue mentioned in this thread so we were able to use parameterized queries (I think 3.3.3 can also work). Then we saw that in some cases pgpool connections are full and no new connections can be made even though we used very few connections. It turned out that in node-pg you should create connections with "new Client()" rather than "pg.connect" since the latter uses internal pooling for node. I guess that the latter sometimes sends session cleanup or alike messages to clean between users, anyway our dba told us that it sends something that cause pgpool to invalidate connections. We did not have time to fully investigate it but using "new Client()" worked fine (and actually makes more since since no need for internal pooling). Right now things are sort of working but here and there a connection gets invalid for some reason, or pgpool does not identify a closed connection. Not sure if this is a pgpool maturity issue, or maybe pg and pgpool have some protocol differences.

[IronBridge]

Thanks for the response yaronn. We rolled our own connection pooling early because we have multi-databases with one api and we have also tested with built in pooling and have experienced the same issues. with invalid connections, running out of connections, etc. I'm glad you mentioned the new Client() option because that was what we were going going to test next because we were going to lean on pgpool to manage the connection pool. I'll report back on our testing with using pgpool with the new Client() method. Thanks again for the response.

[aLooseGoose]

When using pgpool 3.4.3, parameterized queries don't seem to be a problem.