7.18.2: "Connection terminated unexpectedly" when using client.query with a pool when pool has been idle for 10 minutes (running in AWS Lambda)

[jcollum]

Code is running in a lambda. When we run the function below it runs fine. But if we run it and then wait 10 minutes then run it again, we get an error every time. We are querying Aurora Postgres on AWS.

Code:

const {Pool} = require('pg');

// Global Connection, can be re-used!!
const pgPool = new Pool({
    user: process.env.PG_USER,
    host: process.env.PG_HOST,
    database: process.env.PG_DATABASE,
    password: process.env.PG_PASSWORD,
    port: process.env.PG_PORT,
    max: process.env.MAX_CLIENTS
});

pgPool.on('error', (err, client) => {
    console.error('Unexpected error in Postgress connection pool', err);
});

async function performQuery(event) {

    let queryString = null;
    let args = null;

    try {
        // some setup code here...  
        const client = await pgPool.connect();
        try {
            const res = await client.query(queryString, args);
            return res.rows;
        } finally {
            client.release();
        }
    } catch (err) {
        console.error('Problem executing export query:');
        console.error(err); // <-- this line is in the log below  
        throw err;
    }
}

This is what I see in the cloudwatch logs:

{
    "errorType": "Error",
    "errorMessage": "Connection terminated unexpectedly",
    "stack": [
    "Error: Connection terminated unexpectedly",
    "    at Connection.<anonymous> (/var/task/node_modules/pg/lib/client.js:255:9)",
    "    at Object.onceWrapper (events.js:312:28)",
    "    at Connection.emit (events.js:223:5)",
    "    at Connection.EventEmitter.emit (domain.js:475:20)",
    "    at Socket.<anonymous> (/var/task/node_modules/pg/lib/connection.js:78:10)",
    "    at Socket.emit (events.js:223:5)",
    "    at Socket.EventEmitter.emit (domain.js:475:20)",
    "    at TCP.<anonymous> (net.js:664:12)"
]
}

I've tried a few variations on this but the constant is the 10 minutes and the use of the Pool. To me this code is almost identical to the code in https://node-postgres.com/features/pooling.

So far it looks like the problem has been solved by using a Client instead:

const client = new Client({
            user: process.env.PG_USER,
            host: process.env.PG_HOST,
            database: process.env.PG_DATABASE,
            password: process.env.PG_PASSWORD,
            port: process.env.PG_PORT
        });

        await client.connect();
        const res = await client.query(queryString, args);
        await client.end();
        return res.rows;

[jamesdixon]

@jcollum this is also happening for us and a number of others (see this thread knex/knex#3636).

We're seeing this in Node 10 / 12 in the Lambda environment. Only solution at the moment was to run a custom Node 8 runtime for our Lambda functions.

[briandamaged]

@jamesdixon : Ah -- I was just about to point you to this thread! lol

[592da]

dealing with the same issue on production,
working with serverless, over AWS lambdas, node v12 (over typeorm).

@briandamaged @jamesdixon any solution?
did not manage to set the runtime to node8...

please help

[brianc]

It looks like it's related to the lambda environment or something and not pg. According to this it's hitting both pg & mysql....which makes it somewhat unlikely to be caused by this library. I'm not sure there's much I can do w/o having steps to reproduce, unfortunately. Looking at @jcollum's example it looks like it's somehow related to the lambda going idle and killing the open connections to the db. Weirdly if you only run the lambda once every 10 minutes that should be well outside the idle timeout and the pool should have closed all it's connections. Anyways I can make lots of assumptions about what's happening but w/o steps to reproduce I'm not gonna be able to provide much concrete support. I'll follow along if more info comes up I'll look into it. Also: PRs are always welcome for issues like this if you figure out what it is! 😉

[jamesdixon]

Thanks for the input, @brianc!

According to this it's hitting both pg & mysql....which makes it somewhat unlikely to be caused by this library

That was the original thought but later on in the thread you referenced, one of the Knex maintainers pointed out that the MySQL error was actually different and may not be related.

The one thing we do know is that the issue isn't present in Node 8 but rears its ugly head in Node 10/12. Are you aware of any major changes in those versions related to this library that might be exacerbated in a Lambda environment?

[briandamaged]

@jamesdixon : Howdy! Just to clarify: what I meant was that Knex did not appear to be directly related to the pg-specific control path. However, I suspect that the same lower-level issue is affecting both "pg" and "mysql".

My guess is that either the server or the network is aggressively closing the connections. This is then causing the client-side libraries to "get confused" when they discover that the connection is already closed. (At least, that appears to be the case for "pg". The Client class checks the this._ending flag to see whether or not it was expecting the connection to be closed)

[jamesdixon]

Got it! Thanks for the clarification!

…

On Tue, Feb 25, 2020 at 11:02 AM Brian Lauber ***@***.***> wrote: @jamesdixon <https://github.com/jamesdixon> : Howdy! Just to clarify: what I meant was that Knex did not appear to be directly related to the pg-specific control path. However, I suspect that the same lower-level issue is affecting both "pg" and "mysql". My guess is that either the server or the network is aggressively closing the connections. This is then causing the client-side libraries to "get confused" when they discover that the connection is already closed. (At least, that appears to be the case for "pg". The Client class checks the this._ending flag to see whether or not it was expecting the connection to be closed) — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#2112?email_source=notifications&email_token=AAA24IXYNC5ZRZGUCSJDUOTREVMJ5A5CNFSM4K2TYUC2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEM44G7I#issuecomment-590988157>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAA24ITEVY7NCGYWPMDCCKDREVMJ5ANCNFSM4K2TYUCQ> .

[jcollum]

I fixed it by not using a pool:

try {

// trimmed code here 

        const client = new Client({
            user: process.env.PG_USER,
            host: process.env.PG_HOST,
            database: process.env.PG_DATABASE,
            password: process.env.PG_PASSWORD,
            port: process.env.PG_PORT
        });

        await client.connect();
        const res = await client.query(queryString, args);
        await client.end();
        return res.rows;

    } catch (err) {
        console.error('Problem executing export query:');
        console.error(err);
        throw err;
    }

Minor performance hit there.

[briandamaged]

@jcollum : My guess is that the issue isn't actually "fixed", but rather "avoided". As in: whenever your code needs to perform a query, it is:

1. Establishing a new connection (via the freshly-created Client instance)
2. Performing the query
3. Ending the connection cleanly. (by invoking client.end() )

BTW: it looks like there is a connection leak in that snippet. It should probably do this:

try {
// trimmed code here 

        const client = new Client({
            user: process.env.PG_USER,
            host: process.env.PG_HOST,
            database: process.env.PG_DATABASE,
            password: process.env.PG_PASSWORD,
            port: process.env.PG_PORT
        });

        await client.connect();
        try {
          const res = await client.query(queryString, args);
          return res.rows;
        } finally {
          await client.end();
        }

    } catch (err) {
        console.error('Problem executing export query:');
        console.error(err);
        throw err;
    }

This will ensure that the connection will be closed even if an error occurs.

[brianc]

Yah opening a new client every time is something you can do, but the latency overhead of opening a client is aprox 20x the overhead of sending a query....so ideally you'd use a pool. You don't have to, particularly if your lambda is going cold then pooling really likely isn't buying you much. There might be a way to simulate this in test by creating a pool, reaching into the internals, and severing the streams manually behind the scenes. Anyone care to make a first pass crack at that in a gist or something? If it reproduces the issue I can spin it into a test, make it pass, and ship a fix!

[jcollum]

@jcollum : My guess is that the issue isn't actually "fixed", but rather "avoided". As in: whenever your code needs to perform a query, it is:

Well yes it's not a fix it's a workaround. Thanks for catching that potential leak.

[briandamaged]

@brianc : Thinking about this a bit more... I suspect that both "pg" and "knex" are encountering the same conceptual issue in their Pool implementations. Specifically: they are not re-checking the validity of the Client instances before yielding them from the pool. Here's what I'm seeing on the "knex" side, at least:

https://github.com/knex/knex/blob/8c07192ade0dde137f52b891d97944733f50713a/lib/client.js#L333-L335

Instead, this function should probably delegate to a pg-specific function that confirms that the Client instance is still valid.

I'll check the "pg" codebase in a few mins to see if I can spot a similar behavior there.

[briandamaged]

@brianc : So, it looks like the "pg" pool has some logic for removing idle clients; however, I suspect that it does not get invoked unless the underlying Client instance actually emits an "error". For ex:

node-postgres/packages/pg-pool/index.js

Line 216 in 1c8b6b9

client.on('error', idleListener)

However, it looks like the Client doesn't necessarily emit the "error" event when it detects that the connection has been closed:

node-postgres/packages/pg/lib/client.js

Lines 252 to 279 in 1c8b6b9

	con.once('end', () => {
	const error = this._ending
	? new Error('Connection terminated')
	: new Error('Connection terminated unexpectedly')
	clearTimeout(connectionTimeoutHandle)
	this._errorAllQueries(error)
	if (!this._ending) {
	// if the connection is ended without us calling .end()
	// on this client then we have an unexpected disconnection
	// treat this as an error unless we've already emitted an error
	// during connection.
	if (this._connecting && !this._connectionError) {
	if (callback) {
	callback(error)
	} else {
	connectedErrorHandler(error)
	}
	} else if (!this._connectionError) {
	connectedErrorHandler(error)
	}
	}
	process.nextTick(() => {
	this.emit('end')
	})
	})

So, if this analysis is correct, then it means there is a way for the Pool to contain Client instances that have already been disconnected. (Or rather: their underlying connection instance has already been ended)