Random crashing

[echel0n]

Describe the bug
I have 4 pgo clusters created and running, randomly after some time they will crash and fail to come back, I've tried restarting the clusters and even killing all the pods in the pgo namespace which just results in a complaint of multi-attached pvc's, so far the only way to fix this is delete the clusters and restore from backups.

Storage for both primary and replication is rook-ceph-block, backrest is S3, I can't for the life of me figure out what is causing the crash as the logs them self do not indicate anything that jumps out at me, please see below:

2020-12-20 02:21:09,854 INFO: no action.  i am the leader with the lock
2020-12-20 02:21:19,847 INFO: Lock owner: keycloak-8445bc9877-997sw; I am keycloak-8445bc9877-997sw
2020-12-20 02:21:19,916 INFO: no action.  i am the leader with the lock
2020-12-20 02:21:29,847 INFO: Lock owner: keycloak-8445bc9877-997sw; I am keycloak-8445bc9877-997sw
2020-12-20 02:21:29,872 INFO: no action.  i am the leader with the lock
2020-12-20 02:21:39,847 WARNING: Postgresql is not running.
2020-12-20 02:21:39,847 INFO: Lock owner: keycloak-8445bc9877-997sw; I am keycloak-8445bc9877-997sw
2020-12-20 02:21:39,907 INFO: Reaped pid=45567, exit status=0
2020-12-20 02:21:39,908 INFO: pg_controldata:

Please tell us about your environment:

• Operating System: Ubuntu 20.04.1 LTS
• Where is this running ( Local, Cloud Provider): Local
• Storage being used (NFS, Hostpath, Gluster, etc): S3 and rook-ceph-block
• Container Image Tag: centos7-12.5-4.5.1
• PostgreSQL Version: 12.5
• Platform (Docker, Kubernetes, OpenShift): Kubernetes 1.20.1
• Platform Version: 4.5.1

[echel0n]

So I deleted the entire namespace and restored it all however now a replica is not working and I've scaled down and back up to create a new replica but the same issue, below is the error I am getting which might give insight to what happened before as well, I suspect its just a matter of time before all the other clusters crash as well.

/tmp:5432 - rejecting connections
/tmp:5432 - rejecting connections
/tmp:5432 - no response
2020-12-20 12:04:34,350 WARNING: Postgresql is not running.
2020-12-20 12:04:34,350 INFO: Lock owner: gitlab-f4bdf7784-g4bjw; I am gitlab-lyji-69d9c489c9-vfwsg
2020-12-20 12:04:34,358 INFO: Reaped pid=1241, exit status=0

[echel0n]

And here is a snipped from the replica's pg_log data:

2020-12-20 12:08:19.033 UTC [6115] FATAL:  the database system is starting up
2020-12-20 12:08:19.041 UTC [6117] FATAL:  the database system is starting up
2020-12-20 12:08:19.195 UTC [6124] FATAL:  the database system is starting up
2020-12-20 12:08:19.480 UTC [6114] LOG:  restored log file "0000000B.history" from archive
2020-12-20 12:08:19.814 UTC [6114] LOG:  entering standby mode
2020-12-20 12:08:20.053 UTC [6134] FATAL:  the database system is starting up
2020-12-20 12:08:20.159 UTC [6114] LOG:  restored log file "0000000B.history" from archive
2020-12-20 12:08:20.211 UTC [6141] FATAL:  the database system is starting up
2020-12-20 12:08:20.586 UTC [6114] LOG:  restored log file "0000000A0000000E0000009F" from archive
2020-12-20 12:08:20.666 UTC [6114] LOG:  invalid xl_info in checkpoint record
2020-12-20 12:08:20.667 UTC [6114] FATAL:  could not locate required checkpoint record
2020-12-20 12:08:20.667 UTC [6114] HINT:  If you are restoring from a backup, touch "/pgdata/gitlab-lyji/recovery.signal" and add required recovery options.
        If you are not restoring from a backup, try removing the file "/pgdata/gitlab-lyji/backup_label".
        Be careful: removing "/pgdata/gitlab-lyji/backup_label" will result in a corrupt cluster if restoring from a backup.
