Connection test occasionally causes TLS handshake failed errors

[mvhatch]

Bug Description

gcr.io/cloud-sql-connectors/cloud-sql-proxy:2.8.0 and gcr.io/cloud-sql-connectors/cloud-sql-proxy:2.8.1 takes 30s to establish a connection when using --run-connection-test. This delay intermittently introduces proxy connection errors.

Stacktrace

Version v2.8.1

2024/01/08 23:07:43 Authorizing with OAuth2 token
2024/01/08 23:07:44 [<project>:<region>:<instance>] Listening on [::]:5432
2024/01/08 23:07:44 The proxy has started successfully and is ready for new connections!
2024/01/08 23:07:44 Connection test started
2024/01/08 23:08:14 Connection test passed
2024/01/08 23:08:14 [<project>:<region>:<instance>] accepted connection from 192.168.192.3:35240
2024/01/08 23:08:44 [<project>:<region>:<instance>] failed to connect to instance: Dial error: handshake failed (connection name = "<project>:<region>:<instance>"): context deadline exceeded
pg_dump: error: connection to database "<databse>" failed: connection to server at "pg_dump--proxy" (192.168.192.2), port 5432 failed: server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.

Version v2.7.2

2024/01/09 19:24:00 Authorizing with OAuth2 token
2024/01/09 19:24:00 [<project>:<region>:<instance>] Listening on [::]:5432
2024/01/09 19:24:00 The proxy has started successfully and is ready for new connections!
2024/01/09 19:24:00 Connection test started
2024/01/09 19:24:00 Connection test passed
2024/01/09 19:24:01 [<project>:<region:<instance>] accepted connection from 172.23.0.3:60642

Steps to reproduce?

Start a proxy container pointing to an instance, run the connection test as part of startup

1. docker run --rm gcr.io/cloud-sql-connectors/cloud-sql-proxy:2.8.0 <project>:<region>:<instance> --run-connection-test

Environment

1. OS type and version:

uname -a
Linux 92671f21852e 6.4.16-linuxkit #1 SMP PREEMPT Wed Oct 25 16:32:24 UTC 2023 x86_64 GNU/Linux 

3. Cloud SQL Proxy version (./cloud-sql-proxy --version): 2.8.1+container
4. Proxy invocation command (for example, ./cloud-sql-proxy --port 5432 INSTANCE_CONNECTION_NAME):

Additional Details

No response

[enocom]

How are you connecting to the Proxy in the container?

[enocom]

FWIW I do this:

docker run --rm -p 5432:5432 gcr.io/cloud-sql-connectors/cloud-sql-proxy:2.8.1 \
  --address 0.0.0.0 <INSTANCE_CONNECTION_NAME> \
  --run-connection-test --token $(gcloud auth print-access-token)

And then connect with psql from my host machine. This works without issue.

[mvhatch]

@enocom - I have no issue connecting my host machine to the proxy; I have an intermittent issue w/ the proxy connecting to cloud sql. However, I have no issue with the proxy connecting to cloud sql when using v2.7.2. The only thing I noticed was a timeout error in v2.8.1.

[enocom]

How often do you see this timeout error? Also I assume you're connecting to public IP?

[mvhatch]

How often do you see this timeout error? Also I assume you're connecting to public IP?

The timeout error has been happening ~50% of the time when running a workload that uses v2.8.1.
It is connecting to the public IP.

[enocom]

Thanks, @mvhatch. In that case, let me hammer this some more to see if I can force out the same problem. Have you tried reproducing outside of docker?

[enocom]

I haven't reproduced this yet, but realize I've seen this same problem when people use the readiness probe.

The key error is:

failed to connect to instance: Dial error: 
  handshake failed (connection name = "<project>:<region>:<instance>"): 
  context deadline exceeded

[mvhatch]

Idk if this is helpful, but I've also seen a timeout error in addition to the context deadline exceeded error:

2024/01/08 22:37:09 Authorizing with OAuth2 token
2024/01/08 22:37:09 <project>:<region>:<instance> Listening on [::]:5432
2024/01/08 22:37:09 The proxy has started successfully and is ready for new connections!
2024/01/08 22:37:09 Connection test started
2024/01/08 22:37:39 Connection test passed
2024/01/08 22:37:39 <project>:<region>:<instance> accepted connection from 192.168.96.3:38646
2024/01/08 22:38:09 <project>:<region>:<instance> failed to connect to instance: Dial error: failed to dial (connection name = "<project>:<region>:<instance>"): dial tcp 35.238.253.130: i/o timeout
pg_dump: error: connection to database "<db>" failed: connection to server at "pg_dump--proxy" (192.168.96.2), port 5432 failed: server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.

[mvhatch]

perhaps it is a red herring, but do you know the reason the connection tests now take 30s in version v2.8.x?