Repository navigation
primary failure and timeline change can lead to replica failure which is not respected correctly #2800
Description
Configuration and Cluster overview
Our cluster consists of 3 replicas (cluster-2, cluster-5 and cluster-7).
This is our configuration:
apiVersion: postgresql.cnpg.io/v1
kind: Cluster
metadata:
name: postgres-cluster
spec:
imageName: ghcr.io/cloudnative-pg/postgresql:15.1
instances: 3
minSyncReplicas: 2
maxSyncReplicas: 2
storage:
storageClass: csi-cinder-sc-retain
size: 10Gi
affinity:
enablePodAntiAffinity: true
topologyKey: failure-domain.beta.kubernetes.io/zone
replicationSlots:
highAvailability:
enabled: true
backup:
retentionPolicy: "60d"
barmanObjectStore:
destinationPath: s3://storage
endpointURL: https://s3-compatible-object-store
s3Credentials:
accessKeyId:
name: s3-postgres-backup
key: ACCESS_KEY_ID
secretAccessKey:
name: s3-postgres-backup
key: SECRET_ACCESS_KEY
postgresql:
parameters:
shared_buffers: 256MB
max_connections: '200'
bootstrap:
initdb:
database: db
owner: db
secret:
name: postgresql-credsObserved behavior
The Primary instance (cluster-2) failed and cluster-5 was selected as the new primary. The failover went as usual.
cluster-5 now decided to switch the timeline (from 38 to 39)
{"level":"info","ts":"2023-09-15T20:06:20Z","logger":"postgres","msg":"record","logging_pod":"postgres-cluster-5","record":{"log_time":"2023-09-15 20:06:20.253 UTC","process_id":"31","session_id":"650001d4.1f","session_line_num":"15","session_start_time":"2023-09-12 06:14:44 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"selected new timeline ID: 39","backend_type":"startup","query_id":"0"}}
cluster-7 acknowledged this change
{"level":"info","ts":"2023-09-15T20:06:29Z","logger":"postgres","msg":"record","logging_pod":"postgres-cluster-7","record":{"log_time":"2023-09-15 20:06:29.934 UTC","process_id":"254432","session_id":"6504b945.3e1e0","session_line_num":"1","session_start_time":"2023-09-15 20:06:29 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"fetching timeline history file for timeline 39 from primary server","backend_type":"walreceiver","query_id":"0"}}
cluster-7 is missing wal files though
{"level":"info","ts":"2023-09-15T20:07:23Z","logger":"postgres","msg":"record","logging_pod":"postgres-cluster-7","record":{"log_time":"2023-09-15 20:07:23.014 UTC","process_id":"25","session_id":"65001585.19","session_line_num":"55","session_start_time":"2023-09-12 07:38:45 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"new timeline 39 forked off current database system timeline 38 before current recovery point AF/3D000000","backend_type":"startup","query_id":"0"}}
cluster-7 attempts to get the wal file from cluster 5 which also does not possess it.
{"level":"info","ts":"2023-09-15T20:07:09Z","logger":"postgres","msg":"record","logging_pod":"postgres-cluster-5","record":{"log_time":"2023-09-15 20:07:09.695 UTC","user_name":"streaming_replica","process_id":"259270","connection_from":"10.0.5.161:43428","session_id":"6504b96d.3f4c6","session_line_num":"1","command_tag":"START_REPLICATION","session_start_time":"2023-09-15 20:07:09 UTC","virtual_transaction_id":"11/0","transaction_id":"0","error_severity":"ERROR","sql_state_code":"XX000","message":"requested starting point AF/3D000000 on timeline 38 is not in this server's history","detail":"This server's history forked from timeline 38 at AF/3C000000.","query":"START_REPLICATION SLOT \"_cnpg_scrumlr_postgres_cluster_7\" AF/3D000000 TIMELINE 38","application_name":"scrumlr-postgres-cluster-7","backend_type":"walsender","query_id":"0"}}
cluster-7 now tries to find the wal files in the s3 but also fails
{"level":"info","ts":"2023-09-15T20:07:26Z","logger":"wal-restore","msg":"WAL file not found in the recovery object store","logging_pod":"postgres-cluster-7","walName":"00000028.history","options":["--endpoint-url","https://object-store.","--cloud-provider","aws-s3","s3://path","postgres-cluster"],"startTime":"2023-09-15T20:07:26Z","endTime":"2023-09-15T20:07:26Z","elapsedWalTime":0.883701889}
At this point the pod stales and constantly attempts to read the wal files.
{"level":"info","ts":"2023-09-16T19:08:21Z","logger":"postgres","msg":"record","logging_pod":"postgres-cluster-7","record":{"log_time":"2023-09-16 19:08:21.663 UTC","process_id":"25","session_id":"65001585.19","session_line_num":"63667","session_start_time":"2023-09-12 07:38:45 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"waiting for WAL to become available at AF/3D000018","backend_type":"startup","query_id":"0"}}
cluster-2 has rejoned the cluster and is running smooth as a replica.
The issue
Now that cluster-7 has become stale the operator marks it as "Standby (file-based)". The cluster shows up as healthy.
This is an issue as we have configured quorum-based replication. The cluster needs at least 3 replicas to write but cluster-7 can not respond (its stuck in wal recovery).
This can become an even bigger issue (as it happend to us) if the 2 other replicas somehow fail the file-based Standby is deemed to be the most in sync and promoted to a primary. Suddenly you are writing on top of potentially 1-2 days old data if you havent configured quorum-based replication.
Expected Behavior
The Operator Should never mark a replica as healthy that is looping wal recovery and out of sync.
You could force terminate the replica and have a new one join the cluster (as the other 2 replicas are in agreement that everything is fine).
The Operator should never ever select a stale file-based replica as a new primary especially not if its heavily out of sync.
If you need any more information (logs or other intel) Id be happy to provide them to you (we have all logs).
Thanks for making and maintaining this awesome operator (startup and docs are <3).
Just unfortunate that we have been running into this issue twice this week now.
Activity
BlakeB415 commentedon Sep 27, 2023
We are also having this same issue. It's been putting our PG cluster in a precarious state.
This is making me reconsider whether or not I should continue using CloudNative-PG in production.
Lennart01 commentedon Sep 27, 2023
@BlakeB415 can you reproduce this issue by using the strategy outlined here
For now scaling your cluster down to 2 replicas should circumvent this issue (at least it does for us).
You can also check out this PR containing an alert that covers this edge case.
gbartolini commentedon Sep 27, 2023
The symptom you are seeing (file based replication) is not the cause. Simply,
cluster-7has no way to attach via streaming to the primary, so PostgreSQL uses the fallback method to fetch the file. Hence the plugin thinks that the standby is in file based replication.This is very strange and we would really love to work with you on fixing this. We should use the next office hours if possible, or we can organize a meeting.
gbartolini commentedon Sep 28, 2023
This might be related to #2910
BlakeB415 commentedon Oct 6, 2023
All our database pods completely failed on us due to this issue. Our cluster was undergoing maintenance and some of the nodes were stopped. The failover worked, but when we brought the nodes back online, the pods started crashing. Eventually, all of the database pods were in a crash loop. It is not able to recover automatically at all.
The errors are the same as the ones listed above. Except for one which errors
dial unix /controller/run/.s.PGSQL.5432: connect: no such file or directoryrepeatedly before it crashes.What is currently the best way to recover from this issue...?
Update: Recovered the primary instance, but the replicas are still crashing.
Lennart01 commentedon Oct 6, 2023
@BlakeB415 would be nice to know what error you are seeing on the crash loopin replicas
BlakeB415 commentedon Oct 6, 2023
This is the error before it crashes.
{"level":"info","ts":"2023-10-06T20:05:53Z","logger":"postgres","msg":"record","logging_pod":"vanillo-db-9","record":{"log_time":"2023-10-06 20:05:53.687 UTC","process_id":"20","session_id":"65206896.14","session_line_num":"6","session_start_time":"2023-10-06 20:05:42 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"XX000","message":"requested timeline 20 is not a child of this server's history","detail":"Latest checkpoint is at 92/49000060 on timeline 19, but in the history of the requested timeline, the server forked off from that timeline at 8D/901FAA8.","backend_type":"startup","query_id":"0"}}Lennart01 commentedon Oct 6, 2023
Please make sure all the data you want is on the current primary to avoid data loss. Now what you want to do is delete the PVC assigned to one of your replicas and then kill the replicas pod. This will lead to a fresh replica joining the cluster wich will bootstrap correctly.
BlakeB415 commentedon Oct 6, 2023
I've done this, and the result is the same. Every replica I create in this cluster has the same issue. I am currently backing up the data on the primary and moving to another operator. I cannot have this happening in production.
gbartolini commentedon Oct 23, 2023
I am really sorry @BlakeB415 that you moved to another operator, as CloudNativePG is a production ready operator.
I still suspect that the issue is due to using the default timeout values (which have all been changed and raised in the last patch release - see https://cloudnative-pg.io/documentation/current/installation_upgrade/#upgrading-to-1210-1203-or-1195).
We recommended to change those values based on the existing environment, but noticed that most users were not doing that - hence why we took that step. With the current default settings, those issues should not happen anymore.
Related to #3030 #2848 #2847 #2846
gbartolini commentedon Oct 27, 2023
@Lennart01 ok to close this ticket?
Lennart01 commentedon Oct 30, 2023
@gbartolini I would like to retest this issue with the new release. I will report back.
Lennart01 commentedon Nov 27, 2023
Could not reproduce this with the latest version. I'm closing this.
Thanks for the help 🥳