readiness failed: context deadline exceeded: how to investigate what the root cause is

[mweibel]

Question

We upgraded recently to v2.0.0 of cloud-sql-proxy and with that also enabled http health checks. We have cloudsql-proxy deployed as a sidecar to roughly 15 applications in a GKE cluster running v1.23.14-gke.1800.

The sidecar is configured the same way:

  - name: cloudsql-proxy
    image: gcr.io/cloud-sql-connectors/cloud-sql-proxy:2.0.0
    command:
      - /cloud-sql-proxy
    args:
      - <instance>
      - --auto-iam-authn
      - --credentials-file=/secrets/cloudsql/credentials
      - --http-port=9080
      - --http-address=0.0.0.0
      - --health-check
      - --structured-logs
      - --max-connections=25
      - --max-sigterm-delay=30s
    startupProbe:
      httpGet:
        path: /startup
        port: 9080
      periodSeconds: 30
      timeoutSeconds: 5
    readinessProbe:
      httpGet:
        path: /readiness
        port: 9080
      periodSeconds: 30
      timeoutSeconds: 5
    livenessProbe:
      httpGet:
        path: /liveness
        port: 9080
      periodSeconds: 30
      timeoutSeconds: 5
    volumeMounts:
      - name: database-credentials
        mountPath: /secrets/cloudsql
        readOnly: true

Two types of applications:

• Go apps using upper/db which uses lib/pq and database/sql under the hood.
• Node apps using Next-Auth and Prisma

The apps all connect to the same Cloud SQL instance (PostgreSQL 13.7, vCPUs: 2, Memory: 7.5 GB, configured with 400 connection limit but peak connections 114 in the last 24h). System insights don't show high CPU or memory usage but all rather low. Ingress/Egress is a bit high (~2-3Mbit/s) - this we're working on anyway.

All apps have connection pool limits defined and we have an additional, slightly higher limit on the cloudsql-proxy itself.

In the last 24h we had 2'892 readiness failed errors ([Health Check] Readiness failed: refresh failed: context deadline exceeded) and 43 connection reset by peer (connection aborted - error reading from client: read tcp 127.0.0.1:5432->127.0.0.1:57628: read: connection reset by peer).

There is no real regularity in the log intervals which would point to certain scheduled queries to run, plus we reduced some of those to the minimum (~3 analytics queries running every hour now).

What we're trying right now:

• Remove max-connections flag from cloudsql-proxy to see if that makes any difference (also we know the pool limits of the apps work so it's not that)
• Switch over to private IP instead of public IP - though I'm not sure if that has any effect TBH

Questions:

• Is there anything else we can do to investigate what is happening?
• Should we set resource requests/limits on cloudsql-proxy sidecar? Our CloudSQL sidecars don't have resource requests/limits defined, but all our apps have I took some configuration info from the cloud-sql-proxy operator and I think there the resource requests/limits are not configured too
• Should we switch to a central CloudSQL proxy instance with PGBouncer in front instead?

Thanks!

[hessjcg]

Hi Y'all. I'd like to help you investigate the issue. Here's what I think is happening:

1. There are transient errors in the health check. (We're not sure why.)
2. The k8s probe logic will determin that the pod is "not ready" after 1 error.
3. The k8s probe restarts the pod frequently.
4. More proxy restarts means more chance for other failures related to dropped connections, rate limits, etc.

We have two questions to pursue:

1. Can we reduce the impact of a transient error?
2. Why are there transient errors in the first place?

I already have a recommendation for #1: Set failureThreshold on the the livenessProbe, readnessProbe, and startupProbe 3. This means that the pod is "not ready" after the probe fails 3 times in a row. So a single transient error does not cause a pod to restart. See k8s docs: configure probes for more on how to configure probes. If this helps, I may update the example code to include failureThreshold.

For #2, I'd like more information from you. Did this bad behavior occur as soon as you upgraded to proxy 2.0.0, or did it start happening later? That would help narrow down if it is a just a code problem in v2.0.0, or if a change in the environment also contributed.

[mweibel]

hi @hessjcg

Thanks for the replies!

for # 1: As far as I'm aware failureThreshold is already at 3 by default. I'm not 100% sure on this since I haven't found the documentation for it but I think this should be the relevant code. It currently doesn't immediately kill the pod, but for some pods it does fail a couple of times so it becomes unresponsive since pod gets killed.

for # 2: Good question. Unfortunately we didn't use probes on the cloudsql-proxy before upgrading. What I can try to narrow down the issue: downgrade to the previous version, adjust the flags accordingly but enable probes. We did have some DB issues in general (too long queries, too many connections to it, resource exhaustion) and that's why I also, in working on the issue, upgraded cloudsql-proxy to make sure we don't stumble upon an issue in that regard somehow.

[enocom]

Related to GoogleCloudPlatform/cloud-sql-go-connector#384.

If you look through all the context's involved in the health check path, there's only one with a timeout inside the Go connector that has a 30 second limit. I've either missed another context here, or what's happening is that the pod CPU load is high and the Proxy can't complete a connection check in time.

One thing to get a better view into what's happening here would be to enable tracing with Cloud Trace.

See https://github.com/GoogleCloudPlatform/cloud-sql-proxy/blob/main/cmd/root.go#L388. Note, you'll probably want to set the frequency of traces to be at a high interval (1 / 100 or even 1 / 10) while looking at this.

[enocom]

So the CLI invocation would add these flags:

--telemetry-project=SOME_PROJECT and --telemetry-sample-rate=10. Note you'll want to turn the rate back down (maybe 1/1000 or even higher) after capturing some representative traces to avoid the costs of frequent traces.

[mweibel]

I downgraded one app to use version 1.33.2 with probes and since deploying that yesterday, this app never had issues. Might be some bug in v2 then. I'll downgrade all of them on Monday to make sure.
Would enabling tracing help in tracking the bug? I'll try that on Monday too, just on one app.

[mweibel]

Looking at the healthcheck code, I wonder if you shouldn't use req.Context() instead of context.Background() here:
https://github.com/GoogleCloudPlatform/cloud-sql-proxy/blob/main/internal/healthcheck/healthcheck.go#L72

Not sure if that helps with the specific error, but just what I saw just glancing over the code.

[enocom]

That's certainly one improvement. I'll be auditing the context's again as part of getting to the bottom of this.

[enocom]

FYI: We have a fix for this working its way through review in the Go Connector: GoogleCloudPlatform/cloud-sql-go-connector#384.