Skip to content

"pg_probackup-15 archive-get" ignores archived wals while recovering to latest state  #621

@gsl23

Description

@gsl23

Hi guys ! I'm testing wal archive recovery and cant to understand why archive-get just lose some last wals :

postgresql.auto.conf:

 Do not edit this file manually!
# It will be overwritten by the ALTER SYSTEM command.

# recovery settings added by pg_probackup restore of backup SE7QA1 at '2024-05-29 15:19:25+05'
## recovery settings
recovery_target_timeline = 'current'
recovery_target_action = 'pause'
restore_command = '"/usr/bin/pg_probackup-15" archive-get -B "/backup/postgres" --instance "pgw-db-p02" --wal-file-path=%p --wal-file-name=%f  --remote-host=bkp_host'

wals in pg_probackup archive :

-rw-------. 1 postgres postgres    95587 May 29 10:41 0000000A0000000000000031.gz
-rw-------. 1 postgres postgres    95648 May 29 11:11 0000000A0000000000000032.gz
-rw-------. 1 postgres postgres    96702 May 29 11:42 0000000A0000000000000033.gz
-rw-------. 1 postgres postgres   106265 May 29 12:12 0000000A0000000000000034.gz
-rw-------. 1 postgres postgres    95951 May 29 12:41 0000000A0000000000000035.gz
-rw-------. 1 postgres postgres    79297 May 29 12:44 0000000A0000000000000036.gz
-rw-------. 1 postgres postgres 16777216 May 29 12:44 0000000A0000000000000037.partial
-rw-------. 1 postgres postgres      378 May 28 19:11 0000000A.history
-rw-------. 1 postgres postgres   128597 May 29 13:14 0000000B0000000000000037.gz
-rw-------. 1 postgres postgres    79741 May 29 13:18 0000000B0000000000000038.gz
-rw-------. 1 postgres postgres    83013 May 29 13:25 0000000B0000000000000039.gz
-rw-------. 1 postgres postgres    98973 May 29 13:55 0000000B000000000000003A.gz
-rw-------. 1 postgres postgres   100455 May 29 14:25 0000000B000000000000003B.gz
-rw-------. 1 postgres postgres   101462 May 29 14:55 0000000B000000000000003C.gz
-rw-------. 1 postgres postgres   117154 May 29 15:25 0000000B000000000000003D.gz
-rw-------. 1 postgres postgres      422 May 29 12:44 0000000B.history

postgresql.log while recovery :

2024-05-29 15:24:58 +05 [400240]: [1-1]: INFO: pg_probackup archive-get WAL file: 0000000A0000000000000037, remote: ssh, threads: 1/1, batch: 1
2024-05-29 15:24:59 +05 [400240]: [1-1]: INFO: pg_probackup archive-get completed successfully, fetched: 1/1, time elapsed: 145ms
2024-05-29 15:24:59.040 +05 [400156] LOG:  restored log file "0000000A0000000000000037" from archive
2024-05-29 15:24:59.052 +05 [400156] LOG:  invalid resource manager ID 114 at 0/370000A0
2024-05-29 15:24:59.052 +05 [400156] LOG:  redo done at 0/37000028 system usage: CPU: user: 0.02 s, system: 0.17 s, elapsed: 5.91 s
2024-05-29 15:24:59.052 +05 [400156] LOG:  last completed transaction was at log time 2024-05-29 12:44:00.017459+05
2024-05-29 15:24:59 +05 [400247]: [1-1]: INFO: pg_probackup archive-get WAL file: 0000000A0000000000000037, remote: ssh, threads: 1/1, batch: 1
2024-05-29 15:24:59 +05 [400247]: [1-1]: INFO: pg_probackup archive-get completed successfully, fetched: 1/1, time elapsed: 140ms
2024-05-29 15:24:59.199 +05 [400156] LOG:  restored log file "0000000A0000000000000037" from archive
2024-05-29 15:24:59 +05 [400249]: [1-1]: INFO: pg_probackup archive-get WAL file: 0000000B.history, remote: ssh, threads: 1/1, batch: 1
2024-05-29 15:24:59 +05 [400249]: [1-1]: INFO: pg_probackup archive-get completed successfully, fetched: 1/1, time elapsed: 144ms
2024-05-29 15:24:59.369 +05 [400156] LOG:  restored log file "0000000B.history" from archive
2024-05-29 15:24:59 +05 [400251]: [1-1]: INFO: pg_probackup archive-get WAL file: 0000000C.history, remote: ssh, threads: 1/1, batch: 1
2024-05-29 15:24:59 +05 [400251]: [1-1]: ERROR: pg_probackup archive-get failed to deliver WAL file: 0000000C.history, time elapsed: 186ms
2024-05-29 15:24:59.566 +05 [400156] LOG:  selected new timeline ID: 12
2024-05-29 15:24:59 +05 [400254]: [1-1]: INFO: pg_probackup archive-get WAL file: 0000000A.history, remote: ssh, threads: 1/1, batch: 1
2024-05-29 15:24:59 +05 [400254]: [1-1]: INFO: pg_probackup archive-get completed successfully, fetched: 1/1, time elapsed: 139ms
2024-05-29 15:24:59.784 +05 [400156] LOG:  restored log file "0000000A.history" from archive
2024-05-29 15:24:59.793 +05 [400156] LOG:  archive recovery complete

Why it is ended on 0000000A0000000000000037 last completed transaction was at log time 2024-05-29 12:44:00.017459+05 ??
Where is
-rw-------. 1 postgres postgres 79741 May 29 13:18 0000000B0000000000000038.gz
-rw-------. 1 postgres postgres 83013 May 29 13:25 0000000B0000000000000039.gz
etc.... ???

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions