Cloudsql-proxy: net/http: timeout awaiting response headers

[tSte]

I am getting a lot of net/http: timeout awaiting response headers from the proxy in my GKE. I'm connecting to regional PSQL 11 instance with private IP address and production maintenance release channel that requires SSL.

I'm getting failures on certificate refresh requests

ephemeral certificate for instance <my-project>:<my-region>:<my-insatnce> will expire soon, refreshing now.
failed to refresh the ephemeral certificate for <my-project>:<my-region>:<my-insatnce> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<my-project>/instances/<my-insatnce>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers

and connection requests

New connection for "<my-project>:<my-region>:<my-insatnce>"
couldn't connect to "<my-project>:<my-region>:<my-insatnce>": Post https://www.googleapis.com/sql/v1beta4/projects/<my-project>/instances/<my-insatnce>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers

I've got a lot of these messages. For example there was ~25 failed connection attempts yesterday between 15:33:15 and 15:38:58.

Deployment's spec:

spec:
  serviceAccount: sql-proxy
  containers:
    - command:
        - /cloud_sql_proxy
        - -ip_address_types=PRIVATE
        - -instances=<my-project>:<my-region>:<my-insatnce>=tcp:0.0.0.0:5432
      image: gcr.io/cloudsql-docker/gce-proxy:1.16
      imagePullPolicy: IfNotPresent
      name: sqlproxy
      ports:
        - name: postgresql
          protocol: TCP
          containerPort: 5432
      resources:
        requests:
          cpu: 100m
          memory: 100Mi
  dnsPolicy: ClusterFirst
  restartPolicy: Always
  terminationGracePeriodSeconds: 30
  securityContext:
    runAsNonRoot: true
    runAsUser: 2

I'm not sure if this mattes, but here is the Kubernetes setup:
I've got several GKE deployments with multiple replicas connecting to single Cloud SQL proxy deployment (also with multiple replicas).

| deployment 1 | ----> |
                       | ClusterIP | ----> | Cloud SQL Proxy | ---->
| deployment N | ----> |

All deployments use the same Cloud SQL Instance, but connect to different PostgreSQL DB (different credentials). GKE cluster has enabled Workload Identity and Cloud SQL Proxy deployment uses service account with roles/cloudsql.client role.

Any ideas why this happens and how can I fix it? Many thanks!

[Carrotman42]

Thanks for the detailed logs and timestamps!

Those look to me like the internet connection was temporarily broken
between your cloud sql proxy pod and the cloud sql API backend. It's
somewhat hard to debug transient network issues after the fact,
unfortunately.

It looks like the event lasted around 5 minutes; can you confirm that it
only happened around that time? It's possible there was just a transient
issue that may never come back, but if it is happening consistently then
perhaps it's something that we can actually dig into deeper.

On Fri, Feb 28, 2020, 6:33 AM Tomas Stefanicka [e-mail]
wrote:

I am getting a lot of net/http: timeout awaiting response headers from
the proxy in my GKE. I'm connecting to regional PSQL 11 instance with
private IP address and production maintenance release channel that
requires SSL.

I'm getting failures on certificate refresh requests

ephemeral certificate for instance :: will expire soon, refreshing now.
failed to refresh the ephemeral certificate for :: before expering: Post https://www.googleapis.com/sql/v1beta4/projects//instances//createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers

and connection requests

New connection for "::"
couldn't connect to "::": Post https://www.googleapis.com/sql/v1beta4/projects//instances//createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers

I've got a lot of these messages. For example there was ~25 connection
attempts yesterday between 15:33:15 and 15:38:58.

Deployment's spec:

spec:
serviceAccount: sql-proxy
containers:
- command:
- /cloud_sql_proxy
- -ip_address_types=PRIVATE
- -instances=::=tcp:0.0.0.0:5432
image: gcr.io/cloudsql-docker/gce-proxy:1.16
imagePullPolicy: IfNotPresent
name: sqlproxy
ports:
- name: postgresql
protocol: TCP
containerPort: 5432
resources:
requests:
cpu: 100m
memory: 100Mi
dnsPolicy: ClusterFirst
restartPolicy: Always
terminationGracePeriodSeconds: 30
securityContext:
runAsNonRoot: true
runAsUser: 2

I'm not sure if this mattes, but here is the Kubernetes setup:
I've got several GKE deployments with multiple replicas connecting to
single Cloud SQL proxy deployment (also with multiple replicas).

| deployment 1 | ----> |
| ClusterIP | ----> | Cloud SQL Proxy | ---->
| deployment N | ----> |

