Thread: Backup restore question "could not locate required checkpointrecord"
On a new apt-get install of postgresql 11, I performed the following:
backup (pg_start_backup ('b1'), rsync, pg_stop_backup)
CREATE DATABASE
CREATE TABLE
INSERT INTO TABLE
DROP TABLE
backup (pg_start_backup ('b1'), rsync, pg_stop_backup)
The point is to restore point in time, before DROP.
From the logs:
2019-03-08 10:02:17 EET,6/8,0,LOG,00000,"statement: DROP table test;",,,,,,,,,"pgAdmin 4 - CONN:821988"
So I write recovery.conf:
restore_command='cp /pg-data/xlog/%f %p'
recovery_target_time='2019-03-08 10:02:17 EET'
recovery_target_inclusive='false'
recovery_target_timeline=1
Server says:
postgres@postgre01-Virtual-Machine:/pg-data/pglogs$ cat postgresql-2019-03-08_103727..csv
cat: postgresql-2019-03-08_103727..csv: No such file or directory
postgres@postgre01-Virtual-Machine:/pg-data/pglogs$ cat postgresql-2019-03-08_103727.csv
2019-03-08 10:37:27.263 EET,,,39151,,5c8229c6.98ef,1,,2019-03-08 10:37:26 EET,,0,LOG,00000,"ending log output to stderr",,"Future log output will go to log destination ""csvlog"".",,,,,,,""
2019-03-08 10:37:27.349 EET,,,39153,,5c8229c7.98f1,1,,2019-03-08 10:37:27 EET,,0,LOG,00000,"database system was interrupted while in recovery at log time 2019-03-08 10:29:57 EET",,"If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.",,,,,,,""
2019-03-08 10:37:27.856 EET,,,39153,,5c8229c7.98f1,2,,2019-03-08 10:37:27 EET,,0,LOG,00000,"starting archive recovery",,,,,,,,,""
2019-03-08 10:37:27.858 EET,,,39153,,5c8229c7.98f1,3,,2019-03-08 10:37:27 EET,,0,LOG,00000,"invalid checkpoint record",,,,,,,,,""
2019-03-08 10:37:27.858 EET,,,39153,,5c8229c7.98f1,4,,2019-03-08 10:37:27 EET,,0,FATAL,XX000,"could not locate required checkpoint record",,"If you are not restoring from a backup, try removing the file ""/var/lib/postgresql/11/main/backup_label"".",,,,,,,""
2019-03-08 10:37:27.859 EET,,,39151,,5c8229c6.98ef,2,,2019-03-08 10:37:26 EET,,0,LOG,00000,"startup process (PID 39153) exited with exit code 1",,,,,,,,,""
2019-03-08 10:37:27.859 EET,,,39151,,5c8229c6.98ef,3,,2019-03-08 10:37:26 EET,,0,LOG,00000,"aborting startup due to startup process failure",,,,,,,,,""
2019-03-08 10:37:27.861 EET,,,39151,,5c8229c6.98ef,4,,2019-03-08 10:37:26 EET,,0,LOG,00000,"database system is shut down",,,,,,,,,""
However:
.backup file says:
START WAL LOCATION: 0/2000060 (file 000000010000000000000002)
STOP WAL LOCATION: 0/2000168 (file 000000010000000000000002)
CHECKPOINT LOCATION: 0/2000098
And human readable wal (pg_waldump) says:
rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn: 0/02000028, prev 0/0165AF10, desc: RUNNING_XACTS nextXid 569 latestCompletedXid 568 oldestRunningXid 569
rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn: 0/02000060, prev 0/02000028, desc: RUNNING_XACTS nextXid 569 latestCompletedXid 568 oldestRunningXid 569
rmgr: XLOG len (rec/tot): 106/ 106, tx: 0, lsn: 0/02000098, prev 0/02000060, desc: CHECKPOINT_ONLINE redo 0/2000060; tli 1; prev tli 1; fpw true; xid 0:569; oid 13129; multi 1; offset 0; oldest xid 561 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 569; online
rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn: 0/02000108, prev 0/02000098, desc: RUNNING_XACTS nextXid 569 latestCompletedXid 568 oldestRunningXid 569
rmgr: XLOG len (rec/tot): 34/ 34, tx: 0, lsn: 0/02000140, prev 0/02000108, desc: BACKUP_END 0/2000060
rmgr: XLOG len (rec/tot): 24/ 24, tx: 0, lsn: 0/02000168, prev 0/02000140, desc: SWITCH
Why is the checkpoint invalid?
Thank you for any information on the subject.
Regards,
A Farkas
A Farkas wrote:
> On a new apt-get install of postgresql 11, I performed the following:
> backup (pg_start_backup ('b1'), rsync, pg_stop_backup)
> CREATE DATABASE
> CREATE TABLE
> INSERT INTO TABLE
> DROP TABLE
> backup (pg_start_backup ('b1'), rsync, pg_stop_backup)
>
> The point is to restore point in time, before DROP.
> From the logs:
> 2019-03-08 10:02:17 EET,6/8,0,LOG,00000,"statement: DROP table test;",,,,,,,,,"pgAdmin 4 - CONN:821988"
>
> So I write recovery.conf:
> restore_command='cp /pg-data/xlog/%f %p'
> recovery_target_time='2019-03-08 10:02:17 EET'
> recovery_target_inclusive='false'
> recovery_target_timeline=1
>
> Server says:
> postgres@postgre01-Virtual-Machine:/pg-data/pglogs$ cat postgresql-2019-03-08_103727..csv
> cat: postgresql-2019-03-08_103727..csv: No such file or directory
> postgres@postgre01-Virtual-Machine:/pg-data/pglogs$ cat postgresql-2019-03-08_103727.csv
> 2019-03-08 10:37:27.263 EET,,,39151,,5c8229c6.98ef,1,,2019-03-08 10:37:26 EET,,0,LOG,00000,"ending log output to
stderr",,"Futurelog output will go to log destination ""csvlog"".",,,,,,,""
> 2019-03-08 10:37:27.349 EET,,,39153,,5c8229c7.98f1,1,,2019-03-08 10:37:27 EET,,0,LOG,00000,"database system was
interruptedwhile in recovery at log time 2019-03-08 10:29:57 EET",,"If this has occurred more than once some data might
becorrupted and you might need to choose an earlier recovery target.",,,,,,,""
> 2019-03-08 10:37:27.856 EET,,,39153,,5c8229c7.98f1,2,,2019-03-08 10:37:27 EET,,0,LOG,00000,"starting archive
recovery",,,,,,,,,""
> 2019-03-08 10:37:27.858 EET,,,39153,,5c8229c7.98f1,3,,2019-03-08 10:37:27 EET,,0,LOG,00000,"invalid checkpoint
record",,,,,,,,,""
> 2019-03-08 10:37:27.858 EET,,,39153,,5c8229c7.98f1,4,,2019-03-08 10:37:27 EET,,0,FATAL,XX000,"could not locate
requiredcheckpoint record",,"If you are not restoring from a backup, try removing the file
""/var/lib/postgresql/11/main/backup_label"".",,,,,,,""
> 2019-03-08 10:37:27.859 EET,,,39151,,5c8229c6.98ef,2,,2019-03-08 10:37:26 EET,,0,LOG,00000,"startup process (PID
39153)exited with exit code 1",,,,,,,,,""
> 2019-03-08 10:37:27.859 EET,,,39151,,5c8229c6.98ef,3,,2019-03-08 10:37:26 EET,,0,LOG,00000,"aborting startup due to
startupprocess failure",,,,,,,,,""
> 2019-03-08 10:37:27.861 EET,,,39151,,5c8229c6.98ef,4,,2019-03-08 10:37:26 EET,,0,LOG,00000,"database system is shut
down",,,,,,,,,""
That means that either you didn't put "recovery.conf" in the data directory,
or you got the name wrong.
The message "starting archive recovery" is not issued if a "recovery_target_time" is set.
In that case, the database would say "starting point-in-time recovery to ...".
Since your "recovery.conf" is not read, PostgreSQL also has no "restore_command", and
in its "pg_xlog" is cannot find the WAL segment that contains the checkpoint from the
backup. That's why you get the error message.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
Hi Farkas,
It seems your are missing the latest archive while performing the point in time and instead of recovery_target_timeline=1 in recovery.conf file you must have set recovery_target_timeline='latest' and hot_standby=on.
Enabling these parameters will help in to get the latest timeline from the archive.
On Fri, Mar 8, 2019 at 3:15 PM Laurenz Albe <laurenz.albe@cybertec.at> wrote:
A Farkas wrote:
> On a new apt-get install of postgresql 11, I performed the following:
> backup (pg_start_backup ('b1'), rsync, pg_stop_backup)
> CREATE DATABASE
> CREATE TABLE
> INSERT INTO TABLE
> DROP TABLE
> backup (pg_start_backup ('b1'), rsync, pg_stop_backup)
>
> The point is to restore point in time, before DROP.
> From the logs:
> 2019-03-08 10:02:17 EET,6/8,0,LOG,00000,"statement: DROP table test;",,,,,,,,,"pgAdmin 4 - CONN:821988"
>
> So I write recovery.conf:
> restore_command='cp /pg-data/xlog/%f %p'
> recovery_target_time='2019-03-08 10:02:17 EET'
> recovery_target_inclusive='false'
> recovery_target_timeline=1
>
> Server says:
> postgres@postgre01-Virtual-Machine:/pg-data/pglogs$ cat postgresql-2019-03-08_103727..csv
> cat: postgresql-2019-03-08_103727..csv: No such file or directory
> postgres@postgre01-Virtual-Machine:/pg-data/pglogs$ cat postgresql-2019-03-08_103727.csv
> 2019-03-08 10:37:27.263 EET,,,39151,,5c8229c6.98ef,1,,2019-03-08 10:37:26 EET,,0,LOG,00000,"ending log output to stderr",,"Future log output will go to log destination ""csvlog"".",,,,,,,""
> 2019-03-08 10:37:27.349 EET,,,39153,,5c8229c7.98f1,1,,2019-03-08 10:37:27 EET,,0,LOG,00000,"database system was interrupted while in recovery at log time 2019-03-08 10:29:57 EET",,"If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.",,,,,,,""
> 2019-03-08 10:37:27.856 EET,,,39153,,5c8229c7.98f1,2,,2019-03-08 10:37:27 EET,,0,LOG,00000,"starting archive recovery",,,,,,,,,""
> 2019-03-08 10:37:27.858 EET,,,39153,,5c8229c7.98f1,3,,2019-03-08 10:37:27 EET,,0,LOG,00000,"invalid checkpoint record",,,,,,,,,""
> 2019-03-08 10:37:27.858 EET,,,39153,,5c8229c7.98f1,4,,2019-03-08 10:37:27 EET,,0,FATAL,XX000,"could not locate required checkpoint record",,"If you are not restoring from a backup, try removing the file ""/var/lib/postgresql/11/main/backup_label"".",,,,,,,""
> 2019-03-08 10:37:27.859 EET,,,39151,,5c8229c6.98ef,2,,2019-03-08 10:37:26 EET,,0,LOG,00000,"startup process (PID 39153) exited with exit code 1",,,,,,,,,""
> 2019-03-08 10:37:27.859 EET,,,39151,,5c8229c6.98ef,3,,2019-03-08 10:37:26 EET,,0,LOG,00000,"aborting startup due to startup process failure",,,,,,,,,""
> 2019-03-08 10:37:27.861 EET,,,39151,,5c8229c6.98ef,4,,2019-03-08 10:37:26 EET,,0,LOG,00000,"database system is shut down",,,,,,,,,""
That means that either you didn't put "recovery.conf" in the data directory,
or you got the name wrong.
The message "starting archive recovery" is not issued if a "recovery_target_time" is set.
In that case, the database would say "starting point-in-time recovery to ...".
Since your "recovery.conf" is not read, PostgreSQL also has no "restore_command", and
in its "pg_xlog" is cannot find the WAL segment that contains the checkpoint from the
backup. That's why you get the error message.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com