Charts: [bitnami/postgresql-ha] pgpool-ha pod crashes when postgresql pod gets deleted

[joachimnielandt]

Which chart:

postgresql-ha-1.1.5

Description

When using the default configuration, the ha-pgpool pod does not survive a crash of one of the ha-postgresql pods. I am testing this by deleting one of the pods manually. What follows might be intended behaviour, but to me it seems strange.

Steps to reproduce the issue:

1. Running this test on minikube:

﬌ minikube start
😄  minikube v1.6.1 on Arch rolling
✨  Automatically selected the 'virtualbox' driver (alternates: [none])
🔥  Creating virtualbox VM (CPUs=2, Memory=2000MB, Disk=20000MB) ...
🐳  Preparing Kubernetes v1.17.0 on Docker '19.03.5' ...

1. Setting up the test

export POSTGRES_PASSWORD=postgrespass
export REPMGR_PASSWORD=repmgrpass
helm install postgres-test bitnami/postgresql-ha --set postgresql.password=$POSTGRES_PASSWORD --set postgresql.repmgrPassword=$REPMGR_PASSWORD

1. Pods after initial setup

NAME                                                 READY   STATUS    RESTARTS   AGE
postgres-test-postgresql-ha-pgpool-d6b8d9845-sr2mm   1/1     Running   0          104s
postgres-test-postgresql-ha-postgresql-0             1/1     Running   0          104s
postgres-test-postgresql-ha-postgresql-1             1/1     Running   0          78s

1. Deleting a single pod, disrupting the setup intending to check high availability function.

kubectl delete pod postgres-test-postgresql-ha-postgresql-0

This results in the ha-pgpool pod crashing, invalidating all user connections. After a while, and a couple of restarts of ha-pgpool, we get this:

NAME                                                 READY   STATUS    RESTARTS   AGE
postgres-test-postgresql-ha-pgpool-d6b8d9845-sr2mm   1/1     Running   3          4m1s
postgres-test-postgresql-ha-postgresql-0             1/1     Running   1          101s
postgres-test-postgresql-ha-postgresql-1             1/1     Running   0          3m35s

1. Logs of the ha-pgpool pod, after deleting the postgresql pod.