All deployments use the same Cloud SQL Instance, but connect to different
PostgreSQL DB (different credentials). GKE cluster has enabled Workload
Identity and Cloud SQL Proxy deployment uses service account with
roles/cloudsql.client role.

Any ideas why this happens and how can I fix it? Many thanks!

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/GoogleCloudPlatform/cloudsql-proxy/issues/357?email_source=notifications&email_token=AAELF36ICMEU2W7CKDKECSTRFEHCFA5CNFSM4K5QL2R2YY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4IRDTANQ,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AAELF33RYZ4UXH67TNREAOTRFEHCFANCNFSM4K5QL2RQ
.

[tSte]

Hi, thanks for reply!
I am afraid it's not transient (I was suspecting DB maintenance or something) for example these are occurrences in deployment, single replica:

2020/02/01 12:52:59 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/11 17:26:24 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/13 08:53:05 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/13 16:03:50 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:07 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:08 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 197.521899ms ago
2020/02/14 00:48:08 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:08 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 288.310617ms ago
2020/02/14 00:48:08 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:11 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 4.025842661s ago
2020/02/14 00:48:11 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:12 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 4.227946465s ago
2020/02/14 00:48:12 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:32 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 24.526105076s ago
2020/02/14 00:48:32 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:41 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 33.155359468s ago
2020/02/14 00:48:41 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:41 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 33.225600986s ago
2020/02/14 00:48:41 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:47 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 39.319493606s ago
2020/02/14 00:48:47 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:47 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 39.423061739s ago
2020/02/14 00:48:47 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:47 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 39.426195694s ago
2020/02/14 00:48:47 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:47 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 39.523349241s ago
2020/02/14 00:48:47 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:47 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 39.527464168s ago
2020/02/14 00:48:47 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:47 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 39.530798107s ago
2020/02/14 00:48:47 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 00:48:47 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 39.53357712s ago
2020/02/14 00:48:47 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/14 22:42:19 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/17 20:13:41 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/18 02:17:25 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/18 13:02:18 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/18 13:02:18 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 288.881096ms ago
2020/02/18 13:02:18 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/18 13:02:18 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 295.202423ms ago
2020/02/18 13:02:18 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/19 10:48:25 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/19 10:48:25 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 182.635518ms ago
2020/02/19 10:48:25 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/20 00:46:23 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/20 09:58:31 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/20 17:21:16 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/21 00:42:08 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/22 10:52:48 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/24 16:33:25 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/24 16:33:27 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 2.262704535s ago
2020/02/24 16:33:27 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/24 16:33:27 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 2.286160843s ago
2020/02/24 16:33:27 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/24 16:33:27 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 2.380436076s ago
2020/02/24 16:33:27 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/24 16:33:31 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 6.511333737s ago
2020/02/24 16:33:31 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/24 16:33:31 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 6.914318433s ago
2020/02/24 16:33:31 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/24 16:33:31 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 6.916724364s ago
2020/02/24 16:33:31 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/24 16:33:32 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 6.9189473s ago
2020/02/24 16:33:32 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/24 16:33:32 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 6.921067513s ago
2020/02/24 16:33:32 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/24 16:33:32 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 7.012144833s ago
2020/02/24 16:33:32 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:33:17 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:33:17 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 369.383303ms ago
2020/02/27 15:33:17 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:33:17 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 374.711268ms ago
2020/02/27 15:33:17 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:33:19 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 2.388731983s ago
2020/02/27 15:33:19 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:33:25 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 8.173396455s ago
2020/02/27 15:33:25 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:33:25 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 8.179271834s ago
2020/02/27 15:33:25 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:33:36 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 19.441872756s ago
2020/02/27 15:33:36 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:33:36 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 19.450813269s ago
2020/02/27 15:33:36 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:33:36 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 19.453585716s ago
2020/02/27 15:33:36 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:34:12 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 55.336975009s ago
2020/02/27 15:34:12 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:34:12 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 55.442977101s ago
2020/02/27 15:34:12 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:05 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:05 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 3.481635ms ago
2020/02/27 15:37:05 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:05 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 9.098101ms ago
2020/02/27 15:37:05 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:08 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 3.295298035s ago
2020/02/27 15:37:08 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:08 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 3.402672235s ago
2020/02/27 15:37:08 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:08 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 3.408887559s ago
2020/02/27 15:37:08 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:08 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 3.411037553s ago
2020/02/27 15:37:08 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:12 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 6.877045708s ago
2020/02/27 15:37:12 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:12 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 7.131502195s ago
2020/02/27 15:37:12 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:12 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 7.229453509s ago
2020/02/27 15:37:12 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:17 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 11.436448559s ago
2020/02/27 15:37:17 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:17 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 11.539930384s ago
2020/02/27 15:37:17 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:17 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 11.543504406s ago
2020/02/27 15:37:17 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:20 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 14.535267168s ago
2020/02/27 15:37:20 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:20 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 14.703928664s ago
2020/02/27 15:37:20 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:20 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 14.706208911s ago
2020/02/27 15:37:20 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:25 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 20.342855981s ago
2020/02/27 15:37:25 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/27 15:37:26 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 20.728833194s ago
2020/02/27 15:37:26 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/02/28 05:32:02 failed to refresh the ephemeral certificate for <project>:us-central1:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers

[kurtisvg]

Two additional things I notice from your config:

1. You've set your resources requests to 100m (about .1 cpu) and and 100Mi (100 MiB of ram) which is very, very low and could be causing transient network issues

2. It's strongly encouraged to run the Cloud SQL proxy in a sidecar pattern as opposed to as a service. We have a page here in our docs about it, and a detailed codelab here with instructions on deploying as a sidecar.

[tSte]

Thanks @kurtisvg for ideas!

1. Ok then, I'll start by increasing resources. Do you have an idea what a baseline should be? I know that "it depends", but this application does not have large traffic - we are talking about a few small requests per minute...
   I'm not sure if I read this correctly (so please correct me if I'm wrong) but these containers are using very few resources:
   
   

2. I am aware of the lab/docs, but I didn't notice that it would be "strongly encouraged". If it's the case, my bad.

[kurtisvg]

For baseline, I would suggest starting at 1-2 cpus and 1-2 GiBs of memory and monitoring for spikes - any time it consistently hits 80-100% is bad, as it means you've introduced a bottle neck. I probably wouldn't ever go below 1 cpu or or 1 GiB of memory.

Their are quite a few reasons why the sidecar pattern is preferred - the top two that apply to your specific use case would be distributed failure points (if one proxy container fails, your other pods still have access),and that you can better shape the requested resources based to closer match your app's use of it.

[tSte]

@kurtisvg I configured proxy limits to 1 CPU and 1GiB memory and I'll let you guys know. However I find this quite large amount of resources per single container that handles a few small queries per minute. Also nodes in cluster were not utilized that much - the biggest spike I've found was 40% CPU utilization on single node (although sampling interval is 1 minute long) and the time of the spike was different than the time windows of the errors.

Regarding the sidecar pattern, I'll seriously consider it's implementation. But for now, I just limited the amount of application deployments to two (3 replicas each); one deployment is barely used for now.

@Carrotman42 I tried to check out logs in Stackdriver: it's ~150 errors per last month in total and are not clustered in few days, so I don't think it's transient.

Note: As mentioned above, I'm using private cluster + SQL instance without public IP. I checked the firewall logs for jsonPayload.connection.dest_ip:"199.36.153." during the time window when these errors occurred and there were several allowed connections to 199.36.153.4/30 so it shouldn't be FW configuration issue.

[Carrotman42]

Mea culpa; I believe I was incorrect to say this:

Those look to me like the internet connection was temporarily broken
between your cloud sql proxy pod and the cloud sql API backend.

The error you posted is quite long and involved, but it gives a story of what happened. Let's break down the error you pasted from the first post, specifically the one about the connection request failure.

couldn't connect to "<my-project>:<my-region>:<my-insatnce>": Post https://www.googleapis.com/sql/v1beta4/projects/<my-project>/instances/<my-insatnce>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers

1) couldn't connect to "<my-project>:<my-region>:<my-insatnce>" this is the top-level thing we're trying to do, connect to the database
2) Post https://www.googleapis.com/sql/v1beta4/projects/<my-project>/instances/<my-insatnce>/createEphemeral?alt=json&prettyPrint=false: before being able to authenticate with the backend database, the Proxy needs an "ephemeral certificate" which it gets from the Cloud SQL "Admin" API accessible at https://www.googleapis.com/sql/....
3) Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: here we see that we failed to get an oauth "token" (for the purpose of talking to the sqlservice.admin, the Cloud SQL Admin API) from the computeMetadata server. (If you're unfamiliar, the Google Compute Metadata server allows a VM to obtain information about itself as well as is used to obtain oauth tokens to contact Google services.)
4) net/http: timeout awaiting response headers: the last piece; the root cause of the problem was just that the network request timed out.

