0

I use pgbackrest 2.43 for postgresql 14.6 database backup and restore, I got a strange issue for point-in-time recovery. Below are steps I followed to perform the test.

(1) First run a full database backup with pgbackrest.

pgbackrest --stanza=db1 --type=full backup

(2) Delete from area table and then drop table lockinfo

psql (14.6)
Type "help" for help.

DEMO=# select xmin,xmax, * from area;
 xmin | xmax | oid |   name   | osocidentification | controlled 
------+------+-----+----------+--------------------+------------
 1693 |    0 |  11 | Zddd     | Z                  |          1
 1693 |    0 |   1 | Weee     | W                  |          1
 1693 |    0 |   2 | Dddddd   | D                  |          1
 1693 |    0 |   3 | Tt       | C                  |          1
 1693 |    0 |   4 | Eeeeee   | E                  |          1
 1693 |    0 |   5 | Bbbbbbbb | B                  |          1
(6 rows)

DEMO=# select count(*) from lockinfo;
 count 
-------
     0
(1 row)

DEMO=# select current_timestamp;
       current_timestamp       
-------------------------------
 2023-04-20 10:35:54.700455+00
(1 row)

DEMO=# delete from area;
DELETE 6
DEMO=# drop table lockinfo;
DROP TABLE

(3) Run an incremental backup with pgbackrest

pgbackrest --stanza=db1 --type=incr backup

(4) Delete from lutype and then drop table batchrule

psql (14.6)
Type "help" for help.

DEMO=# select current_timestamp;
       current_timestamp       
-------------------------------
 2023-04-20 10:45:23.150276+00
(1 row)

DEMO=# delete from lutype;
DELETE 5
DEMO=# drop table batchrule;
DROP TABLE

(5) Restore to the point before deleting from lutype

pgbackrest --stanza=db1 --type=time --target="2023-04-20 10:45:23.150276+00" restore

psql (14.6)
Type "help" for help.

DEMO=# select xmin,xmax, * from area;
 xmin | xmax | oid |   name   | osocidentification | controlled 
------+------+-----+----------+--------------------+------------
 1693 | 1697 |   1 | Weee     | W                  |          1
 1693 | 1697 |   2 | Dddddd   | D                  |          1
 1693 | 1697 |   3 | Tt       | C                  |          1
 1693 | 1697 |   4 | Eeeeee   | E                  |          1
 1693 | 1697 |   5 | Bbbbbbbb | B                  |          1
(5 rows)

log messages from pgbackrest during restore time