2020-12-20 12:08:20.668 UTC [6111] LOG:  startup process (PID 6114) exited with exit code 1
2020-12-20 12:08:20.668 UTC [6111] LOG:  aborting startup due to startup process failure
2020-12-20 12:08:20.672 UTC [6111] LOG:  database system is shut down
2020-12-20 12:08:21.448 UTC [6160] LOG:  database system was interrupted; last known up at 2020-12-20 11:46:16 UTC
2020-12-20 12:08:21.853 UTC [6160] LOG:  restored log file "0000000B.history" from archive
2020-12-20 12:08:22.183 UTC [6160] LOG:  entering standby mode
2020-12-20 12:08:22.243 UTC [6173] FATAL:  the database system is starting up
2020-12-20 12:08:22.389 UTC [6176] FATAL:  the database system is starting up
2020-12-20 12:08:22.398 UTC [6178] FATAL:  the database system is starting up
2020-12-20 12:08:22.520 UTC [6160] LOG:  restored log file "0000000B.history" from archive
2020-12-20 12:08:22.938 UTC [6160] LOG:  restored log file "0000000A0000000E0000009F" from archive
2020-12-20 12:08:23.005 UTC [6160] LOG:  invalid xl_info in checkpoint record
2020-12-20 12:08:23.005 UTC [6160] FATAL:  could not locate required checkpoint record
2020-12-20 12:08:23.005 UTC [6160] HINT:  If you are restoring from a backup, touch "/pgdata/gitlab-lyji/recovery.signal" and add required recovery options.
        If you are not restoring from a backup, try removing the file "/pgdata/gitlab-lyji/backup_label".
        Be careful: removing "/pgdata/gitlab-lyji/backup_label" will result in a corrupt cluster if restoring from a backup.
2020-12-20 12:08:23.007 UTC [6157] LOG:  startup process (PID 6160) exited with exit code 1
2020-12-20 12:08:23.007 UTC [6157] LOG:  aborting startup due to startup process failure
2020-12-20 12:08:23.011 UTC [6157] LOG:  database system is shut down
2020-12-20 12:08:23.733 UTC [6199] LOG:  database system was interrupted; last known up at 2020-12-20 11:46:16 UTC
2020-12-20 12:08:23.733 UTC [6200] FATAL:  the database system is starting up
2020-12-20 12:08:23.746 UTC [6202] FATAL:  the database system is starting up

[echel0n]

Logs from primary pg_log folder:

2020-12-20 12:10:03.656 UTC [167] DETAIL:  The failed archive command was: source /opt/cpm/bin/pgbackrest/pgbackrest-set-env.sh && pgbackrest archive-push "pg_wal/0000000A0000000E0000009E"
ERROR: [045]: WAL file '0000000A0000000E0000009E' already exists in the archive
2020-12-20 12:10:05.028 UTC [167] LOG:  archive command failed with exit code 45
2020-12-20 12:10:05.028 UTC [167] DETAIL:  The failed archive command was: source /opt/cpm/bin/pgbackrest/pgbackrest-set-env.sh && pgbackrest archive-push "pg_wal/0000000A0000000E0000009E"
ERROR: [045]: WAL file '0000000A0000000E0000009E' already exists in the archive
2020-12-20 12:10:06.417 UTC [167] LOG:  archive command failed with exit code 45
2020-12-20 12:10:06.417 UTC [167] DETAIL:  The failed archive command was: source /opt/cpm/bin/pgbackrest/pgbackrest-set-env.sh && pgbackrest archive-push "pg_wal/0000000A0000000E0000009E"
2020-12-20 12:10:06.417 UTC [167] WARNING:  archiving write-ahead log file "0000000A0000000E0000009E" failed too many times, will try again later

[jkatz]

2020-12-20 12:08:20.586 UTC [6114] LOG:  restored log file "0000000A0000000E0000009F" from archive
2020-12-20 12:08:20.666 UTC [6114] LOG:  invalid xl_info in checkpoint record
2020-12-20 12:08:20.667 UTC [6114] FATAL:  could not locate required checkpoint record
2020-12-20 12:08:20.667 UTC [6114] HINT:  If you are restoring from a backup, touch "/pgdata/gitlab-lyji/recovery.signal" and add required recovery options.
        If you are not restoring from a backup, try removing the file "/pgdata/gitlab-lyji/backup_label".
        Be careful: removing "/pgdata/gitlab-lyji/backup_label" will result in a corrupt cluster if restoring from a backup.

It sounds like there is something wrong with your WAL archive. This could be a result from many different things, including storage corruption or split-brain. It does sound like there was some sort of timeline change based on the error from pgBackRest, which appears its doing its job and is not allowing an overwrite of an existing file. It's hard to determine what happened without a full accounting of your environment and what happened prior.

Your likely bet of recovery is to perform a restore back from the best known state. The safer option is to do a restore to a new PVC so you can inspect your data before bringing it live. Methods for doing so are detailed in a variety of places in the documentation:

• https://access.crunchydata.com/documentation/postgres-operator/latest/tutorial/disaster-recovery/
• https://access.crunchydata.com/documentation/postgres-operator/latest/architecture/disaster-recovery/

It would be good to see what happened in the PostgreSQL logs around this time:

2020-12-20 02:21:39,847 WARNING: Postgresql is not running.
2020-12-20 02:21:39,847 INFO: Lock owner: keycloak-8445bc9877-997sw; I am keycloak-8445bc9877-997sw
2020-12-20 02:21:39,907 INFO: Reaped pid=45567, exit status=0
2020-12-20 02:21:39,908 INFO: pg_controldata:"

as that may give a better understanding of the environment at that time. I decline to speculate if it uncovers as PostgreSQL bug or not, however, I unless I see more evidence, I don't think there is a bug with the Operator itself.

UPDATE: Speaking with one of the pgBackRest authors, this could also be related to an issue fixed in pgBackRest v2.31. Original report: pgbackrest/pgbackrest#1236. This may not be the cause, but I wanted to present this as a possible troubleshooting path.

We will look into updating to pgBackRest 2.31 in the 4.6.0 release.

[jkatz]

An additional note from one of my colleagues: you should ensure that your storage class (in this case rook-ceph-block) is respecting fsync calls. This is a very important part of PostgreSQL to ensure that writes are flushed to disk.

[echel0n]

I do appreciate your time and efforts on this, I will try a PITR to try and correct the archive issue, I do have scheduled full backups set for 1 AM and then diff backups every 3 hours. It's really just been one thing after another so I'm kinda hoping this crashes again on a different cluster so I can take a look at the pg_log folder and finally isolate this to either rook-ceph storage or the s3 storage which is backed by ZFS on a different system.

Another strange thing that happened yesterday was after I adjusted the memory resources for pgBackrest by increasing from 48Mi to 100Mi, the pgBackrest repo pod failed to connect find a bunch of files related to SSHD, killing the pods didn't seem to fix it either.

I'll let you know how things are after the PITR, thanks!

[echel0n]

OK, so here's something else that's happened that's been sort of an issue, I deleted the cluster but forgot to remove the backup data from the s3 bucket, so when the cluster got created, pgbackrest didn't like that, so I deleted the folder and killed the backrest pod, now I get the following error below when I describe the backrest shared repo pod:

Error: couldn't find key aws-s3-key in Secret pgo/gitlab-backrest-repo-config

I should note that I use Bitnami Sealed Secrets and I'm noticing that these secrets seem to get over-written with regular secrets and the aws-s3-key is now in fact missing and seems to be replaced with aws-s3-ca.crt.

Also, I use FluxCD to maintain my cluster from a git repository.

[echel0n]

So now when I delete the cluster and re-sync with Flux to re-create the pgcluster CRD and secrets, I can consistently reproduce the error I mentioned above about the aws-s3-key missing and the secret getting replaced, however, this is not an issue when I delete the pgo namespace and sync using Flux.

Any thoughts on this ?

[echel0n]

Another update on this, so when deleting the cluster I can confirm it removes the gitlab-backrest-repo-config secret but the sealed secret is still present, cause of this the sealed secret was not getting unsealed when syncing with Flux, I deleted the sealed secret and re-synced and all is good now with that, I do not have a full understanding as of yet to how sealed secrets work but I would think that when a secret matching the name gitlab-backrest-repo-config is requested it should unseal it, perhaps this is not the case and that is causing the secret to just be re-created from defaults.

[echel0n]

OK, so a backrest-backup operation just started crashing on another 2 clusters randomly, below is the logs:

time="2020-12-20T23:03:38Z" level=info msg="pgo-backrest starts"
time="2020-12-20T23:03:38Z" level=info msg="debug flag set to false"
time="2020-12-20T23:03:38Z" level=info msg="backrest backup command requested"
time="2020-12-20T23:03:38Z" level=info msg="s3 flag enabled for backrest command"
time="2020-12-20T23:03:38Z" level=info msg="command to execute is [pgbackrest backup  --db-host=10.244.1.159 --db-path=/pgdata/discourse --repo1-type=s3 --no-repo1-s3-verify-tls]"
time="2020-12-20T23:03:38Z" level=info msg="command is pgbackrest backup  --db-host=10.244.1.159 --db-path=/pgdata/discourse --repo1-type=s3 --no-repo1-s3-verify-tls "
time="2020-12-20T23:03:38Z" level=error msg="command terminated with exit code 56"
time="2020-12-20T23:03:38Z" level=info msg="output=[]"
time="2020-12-20T23:03:38Z" level=info msg="stderr=[WARN: option 'repo1-retention-full' is not set for 'repo1-retention-full-type=count', the repository may run out of space\n      HINT: to retain full backups indefinitely (without warning), set option 'repo1-retention-full' to the maximum.\nWARN: unable to check pg-1: [UnknownError] remote-0 process on '10.244.1.159' terminated unexpectedly [255]: ssh_exchange_identification: read: Connection reset by peer\nERROR: [056]: unable to find primary cluster - cannot proceed\n]"
time="2020-12-20T23:03:38Z" level=error msg="command terminated with exit code 56"

Logs from pod for primary:

2020-12-20 22:59:36,034 WARNING: Postgresql is not running.
2020-12-20 22:59:36,034 INFO: Lock owner: discourse-5b568cdbd4-xpfl9; I am discourse-5b568cdbd4-xpfl9
2020-12-20 22:59:36,087 INFO: Reaped pid=63940, exit status=0
2020-12-20 22:59:36,089 INFO: pg_controldata:
  pg_control version number: 1201
  Catalog version number: 201909212
  Database system identifier: 6905921847577006231
  Database cluster state: shutting down
  pg_control last modified: Sun Dec 20 22:59:31 2020

Sun Dec 20 23:00:00 UTC 2020 INFO: New primary still in recovery, waiting one second...
psql: error: could not connect to server: No such file or directory
        Is the server running locally and accepting
        connections on Unix domain socket "/tmp/.s.PGSQL.5432"?

Logs from pg_log folder:

2020-12-20 22:55:28.929 UTC [167] DETAIL:  The failed archive command was: source /opt/cpm/bin/pgbackrest/pgbackrest-set-env.sh && pgbackrest archive-push "pg_wal/0000000C0000002300000079"
ERROR: [125]: remote-0 process on 'discourse-backrest-shared-repo' terminated unexpectedly [255]: ssh_exchange_identification: read: Connection reset by peer
2020-12-20 22:55:29.991 UTC [167] LOG:  archive command failed with exit code 125