2020-01-03 15:36:04: pid 155: LOG:  trying connecting to PostgreSQL server on "postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local:5432" by INET socket
2020-01-03 15:36:04: pid 155: DETAIL:  timed out. retrying...
2020-01-03 15:36:04: pid 134: LOG:  failed to connect to PostgreSQL server on "postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local:5432", getsockopt() detected error "Connection refused"
2020-01-03 15:36:04: pid 134: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:04: pid 134: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:04: pid 1: LOG:  child process with pid: 134 exits with status 256
2020-01-03 15:36:04: pid 1: LOG:  fork a new child process with pid: 276
2020-01-03 15:36:07: pid 276: LOG:  md5 authentication successful with frontend
2020-01-03 15:36:07: pid 276: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:07: pid 276: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:07: pid 276: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:07: pid 1: LOG:  child process with pid: 276 exits with status 256
2020-01-03 15:36:07: pid 1: LOG:  fork a new child process with pid: 286
2020-01-03 15:36:07: pid 159: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:07: pid 159: ERROR:  failed to make persistent db connection
2020-01-03 15:36:07: pid 159: DETAIL:  connection to host:"postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local:5432" failed
2020-01-03 15:36:07: pid 159: LOG:  health check retrying on DB node: 0 (round:1)
2020-01-03 15:36:07: pid 158: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:07: pid 158: ERROR:  failed to make persistent db connection
2020-01-03 15:36:07: pid 158: DETAIL:  connection to host:"postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local:5432" failed
2020-01-03 15:36:09: pid 155: LOG:  failed to connect to PostgreSQL server on "postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local:5432", getsockopt() detected error "Connection refused"
2020-01-03 15:36:09: pid 155: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:09: pid 155: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:09: pid 1: LOG:  child process with pid: 155 exits with status 256
2020-01-03 15:36:09: pid 1: LOG:  fork a new child process with pid: 287
2020-01-03 15:36:09: pid 287: LOG:  md5 authentication successful with frontend
2020-01-03 15:36:09: pid 287: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:09: pid 287: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:09: pid 287: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:09: pid 1: LOG:  child process with pid: 287 exits with status 256
2020-01-03 15:36:09: pid 1: LOG:  fork a new child process with pid: 298
2020-01-03 15:36:12: pid 159: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:12: pid 159: ERROR:  failed to make persistent db connection
2020-01-03 15:36:12: pid 159: DETAIL:  connection to host:"postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local:5432" failed
2020-01-03 15:36:12: pid 159: LOG:  health check retrying on DB node: 0 (round:2)
2020-01-03 15:36:14: pid 286: LOG:  md5 authentication successful with frontend
2020-01-03 15:36:14: pid 286: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:14: pid 286: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:14: pid 286: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:14: pid 1: LOG:  child process with pid: 286 exits with status 256
2020-01-03 15:36:14: pid 1: LOG:  fork a new child process with pid: 310
2020-01-03 15:36:17: pid 310: LOG:  md5 authentication successful with frontend
2020-01-03 15:36:17: pid 310: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:17: pid 310: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:17: pid 310: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:17: pid 1: LOG:  child process with pid: 310 exits with status 256
2020-01-03 15:36:17: pid 1: LOG:  fork a new child process with pid: 320
2020-01-03 15:36:17: pid 159: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:17: pid 159: ERROR:  failed to make persistent db connection
2020-01-03 15:36:17: pid 159: DETAIL:  connection to host:"postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local:5432" failed
2020-01-03 15:36:17: pid 159: LOG:  health check retrying on DB node: 0 (round:3)
2020-01-03 15:36:19: pid 320: LOG:  md5 authentication successful with frontend
2020-01-03 15:36:19: pid 320: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:19: pid 320: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:19: pid 320: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:19: pid 320: LOG:  md5 authentication successful with frontend
2020-01-03 15:36:19: pid 320: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:19: pid 320: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:19: pid 320: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:19: pid 1: LOG:  child process with pid: 320 exits with status 256
2020-01-03 15:36:19: pid 1: LOG:  fork a new child process with pid: 329
2020-01-03 15:36:22: pid 159: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:22: pid 159: ERROR:  failed to make persistent db connection
2020-01-03 15:36:22: pid 159: DETAIL:  connection to host:"postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local:5432" failed
2020-01-03 15:36:22: pid 159: LOG:  health check retrying on DB node: 0 (round:4)
2020-01-03 15:36:24: pid 145: LOG:  md5 authentication successful with frontend
2020-01-03 15:36:24: pid 145: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:24: pid 145: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:24: pid 145: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:24: pid 1: LOG:  child process with pid: 145 exits with status 256
2020-01-03 15:36:24: pid 1: LOG:  fork a new child process with pid: 338
2020-01-03 15:36:27: pid 338: LOG:  md5 authentication successful with frontend
2020-01-03 15:36:27: pid 338: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:27: pid 338: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:27: pid 338: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:27: pid 1: LOG:  child process with pid: 338 exits with status 256
2020-01-03 15:36:27: pid 1: LOG:  fork a new child process with pid: 348
2020-01-03 15:36:27: pid 159: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:27: pid 159: ERROR:  failed to make persistent db connection
2020-01-03 15:36:27: pid 159: DETAIL:  connection to host:"postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local:5432" failed
2020-01-03 15:36:27: pid 159: LOG:  health check retrying on DB node: 0 (round:5)
2020-01-03 15:36:29: pid 348: LOG:  md5 authentication successful with frontend
2020-01-03 15:36:29: pid 348: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:29: pid 348: FATAL:  failed to create a backend 0 connection
2020-01-03 15:36:29: pid 348: DETAIL:  not executing failover because failover_on_backend_error is off
2020-01-03 15:36:29: pid 1: LOG:  child process with pid: 348 exits with status 256
2020-01-03 15:36:29: pid 1: LOG:  fork a new child process with pid: 362
2020-01-03 15:36:32: pid 159: WARNING:  failed to connect to PostgreSQL server, getaddrinfo() failed with error "Name or service not known"
2020-01-03 15:36:32: pid 159: ERROR:  failed to make persistent db connection
2020-01-03 15:36:32: pid 159: DETAIL:  connection to host:"postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local:5432" failed
2020-01-03 15:36:32: pid 159: LOG:  health check failed on node 0 (timeout:0)
2020-01-03 15:36:32: pid 159: LOG:  received degenerate backend request for node_id: 0 from pid [159]
2020-01-03 15:36:32: pid 1: LOG:  Pgpool-II parent process has received failover request
2020-01-03 15:36:32: pid 1: LOG:  starting degeneration. shutdown host postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local(5432)
2020-01-03 15:36:32: pid 1: LOG:  Restart all children
2020-01-03 15:36:32: pid 1: LOG:  execute command: echo ">>> Failover - that will initialize new primary node search!"
>>> Failover - that will initialize new primary node search!
2020-01-03 15:36:32: pid 1: LOG:  find_primary_node_repeatedly: waiting for finding a primary node
2020-01-03 15:36:32: pid 1: LOG:  find_primary_node: primary node is 1
2020-01-03 15:36:32: pid 1: LOG:  failover: set new primary node: 1
2020-01-03 15:36:32: pid 1: LOG:  failover: set new master node: 1
2020-01-03 15:36:32: pid 158: ERROR:  Failed to check replication time lag
2020-01-03 15:36:32: pid 158: DETAIL:  No persistent db connection for the node 0
2020-01-03 15:36:32: pid 158: HINT:  check sr_check_user and sr_check_password
2020-01-03 15:36:32: pid 158: CONTEXT:  while checking replication time lag
2020-01-03 15:36:32: pid 158: LOG:  worker process received restart request
failover done. shutdown host postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local(5432)2020-01-03 15:36:32: pid 1: LOG:  failover done. shutdown host postgres-test-postgresql-ha-postgresql-0.postgres-test-postgresql-ha-postgresql-headless.default.svc.cluster.local(5432)
2020-01-03 15:36:33: pid 157: LOG:  restart request received in pcp child process
2020-01-03 15:36:33: pid 1: LOG:  PCP child 157 exits with status 0 in failover()
2020-01-03 15:36:33: pid 396: LOG:  PCP process: 396 started
2020-01-03 15:36:33: pid 1: LOG:  fork a new PCP child pid 396 in failover()
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 125 exits with status 256
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 125 exited with success and will not be restarted
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 126 exits with status 256
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 126 exited with success and will not be restarted
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 127 exits with status 256
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 127 exited with success and will not be restarted
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 128 exits with status 256
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 128 exited with success and will not be restarted
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 129 exits with status 256
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 129 exited with success and will not be restarted
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 130 exits with status 256
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 130 exited with success and will not be restarted
2020-01-03 15:36:33: pid 1: LOG:  worker child process with pid: 158 exits with status 256
2020-01-03 15:36:33: pid 1: LOG:  fork a new worker child process with pid: 397
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 298 exits with status 256
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 298 exited with success and will not be restarted
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 329 exits with status 256
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 329 exited with success and will not be restarted
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 362 exits with status 256
2020-01-03 15:36:33: pid 1: LOG:  child process with pid: 362 exited with success and will not be restarted
2020-01-03 15:36:33: pid 397: LOG:  get_query_result: no rows returned
2020-01-03 15:36:33: pid 397: DETAIL:  node id (1)
2020-01-03 15:36:33: pid 397: CONTEXT:  while checking replication time lag
2020-01-03 15:36:33: pid 397: LOG:  get_query_result falied: status: -1
2020-01-03 15:36:33: pid 397: CONTEXT:  while checking replication time lag
2020-01-03 15:36:34: pid 389: LOG:  md5 authentication successful with frontend
2020-01-03 15:36:37: pid 364: LOG:  md5 authentication successful with frontend

