restore backups are missing vital information

[KlavsKlavsen]

Using 1.8.2 with non-aws s3 for backup.

We tried to follow: https://postgres-operator.readthedocs.io/en/latest/user/#clone-directly
setting:

 apiVersion: acid.zalan.do/v1
 kind: postgresql
 metadata:
   name: mattermost-pgsql
 spec:
   env:
   - name: AWS_SECRET_ACCESS_KEY
     valueFrom:
       secretKeyRef:
         name: mattermost-pgsql-postgres-pod-env
         key: AWS_SECRET_ACCESS_KEY
   databases:
     mattermost: mattermost
   preparedDatabases:
     mattermost: {}
   enableMasterLoadBalancer: false
   numberOfInstances: 1
   postgresql:
     version: "12"
   teamId: mattermost
   users:
     mattermost:
     - superuser
   clone:
     cluster: "mattermost-pgsql"  # Inplace restore when having the same cluster name as the source
     timestamp: "2022-05-03T19:50:00+00:00"  # timezone required (offset relative to UTC, see RFC 3339 section 5.6)
   volume:
     size: 8Gi

But that fails with:
2023-01-30 10:51:02,543 - bootstrapping - WARNING - Cloning with WAL-E is only possible when CLONE_WALE_PREFIX or CLONE_WALGPREFIX or CLONE_WAL*_BUCKET and CLONE_SCOPE are set.
and does onthing

Turns out we NEED to also set some CLONE_WALG_.. settings (since postgres-operator uses walg for backups it seems ?)

[KlavsKlavsen]

We then tried to set these vars:

    - name: CLONE_USE_WALG_RESTORE
      value: "true"
    - name: CLONE_AWS_REGION
      value: eu-west-1
    - name: CLONE_AWS_ACCESS_KEY_ID
      value: kam
    - name: CLONE_AWS_SECRET_ACCESS_KEY
      value: ouraccesskey
    - name: CLONE_METHOD
      value: CLONE_WITH_WALG
    - name: CLONE_AWS_ENDPOINT
      value: https://s3.ourtld.com
    - name: CLONE_WAL_S3_BUCKET
      value: kam-postgres-backups
    - name: CLONE_WALG_BUCKET_SCOPE_SUFFIX
    - name: CLONE_TARGET_TIME
      value: "2023-01-29T10:04:06+00:00"
    - name: CLONE_SCOPE
      value: mattermost-pgsql

and now it actually tries to do restore but fails - restore being invalid:

2023-01-30 11:15:04,094 INFO: trying to bootstrap a new cluster
2023-01-30 11:15:04,094 INFO: Running custom bootstrap script: envdir "/run/etc/wal-e.d/env-clone-mattermost-pgsql" python3 /scripts/clone_with_wale.py --recovery-target-time="2023-01-29T10:04:06+00:00"
2023-01-30 11:15:04,219 INFO: Trying s3://kam-postgres-backups/spilo/mattermost-pgsql/wal/12/ for clone
2023-01-30 11:15:04,330 INFO: cloning cluster mattermost-pgsql using wal-g backup-fetch /home/postgres/pgdata/pgroot/data base_0000000200000006000000BC
INFO: 2023/01/30 11:15:04.348509 Selecting the backup with name base_0000000200000006000000BC...
INFO: 2023/01/30 11:15:04.554974 AO files metadata was not found. Skipping the AO segments unpacking.
INFO: 2023/01/30 11:15:04.769153 Finished extraction of part_005.tar.lz4
2023-01-30 11:15:14,436 INFO: Lock owner: None; I am mattermost-pgsql-0
2023-01-30 11:15:14,436 INFO: not healthy enough for leader race
2023-01-30 11:15:14,505 INFO: bootstrap in progress
..
INFO: 2023/01/30 11:18:16.896199 Finished extraction of part_001.tar.lz4
INFO: 2023/01/30 11:18:17.053015 Finished extraction of pg_control.tar.lz4
INFO: 2023/01/30 11:18:17.053056 
Backup extraction complete.
2023-01-30 11:18:17,366 maybe_pg_upgrade INFO: No PostgreSQL configuration items changed, nothing to reload.
2023-01-30 11:18:17,377 maybe_pg_upgrade INFO: Cluster version: 12, bin version: 12
2023-01-30 11:18:17,377 maybe_pg_upgrade INFO: Trying to perform point-in-time recovery
2023-01-30 11:18:17,378 maybe_pg_upgrade INFO: Running custom bootstrap script: true
2023-01-30 11:18:17,607 maybe_pg_upgrade INFO: postmaster pid=165
/var/run/postgresql:5432 - no response
2023-01-30 11:18:17 UTC [165]: [1-1] 63d7a779.a5 0     LOG:  Auto detecting pg_stat_kcache.linux_hz parameter...
2023-01-30 11:18:17 UTC [165]: [2-1] 63d7a779.a5 0     LOG:  pg_stat_kcache.linux_hz is set to 1000000
2023-01-30 11:18:17 UTC [165]: [3-1] 63d7a779.a5 0     LOG:  starting PostgreSQL 12.11 (Ubuntu 12.11-1.pgdg18.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 7.5.0-3ubuntu1~18.04) 7.5.0, 64-bit
2023-01-30 11:18:17 UTC [165]: [4-1] 63d7a779.a5 0     LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-01-30 11:18:17 UTC [165]: [5-1] 63d7a779.a5 0     LOG:  listening on IPv6 address "::", port 5432
2023-01-30 11:18:17 UTC [165]: [6-1] 63d7a779.a5 0     LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-01-30 11:18:17 UTC [165]: [7-1] 63d7a779.a5 0     LOG:  redirecting log output to logging collector process
2023-01-30 11:18:17 UTC [165]: [8-1] 63d7a779.a5 0     HINT:  Future log output will appear in directory "../pg_log".
/var/run/postgresql:5432 - rejecting connections
/var/run/postgresql:5432 - rejecting connections
/var/run/postgresql:5432 - rejecting connections
/var/run/postgresql:5432 - rejecting connections
/var/run/postgresql:5432 - no response
Traceback (most recent call last):
  File "/scripts/maybe_pg_upgrade.py", line 51, in perform_pitr
    raise Exception('Point-in-time recovery failed')