2020-12-20 22:59:31.480 UTC [167] DETAIL:  The failed archive command was: source /opt/cpm/bin/pgbackrest/pgbackrest-set-env.sh && pgbackrest archive-push "pg_wal/0000000C0000002300000079"
2020-12-20 22:59:31.480 UTC [167] WARNING:  archiving write-ahead log file "0000000C0000002300000079" failed too many times, will try again later
2020-12-20 22:59:31.637 UTC [165] PANIC:  could not write to file "pg_wal/xlogtemp.165": No space left on device
2020-12-20 22:59:31.814 UTC [159] LOG:  WAL writer process (PID 165) was terminated by signal 6: Aborted

I am using S3 storage for backrest so not sure why it would state "No space left on device"

[echel0n]

OK, I've increased the PVC size for the primary and replica's and will monitor, btw pgo df just returns an error when attempting to use it.

[echel0n]

So I shutdown one of the clusters so I could restart it in hopes that it would fix the failing backup pod and now it won't start, the backrest-shared-repo pod logs show this:

Starting the pgBackRest repo
cp: cannot stat '/sshd/config': No such file or directory
cp: cannot stat '/sshd/id_ed25519': No such file or directory
chmod: cannot access '/tmp/id_ed25519': No such file or directory
chmod: cannot access '/home/pgbackrest/.ssh/config': No such file or directory
The pgBackRest repo has been started
/sshd/sshd_config: No such file or directory

Primary pod logs:

Sun Dec 20 23:36:07 UTC 2020 INFO: Applying SSHD..
Sun Dec 20 23:36:07 UTC 2020 INFO: Checking for SSH Host Keys in /sshd..
Sun Dec 20 23:36:07 UTC 2020 ERROR: No ssh_host_ed25519_key found in /sshd.  Exiting..

Logs from operator:

time="2020-12-20T23:31:43Z" level=error msg="command terminated with exit code 137" func="internal/kubeapi.ExecToPodThroughAPI()" file="internal/kubeapi/exec.go:76" version=4.5.1
time="2020-12-20T23:31:43Z" level=error msg="Operation cannot be fulfilled on deployments.apps \"discourse\": the object has been modified; please apply your changes to the latest version and try again" func="internal/controller/pgcluster.(*Controller).onUpdate()" file="internal/controller/pgcluster/pgclustercontroller.go:236" version=4.5.1

Any ideas ?

[jkatz]

We don't test with FluxCD (and this is the first I'm hearing of it) so I really can't comment on what is going on with your setup. The best I can tell is that the <clusterName>-backrest-repo-config Secret is either missing or it does not container it's expected values.

The Postgres Operator itself will generate that Secret and populate it with the correct values for each cluster. If you are creating the custom resource directly, this happens as of the 4.5.1 release (note instructions here: https://access.crunchydata.com/documentation/postgres-operator/4.5.1/custom-resources/.

Some of these values are defaults that the Operator loads into the Secret. The SSH keys are randomly generated for each new cluster.

If all else fails, you can delete the cluster with the --keep-data (and potentially --keep-backups) flag, and then create a cluster of the same name, which will start a cluster with the existing PVC.

Anyway, outside of the potential fix to ameliorate the issue mentioned in #2138 (comment) this is skewing towards support as I do not see any additional bugs or programmatic work we can do on the Operator for this.

[echel0n]

OK, so I was able to resolve from what I can tell 2 issues that plagued this setup.

#1. 2 clusters did indeed run out of storage space, resolution to this was to increase PVC size for both primary and replication

#2. -backrest-repo-config was missing authorized_keys, aws-s3-ca.crt, config, id_ed25519, ssh_host_ed25519_key, and sshd_config, adding those keys into the config resolved it, since FluxCD keeps the cluster in sync with the repo, it, in fact, was overwriting whatever PGO was adding to that secret, maybe FluxCD has a option to control what or if a file should stay in sync for matters such as this but easiest solution was to just copy the values from a test cluster and move on.

I do again appreciate all the help you have provided and I hope this ticket helps others in the future!