Subject: Re: PgbackRest PointTIme Recovery : server unable to start back

From: Muhammad Ikram <[email-masked]>
Date: Fri, 26 Jul 2024 10:15:15 +0500

Hi KK CHN

Could you check server logs ?
Your service trace suggests that it started server and then failure happened

ul 26 09:48:49 service01 systemd[1]: Started EDB Postgres Advanced Server
16.
Jul 26 09:48:50 service01 systemd[1]: edb-as-16.service: Main process
exited, code=exited, status=1/FAILURE

Regards,
Ikram

On Fri, Jul 26, 2024 at 10:04 AM KK CHN <[email-masked]> wrote:

> List,
>
> Reference: https://pgbackrest.org/user-guide-rhel.html#pitr
> I am following the   PTR  on RHEL9 EPAS16.
> I am able to do a  backup(Full, diff and incr)  and   restore from a full
> backup  and restart of EPAS16 works fine.
>
> But when I do an incremental backup  after doing the   procedures
> mentioned in the PTR section of the above  reference link and  try
> restoring the EDB database from the INCR backup   and then starting up the
> EPAS16 the server  always results in dead state
>
>  My repo server is another machine.  If  I do  a  full restore  on the DB
> server  ( sudo -u enterprisedb pgbackrest --stanza=Demo_Repo  --delta
> restore) it works  and the server starts without any issue.
> Restoring  from  Incremental backup tty output shows successful but edb
> service start  results in  failure.
>
> Any help is much appreciated.
>
> Krishane.
>
>
>
>
> STEPS followed:
>
> after dropping  the table  pg-primary *⇒* Drop the important table
> ([section]
> stopped the EDB server.
>
> $ sudo -u enterprisedb pgbackrest --stanza=Demo_Repo    --delta
> --set=20240719-122703F_20240724-094727I --target-timeline=current
> --type=time "--target=2024-07-24 09:44:01.3255+05:30"
> --target-action=promote  restore
> .....................................................
>
> 2024-07-26 09:48:06.343 P00   INFO: restore command end: completed
> successfully (1035ms)
>
>
> But
>
> [root@rservice01 ~]# sudo systemctl start edb-as-16.service
> [root@service01 ~]# sudo systemctl status edb-as-16.service
> × edb-as-16.service - EDB Postgres Advanced Server 16
>      Loaded: loaded (/etc/systemd/system/edb-as-16.service; disabled;
> preset: disabled)
>    *  Active: failed* (Result: exit-code) since Fri 2024-07-26 09:48:50
> IST; 8s ago
>    Duration: 242ms
>     Process: 41903 ExecStartPre=/usr/edb/as16/bin/edb-as-16-check-db-dir
> ${PGDATA} (code=exited, status=0/SUCCESS)
>     Process: 41908 ExecStart=/usr/edb/as16/bin/edb-postgres -D ${PGDATA}
> (code=exited, status=1/FAILURE)
>    Main PID: 41908 (code=exited, status=1/FAILURE)
>         CPU: 331ms
>
> Jul 26 09:48:48 service01 systemd[1]: Starting EDB Postgres Advanced
> Server 16...
> Jul 26 09:48:48 service01 edb-postgres[41908]: 2024-07-26 09:48:48 IST
> LOG:  redirecting log output to logging collector process
> Jul 26 09:48:48 service01 edb-postgres[41908]: 2024-07-26 09:48:48 IST
> HINT:  Future log output will appear in directory "log".
> Jul 26 09:48:49 service01 systemd[1]: Started EDB Postgres Advanced Server
> 16.
> Jul 26 09:48:50 service01 systemd[1]: edb-as-16.service: Main process
> exited, code=exited, status=1/FAILURE
> Jul 26 09:48:50 service01 systemd[1]: edb-as-16.service: Killing process
> 41909 (edb-postgres) with signal SIGKILL.
> Jul 26 09:48:50 service01 systemd[1]: edb-as-16.service: Failed with
> result 'exit-code'.
> [root@service01 ~]#
>
> why is it unable to perform a restore and recovery  from an incr  backup ?
>
>
>
>
>
>
>
> On The Repo Server
> [root@service02 ~]#  sudo -u postgres pgbackrest --stanza=Demo_Repo info
> stanza: Demo_Repo
>     status: ok
>     cipher: aes-256-cbc
>
>     db (current)
>         wal archive min/max (16):
> 000000020000000000000021/0000000B0000000000000041
>
>         full backup: 20240719-122703F
>             timestamp start/stop: 2024-07-19 12:27:03+05:30 / 2024-07-19
> 12:27:06+05:30
>             wal start/stop: 00000002000000000000002A /
> 00000002000000000000002A
>             database size: 61.7MB, database backup size: 61.7MB
>             repo1: backup size: 9.6MB
>
>         incr backup: 20240719-122703F_20240719-123353I
>             timestamp start/stop: 2024-07-19 12:33:53+05:30 / 2024-07-19
> 12:33:56+05:30
>             wal start/stop: 00000002000000000000002C /
> 00000002000000000000002C
>             database size: 61.7MB, database backup size: 6.4MB
>             repo1: backup size: 6.2KB
>             backup reference list: 20240719-122703F
>
>         diff backup: 20240719-122703F_20240719-123408D
>             timestamp start/stop: 2024-07-19 12:34:08+05:30 / 2024-07-19
> 12:34:10+05:30
>             wal start/stop: 00000002000000000000002E /
> 00000002000000000000002E
>             database size: 61.7MB, database backup size: 6.4MB
>             repo1: backup size: 6.4KB
>             backup reference list: 20240719-122703F
>
>         incr backup: 20240719-122703F_20240723-110212I
>             timestamp start/stop: 2024-07-23 11:02:12+05:30 / 2024-07-23
> 11:02:15+05:30
>             wal start/stop: 000000070000000000000038 /
> 000000070000000000000038
>             database size: 48MB, database backup size: 6.4MB
>             repo1: backup size: 9.8KB
>             backup reference list: 20240719-122703F,
> 20240719-122703F_20240719-123408D
>
>         incr backup: 20240719-122703F_20240723-141818I
>             timestamp start/stop: 2024-07-23 14:18:18+05:30 / 2024-07-23
> 14:18:22+05:30
>             wal start/stop: 00000008000000000000003C /
> 00000008000000000000003C
>             database size: 75.4MB, database backup size: 33.8MB
>             repo1: backup size: 4.7MB
>             backup reference list: 20240719-122703F,
> 20240719-122703F_20240719-123408D, 20240719-122703F_20240723-110212I
>
>         incr backup: 20240719-122703F_20240724-094727I
>             timestamp start/stop: 2024-07-24 09:47:27+05:30 / 2024-07-24
> 09:47:30+05:30
>             wal start/stop: 00000009000000000000003D /
> 00000009000000000000003D
>             database size: 62MB, database backup size: 11.5MB
>             repo1: backup size: 72KB
>             backup reference list: 20240719-122703F,
> 20240719-122703F_20240719-123408D, 20240719-122703F_20240723-110212I,
> 20240719-122703F_20240723-141818
>
>
>
>

-- 
Muhammad Ikram

---

From: KK CHN <[email-masked]>
Date: Fri, 26 Jul 2024 12:03:49 +0530

here the log outputs....

When I ran

$sudo -u enterprisedb pgbackrest --stanza=Demo_Repo  --delta
 --set=20240719-122703F_20240724-094727I --target-timeline=current
--type=time "--target=2024-07-24 09:44:01.3255+05:30"
--target-action=promote  restore

The Edb server  log out put shows
...........................................................................
................................................................
2024-07-23 15:34:12 IST ERROR:  syntax error at or near "selecct" at
character 1
2024-07-23 15:34:12 IST STATEMENT:  selecct current_timestamp
2024-07-23 15:34:26 IST FATAL:  database "enterprisedb" does not exist
2024-07-24 09:38:20 IST FATAL:  database "enterprisedb" does not exist
2024-07-24 09:42:17 IST FATAL:  database "test1" does not exist
2024-07-24 09:43:56 IST FATAL:  database "enterprisedb" does not exist
2024-07-24 09:45:07 IST FATAL:  database "enterprisedb" does not exist
2024-07-24 09:45:16 IST ERROR:  relation "important_table" does not exist
at character 58
2024-07-24 09:45:16 IST STATEMENT:  begin; drop table important_table;
commit; select * from important_table;
2024-07-24 09:46:00 IST LOG:  checkpoint starting: time
2024-07-24 09:46:02 IST LOG:  checkpoint complete: wrote 16 buffers (0.1%);
0 WAL file(s) added, 0 removed, 0 recycled; write=1.506 s, sync=0.001 s,
total=1.509 s; sync files=9, longest=0.001 s, average=0.001 s; distance=93
kB, estimate=171 kB; lsn=0/3C045768, redo lsn=0/3C045730
2024-07-24 09:47:27 IST LOG:  checkpoint starting: immediate force wait
2024-07-24 09:47:27 IST LOG:  checkpoint complete: wrote 2 buffers (0.0%);
0 WAL file(s) added, 0 removed, 1 recycled; write=0.001 s, sync=0.001 s,
total=0.003 s; sync files=1, longest=0.001 s, average=0.001 s;
distance=16106 kB, estimate=16106 kB; lsn=0/3D000060, redo lsn=0/3D000028
2024-07-24 09:47:27.788 P00   INFO: archive-push command begin 2.52.1:
[pg_wal/00000009000000000000003C] --exec-id=34036-c1d6de0b
--log-level-console=info --log-level-file=debug
--pg1-path=/var/lib/edb/as16/data --pg-version-force=16
--repo1-host=10.10.20.7 --repo1-host-user=postgres --stanza=Demo_Repo
2024-07-24 09:47:28.130 P00   INFO: pushed WAL file
'00000009000000000000003C' to the archive
2024-07-24 09:47:28.230 P00   INFO: archive-push command end: completed
successfully (444ms)

When  I ran       $ sudo systemctl start edb-as-16.service

4-07-26 11:32:56 IST LOG:  starting PostgreSQL 16.3 (EnterpriseDB Advanced
Server 16.3.0) on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1
20231218 (Red Hat 11.4.1-3), 64-bit
2024-07-26 11:32:56 IST LOG:  listening on IPv4 address "0.0.0.0", port 5444
2024-07-26 11:32:56 IST LOG:  listening on IPv6 address "::", port 5444
2024-07-26 11:32:56 IST LOG:  listening on Unix socket "/tmp/.s.PGSQL.5444"
2024-07-26 11:32:56 IST LOG:  database system was interrupted; last known
up at 2024-07-24 09:47:27 IST
2024-07-26 11:32:56 IST LOG:  starting point-in-time recovery to 2024-07-24
09:44:01.3255+05:30
2024-07-26 11:32:56 IST LOG:  starting backup recovery with redo LSN
0/3D000028, checkpoint LSN 0/3D000060, on timeline ID 9
2024-07-26 11:32:56.475 P00   INFO: archive-get command begin 2.52.1:
[00000009.history, pg_wal/RECOVERYHISTORY] --exec-id=43293-1d583a8e
--log-level-console=info --log-level-file=debug
--pg1-path=/var/lib/edb/as16/data --pg-version-force=16
--repo1-host=10.10.20.7 --repo1-host-user=postgres --stanza=Demo_Repo
2024-07-26 11:32:56.709 P00   INFO: found 00000009.history in the repo1:
16-1 archive
2024-07-26 11:32:56.809 P00   INFO: archive-get command end: completed
successfully (335ms)
2024-07-26 11:32:56 IST LOG:  restored log file "00000009.history" from
archive
2024-07-26 11:32:56.816 P00   INFO: archive-get command begin 2.52.1:
[00000009000000000000003D, pg_wal/RECOVERYXLOG] --exec-id=43295-55c5d6f7
--log-level-console=info --log-level-file=debug
--pg1-path=/var/lib/edb/as16/data --pg-version-force=16
--repo1-host=10.10.20.7 --repo1-host-user=postgres --stanza=Demo_Repo
2024-07-26 11:32:56.999 P00   INFO: found 00000009000000000000003D in the
repo1: 16-1 archive
2024-07-26 11:32:57.099 P00   INFO: archive-get command end: completed
successfully (285ms)
2024-07-26 11:32:57 IST LOG:  restored log file "00000009000000000000003D"
from archive
2024-07-26 11:32:57 IST LOG:  redo starts at 0/3D000028
2024-07-26 11:32:57.114 P00   INFO: archive-get command begin 2.52.1:
[00000009000000000000003E, pg_wal/RECOVERYXLOG] --exec-id=43297-34867c05
--log-level-console=info --log-level-file=debug
--pg1-path=/var/lib/edb/as16/data --pg-version-force=16
--repo1-host=10.10.20.7 --repo1-host-user=postgres --stanza=Demo_Repo
2024-07-26 11:32:57.282 P00   INFO: found 00000009000000000000003E in the
repo1: 16-1 archive
2024-07-26 11:32:57.382 P00   INFO: archive-get command end: completed
successfully (270ms)
2024-07-26 11:32:57 IST LOG:  restored log file "00000009000000000000003E"
from archive
2024-07-26 11:32:57.400 P00   INFO: archive-get command begin 2.52.1:
[00000009000000000000003F, pg_wal/RECOVERYXLOG] --exec-id=43299-e2db2e1b
--log-level-console=info --log-level-file=debug
--pg1-path=/var/lib/edb/as16/data --pg-version-force=16
--repo1-host=10.10.20.7 --repo1-host-user=postgres --stanza=Demo_Repo
2024-07-26 11:32:57.521 P00   INFO: unable to find 00000009000000000000003F
in the archive
2024-07-26 11:32:57.621 P00   INFO: archive-get command end: completed
successfully (222ms)
2024-07-26 11:32:57 IST LOG:  completed backup recovery with redo LSN
0/3D000028 and end LSN 0/3D000100
2024-07-26 11:32:57 IST LOG:  consistent recovery state reached at
0/3D000100
2024-07-26 11:32:57 IST LOG:  database system is ready to accept read-only
connections
2024-07-26 11:32:57.632 P00   INFO: archive-get command begin 2.52.1:
[00000009000000000000003F, pg_wal/RECOVERYXLOG] --exec-id=43301-f613dae9
--log-level-console=info --log-level-file=debug
--pg1-path=/var/lib/edb/as16/data --pg-version-force=16
--repo1-host=10.10.20.7 --repo1-host-user=postgres --stanza=Demo_Repo
2024-07-26 11:32:57.761 P00   INFO: unable to find 00000009000000000000003F
in the archive
2024-07-26 11:32:57.861 P00   INFO: archive-get command end: completed
successfully (231ms)
2024-07-26 11:32:57 IST LOG:  redo done at 0/3E000060 system usage: CPU:
user: 0.00 s, system: 0.00 s, elapsed: 0.75 s
2024-07-26 11:32:57 IST FATAL:  recovery ended before configured recovery
target was reached
2024-07-26 11:32:57 IST LOG:  startup process (PID 43292) exited with exit
code 1

ONLY inference  I can make is

  INFO  unable to find   00000009000000000000003F in the archive    ( This
means  the  EDB server  (10.10.20.6  ) unable to push the archives to the
 Repo server(10.10.20.7 ) ?    Is that the reason for the  recovery and
start backing of edb server fails ?

the pg_hba.conf   entry in the EDB Server machine is as

host    all             all             127.0.0.1/32            ident
host    all             all             10.10.20.7/32          scram-sha-256
#host    all             all              10.10.20.7/32          trust
# IPv6 local connections:
host    all             all             ::1/128                 ident
#host    all             all             10.10.20.7/24           trust

# Allow replication connections from localhost, by a user with the
# replication privilege.
local   replication     all                                     peer
host    replication     all             10.10.20.7/32
scram-sha-256
host    replication     all             127.0.0.1/32            ident
host    replication     all             ::1/128                 ident

Do I have to change anything in pg_hba.conf ?

my EDB Server conf as  this

archive_mode = on
archive_command = 'pgbackrest --stanza=Demo_Repo  archive-push %p'
log_filename = 'postgresql.log'
max_wal_senders = 5
wal_level = replica

Any help ?

Krishane

On Fri, Jul 26, 2024 at 10:45 AM Muhammad Ikram <[email-masked]> wrote:

>> Jul 26 09:48:49 service01 systemd[1]: Started EDB Postgres Advanced
>> Server 16.

---

From: Muhammad Ikram <[email-masked]>
Date: Fri, 26 Jul 2024 11:57:39 +0500

I don't think it has anything to do with the pg_hba.conf file. Archive
seems missing. I will suggest taking a full backup, as you have mentioned
that you are able to take full backup.

Regards,
Ikram

On Fri, Jul 26, 2024 at 11:24 AM KK CHN <[email-masked]> wrote:

> 2024-07-24 09:46:02 IST LOG:  checkpoint complete: wrote 16 buffers
> (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=1.506 s,
> sync=0.001 s, total=1.509 s; sync files=9, longest=0.001 s, average=0.001
> s; distance=93 kB, estimate=171 kB; lsn=0/3C045768, redo lsn=0/3C045730
> 2024-07-26 11:32:56 IST LOG:  starting point-in-time recovery to
> 2024-07-24 09:44:01.3255+05:30
> 2024-07-26 11:32:57.521 P00   INFO: unable to find
> 00000009000000000000003F in the archive
> 2024-07-26 11:32:57.761 P00   INFO: unable to find
> 00000009000000000000003F in the archive
>>> I am able to do a  backup(Full, diff and incr)  and   restore from a
>>> full backup  and restart of EPAS16 works fine.
>>>
>>>  My repo server is another machine.  If  I do  a  full restore  on the
>>> DB server  ( sudo -u enterprisedb pgbackrest --stanza=Demo_Repo  --delta

-- 
Muhammad Ikram