2023-04-20 10:45:31.198 GMT [18] LOG:  listening on IPv6 address "::1", port 5432
2023-04-20 10:45:31.198 GMT [18] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2023-04-20 10:45:31.201 GMT [18] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-04-20 10:45:31.217 GMT [19] LOG:  database system was interrupted; last known up at 2023-04-20 10:44:47 GMT
2023-04-20 10:45:31.424 GMT [19] LOG:  starting point-in-time recovery to 2023-04-20 10:45:12+00
2023-04-20 10:45:31.498 GMT [19] LOG:  restored log file "00000015.history" from archive
2023-04-20 10:45:31.892 GMT [19] LOG:  restored log file "000000150000000000000026" from archive
2023-04-20 10:45:32.256 GMT [19] LOG:  redo starts at 0/26000028
2023-04-20 10:45:32.260 GMT [19] LOG:  consistent recovery state reached at 0/26000100
2023-04-20 10:45:32.260 GMT [18] LOG:  database system is ready to accept read-only connections
2023-04-20 10:45:32.381 GMT [19] LOG:  restored log file "000000150000000000000027" from archive
2023-04-20 10:45:32.637 GMT [19] LOG:  recovery stopping before commit of transaction 1672, time 2023-04-20 10:45:12.203849+00
2023-04-20 10:45:32.637 GMT [19] LOG:  redo done at 0/27017378 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.38 s
2023-04-20 10:45:32.637 GMT [19] LOG:  last completed transaction was at log time 2023-04-20 10:45:08.136524+00
2023-04-20 10:45:32.690 GMT [19] LOG:  selected new timeline ID: 22
2023-04-20 10:45:32.997 GMT [19] LOG:  archive recovery complete
2023-04-20 10:45:33.025 GMT [19] LOG:  restored log file "00000015.history" from archive
2023-04-20 10:45:33.093 GMT [18] LOG:  database system is ready to accept connections
2023-04-20 10:45:33.098 GMT [35] LOG:  archive command failed with exit code 1
2023-04-20 10:45:33.098 GMT [35] DETAIL:  The failed archive command was: false
2023-04-20 10:45:34.101 GMT [35] LOG:  archive command failed with exit code 1
2023-04-20 10:45:34.101 GMT [35] DETAIL:  The failed archive command was: false
2023-04-20 10:45:34.315 GMT [18] LOG:  received fast shutdown request
2023-04-20 10:45:34.318 GMT [18] LOG:  aborting any active transactions
2023-04-20 10:45:34.321 GMT [18] LOG:  background worker "logical replication launcher" (PID 36) exited with exit code 1
2023-04-20 10:45:34.321 GMT [23] LOG:  shutting down
2023-04-20 10:45:34.677 GMT [35] LOG:  archive command failed with exit code 1
2023-04-20 10:45:34.677 GMT [35] DETAIL:  The failed archive command was: false
2023-04-20 10:45:34.677 GMT [35] WARNING:  archiving write-ahead log file "00000016.history" failed too many times, will try again later
2023-04-20 10:45:34.682 GMT [35] LOG:  archive command failed with exit code 1
2023-04-20 10:45:34.682 GMT [35] DETAIL:  The failed archive command was: false
2023-04-20 10:45:35.685 GMT [35] LOG:  archive command failed with exit code 1
2023-04-20 10:45:35.685 GMT [35] DETAIL:  The failed archive command was: false
2023-04-20 10:45:36.689 GMT [35] LOG:  archive command failed with exit code 1
2023-04-20 10:45:36.689 GMT [35] DETAIL:  The failed archive command was: false
2023-04-20 10:45:36.689 GMT [35] WARNING:  archiving write-ahead log file "00000016.history" failed too many times, will try again later
2023-04-20 10:45:36.694 GMT [18] LOG:  database system is shut down

Log messages from postgres master