At this point, the pod crashed and is restarted.

1. Behaviour of the pods during the crash (repeated the experiment to get this output).
   It takes a while for the situation to stabilise. The dead postgresql node needs to come back, then the ha-pgpool node is revived.

postgres-test-postgresql-ha-postgresql-0             1/1     Terminating         1          23m
postgres-test-postgresql-ha-postgresql-0             0/1     Terminating         1          23m
postgres-test-postgresql-ha-postgresql-0             0/1     Terminating         1          23m
postgres-test-postgresql-ha-postgresql-0             0/1     Terminating         1          23m
postgres-test-postgresql-ha-postgresql-0             0/1     Pending             0          0s
postgres-test-postgresql-ha-postgresql-0             0/1     Pending             0          0s
postgres-test-postgresql-ha-postgresql-0             0/1     ContainerCreating   0          0s
postgres-test-postgresql-ha-postgresql-0             0/1     Running             0          1s
postgres-test-postgresql-ha-pgpool-d6b8d9845-sr2mm   0/1     Running             6          26m
postgres-test-postgresql-ha-pgpool-d6b8d9845-sr2mm   1/1     Running             6          26m
postgres-test-postgresql-ha-pgpool-d6b8d9845-sr2mm   0/1     Running             7          26m
postgres-test-postgresql-ha-pgpool-d6b8d9845-sr2mm   0/1     Error               7          27m
postgres-test-postgresql-ha-pgpool-d6b8d9845-sr2mm   0/1     CrashLoopBackOff    7          27m
postgres-test-postgresql-ha-postgresql-0             0/1     Error               0          71s
postgres-test-postgresql-ha-postgresql-0             0/1     Running             1          72s
postgres-test-postgresql-ha-postgresql-0             1/1     Running             1          79s
postgres-test-postgresql-ha-pgpool-d6b8d9845-sr2mm   0/1     Running             8          28m
postgres-test-postgresql-ha-pgpool-d6b8d9845-sr2mm   1/1     Running             8          28m

