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

[Ron <ronljohnsonjr@xxxxxxxxx>]

    "26.3.3.2. Making An Exclusive Low-Level Backup

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.

On 8/8/23 02:39, Meera Nair wrote:

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

 

--
Born in Arizona, moved to Babylonia.