zalando / zalando/postgres-operator
Clone error - Failed to bootstrap cluster. Could not locate required checkpoint record
Nobody has claimed this yet.
- Dominant language
- Go
- Stars
- 5.2k
- Forks
- 1.1k
- Avg merge
- 2d 16h
- Merged PRs (30d)
- 3
Description
I am trying to restore from an existing cluster and I get the error
Failed to bootstrap cluster.
When I check the logs in /pgdata/pgroot/pg_log folder I see the below error
FATAL,XX000,"could not locate required checkpoint record",,"If you are not restoring from a backup, try removing the file ""/home/postgres/pgdata/pgroot/data/backup_label"".",,,,,,,""
In kubernetes
spec:
...
postgresql:
version: "11"
clone:
uid: 22c208a2-3d7b-11ea-8305-42010a00000a
cluster: "alchemy-database"
timestamp: "2050-12-31T12:40:33+01:00"
I took a full backup from the existing cluster
$ wal-g backup-push /home/postgres/pgdata/pgroot/data
I can see backup in gcp bucket
$ wal-g backup-list
name last_modified wal_segment_backup_start
base_0000001C0000000000000072 2020-02-03T04:32:08Z 0000001C0000000000000072
Spilo image: registry.opensource.zalan.do/acid/spilo-cdp-12:1.6-p16
patroni version: patronictl version 1.6.3
wal-g version: v0.2.14
Logs from database server
2020-02-03 04:38:29,664 INFO: No PostgreSQL configuration items changed, nothing to reload.
2020-02-03 04:38:29,670 INFO: Lock owner: None; I am alchemy-database-0
2020-02-03 04:38:29,715 INFO: trying to bootstrap a new cluster
2020-02-03 04:38:29,716 INFO: Running custom bootstrap script: envdir "/home/postgres/etc/wal-e.d/env-clone-alchemy-database" python3 /scripts/clone_with_wale.py --recovery-target-time="2050-12-31T12:40:33+01:00"
2020-02-03 04:38:30,161 INFO: cloning cluster alchemy-database using wal-g backup-fetch /home/postgres/pgdata/pgroot/data base_0000001C0000000000000072
INFO: 2020/02/03 04:38:31.527411 Finished decompression of part_003.tar.lz4
INFO: 2020/02/03 04:38:31.527446 Finished extraction of part_003.tar.lz4
INFO: 2020/02/03 04:38:37.611955 Finished decompression of part_001.tar.lz4
INFO: 2020/02/03 04:38:37.611975 Finished extraction of part_001.tar.lz4
INFO: 2020/02/03 04:38:37.802375 Finished decompression of pg_control.tar.lz4
INFO: 2020/02/03 04:38:37.802391 Finished extraction of pg_control.tar.lz4
INFO: 2020/02/03 04:38:37.802398
Backup extraction complete.
2020-02-03 04:38:38,049 maybe_pg_upgrade INFO: No PostgreSQL configuration items changed, nothing to reload.
2020-02-03 04:38:38 UTC [932]: [1-1] 5e37a3ce.3a4 0 LOG: Auto detecting pg_stat_kcache.linux_hz parameter...
2020-02-03 04:38:38 UTC [932]: [2-1] 5e37a3ce.3a4 0 LOG: pg_stat_kcache.linux_hz is set to 500000
2020-02-03 04:38:38 UTC [932]: [3-1] 5e37a3ce.3a4 0 LOG: listening on IPv4 address "0.0.0.0", port 5432
2020-02-03 04:38:38 UTC [932]: [4-1] 5e37a3ce.3a4 0 LOG: listening on IPv6 address "::", port 5432
2020-02-03 04:38:38 UTC [932]: [5-1] 5e37a3ce.3a4 0 LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2020-02-03 04:38:38,471 INFO: postmaster pid=932
2020-02-03 04:38:38 UTC [932]: [6-1] 5e37a3ce.3a4 0 LOG: redirecting log output to logging collector process
2020-02-03 04:38:38 UTC [932]: [7-1] 5e37a3ce.3a4 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
2020-02-03 04:38:39,670 INFO: Lock owner: None; I am alchemy-database-0
2020-02-03 04:38:39,670 INFO: not healthy enough for leader race
2020-02-03 04:38:39,685 INFO: bootstrap in progress
/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
2020-02-03 04:38:44,611 INFO: removing initialize key after failed attempt to bootstrap the cluster
2020-02-03 04:38:44,626 INFO: renaming data directory to /home/postgres/pgdata/pgroot/data_2020-02-03-04-38-44
2020-02-03 04:38:44,684 INFO: Lock owner: None; I am alchemy-database-0
Traceback (most recent call last):
File "/usr/local/bin/patroni", line 11, in <module>
load_entry_point('patroni==1.6.3', 'console_scripts', 'patroni')()
File "/usr/local/lib/python3.6/dist-packages/patroni/__init__.py", line 221, in main
return patroni_main()
File "/usr/local/lib/python3.6/dist-packages/patroni/__init__.py", line 185, in patroni_main
patroni.run()
File "/usr/local/lib/python3.6/dist-packages/patroni/__init__.py", line 134, in run
logger.info(self.ha.run_cycle())
File "/usr/local/lib/python3.6/dist-packages/patroni/ha.py", line 1336, in run_cycle
info = self._run_cycle()
File "/usr/local/lib/python3.6/dist-packages/patroni/ha.py", line 1244, in _run_cycle
return self.post_bootstrap()
File "/usr/local/lib/python3.6/dist-packages/patroni/ha.py", line 1141, in post_bootstrap
self.cancel_initialization()
File "/usr/local/lib/python3.6/dist-packages/patroni/ha.py", line 1136, in cancel_initialization
raise PatroniException('Failed to bootstrap cluster')
patroni.exceptions.PatroniException: 'Failed to bootstrap cluster'
Postgres logs
```2020-02-03 04:41:08.525 UTC,,,2196,,5e37a464.894,2,,2020-02-03 04:41:08 UTC,,0,LOG,00000,"creating missing WAL directory ""pg_wal/archive_status""",,,,,,,,,""
2020-02-03 04:41:08.527 UTC,,,2198,"[local]",5e37a464.896,1,"",2020-02-03 04:41:08 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-02-03 04:41:08.527 UTC,"postgres","postgres",2198,"[local]",5e37a464.896,2,"",2020-02-03 04:41:08 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-02-03 04:41:08.544 UTC,,,2202,"[local]",5e37a464.89a,1,"",2020-02-03 04:41:08 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-02-03 04:41:08.544 UTC,"postgres","postgres",2202,"[local]",5e37a464.89a,2,"",2020-02-03 04:41:08 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-02-03 04:41:09.557 UTC,,,2224,"[local]",5e37a465.8b0,1,"",2020-02-03 04:41:09 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-02-03 04:41:09.557 UTC,"postgres","postgres",2224,"[local]",5e37a465.8b0,2,"",2020-02-03 04:41:09 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-02-03 04:41:10.389 UTC,,,2196,,5e37a464.894,3,,2020-02-03 04:41:08 UTC,,0,LOG,00000,"starting point-in-time recovery to 2050-12-31 11:40:33+00",,,,,,,,,""
2020-02-03 04:41:10.574 UTC,,,2244,"[local]",5e37a466.8c4,1,"",2020-02-03 04:41:10 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-02-03 04:41:10.574 UTC,"postgres","postgres",2244,"[local]",5e37a466.8c4,2,"",2020-02-03 04:41:10 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-02-03 04:41:11.587 UTC,,,2248,"[local]",5e37a467.8c8,1,"",2020-02-03 04:41:11 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-02-03 04:41:11.587 UTC,"postgres","postgres",2248,"[local]",5e37a467.8c8,2,"",2020-02-03 04:41:11 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-02-03 04:41:12.602 UTC,,,2270,"[local]",5e37a468.8de,1,"",2020-02-03 04:41:12 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-02-03 04:41:12.602 UTC,"postgres","postgres",2270,"[local]",5e37a468.8de,2,"",2020-02-03 04:41:12 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-02-03 04:41:13.622 UTC,,,2272,"[local]",5e37a469.8e0,1,"",2020-02-03 04:41:13 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-02-03 04:41:13.622 UTC,"postgres","postgres",2272,"[local]",5e37a469.8e0,2,"",2020-02-03 04:41:13 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-02-03 04:41:13.898 UTC,,,2196,,5e37a464.894,4,,2020-02-03 04:41:08 UTC,,0,LOG,00000,"invalid checkpoint record",,,,,,,,,""
2020-02-03 04:41:13.898 UTC,,,2196,,5e37a464.894,5,,2020-02-03 04:41:08 UTC,,0,FATAL,XX000,"could not locate required checkpoint record",,"If you are not restoring from a backup, try removing the file ""/home/postgres/pgdata/pgroot/data/backup_label"".",,,,,,,""
2020-02-03 04:41:13.902 UTC,,,2193,,5e37a464.891,2,,2020-02-03 04:41:08 UTC,,0,LOG,00000,"startup process (PID 2196) exited with exit code 1",,,,,,,,,""
2020-02-03 04:41:13.902 UTC,,,2193,,5e37a464.891,3,,2020-02-03 04:41:08 UTC,,0,LOG,00000,"aborting startup due to startup process failure",,,,,,,,,""
2020-02-03 04:41:13.904 UTC,,,2193,,5e37a464.891,4,,2020-02-03 04:41:08 UTC,,0,LOG,00000,"database system is shut down",,,,,,,,,""
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start with the clone_with_wale.py bootstrap entry point and the Patroni and PostgreSQL logs in this report; reproduce the Kubernetes clone using the shown wal-g backup and recovery target. Trace the failed checkpoint recovery and determine the repository change needed for the clone to bootstrap successfully, then verify the result with the relevant restore or bootstrap checks.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- kubernetes, postgresql, python
- Domain
- databases, infrastructure
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100