Describe the results you received:

I'm seeing that the ha-pgpool pod detects the lost connection and initiates a failover to the other node. A new master is being selected. So far, that seems to be expected. Then, the pod crashes and is restarted.

Describe the results you expected:

I'd expect the ha-pgpool pod to survive, so that the user experience is not interrupted. As it stands, any live connection is obviously terminated when the ha-pgpool pod dies.

Version of Helm and Kubernetes:

• Output of helm version:

 ﬌ helm version
version.BuildInfo{Version:"v3.0.1", GitCommit:"7c22ef9ce89e0ebeb7125ba2ebf7d421f3e82ffa", GitTreeState:"clean", GoVersion:"go1.13.4"}

• Output of kubectl version:

 ﬌ kubectl version
Client Version: version.Info{Major:"1", Minor:"17", GitVersion:"v1.17.0", GitCommit:"70132b0f130acc0bed193d9ba59dd186f0e634cf", GitTreeState:"clean", BuildDate:"2019-12-07T21:20:10Z", GoVersion:"go1.13.4", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"17", GitVersion:"v1.17.0", GitCommit:"70132b0f130acc0bed193d9ba59dd186f0e634cf", GitTreeState:"clean", BuildDate:"2019-12-07T21:12:17Z", GoVersion:"go1.13.4", Compiler:"gc", Platform:"linux/amd64"}

[sameersbn]

@CountZukula I followed the steps on a GKE cluster and did not encounter any problems. I am launching a minikube cluster to check if I can reproduce the issue. Thanks for creating the report.

[mikesplain]

We're running into the same issue, even when one pg replica is up. Pgpool starts failing it's healthcheck.

To reproduce, we disabled autoscaling on our cluster, tainted all nodes with a NoSchedule taint, then deleted a postgres pod. After a few minutes, pgpool enters crashloopbackoff, even though one replica is still up.

[carrodher]

Hi, we just created a task to investigate properly this issue. We will update this thread as soon as we have more news.

I am adding the proper labels to avoid stale bot closing the issue.

[sameersbn]

thank you everyone for your patience with this issue, it was a tricky one to fix mainly because pgpool and repmgr don't get alone too well. I have implemented a fix in https://github.com/bitnami/charts/pull/1868 and I believe it makes the postgresql-ha chart more resilient to nodes going offline. There is a related fix for the bitnami/pgpool docker image that will be pushed out soon.

[BenchmarkingBuffalo]

Hi there,
I am currently experiencing the exact same issue @CountZukula was talking about. In my case, it is a bare metal setup of k8s and I am using the chart in version postgresql-ha-3.3.1. Did this bug came up again?
I was also wondering if I can tune the times pgpool checks the readyness of the backends. In my case it takes 1.5 minutes until pgpool is back up again and has accepted the new master (5 times check plus delay in between). I would like pgpool to switch to the new master as fast as possible. The backend nodes need about 13 seconds after the last failed check to promote a new one.
I am using the production values.
Thank you for your help.

[marcosbc]

@BenchmarkingBuffalo Unfortunately I don't know if the user found the bug again. As for tuning the readiness/liveness checks, you can edit the following properties:

• postgresql.livenessProbe and postgresql.readinessProbe
• pgpool.livenessProbe and pgpool.readinessProbe

I.e. helm install mydeployment --set postgresql.livenessProbe.initialDelaySeconds=90 bitnami/postgresql-ha (see initialDelaySeconds in values.yaml).

Refer to the values.yaml file and the Parameters section in the README for more info.

[cybercoder]

me too. I did import a huge database into cluster and replicas restarts simultaneously. So it never sync

[marcosbc]

@cybercoder In that case, you should consider tweaking the liveness/readiness probes in your deployment like we mentioned earlier. If you continue finding this, please open a new issue so we can help you further there.

[rafariossaa]

Hi,
Could you test chart version 3.9.2 and check if this fix the issue for you ?