The interpretation is: during the attempt to contact your database, we needed to refresh the "ephemeral" certificate; the last oauth token we were using had expired so we needed to get a new one before contacting the Cloud SQL API; then, the attempt to get that oauth token failed due to a timeout. This timeout was not necessarily due to a network event; it could be explained by resource contention.

Thanks for mentioning the frequency at which you're seeing the issue; I agree that it seems like a higher number than something "transient" would imply. Are you able to check if these time periods are correlated to high CPU usage of the Proxy, or other services in your cluster which might be running on the same host as the Proxy?

I agree with @kurtisvg 's suggestion to increase the resource allocation; a timeout like this could definitely be explained by overload on the host/container. I would suggest leaving the resource settings higher than before to see if that reduces the frequency of the issue, and then gradually reducing them down to find a sweet spot for your application. (Since the Proxy is written in Go, a garbage collected language, increasing memory may reduce GC frequency and therefore reduce overall CPU usage, so there is a small amount of trading memory for CPU involved; just be aware that changing either one may result in non-linear changes to performance, depending on your workload.)

[Carrotman42]

Oh, so since the root cause actually seems related to the Google Compute Engine infrastructure, it doesn't appear to be directly related to what the Cloud SQL team runs. If increasing resources doesn't work (and no one here has more ideas) you should consider following up with the Compute Engine folks to see if there's some issue on that side.

[tSte]

@Carrotman42 so my current resources.limits is set to 1 CPU and 1GiB memory and I still have the same problem. For example this:

2020/03/02 08:55:04 Ready for new connections
2020/03/03 13:17:39 New connection for "<project>:us-central1:<instance>"
2020/03/03 13:17:42 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/03/03 13:17:44 New connection for "<project>:us-central1:<instance>"
2020/03/03 13:17:44 Throttling refreshCfg(<project>:us-central1:<instance>): it was only called 2.668859429s ago
2020/03/03 13:17:44 couldn't connect to "<project>:us-central1:<instance>": Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: Get http://169.254.169.254/computeMetadata/v1/instance/service-accounts/default/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fsqlservice.admin: net/http: timeout awaiting response headers
2020/03/03 13:36:30 New connection for "<project>:us-central1:<instance>"
2020/03/03 13:36:31 Client closed local connection on 10.12.0.42:5432
2020/03/03 14:36:01 ephemeral certificate for instance <project>:us-central1:<instance> will expire soon, refreshing now.
2020/03/03 15:06:03 New connection for "<project>:us-central1:<instance>"
2020/03/03 15:06:03 Client closed local connection on 10.12.0.42:5432
2020/03/03 15:06:12 New connection for "<project>:us-central1:<instance>"
2020/03/03 15:06:14 Client closed local connection on 10.12.0.42:5432
2020/03/03 15:06:14 New connection for "<project>:us-central1:<instance>"
2020/03/03 15:06:15 Client closed local connection on 10.12.0.42:5432

And I don't really see any spikes there...
Pod resources

Node resources (machine type n1-standard-2)

The actual usage is just a fraction of resources.requests (or resources.limits). Or am I reading this wrong?

[tSte]

BTW out of curiosity:
Why are all cloud sql proxy container logs (even the harmless ones, like 2020/03/04 09:10:10 Ready for new connections) interpreted by the StackDriver as severity: "ERROR"?

[kurtisvg]

If the resource constraints aren't the problem, then it seems likely that the the Metadata server is becoming temporarily unavailable. There really isn't anything we can do from the proxy side to fix this.

With regards to the logging - Stackdriver automatically assumes that anything logged to stderr is an error. There was a flag add in #150 that can change how the proxy logs.

[seanson]

I can confirm we are also seeing this behaviour across two of our workload identity enabled clusters in two different shared VPCs, with no resource limits.

If the resource constraints aren't the problem, then it seems likely that the the Metadata server is becoming temporarily unavailable. There really isn't anything we can do from the proxy side to fix this.

I agree that the Metadata server becoming unavailable isn't something we can fix, but I think it would be good to see what we can do to improve the client connection during degraded service.

[Carrotman42]

I'm not quite sure what the client can do after it finds itself in that
situation: when the token is expired, we need to get a new token. We can't
access the API with a valid token.

From the perspective of preparing for this possible situation, I'm also
drawing a blank on how to handle it proactively: at least in the past, the
metadata server reused the same temporary token until it is close to expiry
so we cant just get more tokens ahead of time in case the metadata server
starts transiently failing.

Restarting the underlying host VM might un-bork the associated metadata
server, but generally you shouldn't just restart things when they start to
fail unless you know what you're doing. Since there's probably other things
on the VM than the Proxy (and those things are likely more important than
this stateless service), it doesn't seem like something the Proxy should be
doing.

[zya-codes]

What library and version is your code using to reach the metadata server endpoint: http://metadata.google.internal/computeMetadata/v1/*

What is the GKE master version? Perhaps you can try updating the version and seeing if that stops the net/http timeouts from occuring. You can always find the available master versions using this command:
$ gcloud container get-server-config

I suspect outdated versions may not be able to successfully get tokens from the metadata server

[tSte]

I can confirm we are also seeing this behaviour across two of our workload identity enabled clusters in two different shared VPCs, with no resource limits.

@seanson is it a private cluster? Do you have Cloud NAT in place?

@zya-codes I don't really think it's my code. It's cloud SQL proxy container pulled from GCR. I'm not sure what version is my cluster/master running (I can check in an hour) but it was created with --release-channel=regular so I assume it runs "latest version in regular channel".

[seanson]

I suspect outdated versions may not be able to successfully get tokens from the metadata server

I raised the metadata timeout as a ticket and was advised by a support engineer that this:
https://github.com/googleapis/google-cloud-go/commit/fbf2f5121ef6008eb9b7e5c67aa0c9abfa7ac7fc
may be the cause as 2 seconds is a particularly aggressive timeout limit.
I've upgraded from v1.14.8-gke.33 and v1.14.10-gke.10 to v1.14.10-gke.27 and haven't received any of these timeouts in the last 24 hours.

[tSte]

I'm running 1.15.9-gke.8.

[rlweb]

Could we get the internal package to use 0.54.0 of the Google Cloud Go client - https://github.com/googleapis/google-cloud-go/commit/fbf2f5121ef6008eb9b7e5c67aa0c9abfa7ac7fc

[tSte]

@rlweb might be - GCP support just pointed me to the same direction.

I'd open PR myself, but I've never touched golang before. I'm not sure if I need to just modify go.mod and run tests or there is more to do. Nor am I familiar with the cloud sql proxy release cycle...

[gregmsanderson]

Hello,

From reading this am I right in thinking therefore that 2 seconds is currently the timeout for obtaining the authentication, and so if it doesn't (for whatever reason) in that time, connections will fail (and so the database is essentially cut off)?

I don't know how the retry logic was set up from that log above, but it looks like the connection failed, so a client would see errors. Which wouldn't be good. If that is the case, likewise it would be good to get a release to increase that. I am also not familiar enough to edit go myself to do it.

[kurtisvg]

Fixed in #364.

[dinvlad]

I believe we've run across a very similar issue in the past 2 days. The only difference is, we don't get net/http: timeout awaiting response headers message, just the errors like these:

2020/04/28 22:24:04 failed to refresh the ephemeral certificate for <project>:<region>:<instance> before expering: Post https://www.googleapis.com/sql/v1beta4/projects/<project>/instances/<instance>/createEphemeral?alt=json&prettyPrint=false: compute: Received 403 `
Unable to generate token; IAM returned 403 Forbidden: Request had insufficient authentication scopes.
This error could be caused by a missing IAM policy binding on the target IAM service account.
You can create the necessary policy binding with:
...

This doesn't appear to be related to auth scopes, as we do use Workload Identity and I did verify that the same request using Curl from the affected Pods succeeds.

Do you think that deserves a separate issue?

EDIT: I should also note that rebuilding cloudsql-proxy image from master didn't help, in our case.

[Carrotman42]

That error seems quite different than the one mentioned in this issue (HTTP
error code 403, not HTTP timeout). Please file a new issue.

On Thu, Apr 30, 2020 at 10:36 PM Denis Loginov [e-mail]
wrote:

I believe we've run across a very similar issue in the past 2 days. The
only difference is, we don't get net/http: timeout awaiting response
headers message, just the errors like these:

2020/04/28 22:24:04 failed to refresh the ephemeral certificate for :: before expering: Post https://www.googleapis.com/sql/v1beta4/projects//instances//createEphemeral?alt=json&prettyPrint=false: compute: Received 403 `
Unable to generate token; IAM returned 403 Forbidden: Request had insufficient authentication scopes.
This error could be caused by a missing IAM policy binding on the target IAM service account.
You can create the necessary policy binding with:
...

This doesn't appear to be related to auth scopes, as we do use Workload
Identity and I did verify that the same request using Curl from the
affected Pods succeeds.

Do you think that deserves a separate issue?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/GoogleCloudPlatform/cloudsql-proxy/issues/357#issuecomment-622244113,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AAELF34G4R43MODMI4MSGNLRPJGV3ANCNFSM4K5QL2RQ
.