Exception: Point-in-time recovery failed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/scripts/maybe_pg_upgrade.py", line 140, in <module>
    main()
  File "/scripts/maybe_pg_upgrade.py", line 87, in main
    perform_pitr(upgrade, cluster_version, bin_version, config['bootstrap'])
  File "/scripts/maybe_pg_upgrade.py", line 70, in perform_pitr
    raise Exception('Point-in-time recovery failed.\nLOGS:\n--\n' + logs)
Exception: Point-in-time recovery failed.
LOGS:
--
2023-01-30 11:18:20.654 UTC,"postgres","postgres",332,"[local]",63d7a77c.14c,2,"",2023-01-30 11:18:20 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2023-01-30 11:18:20.994 UTC,,,168,,63d7a77a.a8,8,,2023-01-30 11:18:18 UTC,,0,FATAL,XX000,"requested timeline 4 is not a child of this server's history","Latest checkpoint is at 6/BC000098 on timeline 2, but in the history of the requested timeline, the server forked off from that timeline at 0/50000A0.",,,,,,,,""
2023-01-30 11:18:20.995 UTC,,,165,,63d7a779.a5,2,,2023-01-30 11:18:17 UTC,,0,LOG,00000,"startup process (PID 168) exited with exit code 1",,,,,,,,,""
2023-01-30 11:18:20.995 UTC,,,165,,63d7a779.a5,3,,2023-01-30 11:18:17 UTC,,0,LOG,00000,"aborting startup due to startup process failure",,,,,,,,,""
2023-01-30 11:18:20.996 UTC,,,165,,63d7a779.a5,4,,2023-01-30 11:18:17 UTC,,0,LOG,00000,"database system is shut down",,,,,,,,,""

2023-01-30 11:18:21,684 ERROR: /scripts/maybe_pg_upgrade.py script failed
2023-01-30 11:18:21,693 INFO: removing initialize key after failed attempt to bootstrap the cluster
2023-01-30 11:18:21,761 INFO: renaming data directory to /home/postgres/pgdata/pgroot/data_2023-01-30-11-18-21
Traceback (most recent call last):
  File "/usr/local/bin/patroni", line 11, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.6/dist-packages/patroni/__main__.py", line 143, in main
    return patroni_main()
  File "/usr/local/lib/python3.6/dist-packages/patroni/__main__.py", line 135, in patroni_main
    abstract_main(Patroni, schema)
  File "/usr/local/lib/python3.6/dist-packages/patroni/daemon.py", line 100, in abstract_main
    controller.run()
  File "/usr/local/lib/python3.6/dist-packages/patroni/__main__.py", line 105, in run
    super(Patroni, self).run()
  File "/usr/local/lib/python3.6/dist-packages/patroni/daemon.py", line 59, in run
    self._run_cycle()
  File "/usr/local/lib/python3.6/dist-packages/patroni/__main__.py", line 108, in _run_cycle
    logger.info(self.ha.run_cycle())
  File "/usr/local/lib/python3.6/dist-packages/patroni/ha.py", line 1514, in run_cycle
    info = self._run_cycle()
  File "/usr/local/lib/python3.6/dist-packages/patroni/ha.py", line 1388, in _run_cycle
    return self.post_bootstrap()
  File "/usr/local/lib/python3.6/dist-packages/patroni/ha.py", line 1280, in post_bootstrap
    self.cancel_initialization()
  File "/usr/local/lib/python3.6/dist-packages/patroni/ha.py", line 1273, in cancel_initialization
    raise PatroniFatalException('Failed to bootstrap cluster')
