db hangs at starting up, connection problems: Archive '00000004.history' does not exist.

[yannick]

• Which image of the operator are you using? e.g. registry.opensource.zalan.do/acid/postgres-operator:v1.5.0
  and own one build from spilo master with docker build --build-arg TIMESCALEDB_APACHE_ONLY=false --build-arg PGVERSION="12"

• Where do you run it - cloud or metal? Kubernetes or OpenShift?
  AWS k8s

• Are you running Postgres Operator in production?
  Yes

• Type of issue? [Bug report, question, feature request, etc.]
  after node failures the databases take very long to come up or fail at it.
  sometimes it works but most of the time they get stuck. db's are relatively small. backups and WAL are on s3.
  every so often ( ~10mins)

the most prominent error i see is:

ERROR: 2020/12/17 07:52:56.292259 Archive '00000004.history' does not exist.

https://gist.github.com/yannick/461741dad6a2f09b0d67316380e1bd42

is there a way to solve this, and generall how long should it take to restart a pod that has been killed?

[FxKu]

Not sure, how much you could reduce downtime when having two instances on different nodes and not just one master.
Regarding this "error" Postgres tries to restore the WAL file from the timeline 3, and if it doesn't exists it tries the history file form the next timeline which doesn't yet exist. Why does the node fail?

[yannick]

i am aware that the whole point of a HA setup is that you have multiple slaves and that you can reduce downtime by having stable k8s nodes. however this should not be an excuse to not properly and promptly recover.
we yolo'd the setup on spot instances and probably someone submitted a poorly written Neural Network training job that kept killing our spot nodes :P
but lets ignore our specific setup ( i migrated the production workload to RDS instances meanwhile), i am still interested to make this work for certain use cases.

i nailed most of the problems down to the fact that recovering with timescaledb seems to be a problem.
( possibly the backup process isnt fully implemented?
and i have seen this repeatedly. so it seems that operator instances with timescale database seem not to fully work. i unfortunately do not understand enough about patroni to nail down what it waits for so long.

[Reuuke]

@yannick We have also had this problem on AWS EKS. It can be easily solved:
Need to increase HttpPutResponseHopLimit to 2 (default is 1) on EC2 Instance Metadata configuration.
It is metadata_http_put_response_hop_limit parameter if you are using https://github.com/terraform-aws-modules/terraform-aws-eks module :)

[yannick]

@Reuuke many thanks! i will check it out. for this particular cluster i am using kops with aws cni but i guess there is a way. do you have any idea what part of postgres-operator fails here so maybe we can improve the error message or at least docs ?!

[haslersn]

I had the same error. The problem was that, in S3, there was a timeline under the prefixes

cluster01-postgres-backups/spilo/gitlab-gitlab-db/wal/basebackups_005/base_00000004
cluster01-postgres-backups/spilo/gitlab-gitlab-db/wal/wal_005/00000004

that did not belong to the postgresql cluster. (00000004 is just an example – it could be any number.) In my case the bucket is cluster01-postgres-backups, the namespace is gitlab and the postgresql cluster name is gitlab-db. The objects of the timeline 00000004 were older than the objects of the timeline 00000001. Therefore, I assume that the 00000004 timeline was created by a previous postgresql cluster with the same namespace and name, that has since been recreated.

Diagnosis

As follows, you can check whether you experience the same problem. Usually one of the Pods repeatedly attempts to bootstrap and each time shows the following partial log:

/var/run/postgresql:5432 - rejecting connections
/var/run/postgresql:5432 - rejecting connections
/var/run/postgresql:5432 - no response
2021-01-31 19:37:30,064 WARNING: Postgresql is not running.

Exec into that Pod (in my case gitlab-db-0):

$ kubectl exec -it gitlab-db-0 -- bash
root@gitlab-db-0:/home/postgres# cd pgdata/pgroot/pg_log
root@gitlab-db-0:/home/postgres/pgdata/pgroot/pg_log# ls

Now watch the postgresql-x.csv that has the highest number x:

root@gitlab-db-0:/home/postgres/pgdata/pgroot/pg_log# tail -f postgresql-7.csv

If you see some fatal error that tells you that the 00000004 is not compatible with the latest checkpoint (or something like that – sorry, I don't have the log anymore), then you probably have the same problem like me.

Manual fix

Delete all objects belonging to timelines that are older than lower-numbered timelines. For example, if your S3 server has the mc alias my-s3, then you could run:

$ rm -r --force my-s3/cluster01-postgres-backups/spilo/gitlab-gitlab-db/wal/basebackups_005/base_00000004
$ rm -r --force my-s3/cluster01-postgres-backups/spilo/gitlab-gitlab-db/wal/wal_005/00000004

Root cause

The root cause seems to be that the S3 path cluster01-postgres-backups/spilo/gitlab-gitlab-db/wal/ does not contain the postgresql cluster uid. Therefore it can conflict between new and old variants of recreated postgresql clusters. I've read here that the S3 path should contain the uid:

The uid field is also mandatory. The operator will use it to find a correct key inside an S3 bucket.

Does somebody have an idea why that's not the case for me? I use the following pod_environment_configmap:

configMapGenerator:
  - name: pod-env
    literals:
      - CLONE_USE_WALG_BACKUP=true
      - CLONE_USE_WALG_RESTORE=true
      - CLONE_WAL_S3_BUCKET=cluster01-postgres-backups
      - CLONE_AWS_ENDPOINT=https://<redacted>.de
      - CLONE_AWS_REGION=minio
      - CLONE_AWS_S3_FORCE_PATH_STYLE=true
      - CLONE_AWS_ACCESS_KEY_ID=<redacted>
      - CLONE_AWS_SECRET_ACCESS_KEY=<redacted>
      - USE_WALG_BACKUP=true
      - USE_WALG_RESTORE=true
      - WAL_S3_BUCKET=cluster01-postgres-backups
      - AWS_ENDPOINT=https://<redacted>.de
      - AWS_REGION=minio
      - AWS_S3_FORCE_PATH_STYLE=true
      - AWS_ACCESS_KEY_ID=<redacted>
      - AWS_SECRET_ACCESS_KEY=<redacted>
      - WALG_COMPRESSION_METHOD=lzma

generatorOptions:
  disableNameSuffixHash: true

[bchrobot]

The objects of the timeline 00000004 were older than the objects of the timeline 00000001. Therefore, I assume that the 00000004 timeline was created by a previous postgresql cluster with the same namespace and name, that has since been recreated.

We encountered this issue after an in-place major version upgrade combined with an unexpected failover in line with #1163. This resulted in the replica-replica issue mentioned in #1460.

I am also wondering what the right way to handle UID in S3 backup path is. Our pod config looks like:

kind: ConfigMap
apiVersion: v1
metadata:
  name: postgres-pod-config
data:
  CLONE_WALG_S3_PREFIX: s3://backups.domain.com/spilo/$(CLONE_SCOPE)
  WALE_S3_PREFIX: s3://backups.domain.com/spilo/$(SCOPE)
  WALG_S3_PREFIX: s3://backups.domain.com/spilo/$(SCOPE)

[haslersn]

I since found out that, if you set wal_s3_bucket in the OperatorConfiguration and remove the _BUCKET variables from the Pod environment ConfigMap, then it will put the UID into the S3 path.

And I think the _PREFIX variables which you have there are not required. At least we don't have them set.

[bchrobot]

Hmm, interesting. We had a very difficult time getting archive and restore to work. Our pod config is based on Kenneth Rørvik's post -- the only fully worked example of backup and recovery using postgres-operator that we've been able to find.