2023-04-20 10:43:59 UTC [921]: [13-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 9.971 ms  statement: set application_name = 'pgBackRest [backup]'
2023-04-20 10:43:59 UTC [921]: [14-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:43:59 UTC [921]: [15-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.045 ms  statement: set max_parallel_workers_per_gather = 0
2023-04-20 10:43:59 UTC [921]: [16-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:43:59 UTC [921]: [17-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.157 ms  statement: select pg_catalog.pg_is_in_recovery()
2023-04-20 10:43:59 UTC [921]: [18-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:00 UTC [921]: [19-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 1.372 ms  statement: select (extract(epoch from clock_timestamp()) * 1000)::bigint
2023-04-20 10:44:00 UTC [921]: [20-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:00 UTC [921]: [21-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.397 ms  statement: select pg_catalog.pg_try_advisory_lock(12340078987004321)::bool
2023-04-20 10:44:00 UTC [921]: [22-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:00 UTC [921]: [23-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.360 ms  statement: select pg_catalog.pg_walfile_name(pg_catalog.pg_current_wal_insert_lsn())::text
2023-04-20 10:44:00 UTC [921]: [24-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:00 UTC [88]: [5-1] user=,db=,app=,client= LOG:  00000: checkpoint starting: force wait
2023-04-20 10:44:00 UTC [88]: [6-1] user=,db=,app=,client= LOCATION:  LogCheckpointStart, xlog.c:8782
2023-04-20 10:44:00 UTC [88]: [7-1] user=,db=,app=,client= LOG:  00000: checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.001 s, total=0.036 s; sync files=0, longest=0.000 s, average=0.000 s; distance=14872 kB, estimate=14872 kB
2023-04-20 10:44:00 UTC [88]: [8-1] user=,db=,app=,client= LOCATION:  LogCheckpointEnd, xlog.c:8871
2023-04-20 10:44:00 UTC [921]: [25-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 327.337 ms  statement: select lsn::text as lsn,
               pg_catalog.pg_walfile_name(lsn)::text as wal_segment_name
          from pg_catalog.pg_start_backup('pgBackRest backup started at ' || current_timestamp, false, false) as lsn
2023-04-20 10:44:00 UTC [921]: [26-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:00 UTC [921]: [27-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.830 ms  statement: select oid::oid, datname::text, (select oid::oid from pg_catalog.pg_database where datname = 'template0') as datlastsysoid from pg_catalog.pg_database
2023-04-20 10:44:00 UTC [921]: [28-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:00 UTC [921]: [29-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.396 ms  statement: select oid::oid, spcname::text from pg_catalog.pg_tablespace
2023-04-20 10:44:00 UTC [921]: [30-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:01 UTC [921]: [31-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.171 ms  statement: select (extract(epoch from clock_timestamp()) * 1000)::bigint
2023-04-20 10:44:01 UTC [921]: [32-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:02 UTC [921]: [33-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.160 ms  statement: select (extract(epoch from clock_timestamp()) * 1000)::bigint
2023-04-20 10:44:02 UTC [921]: [34-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:02 UTC [921]: [35-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.075 ms  statement: select pg_catalog.pg_is_in_recovery()
2023-04-20 10:44:02 UTC [921]: [36-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:47:32 UTC [77]: [6-1] user=,db=,app=,client= LOG:  00000: starting PostgreSQL 14.6 on powerpc64le-unknown-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-4), 64-bit
2023-04-20 10:47:32 UTC [77]: [7-1] user=,db=,app=,client= LOCATION:  PostmasterMain, postmaster.c:1129
2023-04-20 10:47:32 UTC [77]: [8-1] user=,db=,app=,client= LOG:  00000: listening on IPv4 address "0.0.0.0", port 5432
2023-04-20 10:47:32 UTC [77]: [9-1] user=,db=,app=,client= LOCATION:  StreamServerPort, pqcomm.c:585
2023-04-20 10:47:32 UTC [77]: [10-1] user=,db=,app=,client= LOG:  00000: listening on IPv6 address "::", port 5432
2023-04-20 10:47:32 UTC [77]: [11-1] user=,db=,app=,client= LOCATION:  StreamServerPort, pqcomm.c:585
2023-04-20 10:47:32 UTC [77]: [12-1] user=,db=,app=,client= LOG:  00000: listening on Unix socket "/tmp/postgres/.s.PGSQL.5432"

Log message from postgres replica

2023-04-20 10:44:00 UTC [921]: [22-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:00 UTC [921]: [23-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.360 ms  statement: select pg_catalog.pg_walfile_name(pg_catalog.pg_current_wal_insert_lsn())::text
2023-04-20 10:44:00 UTC [921]: [24-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:00 UTC [88]: [5-1] user=,db=,app=,client= LOG:  00000: checkpoint starting: force wait
2023-04-20 10:44:00 UTC [88]: [6-1] user=,db=,app=,client= LOCATION:  LogCheckpointStart, xlog.c:8782
2023-04-20 10:44:00 UTC [88]: [7-1] user=,db=,app=,client= LOG:  00000: checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.001 s, total=0.036 s; sync files=0, longest=0.000 s, average=0.000 s; distance=14872 kB, estimate=14872 kB
2023-04-20 10:44:00 UTC [88]: [8-1] user=,db=,app=,client= LOCATION:  LogCheckpointEnd, xlog.c:8871
2023-04-20 10:44:00 UTC [921]: [25-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 327.337 ms  statement: select lsn::text as lsn,
               pg_catalog.pg_walfile_name(lsn)::text as wal_segment_name
          from pg_catalog.pg_start_backup('pgBackRest backup started at ' || current_timestamp, false, false) as lsn
2023-04-20 10:44:00 UTC [921]: [26-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:00 UTC [921]: [27-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.830 ms  statement: select oid::oid, datname::text, (select oid::oid from pg_catalog.pg_database where datname = 'template0') as datlastsysoid from pg_catalog.pg_database
2023-04-20 10:44:00 UTC [921]: [28-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:00 UTC [921]: [29-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.396 ms  statement: select oid::oid, spcname::text from pg_catalog.pg_tablespace
2023-04-20 10:44:00 UTC [921]: [30-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:01 UTC [921]: [31-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.171 ms  statement: select (extract(epoch from clock_timestamp()) * 1000)::bigint
2023-04-20 10:44:01 UTC [921]: [32-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:02 UTC [921]: [33-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.160 ms  statement: select (extract(epoch from clock_timestamp()) * 1000)::bigint
2023-04-20 10:44:02 UTC [921]: [34-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:44:02 UTC [921]: [35-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOG:  00000: duration: 0.075 ms  statement: select pg_catalog.pg_is_in_recovery()
2023-04-20 10:44:02 UTC [921]: [36-1] user=postgres,db=postgres,app=pgBackRest [backup],client=[local] LOCATION:  exec_simple_query, postgres.c:1306
2023-04-20 10:47:32 UTC [77]: [6-1] user=,db=,app=,client= LOG:  00000: starting PostgreSQL 14.6 on powerpc64le-unknown-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-4), 64-bit
2023-04-20 10:47:32 UTC [77]: [7-1] user=,db=,app=,client= LOCATION:  PostmasterMain, postmaster.c:1129
2023-04-20 10:47:32 UTC [77]: [8-1] user=,db=,app=,client= LOG:  00000: listening on IPv4 address "0.0.0.0", port 5432
2023-04-20 10:47:32 UTC [77]: [9-1] user=,db=,app=,client= LOCATION:  StreamServerPort, pqcomm.c:585
2023-04-20 10:47:32 UTC [77]: [10-1] user=,db=,app=,client= LOG:  00000: listening on IPv6 address "::", port 5432
2023-04-20 10:47:32 UTC [77]: [11-1] user=,db=,app=,client= LOCATION:  StreamServerPort, pqcomm.c:585
2023-04-20 10:47:32 UTC [77]: [12-1] user=,db=,app=,client= LOG:  00000: listening on Unix socket "/tmp/postgres/.s.PGSQL.5432"
2023-04-20 10:47:32 UTC [77]: [13-1] user=,db=,app=,client= LOCATION:  StreamServerPort, pqcomm.c:579
2023-04-20 10:47:32 UTC [80]: [1-1] user=,db=,app=,client= LOG:  00000: database system was shut down at 2023-04-20 10:47:15 UTC
2023-04-20 10:47:32 UTC [80]: [2-1] user=,db=,app=,client= LOCATION:  StartupXLOG, xlog.c:6538
2023-04-20 10:47:32 UTC [77]: [14-1] user=,db=,app=,client= LOG:  00000: database system is ready to accept connections
2023-04-20 10:47:32 UTC [77]: [15-1] user=,db=,app=,client= LOCATION:  reaper, postmaster.c:3067

The expected result: there is no data in table area after the restore.
Actual result: there are 5 rows in table area after the restore.
It does not happen always, may occur 2-3 times out of 10 times testing.

Eric
  • 11
  • 2
  • 1
    This question might receive better answers on https://dba.stackexchange.com/ – Fabián Heredia Montiel Apr 19 '23 at 04:27
  • Please add the PostgreSQL log file entries from the restore to the question. That will show what pgBackRest actually did. – Laurenz Albe Apr 19 '23 at 06:06
  • @LaurenzAlbe Thank you. After many times testing, I found an intesting thing: if I ignore the incremental backup step, there is no such issue. Do you know if pgbackrest has an option to restore database without using an incremental backup, I did some search and I did not find one. – Eric Apr 21 '23 at 05:42
  • @FabiánHerediaMontiel Thank you, I have posted the same question to dba.stackexchange.com – Eric Apr 21 '23 at 05:48
  • Thanks. The log you posted shows a different point in time from the beginning of your question. The log file looks as it should (except for the failing `archive_command`). I would have liked to verify that the time shown in the log is the same as the time you specified on the restore command line. I suspect something like a time zone confusion, because the restore should not work any differently if you have an incremental backup or not. – Laurenz Albe Apr 21 '23 at 05:57
  • @LaurenzAlbe Sorry, there is a confusion for the time in the logs, because I did not capture the logs in the first time testing, and the logs were got from another round's testign. – Eric Apr 24 '23 at 01:24
  • That is ok, but perhaps you could run it again and check if the timestamp you use for `pgbackrest restore` is the same timestamp that appears in the log. – Laurenz Albe Apr 24 '23 at 01:30

0 Answers0