"timeout exceeded when trying to connect" spike after upgrading to 8.2.1

[mriedem]

Yesterday we upgraded from pg@8.0.3 (with pg-pool@3.1.1) to pg@8.2.1 (with pg-pool@3.2.1), specifically from our package-lock.json:

    "pg": {
      "version": "8.2.1",
      "resolved": "https://registry.npmjs.org/pg/-/pg-8.2.1.tgz",
      "integrity": "sha512-DKzffhpkWRr9jx7vKxA+ur79KG+SKw+PdjMb1IRhMiKI9zqYUGczwFprqy+5Veh/DCcFs1Y6V8lRLN5I1DlleQ==",
      "requires": {
        "buffer-writer": "2.0.0",
        "packet-reader": "1.0.0",
        "pg-connection-string": "^2.2.3",
        "pg-pool": "^3.2.1",
        "pg-protocol": "^1.2.4",
        "pg-types": "^2.1.0",
        "pgpass": "1.x",
        "semver": "4.3.2"
      },
      "dependencies": {
        "pg-connection-string": {
          "version": "2.2.3",
          "resolved": "https://registry.npmjs.org/pg-connection-string/-/pg-connection-string-2.2.3.tgz",
          "integrity": "sha512-I/KCSQGmOrZx6sMHXkOs2MjddrYcqpza3Dtsy0AjIgBr/bZiPJRK9WhABXN1Uy1UDazRbi9gZEzO2sAhL5EqiQ=="
        },
        "semver": {
          "version": "4.3.2",
          "resolved": "https://registry.npmjs.org/semver/-/semver-4.3.2.tgz",
          "integrity": "sha1-x6BxWKgL7dBSNVt3DYLWZA+AO+c="
        }
      }
    }

We started seeing a spike in timeout exceeded when trying to connect errors with this stacktrace:

Error: timeout exceeded when trying to connect
    at Timeout._onTimeout (/usr/src/app/node_modules/pg-pool/index.js:188:27)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7)

This is a pretty basic express app with a postgres 12 backend running on node 12.

We report metrics on the connection pool max/total/idle/waiting count values and there is an obvious spike in the wait count from the time the 8.2.1 upgrade was deployed (around 9am CT yesterday) and then the drop when we reverted that change (about 6am CT today):

That corresponds with our API request/response/error rates (again, just a simple express app over a pg db):

We're not sure how to debug this. These are the relevant values we're using related to the Pool config:

• connectionTimeoutMillis = 60000
• idleTimeoutMillis = 60000
• max = 150

We have a staging environment where this showed up as well but we didn't have an alert setup for it (we do now). So if there is something we can do to help debug this and provide information back we can probably do that in our staging environment.

[jsatsvat]

We're having the same issue - causing us some headache. Just looking at 8.2.2 to see if that fixed it.

[mriedem]

Looking at the changes in 8.2.2 I'm not sure those are going to resolve my issue since I'm not using bytea type columns:

https://github.com/brianc/node-postgres/compare/pg@8.2.1...pg@8.2.2

[charmander]

@mriedem The fix applies to any long message.

[brianc]

hmm sorry this is happening - I'm assuming this isn't happening all the time or in a reproducible way, just sometimes at random? Those issues are hard to debug. I'm gonna check my app logs & see if I can see any of this - I usually run the latest on our systems and they're under pretty heavy load all day.

[mriedem]

I'm assuming this isn't happening all the time or in a reproducible way, just sometimes at random?

It's definitely reproducible / persistent to the point that we had to revert the package upgrade in our app because of the regression. I mean, if we had some debug patch or something applied in our staging environment I'm sure we'd hit it to get more data if you have something in mind. I can't say there is a specific query that fails 100% of the time though.

I'm not sure if it helps, but there were quite a few of the errors happening on queries to fetch data from tables with json columns, so I'm not sure if that would be impacted by #2240? But we had other failures on queries that didn't involve json columns, e.g. a simple count query: SELECT COUNT(job_id) FROM jobs WHERE queue_name = $1 AND execution_time IS NULL;, though those might have been on the same pod (db connection pool) so if the problem causes an issue for all connections in the same pool then that might explain the issue in other basic queries.

[mriedem]

@jsatsvat did moving to 8.2.2 resolve the issue for you?

[jsatsvat]

did moving to 8.2.2 resolve the issue for you?

No, it didn't unfortunately.

there were quite a few of the errors happening on queries to fetch data from tables with json columns, so I'm not sure if that would be impacted by #2240

FYI - We don't have any JSON columns as far as I am aware.

[brianc]

It's definitely reproducible / persistent to the point that we had to revert the package upgrade in our app because of the regression.

yeah I mean is there a way this can be reproduced in an isolated script so I could run it locally and analyze what's going on?

[brianc]

Are y'all using an ORM (knex, typeorm, etc) or using pg directly?

[mriedem]

Are y'all using an ORM (knex, typeorm, etc) or using pg directly?

We're not using an ORM, just pg directly.

[brianc]

okay - and I'm guessing it happens some what "at random" meaning your app has been running for a while & then you get a timeout? Once you get a timeout do you get a bunch or is it just one every once and a while?

[jsatsvat]

We're using slonik.

And yes, at least for us, it happens randomly out of a sudden with a bunch of timeouts at once.

[brianc]

dang - do you have numbers around how long it takes before it happens? What's the recovery you do? restart the app?

[jsatsvat]

For now we've drastically increased the pool size (previously set to 100) which temporarily takes some pressure off it; but as a quick recovery measure we do indeed restart the affected service.

As it seems to happen randomly, I am not sure as to how helpful numbers will be as we can't really determine a certain interval or similar.

[mriedem]

okay - and I'm guessing it happens some what "at random" meaning your app has been running for a while & then you get a timeout? Once you get a timeout do you get a bunch or is it just one every once and a while?

I would have to dig into this. In our production cluster we have the app running in 20 replicas and each has a pool configured for 150 connections. Our readiness probe is set to hit an API which does a select now(); query to make sure that pod's connection pool is OK because if it's full then we want that pod to go out of rotation for traffic until it can drain its connection requests. The pod will only crash and restart automatically if an uncaught error slips through.

I think I can say when it hits we get a bunch of timeouts which would probably explain why the waiting count per pod (in the graph in the issue description) spikes, because presumably something is blocking in the pool and so other requests are waiting until a timeout occurs.