patroni.exceptions.PatroniFatalException: 'Failed to bootstrap cluster'
/etc/runit/runsvdir/default/patroni: finished with code=1 signal=0
/etc/runit/runsvdir/default/patroni: sleeping 30 seconds
q2023-01-30 11:18:52,109 WARNING: Kubernetes RBAC doesn't allow GET access to the 'kubernetes' endpoint in the 'default' namespace. Disabling 'bypass_api_service'.
2023-01-30 11:18:52,132 INFO: No PostgreSQL configuration items changed, nothing to reload.
2023-01-30 11:18:52,134 INFO: Lock owner: None; I am mattermost-pgsql-0
2023-01-30 11:18:52,160 INFO: trying to bootstrap a new cluster
2023-01-30 11:18:52,161 INFO: Running custom bootstrap script: envdir "/run/etc/wal-e.d/env-clone-mattermost-pgsql" python3 /scripts/clone_with_wale.py --recovery-target-time="2023-01-29T10:04:06+00:00"
2023-01-30 11:18:52,206 INFO: Trying s3://kam-postgres-backups/spilo/mattermost-pgsql/wal/12/ for clone
2023-01-30 11:18:52,336 INFO: cloning cluster mattermost-pgsql using wal-g backup-fetch /home/postgres/pgdata/pgroot/data base_0000000200000006000000BC
INFO: 2023/01/30 11:18:52.354880 Selecting the backup with name base_0000000200000006000000BC...
INFO: 2023/01/30 11:18:52.466086 AO files metadata was not found. Skipping the AO segments unpacking.
INFO: 2023/01/30 11:18:52.721222 Finished extraction of part_005.tar.lz4

and pg log says:

2023-01-30 11:18:20.654 UTC,"postgres","postgres",332,"[local]",63d7a77c.14c,2,"",2023-01-30 11:18:20 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2023-01-30 11:18:20.994 UTC,,,168,,63d7a77a.a8,8,,2023-01-30 11:18:18 UTC,,0,FATAL,XX000,"requested timeline 4 is not a child of this server's history","Latest checkpoint is at 6/BC000098 on timeline 2, but in the history of the requested timeline, the server forked off from that timeline at 0/50000A0.",,,,,,,,""
2023-01-30 11:18:20.995 UTC,,,165,,63d7a779.a5,2,,2023-01-30 11:18:17 UTC,,0,LOG,00000,"startup process (PID 168) exited with exit code 1",,,,,,,,,""

[KlavsKlavsen]

It seems it may be picking the latest backup (even though we set timestamp to previously) - and was broken "somehow" by operator/patroni :(
Before this we had 2 instances and (-0 was not starting - and -1 was working)

[KlavsKlavsen]

We have basebackups_005 and wal_005 in s3.. but above is what we get - even if we try to point to older backup (back to 29th).. we also tried removing any backupfolders in basebackups_005 from 29th+ - but still same error.

[KlavsKlavsen]

we did not remove wal_005 files from the 29th/30th - so they may be spooled on top and causing the problem ?

[KlavsKlavsen]

It turned out we had some corrupt data - and no matter what timestamp we tried to set - it ended up with exact same above error.. BY deleting the failed backups and walgf iles (back to the 28th included) - restore worked.
So docs really should show the settings above CLONE_* and clearly a LogicalBackup is VERY important - for WALG corruption or whatever this exactly was :(
and the timestamnp thing does not work (it should?) - so either:

1. timestamp given was deemed invalid - so it just took latest.. it SHOULD have then complained about invalid timestamp and not silently choose latest
2. or it just will always fail if there is defunct data ?

[KlavsKlavsen]

Turns out the walg backup that worked - was partial.. How can that ever happen? so some data was there - but not enough for mattermost to work with it - so it got us no where :(
Any tips on how to restore a complete dump from default WALG backups - or anymore info I can provide?
This all started due to #2190 and POOF - appearently data and backups magicly corrupted :(

[KillJohn]

We have the same issue as described above. We try to clone db from blob storage. Firstly we clone db from 10th of july and it suceed but we are not able to restore any other wal backups after that time. Of course we cleaned up everything after first restore.

[KillJohn]

@KlavsKlavsen Did you find solution for this problem?

[KlavsKlavsen]

@KillJohn we ended up copying the PV data to local.. doing some modifications to remove the "patroni addons" - I don't remember right now - and then we could startup local PG - and read data.. And now we've moved to cloudnativepg - as it actually works with master/slave setup and failover.. and we've also enabled logicalbackups (to have good old pgumps) - so we have an alternative restore method, if WALG fails us again.
pg gives tips on what its "mad about" - when you try to start it from the PV data - and then you just remove the tables etc. until it starts :)

[KillJohn]

will try that. Thank you @KlavsKlavsen :)