[Bug]: "pod not available", "Cannot extract Pod status", "WAL file not found in the recovery object store" #4551
Comments
|
I fixed the unhealthy state of the cluster by destroying the instance for now. The operator created a new pod However that should not be the solution to this kind of error. The operator should be able to heal the cluster if one worker node goes down for whatever reason. I still hope it is just a misconfiguration but I am quite sure I did nothing wrong here. |
|
Before I had destroyed I found it kind of weird that the file |
Is there an existing issue already for this bug?
I have read the troubleshooting guide
I am running a supported version of CloudNativePG
Contact Details
No response
Version
older in 1.21.x
What version of Kubernetes are you using?
1.29
What is your Kubernetes environment?
Self-managed: RKE
How did you install the operator?
Helm
What happened?
We have a kubernetes cluster with 6 worker nodes, distributed into 3 zones with each having 2 nodes.
The CNPG cluster consists of 3 instances and a pooler, created with the CNPG Operator.
I then shut down the worker node containing the primary instance of the postgres cluster forcefully to see if it heals itself properly.
Within seconds another instance was promoted as the primary and it seems to work fine.
But I assumed that after a while the operator will spawn a new standby instance on the other worker in the same zone that is still runnung. That never happened, even after waiting for 20 minutes. So the cluster never became healthy again on its own.
I then started the node again which I shut down before. After a while the missing postgres instance pod got created again but now it is stuck and
kubectl cnpg statusshowspod not availablewhile the pod logs show that it has restored itself from the archived WAL files in the S3 bucket except that it tries to restore from a file that is newer than the backup status shows. But see for yourself:Cluster status:
As you can see it still thinks it is in the failing over state although the primary is ready again since 20 hours.
You can also see that the latest WAL archive is
0000000D0000000000000039.Now let's have a look into the pod
keycloak-db-pgcluster-5(I removed a bit of clutter from the logs so they are more easy to read):[ { "ts": "2024-05-16T10:41:33Z", "msg": "WAL file not found in the recovery object store", "walName": "0000000E.history", "options": [ "--endpoint-url", "https://s3.example.com", "--cloud-provider", "aws-s3", "s3://project-dev/postgres-keycloak-backup", "keycloak-db-pgcluster" ] }, { "ts": "2024-05-16T10:41:34Z", "msg": "Restored WAL file", "walName": "0000000D.history" }, { "ts": "2024-05-16T10:41:34Z", "msg": "WAL restore command completed (parallel)", "walName": "0000000D.history", "maxParallel": 1, "successfulWalRestore": 1, "failedWalRestore": 0, "endOfWALStream": false }, { "ts": "2024-05-16T10:41:36Z", "msg": "Restored WAL file", "walName": "0000000D0000000000000039" }, { "ts": "2024-05-16T10:41:36Z", "msg": "WAL restore command completed (parallel)", "walName": "0000000D0000000000000039", "maxParallel": 1, "successfulWalRestore": 1, "failedWalRestore": 0, "endOfWALStream": false }, { "ts": "2024-05-16T10:41:38Z", "msg": "Restored WAL file", "walName": "0000000D0000000000000038" }, { "ts": "2024-05-16T10:41:38Z", "msg": "WAL restore command completed (parallel)", "walName": "0000000D0000000000000038", "maxParallel": 1, "successfulWalRestore": 1, "failedWalRestore": 0, "endOfWALStream": false }, { "ts": "2024-05-16T10:41:40Z", "msg": "Restored WAL file", "walName": "0000000D0000000000000039" }, { "ts": "2024-05-16T10:41:40Z", "msg": "WAL restore command completed (parallel)", "walName": "0000000D0000000000000039", "maxParallel": 1, "successfulWalRestore": 1, "failedWalRestore": 0, "endOfWALStream": false }, { "ts": "2024-05-16T10:41:42Z", "msg": "WAL file not found in the recovery object store", "walName": "0000000D000000000000003A", "options": [ "--endpoint-url", "https://s3.example.com", "--cloud-provider", "aws-s3", "s3://project-dev/postgres-keycloak-backup", "keycloak-db-pgcluster" ] } ]Why does it try to read
0000000D000000000000003A? And why isendOfWALStreamset tofalseon the last WAL file when it should betrue? Or am I misinterpreting something here?And here is the log of the postgres-operator which is repeating every 2 seconds:
{ "ts": "2024-05-16T12:03:38Z", "msg": "Cannot extract Pod status", "controller": "cluster", "controllerGroup": "postgresql.cnpg.io", "controllerKind": "Cluster", "Cluster": { "name": "keycloak-db-pgcluster", "namespace": "middleware-svc-keycloak" }, "namespace": "middleware-svc-keycloak", "name": "keycloak-db-pgcluster", "name": "keycloak-db-pgcluster-5", "error": "error status code: 500, body: failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is not yet accepting connections (SQLSTATE 57P03))\n" } { "level": "info", "ts": "2024-05-16T12:03:39Z", "msg": "pooler not automatically configured, manual configuration required", "cluster": "keycloak-db-pgcluster", "pooler": "keycloak-db-pgcluster-pooler-rw" }We experience that problem quite often when we do maintenance on the kubernetes nodes and need to restart them. The already destroyed multiple clusters because of that. The only way to fix this is to destroy the instance with
kubectl cnpg destroy keycloak-db-pgcluster 5and wait for a fresh instance to come up. Afterwards we can delete the PVC and PV of the old instance since it makes no sense to keep it.We want to upgrade soon to the latest version but after finding this recent bug I think this still can happen in newer versions: #4412
Cluster resource
apiVersion: postgresql.cnpg.io/v1 kind: Cluster metadata: annotations: cnpg.io/reconciliationLoop: enabled meta.helm.sh/release-name: keycloak-db meta.helm.sh/release-namespace: middleware-svc-keycloak generation: 3 labels: app.kubernetes.io/instance: keycloak-db app.kubernetes.io/managed-by: Helm app.kubernetes.io/name: pgcluster app.kubernetes.io/version: '15.1' helm.sh/chart: pgcluster-0.1.14 helm.toolkit.fluxcd.io/name: keycloak-db helm.toolkit.fluxcd.io/namespace: middleware-svc-keycloak k8slens-edit-resource-version: v1 name: keycloak-db-pgcluster namespace: middleware-svc-keycloak spec: affinity: podAntiAffinityType: required topologyKey: topology.kubernetes.io/zone backup: barmanObjectStore: destinationPath: s3: //project-dev/postgres-keycloak-backup endpointURL: https: //s3.example.com s3Credentials: accessKeyId: key: ACCESS_KEY_ID name: keycloak-backup-s3 inheritFromIAMRole: false secretAccessKey: key: ACCESS_SECRET_KEY name: keycloak-backup-s3 wal: compression: gzip retentionPolicy: 30d target: prefer-standby bootstrap: initdb: database: keycloak encoding: UTF8 localeCType: C localeCollate: C owner: keycloak secret: name: postgresql-keycloak-password description: Postgres general configuration enableSuperuserAccess: true failoverDelay: 0 imageName: ghcr.io/cloudnative-pg/postgresql:15.3 imagePullPolicy: IfNotPresent inheritedMetadata: labels: app.kubernetes.io/instance: keycloak-db app.kubernetes.io/managed-by: Helm app.kubernetes.io/name: pgcluster app.kubernetes.io/version: '15.1' helm.sh/chart: pgcluster-0.1.14 instances: 3 logLevel: warning maxSyncReplicas: 2 minSyncReplicas: 1 monitoring: customQueriesConfigMap: - key: queries name: cnpg-default-monitoring disableDefaultQueries: false enablePodMonitor: true nodeMaintenanceWindow: inProgress: false reusePVC: false postgresGID: 26 postgresUID: 26 postgresql: parameters: archive_mode: 'on' archive_timeout: 5min auto_explain.log_min_duration: 10s dynamic_shared_memory_type: posix log_destination: csvlog log_directory: /controller/log log_filename: postgres log_rotation_age: '0' log_rotation_size: '0' log_truncate_on_rotation: 'false' logging_collector: 'on' max_parallel_workers: '32' max_replication_slots: '32' max_worker_processes: '32' pg_stat_statements.max: '10000' pg_stat_statements.track: all shared_buffers: 256MB shared_memory_type: mmap shared_preload_libraries: '' wal_keep_size: 512MB wal_receiver_timeout: 5s wal_sender_timeout: 5s syncReplicaElectionConstraint: enabled: false primaryUpdateMethod: restart primaryUpdateStrategy: unsupervised resources: requests: cpu: 250m memory: 512Mi startDelay: 300 stopDelay: 300 storage: resizeInUseVolumes: true size: 1Gi storageClass: longhorn-2-repl-retain switchoverDelay: 2Relevant log output
No response
Code of Conduct
The text was updated successfully, but these errors were encountered: