Re: PostgreSQL 14.8 - server fails to start even though all transaction logs with base backup are restored

Note

The exclusive backup method is deprecated and should be avoided. Prior to PostgreSQL 9.6, this was the only low-level method available, but it is now recommended that all users upgrade their scripts to use non-exclusive backups."
Use PgBackRest, instead.

@font-face {font-family:"Cambria Math"; panose-1:2 4 5 3 5 4 6 3 2 4;}@font-face {font-family:Calibri; panose-1:2 15 5 2 2 2 4 3 2 4;}@font-face {font-family:Consolas; panose-1:2 11 6 9 2 2 4 3 2 4;}p.MsoNormal, li.MsoNormal, div.MsoNormal {margin:0in; font-size:11.0pt; font-family:"Calibri",sans-serif;}a:link, span.MsoHyperlink {mso-style-priority:99; color:#0563C1; text-decoration:underline;}span.EmailStyle19 {mso-style-type:personal-compose; font-family:"Calibri",sans-serif; color:windowtext;}.MsoChpDefault {mso-style-type:export-only; font-size:10.0pt; font-family:"Calibri",sans-serif; mso-ligatures:none;}div.WordSection1 {page:WordSection1;}

Hi Team,

 

We are following https://www.postgresql.org/docs/14/continuous-archiving.html#BACKUP-LOWLEVEL-BASE-BACKUP

Making An Exclusive Low-Level Backup.

 

After restoring, we see the server fails to start with below error:

 

PostgreSQL server log:

2023-08-04 16:47:47.227 IST [40582] LOG:  starting PostgreSQL 14.8 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit

2023-08-04 16:47:47.228 IST [40582] LOG:  listening on IPv4 address "0.0.0.0", port 5414

2023-08-04 16:47:47.228 IST [40582] LOG:  listening on IPv6 address "::", port 5414

2023-08-04 16:47:47.231 IST [40582] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5414"

2023-08-04 16:47:47.236 IST [40582] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5414"

2023-08-04 16:47:47.243 IST [40584] LOG:  database system was interrupted; last known up at 2023-08-04 14:48:29 IST

2023-08-04 16:47:49.254 IST [40584] LOG:  starting archive recovery

cp: cannot stat ‘/var/lib/pgsql/14/wal/00000004.history’: No such file or directory

2023-08-04 16:47:49.275 IST [40584] LOG:  restored log file "000000040000000200000041" from archive

2023-08-04 16:47:49.290 IST [40584] LOG:  redo starts at 2/41000028

2023-08-04 16:47:49.310 IST [40584] LOG:  restored log file "000000040000000200000042" from archive

2023-08-04 16:47:49.344 IST [40584] LOG:  restored log file "000000040000000200000043" from archive

2023-08-04 16:47:49.368 IST [40584] LOG:  restored log file "000000040000000200000044" from archive

2023-08-04 16:47:49.395 IST [40584] LOG:  restored log file "000000040000000200000045" from archive

2023-08-04 16:47:49.423 IST [40584] LOG:  restored log file "000000040000000200000046" from archive

2023-08-04 16:47:49.460 IST [40584] LOG:  restored log file "000000040000000200000047" from archive

2023-08-04 16:47:50.649 IST [40584] LOG:  restored log file "000000040000000200000048" from archive

2023-08-04 16:47:51.219 IST [40584] LOG:  restored log file "000000040000000200000049" from archive

cp: cannot stat ‘/var/lib/pgsql/14/wal/00000004000000020000004A’: No such file or directory

2023-08-04 16:47:51.603 IST [40584] LOG:  redo done at 2/49013500 system usage: CPU: user: 0.00 s, system: 0.19 s, elapsed: 2.31 s

2023-08-04 16:47:51.603 IST [40584] LOG:  last completed transaction was at log time 2023-08-04 14:58:51.021414+05:30

2023-08-04 16:47:51.628 IST [40584] LOG:  restored log file "000000040000000200000049" from archive

2023-08-04 16:47:51.973 IST [40584] FATAL:  WAL ends before end of online backup

2023-08-04 16:47:51.973 IST [40584] HINT:  Online backup started with pg_start_backup() must be ended with pg_stop_backup(), and all WAL up to that point must be available at recovery.

2023-08-04 16:47:51.975 IST [40582] LOG:  startup process (PID 40584) exited with exit code 1

2023-08-04 16:47:51.975 IST [40582] LOG:  terminating any other active server processes

2023-08-04 16:47:51.975 IST [40582] LOG:  shutting down due to startup process failure

2023-08-04 16:47:51.977 IST [40582] LOG:  database system is shut down

 

 

Backup_label from data directory:

 

[root@gkstandby2 data]# cat backup_label

START WAL LOCATION: 2/41000028 (file 000000040000000200000041)

CHECKPOINT LOCATION: 2/41000060

BACKUP METHOD: pg_start_backup

BACKUP FROM: primary

START TIME: 2023-08-04 14:48:29 IST

LABEL: pgida_backup_5414_108625_1691140709

START TIMELINE: 4

[root@gkstandby2 data]#

 

 

Archive log directory:

 

[root@gkstandby2 wal]# ls

00000002000000020000003B                  00000002000000020000003E.00000028.backup  000000040000000200000040.00000028.backup  000000040000000200000044                  000000040000000200000048

00000002000000020000003C                  00000002.history                          000000040000000200000041                  000000040000000200000045                  000000040000000200000049

00000002000000020000003C.00000028.backup  0000000300000005000000E4                  000000040000000200000042                  000000040000000200000045.00005AE0.backup 

00000002000000020000003D                  00000004000000020000003F                  000000040000000200000043                  000000040000000200000046

00000002000000020000003E                  000000040000000200000040                  000000040000000200000043.00000028.backup  000000040000000200000047

 

 

[root@gkstandby2 wal]# /usr/pgsql-14/bin/pg_waldump 000000040000000200000046 | grep BACKUP

rmgr: XLOG        len (rec/tot):     34/    34, tx:          0, lsn: 2/46000110, prev 2/46000098, desc: BACKUP_END 2/45005AE0

[root@gkstandby2 wal]#

 

 

We are restoring all the transaction logs required for base backup to be consistent.

BACKUP_END is present in the 000000040000000200000046 segment. Why did recovery fail to find this?

 

 

Regards,

Meera