Hello.
We had PostgreSQL v11 and used PITR with our database.
But PITR behavior was changed in v13
>https://www.postgresql.org/docs/release/13.0/
>Generate an error if recovery does not reach the specified recovery target (Leif Gunnar Erlandsen, Peter Eisentraut)
>Previously, a standby would promote itself upon reaching the end of WAL, even if the target was not reached.
I tried to change our scripts to include the time where base backup is
started (also I tried the time when the base backup was finished).
But all my recoveries failed with: `XX000: recovery ended before
configured recovery target was reached`
So we decided to use `recovery_target_name` instead of
`recovery_target_time`. But this attempt also failed with the error
above.
Backup procedure looks like this:
1. Insert data
2. t3=$(date +"%Y-%m-%d %T")
3. psql -c "select pg_create_restore_point( '$t3' )"
4. wal-g backup-push $PGDATA. This tool lever low level API
https://www.postgresql.org/docs/current/continuous-archiving.html#BACKUP-LOWLEVEL-BASE-BACKUP.
't3' value was used for `recoverty_target_name`.
Issue here is that `t3` name was not included into base backup and
following WAL files. Logs looks like this:
xargs -n1 '-I{}' docker exec test-userdb-restore psql -d userdb -U
user_api -c 'INSERT INTO test (num) VALUES ({});'
INSERT 0 1
docker exec test-userdb-restore psql -c 'select
pg_create_restore_point( '\''2023-10-10 14:48:46'\'' )'
pg_create_restore_point
-------------------------
0/5000640
(1 row)
wal-g wal-push pg_wal/000000010000000000000006.00000028.backup
/dbdata/postgres/pg_wal:
total 65540
-rw------- 1 postgres postgres 16777216 Oct 10 14:48 000000010000000000000005
-rw------- 1 postgres postgres 16777216 Oct 10 14:48 000000010000000000000006
-rw------- 1 postgres postgres 364 Oct 10 14:48
000000010000000000000006.00000028.backup
-rw------- 1 postgres postgres 16777216 Oct 10 14:48 000000010000000000000007
-rw------- 1 postgres postgres 16777216 Oct 10 14:48 000000010000000000000008
drwx------ 5 postgres postgres 160 Oct 10 14:48 archive_status
drwx------ 3 root root 96 Oct 10 14:48 walg_data
/dbdata/postgres/pg_wal/archive_status:
total 0
-rw------- 1 postgres postgres 0 Oct 10 14:48 000000010000000000000005.done
-rw------- 1 root root 0 Oct 10 14:48
000000010000000000000006.00000028.backup.done
-rw------- 1 root root 0 Oct 10 14:48 000000010000000000000006.done
/dbdata/postgres/pg_wal/walg_data:
total 0
drwx------ 2 postgres postgres 64 Oct 10 14:48 walg_archive_status
/dbdata/postgres/pg_wal/walg_data/walg_archive_status:
total 0
+ docker exec test-userdb-restore bash -c 'cat $PGDATA/pg_wal/$(ls -R
$PGDATA/pg_wal | grep backup | head -n 1)'
START WAL LOCATION: 0/6000028 (file 000000010000000000000006)
STOP WAL LOCATION: 0/6000100 (file 000000010000000000000006)
CHECKPOINT LOCATION: 0/6000060
BACKUP METHOD: streamed
BACKUP FROM: primary
START TIME: 2023-10-10 14:48:46 UTC
LABEL: 2023-10-10 14:48:46.482532 +0000 UTC m=+0.058620814
START TIMELINE: 1
STOP TIME: 2023-10-10 14:48:47 UTC
STOP TIMELINE: 1
When server was stopped couple of WAL files are created:
+ cd /dbdata/postgres/pg_wal
+ ls -R
.:
000000010000000000000006.00000028.backup
000000010000000000000007
000000010000000000000008
000000010000000000000009
00000001000000000000000A
archive_status
walg_data
./archive_status:
000000010000000000000006.00000028.backup.done
**Created `recovery.signal` and started server**
+ echo 'recovery_target_name= '\''2023-10-10 14:48:46'\'''
+ echo 'recovery_target_action= '\''promote'\'''
+ touch /dbdata/postgres/recovery.signal
2023-10-10 14:48:51.825 UTC [127] database system was interrupted;
last known up at 2023-10-10 14:48:46 UTC
2023-10-10 14:48:51.985 UTC [127] LOG: starting point-in-time
recovery to "2023-10-10 14:48:46"
2023-10-10 14:48:52.065 UTC [127] LOG: restored log file
"000000010000000000000006" from archive
2023-10-10 14:48:52.082 UTC [127] LOG: redo starts at 0/6000028
2023-10-10 14:48:52.141 UTC [127] LOG: consistent recovery state
reached at 0/6000100
2023-10-10 14:48:52.141 UTC [124] LOG: database system is ready to
accept read-only connections
2023-10-10 14:48:52.188 UTC [127] LOG: redo done at 0/6000100 system
usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.10 s
2023-10-10 14:48:52.188 UTC [127] FATAL: recovery ended before
configured recovery target was reached
See full logs in `experiment1.txt` attachment.
Ok. Some name in the past is not included into the base backup which
was done just now.
This is expected, so I created the named restore point after base backup.
Now logs are:
+ docker exec test-userdb-restore psql -c 'select
pg_create_restore_point( '\''2023-10-10 15:07:37'\'' )'
pg_create_restore_point
-------------------------
0/7000090
(1 row)
+ cat 000000010000000000000006.00000028.backup
START WAL LOCATION: 0/6000028 (file 000000010000000000000006)
STOP WAL LOCATION: 0/6000100 (file 000000010000000000000006)
CHECKPOINT LOCATION: 0/6000060
BACKUP METHOD: streamed
BACKUP FROM: primary
START TIME: 2023-10-10 15:07:37 UTC
LABEL: 2023-10-10 15:07:37.844015 +0000 UTC m=+0.057006433
START TIMELINE: 1
STOP TIME: 2023-10-10 15:07:38 UTC
STOP TIMELINE: 1
2023-10-10 15:07:43.451 UTC [128] LOG: starting point-in-time
recovery to "2023-10-10 15:07:37"
2023-10-10 15:07:43.525 UTC [128] LOG: restored log file
"000000010000000000000006" from archive
2023-10-10 15:07:43.540 UTC [128] LOG: redo starts at 0/6000028
2023-10-10 15:07:43.677 UTC [128] LOG: consistent recovery state
reached at 0/6000100
2023-10-10 15:07:43.677 UTC [128] LOG: recovery stopping at restore
point "2023-10-10 15:07:37", time 2023-10-10 15:07:38.846288+00
2023-10-10 15:07:43.677 UTC [128] LOG: redo done at 0/7000028 system
usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.13 s
2023-10-10 15:07:43.677 UTC [125] LOG: database system is ready to
accept read-only connections
1. Why here (in experiment2.txt) redo done at 0/7000028 when recovery
target name "2023-10-10 15:07:37" is at 0/7000090?
I suppose 0/7000090 should be included, because
`recovery_target_inclusive=true` by default.
2. Is there any way to include a label into a base backup which I can
use as `recoverty_target_name`?
This is not clear from documentation
https://www.postgresql.org/docs/current/continuous-archiving.html#BACKUP-LOWLEVEL-BASE-BACKUP
Is 'label' the name for `recovery_target_name` /
`pg_create_restore_point` is called by `pg_backup_start`?
3. Is there any way to get the latest time from a base backup which is
reachable and could be used as the value for `recovery_target_time`?
As a workaround for XX000 error I inserted one additional record into
the database, so a new WAL file is generated. Then I can use the t3
value for `recovery_target_time`.
This only works when archive_command/restore_command was configured.
But without them it seems I can not use the `recovery_target_time`
option. Is this true?
Thank you.
--
Eugen Konkov
DevOps Engineer, Planitar Inc.
+ (( i++ ))
+ (( i<=15 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - no response
+ sleep 1s
+ (( i++ ))
+ (( i<=15 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - no response
+ sleep 1s
+ (( i++ ))
+ (( i<=15 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - no response
+ sleep 1s
+ (( i++ ))
+ (( i<=15 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - no response
+ sleep 1s
+ (( i++ ))
+ (( i<=15 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - accepting connections
+ exit 0
+ test-table-create test-userdb-restore
+ local id=test-userdb-restore
+ docker exec test-userdb-restore psql -d userdb -U user_api -c 'CREATE TABLE test (num SMALLINT);'
CREATE TABLE
+ test-table-write-seq test-userdb-restore 1 5
+ local id=test-userdb-restore
+ seq 1 5
+ xargs -n1 '-I{}' docker exec test-userdb-restore psql -d userdb -U user_api -c 'INSERT INTO test (num) VALUES ({});'
xargs: warning: options --max-args and --replace/-I/-i are mutually exclusive, ignoring previous --max-args value
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
++ docker exec test-userdb-restore date '+%Y-%m-%d %T'
+ t1='2023-10-10 14:48:40'
+ backup test-userdb-restore
+ local id=test-userdb-restore
+ docker exec test-userdb-restore backup
+ historylength=10
+ case "${CONTINOUS_BACKUP}" in
+ is_ready
+ '[' '' == -r ']'
+ WAIT_TIME=30
+ (( i=1 ))
+ (( i<=30 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - accepting connections
+ exit 0
+ echo '[backup]: Starting wal-g backup-push base backup...'
+ wal-g backup-push /dbdata/postgres
[backup]: Starting wal-g backup-push base backup...
INFO: 2023/10/10 14:48:41.133449 Calling pg_start_backup()
INFO: 2023/10/10 14:48:41.227876 Starting a new tar bundle
INFO: 2023/10/10 14:48:41.227935 Walking ...
INFO: 2023/10/10 14:48:41.229261 Starting part 1 ...
INFO: 2023/10/10 14:48:41.883465 Packing ...
INFO: 2023/10/10 14:48:41.886932 Finished writing part 1.
INFO: 2023/10/10 14:48:41.948913 Starting part 2 ...
INFO: 2023/10/10 14:48:41.949000 /global/pg_control
INFO: 2023/10/10 14:48:41.971451 Finished writing part 2.
INFO: 2023/10/10 14:48:41.971489 Calling pg_stop_backup()
INFO: 2023/10/10 14:48:42.008483 Starting part 3 ...
INFO: 2023/10/10 14:48:42.010942 backup_label
INFO: 2023/10/10 14:48:42.010989 tablespace_map
INFO: 2023/10/10 14:48:42.011016 Finished writing part 3.
INFO: 2023/10/10 14:48:42.044140 Wrote backup with name base_000000010000000000000002
+ echo '[backup]: '\''wal-g backup-push'\'' base backup complete...'
[backup]: 'wal-g backup-push' base backup complete...
++ docker exec test-userdb-restore sh -c 'wal-g backup-list'
++ grep base
++ awk '{print $1}'
++ tail -n 1
+ BACKUP_NAME1=base_000000010000000000000002
+ test-table-write-seq test-userdb-restore 6 10
+ local id=test-userdb-restore
+ seq 6 10
+ xargs -n1 '-I{}' docker exec test-userdb-restore psql -d userdb -U user_api -c 'INSERT INTO test (num) VALUES ({});'
xargs: warning: options --max-args and --replace/-I/-i are mutually exclusive, ignoring previous --max-args value
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
++ docker exec test-userdb-restore date '+%Y-%m-%d %T'
+ t2='2023-10-10 14:48:43'
+ backup test-userdb-restore
+ local id=test-userdb-restore
+ docker exec test-userdb-restore backup
+ historylength=10
+ case "${CONTINOUS_BACKUP}" in
+ is_ready
+ '[' '' == -r ']'
+ WAIT_TIME=30
+ (( i=1 ))
+ (( i<=30 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - accepting connections
+ exit 0
+ echo '[backup]: Starting wal-g backup-push base backup...'
+ wal-g backup-push /dbdata/postgres
[backup]: Starting wal-g backup-push base backup...
INFO: 2023/10/10 14:48:43.370323 Calling pg_start_backup()
INFO: 2023/10/10 14:48:43.484141 Starting a new tar bundle
INFO: 2023/10/10 14:48:43.484760 Walking ...
INFO: 2023/10/10 14:48:43.487512 Starting part 1 ...
INFO: 2023/10/10 14:48:44.134464 Packing ...
INFO: 2023/10/10 14:48:44.137944 Finished writing part 1.
INFO: 2023/10/10 14:48:44.201006 Starting part 2 ...
INFO: 2023/10/10 14:48:44.201076 /global/pg_control
INFO: 2023/10/10 14:48:44.205647 Finished writing part 2.
INFO: 2023/10/10 14:48:44.205770 Calling pg_stop_backup()
INFO: 2023/10/10 14:48:44.235631 Starting part 3 ...
INFO: 2023/10/10 14:48:44.238412 backup_label
INFO: 2023/10/10 14:48:44.238458 tablespace_map
INFO: 2023/10/10 14:48:44.238958 Finished writing part 3.
INFO: 2023/10/10 14:48:44.267045 Wrote backup with name base_000000010000000000000004
+ echo '[backup]: '\''wal-g backup-push'\'' base backup complete...'
[backup]: 'wal-g backup-push' base backup complete...
++ docker exec test-userdb-restore sh -c 'wal-g backup-list'
++ grep base
++ awk '{print $1}'
++ tail -n 1
+ BACKUP_NAME2=base_000000010000000000000004
+ test-table-write-seq test-userdb-restore 11 20
+ local id=test-userdb-restore
+ seq 11 20
+ xargs -n1 '-I{}' docker exec test-userdb-restore psql -d userdb -U user_api -c 'INSERT INTO test (num) VALUES ({});'
xargs: warning: options --max-args and --replace/-I/-i are mutually exclusive, ignoring previous --max-args value
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
++ docker exec test-userdb-restore date '+%Y-%m-%d %T'
+ t3='2023-10-10 14:48:46'
+ docker exec test-userdb-restore psql -c 'select pg_create_restore_point( '\''2023-10-10 14:48:46'\'' )'
pg_create_restore_point
-------------------------
0/5000640
(1 row)
+ backup test-userdb-restore
+ local id=test-userdb-restore
+ docker exec test-userdb-restore backup
+ historylength=10
+ case "${CONTINOUS_BACKUP}" in
+ is_ready
+ '[' '' == -r ']'
+ WAIT_TIME=30
+ (( i=1 ))
+ (( i<=30 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - accepting connections
+ exit 0
[backup]: Starting wal-g backup-push base backup...
+ echo '[backup]: Starting wal-g backup-push base backup...'
+ wal-g backup-push /dbdata/postgres
INFO: 2023/10/10 14:48:46.482566 Calling pg_start_backup()
INFO: 2023/10/10 14:48:46.542895 Starting a new tar bundle
INFO: 2023/10/10 14:48:46.542953 Walking ...
INFO: 2023/10/10 14:48:46.544535 Starting part 1 ...
INFO: 2023/10/10 14:48:47.189296 Packing ...
INFO: 2023/10/10 14:48:47.192863 Finished writing part 1.
INFO: 2023/10/10 14:48:47.250145 Starting part 2 ...
INFO: 2023/10/10 14:48:47.250215 /global/pg_control
INFO: 2023/10/10 14:48:47.252662 Finished writing part 2.
INFO: 2023/10/10 14:48:47.252828 Calling pg_stop_backup()
INFO: 2023/10/10 14:48:47.291440 Starting part 3 ...
INFO: 2023/10/10 14:48:47.292183 backup_label
INFO: 2023/10/10 14:48:47.292200 tablespace_map
INFO: 2023/10/10 14:48:47.292238 Finished writing part 3.
INFO: 2023/10/10 14:48:47.337577 Wrote backup with name base_000000010000000000000006
+ echo '[backup]: '\''wal-g backup-push'\'' base backup complete...'
[backup]: 'wal-g backup-push' base backup complete...
++ docker exec test-userdb-restore sh -c 'wal-g backup-list'
++ grep base
++ awk '{print $1}'
++ tail -n 1
+ BACKUP_NAME3=base_000000010000000000000006
+ docker exec test-userdb-restore wal-g backup-list
name modified wal_segment_backup_start
base_000000010000000000000002 2023-10-10T14:48:42Z 000000010000000000000002
base_000000010000000000000004 2023-10-10T14:48:44Z 000000010000000000000004
base_000000010000000000000006 2023-10-10T14:48:47Z 000000010000000000000006
+ docker exec test-userdb-restore cat /backup/restore.log
wal-g wal-push pg_wal/000000010000000000000001
wal-g wal-push pg_wal/000000010000000000000002
wal-g wal-push pg_wal/000000010000000000000002.00000028.backup
wal-g wal-push pg_wal/000000010000000000000003
wal-g wal-push pg_wal/000000010000000000000004
wal-g wal-push pg_wal/000000010000000000000004.00000028.backup
wal-g wal-push pg_wal/000000010000000000000005
wal-g wal-push pg_wal/000000010000000000000006
wal-g wal-push pg_wal/000000010000000000000006.00000028.backup
+ docker exec test-userdb-restore bash -c 'cd $PGDATA && ls -l && ls -lR $PGDATA/pg_wal'
total 60
drwx------ 6 postgres postgres 192 Oct 10 14:48 base
drwx------ 63 postgres postgres 2016 Oct 10 14:48 global
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_commit_ts
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_dynshmem
-rw-------+ 1 root root 4919 Oct 10 14:48 pg_hba.conf
-rw------- 1 postgres postgres 1636 Oct 10 14:48 pg_ident.conf
drwx------ 5 postgres postgres 160 Oct 10 14:48 pg_logical
drwx------ 4 postgres postgres 128 Oct 10 14:48 pg_multixact
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_notify
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_replslot
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_serial
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_snapshots
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_stat
drwx------ 3 postgres postgres 96 Oct 10 14:48 pg_stat_tmp
drwx------ 3 postgres postgres 96 Oct 10 14:48 pg_subtrans
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_tblspc
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_twophase
-rw------- 1 postgres postgres 3 Oct 10 14:48 PG_VERSION
drwx------ 9 postgres postgres 288 Oct 10 14:48 pg_wal
drwx------ 3 postgres postgres 96 Oct 10 14:48 pg_xact
-rw------- 1 postgres postgres 88 Oct 10 14:48 postgresql.auto.conf
-rw-------+ 1 postgres postgres 29865 Oct 10 14:48 postgresql.conf
-rw------- 1 postgres postgres 36 Oct 10 14:48 postmaster.opts
-rw------- 1 root root 86 Oct 10 14:48 postmaster.pid
/dbdata/postgres/pg_wal:
total 65540
-rw------- 1 postgres postgres 16777216 Oct 10 14:48 000000010000000000000005
-rw------- 1 postgres postgres 16777216 Oct 10 14:48 000000010000000000000006
-rw------- 1 postgres postgres 364 Oct 10 14:48 000000010000000000000006.00000028.backup
-rw------- 1 postgres postgres 16777216 Oct 10 14:48 000000010000000000000007
-rw------- 1 postgres postgres 16777216 Oct 10 14:48 000000010000000000000008
drwx------ 5 postgres postgres 160 Oct 10 14:48 archive_status
drwx------ 3 root root 96 Oct 10 14:48 walg_data
/dbdata/postgres/pg_wal/archive_status:
total 0
-rw------- 1 postgres postgres 0 Oct 10 14:48 000000010000000000000005.done
-rw------- 1 root root 0 Oct 10 14:48 000000010000000000000006.00000028.backup.done
-rw------- 1 root root 0 Oct 10 14:48 000000010000000000000006.done
/dbdata/postgres/pg_wal/walg_data:
total 0
drwx------ 2 postgres postgres 64 Oct 10 14:48 walg_archive_status
/dbdata/postgres/pg_wal/walg_data/walg_archive_status:
total 0
+ docker exec test-userdb-restore bash -c 'cat $PGDATA/pg_wal/$(ls -R $PGDATA/pg_wal | grep backup | head -n 1)'
START WAL LOCATION: 0/6000028 (file 000000010000000000000006)
STOP WAL LOCATION: 0/6000100 (file 000000010000000000000006)
CHECKPOINT LOCATION: 0/6000060
BACKUP METHOD: streamed
BACKUP FROM: primary
START TIME: 2023-10-10 14:48:46 UTC
LABEL: 2023-10-10 14:48:46.482532 +0000 UTC m=+0.058620814
START TIMELINE: 1
STOP TIME: 2023-10-10 14:48:47 UTC
STOP TIMELINE: 1
+ docker stop test-userdb-restore
test-userdb-restore
+ echo -e '\n\n\n\nAFTER STOP STATE \n\n\n\n'
AFTER STOP STATE
+ docker run --rm --name test-userdb-restore --net host -e WALG_S3_PREFIX=s3://fakes3/backups/postgres -e AWS_ACCESS_KEY_ID=fakeS3User -e AWS_SECRET_ACCESS_KEY=fakeS3Secret -e AWS_REGION=fakes3 -e AWS_ENDPOINT=http://localhost:54567 -e AWS_S3_FORCE_PATH_STYLE=true -e CONTINOUS_BACKUP=s3 -e RESTORE=s3 -e BACKUP_NAME=base_000000010000000000000006 -e RECOVERY_TARGET_TIME=current -v /userdb/test/db:/dbdata/postgres -v /backup custom/userdb:v15 bash -c 'set -ex \
wal-g backup-list; \
cat /backup/restore.log || :; \
cd $PGDATA && ls -l; \
cd $PGDATA/pg_wal && ls -R || :; \
cat $(ls -R | grep backup | head -n 1); \
'
+ cat /backup/restore.log
cat: /backup/restore.log: No such file or directory
+ :
+ cd /dbdata/postgres
+ ls -l
total 56
drwx------ 6 postgres postgres 192 Oct 10 14:48 base
drwx------ 63 postgres postgres 2016 Oct 10 14:48 global
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_commit_ts
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_dynshmem
-rw-------+ 1 root root 4919 Oct 10 14:48 pg_hba.conf
-rw------- 1 postgres postgres 1636 Oct 10 14:48 pg_ident.conf
drwx------ 5 postgres postgres 160 Oct 10 14:48 pg_logical
drwx------ 4 postgres postgres 128 Oct 10 14:48 pg_multixact
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_notify
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_replslot
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_serial
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_snapshots
drwx------ 4 postgres postgres 128 Oct 10 14:48 pg_stat
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_stat_tmp
drwx------ 3 postgres postgres 96 Oct 10 14:48 pg_subtrans
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_tblspc
drwx------ 2 postgres postgres 64 Oct 10 14:48 pg_twophase
-rw------- 1 postgres postgres 3 Oct 10 14:48 PG_VERSION
drwx------ 9 postgres postgres 288 Oct 10 14:48 pg_wal
drwx------ 3 postgres postgres 96 Oct 10 14:48 pg_xact
-rw------- 1 postgres postgres 88 Oct 10 14:48 postgresql.auto.conf
-rw-------+ 1 postgres postgres 29865 Oct 10 14:48 postgresql.conf
-rw------- 1 postgres postgres 36 Oct 10 14:48 postmaster.opts
+ cd /dbdata/postgres/pg_wal
+ ls -R
.:
000000010000000000000006.00000028.backup
000000010000000000000007
000000010000000000000008
000000010000000000000009
00000001000000000000000A
archive_status
walg_data
./archive_status:
000000010000000000000006.00000028.backup.done
./walg_data:
walg_archive_status
./walg_data/walg_archive_status:
++ ls -R
++ grep backup
++ head -n 1
+ cat 000000010000000000000006.00000028.backup
START WAL LOCATION: 0/6000028 (file 000000010000000000000006)
STOP WAL LOCATION: 0/6000100 (file 000000010000000000000006)
CHECKPOINT LOCATION: 0/6000060
BACKUP METHOD: streamed
BACKUP FROM: primary
START TIME: 2023-10-10 14:48:46 UTC
LABEL: 2023-10-10 14:48:46.482532 +0000 UTC m=+0.058620814
START TIMELINE: 1
STOP TIME: 2023-10-10 14:48:47 UTC
STOP TIMELINE: 1
+ echo -e '\n\n\n^^^^^^^^^^^^^^^^^^'
^^^^^^^^^^^^^^^^^^
+ docker run --rm --name test-userdb-restore --net host -e WALG_S3_PREFIX=s3://fakes3/backups/postgres -e AWS_ACCESS_KEY_ID=fakeS3User -e AWS_SECRET_ACCESS_KEY=fakeS3Secret -e AWS_REGION=fakes3 -e AWS_ENDPOINT=http://localhost:54567 -e AWS_S3_FORCE_PATH_STYLE=true -e CONTINOUS_BACKUP=s3 -e RESTORE=s3 -e BACKUP_NAME=base_000000010000000000000006 -e 'RECOVERY_TARGET_NAME=2023-10-10 14:48:46' -v /dbdata/postgres -v /backup userdb:v15
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.
The database cluster will be initialized with locale "en_US.utf8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".
Data page checksums are disabled.
fixing permissions on existing directory /dbdata/postgres ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... Etc/UTC
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok
syncing data to disk ... initdb: warning: enabling "trust" authentication for local connections
initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
ok
Success. You can now start the database server using:
pg_ctl -D /dbdata/postgres -l logfile start
waiting for server to start....2023-10-10 14:48:49.551 UTC [50] LOG: starting PostgreSQL 15.4 (Debian 15.4-2.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2023-10-10 14:48:49.554 UTC [50] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-10-10 14:48:49.560 UTC [53] LOG: database system was shut down at 2023-10-10 14:48:49 UTC
2023-10-10 14:48:49.564 UTC [50] LOG: database system is ready to accept connections
done
server started
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/100-tune-log.sh
+ echo 'log_destination = '\''stderr'\'''
+ echo 'log_line_prefix = '\''%m [%p] %q%u@%d '\'''
+ echo 'log_statement = '\''all'\'''
+ echo 'log_connections = on'
+ echo 'log_disconnections = on'
+ echo 'log_autovacuum_min_duration = 0'
+ echo 'autovacuum = off'
+ sed -i /dbdata/postgres/pg_hba.conf -e 's/host all all all /# host all all all /g'
Logs were tuned
+ echo 'host all all all trust'
+ echo 'Logs were tuned'
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/101-create-userdb.sh
+ : /dbdata/postgres
+ echo Creating userdb database
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname postgres
Creating userdb database
CREATE DATABASE
+ echo Creating user_api role and granting privileges
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname postgres
Creating user_api role and granting privileges
CREATE ROLE
GRANT
ALTER DATABASE
Creating default extensions
+ echo Creating default extensions
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION citext;
CREATE EXTENSION
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION pgcrypto;
CREATE EXTENSION
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION hstore;
CREATE EXTENSION
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION unaccent;
CREATE EXTENSION
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION pg_trgm;
CREATE EXTENSION
+ sed -i /dbdata/postgres/postgresql.conf -e s/timezone = .*$/timezone = 'UTC'/
+ [ = dev ]
+ sed -i /dbdata/postgres/postgresql.conf -e s/^max_connections = .*$/max_connections = 1000/ -e s/^shared_buffers = .*$/shared_buffers = 1GB/
+ echo host userdb user_api 0.0.0.0/0 trust
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/102-enable-pg_stats_statements.sh
Enabling pg_stat_statements
+ : /dbdata/postgres
+ echo Enabling pg_stat_statements
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION pg_stat_statements;
CREATE EXTENSION
+ sed -i /dbdata/postgres/postgresql.conf -e s/^#shared_preload_libraries /shared_preload_libraries / -e s/^shared_preload_libraries = '/shared_preload_libraries = 'pg_stat_statements / -e s/^#track_activity_query_size = 1024/track_activity_query_size = 2048/
+ echo # Track statements generated by stored procedures as well
+ echo pg_stat_statements.track = all
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/301-create-datadog-hook.sh
Creating datadog user
+ : /dbdata/postgres
+ echo Creating datadog user
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname postgres
CREATE ROLE
GRANT
+ echo host postgres datadog 0.0.0.0/0 md5
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/800-setup-archiving.sh
+ : /dbdata/postgres
+ : s3
+ case "${CONTINOUS_BACKUP}" in
+ echo 'wal_level = replica'
+ echo 'archive_mode = on'
+ echo 'archive_timeout = 1800'
+ echo 'archive_command = '\''log_run wal-g wal-push %p'\'''
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/900-run-restore.sh
+ : s3
+ case "${RESTORE}" in
+ pg_ctl -D /dbdata/postgres -m fast -w stop
waiting for server to shut down...2023-10-10 14:48:50.128 UTC [50] LOG: received fast shutdown request
.2023-10-10 14:48:50.130 UTC [50] LOG: aborting any active transactions
2023-10-10 14:48:50.131 UTC [50] LOG: background worker "logical replication launcher" (PID 56) exited with exit code 1
2023-10-10 14:48:50.133 UTC [51] LOG: shutting down
2023-10-10 14:48:50.134 UTC [51] LOG: checkpoint starting: shutdown immediate
2023-10-10 14:48:50.187 UTC [51] LOG: checkpoint complete: wrote 969 buffers (5.9%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.014 s, sync=0.035 s, total=0.054 s; sync files=313, longest=0.008 s, average=0.001 s; distance=4787 kB, estimate=4787 kB
2023-10-10 14:48:50.193 UTC [50] LOG: database system is shut down
done
server stopped
+ restore
+ : /backup
+ BACKDIR_TMP=/backup/tmp
+ case "${RESTORE}" in
++ wal-g backup-list
++ grep base
+ '[' -z 'base_000000010000000000000002 2023-10-10T14:48:42Z 000000010000000000000002
base_000000010000000000000004 2023-10-10T14:48:44Z 000000010000000000000004
base_000000010000000000000006 2023-10-10T14:48:47Z 000000010000000000000006' ']'
+ echo '[restore]: Starting '\''wal-g backup-fetch'\'' base backup'
+ mkdir -p /backup/tmp
[restore]: Starting 'wal-g backup-fetch' base backup
+ cp /dbdata/postgres/postgresql.conf /dbdata/postgres/pg_hba.conf /dbdata/postgres/pg_ident.conf /backup/tmp
+ rm -rf /dbdata/postgres/base /dbdata/postgres/global /dbdata/postgres/pg_commit_ts /dbdata/postgres/pg_dynshmem /dbdata/postgres/pg_hba.conf /dbdata/postgres/pg_ident.conf /dbdata/postgres/pg_logical /dbdata/postgres/pg_multixact /dbdata/postgres/pg_notify /dbdata/postgres/pg_replslot /dbdata/postgres/pg_serial /dbdata/postgres/pg_snapshots /dbdata/postgres/pg_stat /dbdata/postgres/pg_stat_tmp /dbdata/postgres/pg_subtrans /dbdata/postgres/pg_tblspc /dbdata/postgres/pg_twophase /dbdata/postgres/PG_VERSION /dbdata/postgres/pg_wal /dbdata/postgres/pg_xact /dbdata/postgres/postgresql.auto.conf /dbdata/postgres/postgresql.conf /dbdata/postgres/postmaster.opts
+ wal-g backup-fetch /dbdata/postgres base_000000010000000000000006
INFO: 2023/10/10 14:48:50.350241 Selecting the backup with name base_000000010000000000000006...
INFO: 2023/10/10 14:48:50.371510 Finished extraction of part_003.tar.lz4
INFO: 2023/10/10 14:48:51.736155 Finished extraction of part_001.tar.lz4
INFO: 2023/10/10 14:48:51.743050 Finished extraction of pg_control.tar.lz4
INFO: 2023/10/10 14:48:51.743113
Backup extraction complete.
+ echo '[restore]: '\''wal-g backup-fetch'\'' base backup complete'
+ cp /backup/tmp/pg_hba.conf /backup/tmp/pg_ident.conf /backup/tmp/postgresql.conf /dbdata/postgres/
[restore]: 'wal-g backup-fetch' base backup complete
+ rm -rf /backup/tmp
+ echo 'restore_command = '\''log_run wal-g wal-fetch %f "%p"'\'''
+ test -n ''
+ test -n ''
+ test -n '2023-10-10 14:48:46'
+ echo 'recovery_target_name= '\''2023-10-10 14:48:46'\'''
+ echo 'recovery_target_action= '\''promote'\'''
+ touch /dbdata/postgres/recovery.signal
[restore]: Restore prepared
+ echo '[restore]: Restore prepared'
+ ls -l /dbdata/postgres
+ grep signal
-rw-r--r-- 1 postgres postgres 0 Oct 10 14:48 recovery.signal
YES SIGNAL1
+ echo 'YES SIGNAL1'
+ ls -lR /dbdata/postgres/pg_wal
/dbdata/postgres/pg_wal:
total 0
+ pg_ctl -D /dbdata/postgres -w start -o '-c listen_addresses='\'''\'' -p 5432'
waiting for server to start....2023-10-10 14:48:51.817 UTC [124] LOG: starting PostgreSQL 15.4 (Debian 15.4-2.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2023-10-10 14:48:51.819 UTC [124] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-10-10 14:48:51.825 UTC [127] LOG: database system was interrupted; last known up at 2023-10-10 14:48:46 UTC
2023-10-10 14:48:51.825 UTC [127] LOG: creating missing WAL directory "pg_wal/archive_status"
+ echo wal-g wal-fetch 00000002.history pg_wal/RECOVERYHISTORY
+ wal-g wal-fetch 00000002.history pg_wal/RECOVERYHISTORY
ERROR: 2023/10/10 14:48:51.982036 Archive '00000002.history' does not exist.
2023-10-10 14:48:51.985 UTC [127] LOG: starting point-in-time recovery to "2023-10-10 14:48:46"
+ echo wal-g wal-fetch 000000010000000000000006 pg_wal/RECOVERYXLOG
+ wal-g wal-fetch 000000010000000000000006 pg_wal/RECOVERYXLOG
2023-10-10 14:48:52.065 UTC [127] LOG: restored log file "000000010000000000000006" from archive
2023-10-10 14:48:52.082 UTC [127] LOG: redo starts at 0/6000028
+ echo wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
+ wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
INFO: 2023/10/10 14:48:52.100607 WAL-prefetch file: 000000010000000000000007
INFO: 2023/10/10 14:48:52.111002 WAL-prefetch file: 000000010000000000000008
ERROR: 2023/10/10 14:48:52.111123 Archive '000000010000000000000007' does not exist.
ERROR: 2023/10/10 14:48:52.119669 Archive '000000010000000000000008' does not exist.
INFO: 2023/10/10 14:48:52.121859 WAL-prefetch file: 000000010000000000000009
ERROR: 2023/10/10 14:48:52.130722 Archive '000000010000000000000009' does not exist.
INFO: 2023/10/10 14:48:52.132856 WAL-prefetch file: 00000001000000000000000A
ERROR: 2023/10/10 14:48:52.136413 Archive '000000010000000000000007' does not exist.
2023-10-10 14:48:52.141 UTC [127] LOG: consistent recovery state reached at 0/6000100
2023-10-10 14:48:52.141 UTC [124] LOG: database system is ready to accept read-only connections
ERROR: 2023/10/10 14:48:52.142219 Archive '00000001000000000000000A' does not exist.
INFO: 2023/10/10 14:48:52.143125 WAL-prefetch file: 00000001000000000000000B
+ echo wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
+ wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
ERROR: 2023/10/10 14:48:52.150992 Archive '00000001000000000000000B' does not exist.
INFO: 2023/10/10 14:48:52.154178 WAL-prefetch file: 00000001000000000000000C
ERROR: 2023/10/10 14:48:52.162455 Archive '00000001000000000000000C' does not exist.
INFO: 2023/10/10 14:48:52.164620 WAL-prefetch file: 00000001000000000000000D
done
server started
+ ls -l /dbdata/postgres
+ grep signal
-rw-r--r-- 1 postgres postgres 0 Oct 10 14:48 recovery.signal
+ echo 'YES SIGNAL2'
YES SIGNAL2
+ cat /dbdata/postgres/postgresql.conf
+ grep recovery_target_time
#recovery_target_time = '' # the time stamp up to which recovery will proceed
#recovery_target_timeline = 'latest' # 'current', 'latest', or timeline ID
+ echo -e 'Line1\nLine2\n'
+ grep e2
ERROR: 2023/10/10 14:48:52.173402 Archive '00000001000000000000000D' does not exist.
Line2
+ sleep 5s
INFO: 2023/10/10 14:48:52.175799 WAL-prefetch file: 00000001000000000000000E
ERROR: 2023/10/10 14:48:52.183465 Archive '00000001000000000000000E' does not exist.
ERROR: 2023/10/10 14:48:52.185919 Archive '000000010000000000000007' does not exist.
INFO: 2023/10/10 14:48:52.186720 WAL-prefetch file: 00000001000000000000000F
2023-10-10 14:48:52.188 UTC [127] LOG: redo done at 0/6000100 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.10 s
2023-10-10 14:48:52.188 UTC [127] FATAL: recovery ended before configured recovery target was reached
2023-10-10 14:48:52.190 UTC [124] LOG: startup process (PID 127) exited with exit code 1
2023-10-10 14:48:52.190 UTC [124] LOG: terminating any other active server processes
2023-10-10 14:48:52.191 UTC [124] LOG: shutting down due to startup process failure
ERROR: 2023/10/10 14:48:52.193457 Archive '00000001000000000000000F' does not exist.
INFO: 2023/10/10 14:48:52.197740 WAL-prefetch file: 000000010000000000000010
2023-10-10 14:48:52.201 UTC [124] LOG: database system is shut down
ERROR: 2023/10/10 14:48:52.205151 Archive '000000010000000000000010' does not exist.
+ cat /backup/restore.log
wal-g wal-fetch 00000002.history pg_wal/RECOVERYHISTORY
wal-g wal-fetch 000000010000000000000006 pg_wal/RECOVERYXLOG
wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
pg_ctl: PID file "/dbdata/postgres/postmaster.pid" does not exist
Is server running?
++ report
++ echo -e '\n\n\n\n\n\n\n\n\n**********************EXIT***********************\n\n\n\n\n\n\n'
**********************EXIT***********************
++ docker logs test-userdb-restore
Error response from daemon: No such container: test-userdb-restore
+ cleanup
+ echo -e '\n\n\n\n\n\n\n\n\n****************CLEANUP*****************************\n\n\n\n\n\n\n'
****************CLEANUP*****************************
+ docker rm test-userdb-restore -f
Error response from daemon: No such container: test-userdb-restore
+ docker rm postgres-fakes3 -f
postgres-fakes3
+ rm -rf /Users/kes/tmp/minio
+ echo -e '\n\n\n\n\n\n\n\n\n****************DONE*****************************\n\n\n\n\n\n\n'
****************DONE*****************************
kes@Eugens-MacBook-Pro test $+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - no response
+ sleep 1s
+ (( i++ ))
+ (( i<=15 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - accepting connections
+ exit 0
+ test-table-create test-userdb-restore
+ local id=test-userdb-restore
+ docker exec test-userdb-restore psql -d userdb -U user_api -c 'CREATE TABLE test (num SMALLINT);'
CREATE TABLE
+ test-table-write-seq test-userdb-restore 1 5
+ local id=test-userdb-restore
+ seq 1 5
+ xargs -n1 '-I{}' docker exec test-userdb-restore psql -d userdb -U user_api -c 'INSERT INTO test (num) VALUES ({});'
xargs: warning: options --max-args and --replace/-I/-i are mutually exclusive, ignoring previous --max-args value
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
++ docker exec test-userdb-restore date '+%Y-%m-%d %T'
+ t1='2023-10-10 15:07:32'
+ backup test-userdb-restore
+ local id=test-userdb-restore
+ docker exec test-userdb-restore backup
+ historylength=10
+ case "${CONTINOUS_BACKUP}" in
+ is_ready
+ '[' '' == -r ']'
+ WAIT_TIME=30
+ (( i=1 ))
+ (( i<=30 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - accepting connections
+ exit 0
[backup]: Starting wal-g backup-push base backup...
+ echo '[backup]: Starting wal-g backup-push base backup...'
+ wal-g backup-push /dbdata/postgres
INFO: 2023/10/10 15:07:32.426143 Calling pg_start_backup()
INFO: 2023/10/10 15:07:32.522349 Starting a new tar bundle
INFO: 2023/10/10 15:07:32.522430 Walking ...
INFO: 2023/10/10 15:07:32.524116 Starting part 1 ...
INFO: 2023/10/10 15:07:33.306927 Packing ...
INFO: 2023/10/10 15:07:33.310607 Finished writing part 1.
INFO: 2023/10/10 15:07:33.369013 Starting part 2 ...
INFO: 2023/10/10 15:07:33.369106 /global/pg_control
INFO: 2023/10/10 15:07:33.382594 Finished writing part 2.
INFO: 2023/10/10 15:07:33.382638 Calling pg_stop_backup()
INFO: 2023/10/10 15:07:33.421913 Starting part 3 ...
INFO: 2023/10/10 15:07:33.422833 backup_label
INFO: 2023/10/10 15:07:33.422877 tablespace_map
INFO: 2023/10/10 15:07:33.422946 Finished writing part 3.
INFO: 2023/10/10 15:07:33.448410 Wrote backup with name base_000000010000000000000002
[backup]: 'wal-g backup-push' base backup complete...
+ echo '[backup]: '\''wal-g backup-push'\'' base backup complete...'
++ docker exec test-userdb-restore sh -c 'wal-g backup-list'
++ grep base
++ awk '{print $1}'
++ tail -n 1
+ BACKUP_NAME1=base_000000010000000000000002
+ test-table-write-seq test-userdb-restore 6 10
+ local id=test-userdb-restore
+ seq 6 10
+ xargs -n1 '-I{}' docker exec test-userdb-restore psql -d userdb -U user_api -c 'INSERT INTO test (num) VALUES ({});'
xargs: warning: options --max-args and --replace/-I/-i are mutually exclusive, ignoring previous --max-args value
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
++ docker exec test-userdb-restore date '+%Y-%m-%d %T'
+ t2='2023-10-10 15:07:34'
+ backup test-userdb-restore
+ local id=test-userdb-restore
+ docker exec test-userdb-restore backup
+ historylength=10
+ case "${CONTINOUS_BACKUP}" in
+ is_ready
+ '[' '' == -r ']'
+ WAIT_TIME=30
+ (( i=1 ))
+ (( i<=30 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - accepting connections
+ exit 0
[backup]: Starting wal-g backup-push base backup...
+ echo '[backup]: Starting wal-g backup-push base backup...'
+ wal-g backup-push /dbdata/postgres
INFO: 2023/10/10 15:07:34.800644 Calling pg_start_backup()
INFO: 2023/10/10 15:07:34.945342 Starting a new tar bundle
INFO: 2023/10/10 15:07:34.945401 Walking ...
INFO: 2023/10/10 15:07:34.947736 Starting part 1 ...
INFO: 2023/10/10 15:07:35.651921 Packing ...
INFO: 2023/10/10 15:07:35.655561 Finished writing part 1.
INFO: 2023/10/10 15:07:35.716914 Starting part 2 ...
INFO: 2023/10/10 15:07:35.716983 /global/pg_control
INFO: 2023/10/10 15:07:35.719910 Finished writing part 2.
INFO: 2023/10/10 15:07:35.719961 Calling pg_stop_backup()
INFO: 2023/10/10 15:07:35.753623 Starting part 3 ...
INFO: 2023/10/10 15:07:35.754417 backup_label
INFO: 2023/10/10 15:07:35.754463 tablespace_map
INFO: 2023/10/10 15:07:35.754492 Finished writing part 3.
INFO: 2023/10/10 15:07:35.782908 Wrote backup with name base_000000010000000000000004
[backup]: 'wal-g backup-push' base backup complete...
+ echo '[backup]: '\''wal-g backup-push'\'' base backup complete...'
++ docker exec test-userdb-restore sh -c 'wal-g backup-list'
++ grep base
++ awk '{print $1}'
++ tail -n 1
+ BACKUP_NAME2=base_000000010000000000000004
+ test-table-write-seq test-userdb-restore 11 20
+ local id=test-userdb-restore
+ seq 11 20
+ xargs -n1 '-I{}' docker exec test-userdb-restore psql -d userdb -U user_api -c 'INSERT INTO test (num) VALUES ({});'
xargs: warning: options --max-args and --replace/-I/-i are mutually exclusive, ignoring previous --max-args value
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
INSERT 0 1
++ docker exec test-userdb-restore date '+%Y-%m-%d %T'
+ t3='2023-10-10 15:07:37'
+ backup test-userdb-restore
+ local id=test-userdb-restore
+ docker exec test-userdb-restore backup
+ historylength=10
+ case "${CONTINOUS_BACKUP}" in
+ is_ready
+ '[' '' == -r ']'
+ WAIT_TIME=30
+ (( i=1 ))
+ (( i<=30 ))
+ '[' -n '' -o '!' -f /dbdata/postgres/recovery.conf ']'
+ pg_isready -h localhost
localhost:5432 - accepting connections
+ exit 0
[backup]: Starting wal-g backup-push base backup...
+ echo '[backup]: Starting wal-g backup-push base backup...'
+ wal-g backup-push /dbdata/postgres
INFO: 2023/10/10 15:07:37.844044 Calling pg_start_backup()
INFO: 2023/10/10 15:07:37.907817 Starting a new tar bundle
INFO: 2023/10/10 15:07:37.907883 Walking ...
INFO: 2023/10/10 15:07:37.909196 Starting part 1 ...
INFO: 2023/10/10 15:07:38.535603 Packing ...
INFO: 2023/10/10 15:07:38.539568 Finished writing part 1.
INFO: 2023/10/10 15:07:38.596218 Starting part 2 ...
INFO: 2023/10/10 15:07:38.596290 /global/pg_control
INFO: 2023/10/10 15:07:38.599584 Finished writing part 2.
INFO: 2023/10/10 15:07:38.599622 Calling pg_stop_backup()
INFO: 2023/10/10 15:07:38.636523 Starting part 3 ...
INFO: 2023/10/10 15:07:38.639700 backup_label
INFO: 2023/10/10 15:07:38.639748 tablespace_map
INFO: 2023/10/10 15:07:38.640053 Finished writing part 3.
INFO: 2023/10/10 15:07:38.667890 Wrote backup with name base_000000010000000000000006
+ echo '[backup]: '\''wal-g backup-push'\'' base backup complete...'
[backup]: 'wal-g backup-push' base backup complete...
+ docker exec test-userdb-restore psql -c 'select pg_create_restore_point( '\''2023-10-10 15:07:37'\'' )'
pg_create_restore_point
-------------------------
0/7000090
(1 row)
++ docker exec test-userdb-restore sh -c 'wal-g backup-list'
++ grep base
++ awk '{print $1}'
++ tail -n 1
+ BACKUP_NAME3=base_000000010000000000000006
+ docker exec test-userdb-restore wal-g backup-list
name modified wal_segment_backup_start
base_000000010000000000000002 2023-10-10T15:07:33Z 000000010000000000000002
base_000000010000000000000004 2023-10-10T15:07:35Z 000000010000000000000004
base_000000010000000000000006 2023-10-10T15:07:38Z 000000010000000000000006
+ docker exec test-userdb-restore cat /backup/restore.log
wal-g wal-push pg_wal/000000010000000000000001
wal-g wal-push pg_wal/000000010000000000000002
wal-g wal-push pg_wal/000000010000000000000002.00000028.backup
wal-g wal-push pg_wal/000000010000000000000003
wal-g wal-push pg_wal/000000010000000000000004
wal-g wal-push pg_wal/000000010000000000000004.00000028.backup
wal-g wal-push pg_wal/000000010000000000000005
wal-g wal-push pg_wal/000000010000000000000006
wal-g wal-push pg_wal/000000010000000000000006.00000028.backup
+ docker exec test-userdb-restore bash -c 'cd $PGDATA && ls -l && ls -lR $PGDATA/pg_wal'
total 60
drwx------ 6 postgres postgres 192 Oct 10 15:07 base
drwx------ 63 postgres postgres 2016 Oct 10 15:07 global
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_commit_ts
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_dynshmem
-rw-------+ 1 postgres postgres 4919 Oct 10 15:07 pg_hba.conf
-rw------- 1 postgres postgres 1636 Oct 10 15:07 pg_ident.conf
drwx------ 5 postgres postgres 160 Oct 10 15:07 pg_logical
drwx------ 4 postgres postgres 128 Oct 10 15:07 pg_multixact
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_notify
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_replslot
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_serial
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_snapshots
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_stat
drwx------ 3 postgres postgres 96 Oct 10 15:07 pg_stat_tmp
drwx------ 3 postgres postgres 96 Oct 10 15:07 pg_subtrans
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_tblspc
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_twophase
-rw------- 1 postgres postgres 3 Oct 10 15:07 PG_VERSION
drwx------ 9 postgres postgres 288 Oct 10 15:07 pg_wal
drwx------ 3 postgres postgres 96 Oct 10 15:07 pg_xact
-rw------- 1 postgres postgres 88 Oct 10 15:07 postgresql.auto.conf
-rw-------+ 1 postgres postgres 29865 Oct 10 15:07 postgresql.conf
-rw------- 1 postgres postgres 36 Oct 10 15:07 postmaster.opts
-rw------- 1 root root 86 Oct 10 15:07 postmaster.pid
/dbdata/postgres/pg_wal:
total 65540
-rw------- 1 postgres postgres 16777216 Oct 10 15:07 000000010000000000000005
-rw------- 1 postgres postgres 16777216 Oct 10 15:07 000000010000000000000006
-rw------- 1 postgres postgres 364 Oct 10 15:07 000000010000000000000006.00000028.backup
-rw------- 1 postgres postgres 16777216 Oct 10 15:07 000000010000000000000007
-rw------- 1 postgres postgres 16777216 Oct 10 15:07 000000010000000000000008
drwx------ 5 postgres postgres 160 Oct 10 15:07 archive_status
drwx------ 3 root root 96 Oct 10 15:07 walg_data
/dbdata/postgres/pg_wal/archive_status:
total 0
-rw------- 1 postgres postgres 0 Oct 10 15:07 000000010000000000000005.done
-rw------- 1 root root 0 Oct 10 15:07 000000010000000000000006.00000028.backup.done
-rw------- 1 root root 0 Oct 10 15:07 000000010000000000000006.done
/dbdata/postgres/pg_wal/walg_data:
total 0
drwx------ 2 postgres postgres 64 Oct 10 15:07 walg_archive_status
/dbdata/postgres/pg_wal/walg_data/walg_archive_status:
total 0
+ docker exec test-userdb-restore bash -c 'cat $PGDATA/pg_wal/$(ls -R $PGDATA/pg_wal | grep backup | head -n 1)'
START WAL LOCATION: 0/6000028 (file 000000010000000000000006)
STOP WAL LOCATION: 0/6000100 (file 000000010000000000000006)
CHECKPOINT LOCATION: 0/6000060
BACKUP METHOD: streamed
BACKUP FROM: primary
START TIME: 2023-10-10 15:07:37 UTC
LABEL: 2023-10-10 15:07:37.844015 +0000 UTC m=+0.057006433
START TIMELINE: 1
STOP TIME: 2023-10-10 15:07:38 UTC
STOP TIMELINE: 1
+ docker stop test-userdb-restore
test-userdb-restore
+ echo -e '\n\n\n\nAFTER STOP STATE \n\n\n\n'
AFTER STOP STATE
+ docker run --rm --name test-userdb-restore --net host -e WALG_S3_PREFIX=s3://fakes3/backups/postgres -e AWS_ACCESS_KEY_ID=fakeS3User -e AWS_SECRET_ACCESS_KEY=fakeS3Secret -e AWS_REGION=fakes3 -e AWS_ENDPOINT=http://localhost:54567 -e AWS_S3_FORCE_PATH_STYLE=true -e CONTINOUS_BACKUP=s3 -e RESTORE=s3 -e BACKUP_NAME=base_000000010000000000000006 -e RECOVERY_TARGET_TIME=current -v /userdb/test/db:/dbdata/postgres -v /backup custom/userdb:v15 bash -c 'set -ex \
wal-g backup-list; \
cat /backup/restore.log || :; \
cd $PGDATA && ls -l; \
cd $PGDATA/pg_wal && ls -R || :; \
cat $(ls -R | grep backup | head -n 1); \
'
+ cat /backup/restore.log
cat: /backup/restore.log: No such file or directory
+ :
+ cd /dbdata/postgres
+ ls -l
total 56
drwx------ 6 postgres postgres 192 Oct 10 15:07 base
drwx------ 63 postgres postgres 2016 Oct 10 15:07 global
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_commit_ts
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_dynshmem
-rw-------+ 1 postgres postgres 4919 Oct 10 15:07 pg_hba.conf
-rw------- 1 postgres postgres 1636 Oct 10 15:07 pg_ident.conf
drwx------ 5 postgres postgres 160 Oct 10 15:07 pg_logical
drwx------ 4 postgres postgres 128 Oct 10 15:07 pg_multixact
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_notify
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_replslot
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_serial
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_snapshots
drwx------ 4 postgres postgres 128 Oct 10 15:07 pg_stat
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_stat_tmp
drwx------ 3 postgres postgres 96 Oct 10 15:07 pg_subtrans
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_tblspc
drwx------ 2 postgres postgres 64 Oct 10 15:07 pg_twophase
-rw------- 1 postgres postgres 3 Oct 10 15:07 PG_VERSION
drwx------ 9 postgres postgres 288 Oct 10 15:07 pg_wal
drwx------ 3 postgres postgres 96 Oct 10 15:07 pg_xact
-rw------- 1 postgres postgres 88 Oct 10 15:07 postgresql.auto.conf
-rw-------+ 1 postgres postgres 29865 Oct 10 15:07 postgresql.conf
-rw------- 1 postgres postgres 36 Oct 10 15:07 postmaster.opts
+ cd /dbdata/postgres/pg_wal
+ ls -R
.:
000000010000000000000006.00000028.backup
000000010000000000000007
000000010000000000000008
000000010000000000000009
00000001000000000000000A
archive_status
walg_data
./archive_status:
000000010000000000000006.00000028.backup.done
000000010000000000000007.done
./walg_data:
walg_archive_status
./walg_data/walg_archive_status:
++ ls -R
++ grep backup
++ head -n 1
+ cat 000000010000000000000006.00000028.backup
START WAL LOCATION: 0/6000028 (file 000000010000000000000006)
STOP WAL LOCATION: 0/6000100 (file 000000010000000000000006)
CHECKPOINT LOCATION: 0/6000060
BACKUP METHOD: streamed
BACKUP FROM: primary
START TIME: 2023-10-10 15:07:37 UTC
LABEL: 2023-10-10 15:07:37.844015 +0000 UTC m=+0.057006433
START TIMELINE: 1
STOP TIME: 2023-10-10 15:07:38 UTC
STOP TIMELINE: 1
+ echo -e '\n\n\n^^^^^^^^^^^^^^^^^^'
^^^^^^^^^^^^^^^^^^
+ docker run --rm --name test-userdb-restore --net host -e WALG_S3_PREFIX=s3://fakes3/backups/postgres -e AWS_ACCESS_KEY_ID=fakeS3User -e AWS_SECRET_ACCESS_KEY=fakeS3Secret -e AWS_REGION=fakes3 -e AWS_ENDPOINT=http://localhost:54567 -e AWS_S3_FORCE_PATH_STYLE=true -e CONTINOUS_BACKUP=s3 -e RESTORE=s3 -e BACKUP_NAME=base_000000010000000000000006 -e 'RECOVERY_TARGET_NAME=2023-10-10 15:07:37' -v /dbdata/postgres -v /backup custom/userdb:v15
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.
The database cluster will be initialized with locale "en_US.utf8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".
Data page checksums are disabled.
fixing permissions on existing directory /dbdata/postgres ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... Etc/UTC
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok
syncing data to disk ... ok
Success. You can now start the database server using:
pg_ctl -D /dbdata/postgres -l logfile start
initdb: warning: enabling "trust" authentication for local connections
initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
waiting for server to start....2023-10-10 15:07:41.022 UTC [50] LOG: starting PostgreSQL 15.4 (Debian 15.4-2.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2023-10-10 15:07:41.023 UTC [50] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-10-10 15:07:41.030 UTC [53] LOG: database system was shut down at 2023-10-10 15:07:40 UTC
2023-10-10 15:07:41.035 UTC [50] LOG: database system is ready to accept connections
done
server started
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/100-tune-log.sh
+ echo 'log_destination = '\''stderr'\'''
+ echo 'log_line_prefix = '\''%m [%p] %q%u@%d '\'''
+ echo 'log_statement = '\''all'\'''
+ echo 'log_connections = on'
+ echo 'log_disconnections = on'
+ echo 'log_autovacuum_min_duration = 0'
+ echo 'autovacuum = off'
+ sed -i /dbdata/postgres/pg_hba.conf -e 's/host all all all /# host all all all /g'
+ echo 'host all all all trust'
+ echo 'Logs were tuned'
Logs were tuned
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/101-create-userdb.sh
Creating userdb database
+ : /dbdata/postgres
+ echo Creating userdb database
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname postgres
CREATE DATABASE
Creating user_api role and granting privileges
+ echo Creating user_api role and granting privileges
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname postgres
CREATE ROLE
GRANT
ALTER DATABASE
Creating default extensions
+ echo Creating default extensions
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION citext;
CREATE EXTENSION
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION pgcrypto;
CREATE EXTENSION
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION hstore;
CREATE EXTENSION
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION unaccent;
CREATE EXTENSION
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION pg_trgm;
CREATE EXTENSION
+ sed -i /dbdata/postgres/postgresql.conf -e s/timezone = .*$/timezone = 'UTC'/
+ [ = dev ]
+ sed -i /dbdata/postgres/postgresql.conf -e s/^max_connections = .*$/max_connections = 1000/ -e s/^shared_buffers = .*$/shared_buffers = 1GB/
+ echo host userdb user_api 0.0.0.0/0 trust
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/102-enable-pg_stats_statements.sh
Enabling pg_stat_statements
+ : /dbdata/postgres
+ echo Enabling pg_stat_statements
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname userdb -c CREATE EXTENSION pg_stat_statements;
CREATE EXTENSION
+ sed -i /dbdata/postgres/postgresql.conf -e s/^#shared_preload_libraries /shared_preload_libraries / -e s/^shared_preload_libraries = '/shared_preload_libraries = 'pg_stat_statements / -e s/^#track_activity_query_size = 1024/track_activity_query_size = 2048/
+ echo # Track statements generated by stored procedures as well
+ echo pg_stat_statements.track = all
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/301-create-datadog-hook.sh
Creating datadog user
+ : /dbdata/postgres
+ echo Creating datadog user
+ psql -v ON_ERROR_STOP=1 --username postgres --dbname postgres
CREATE ROLE
GRANT
+ echo host postgres datadog 0.0.0.0/0 md5
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/800-setup-archiving.sh
+ : /dbdata/postgres
+ : s3
+ case "${CONTINOUS_BACKUP}" in
+ echo 'wal_level = replica'
+ echo 'archive_mode = on'
+ echo 'archive_timeout = 1800'
+ echo 'archive_command = '\''log_run wal-g wal-push %p'\'''
/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/900-run-restore.sh
+ : s3
+ case "${RESTORE}" in
+ pg_ctl -D /dbdata/postgres -m fast -w stop
2023-10-10 15:07:41.585 UTC [50] LOG: received fast shutdown request
waiting for server to shut down....2023-10-10 15:07:41.586 UTC [50] LOG: aborting any active transactions
2023-10-10 15:07:41.588 UTC [50] LOG: background worker "logical replication launcher" (PID 56) exited with exit code 1
2023-10-10 15:07:41.588 UTC [51] LOG: shutting down
2023-10-10 15:07:41.590 UTC [51] LOG: checkpoint starting: shutdown immediate
2023-10-10 15:07:41.640 UTC [51] LOG: checkpoint complete: wrote 969 buffers (5.9%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.013 s, sync=0.034 s, total=0.052 s; sync files=313, longest=0.009 s, average=0.001 s; distance=4787 kB, estimate=4787 kB
2023-10-10 15:07:41.645 UTC [50] LOG: database system is shut down
done
server stopped
+ restore
+ : /backup
+ BACKDIR_TMP=/backup/tmp
+ case "${RESTORE}" in
++ wal-g backup-list
++ grep base
[restore]: Starting 'wal-g backup-fetch' base backup
+ '[' -z 'base_000000010000000000000002 2023-10-10T15:07:33Z 000000010000000000000002
base_000000010000000000000004 2023-10-10T15:07:35Z 000000010000000000000004
base_000000010000000000000006 2023-10-10T15:07:38Z 000000010000000000000006' ']'
+ echo '[restore]: Starting '\''wal-g backup-fetch'\'' base backup'
+ mkdir -p /backup/tmp
+ cp /dbdata/postgres/postgresql.conf /dbdata/postgres/pg_hba.conf /dbdata/postgres/pg_ident.conf /backup/tmp
+ rm -rf /dbdata/postgres/base /dbdata/postgres/global /dbdata/postgres/pg_commit_ts /dbdata/postgres/pg_dynshmem /dbdata/postgres/pg_hba.conf /dbdata/postgres/pg_ident.conf /dbdata/postgres/pg_logical /dbdata/postgres/pg_multixact /dbdata/postgres/pg_notify /dbdata/postgres/pg_replslot /dbdata/postgres/pg_serial /dbdata/postgres/pg_snapshots /dbdata/postgres/pg_stat /dbdata/postgres/pg_stat_tmp /dbdata/postgres/pg_subtrans /dbdata/postgres/pg_tblspc /dbdata/postgres/pg_twophase /dbdata/postgres/PG_VERSION /dbdata/postgres/pg_wal /dbdata/postgres/pg_xact /dbdata/postgres/postgresql.auto.conf /dbdata/postgres/postgresql.conf /dbdata/postgres/postmaster.opts
+ wal-g backup-fetch /dbdata/postgres base_000000010000000000000006
INFO: 2023/10/10 15:07:41.807552 Selecting the backup with name base_000000010000000000000006...
INFO: 2023/10/10 15:07:41.828172 Finished extraction of part_003.tar.lz4
INFO: 2023/10/10 15:07:43.206487 Finished extraction of part_001.tar.lz4
INFO: 2023/10/10 15:07:43.214047 Finished extraction of pg_control.tar.lz4
INFO: 2023/10/10 15:07:43.214127
Backup extraction complete.
[restore]: 'wal-g backup-fetch' base backup complete
+ echo '[restore]: '\''wal-g backup-fetch'\'' base backup complete'
+ cp /backup/tmp/pg_hba.conf /backup/tmp/pg_ident.conf /backup/tmp/postgresql.conf /dbdata/postgres/
+ rm -rf /backup/tmp
+ echo 'restore_command = '\''log_run wal-g wal-fetch %f "%p"'\'''
+ test -n ''
+ test -n ''
+ test -n '2023-10-10 15:07:37'
+ echo 'recovery_target_name= '\''2023-10-10 15:07:37'\'''
+ echo 'recovery_target_action= '\''promote'\'''
+ touch /dbdata/postgres/recovery.signal
[restore]: Restore prepared
+ echo '[restore]: Restore prepared'
+ ls -l /dbdata/postgres
+ grep signal
-rw-r--r-- 1 postgres postgres 0 Oct 10 15:07 recovery.signal
+ echo 'YES SIGNAL1'
+ ls -lR /dbdata/postgres/pg_wal
YES SIGNAL1
/dbdata/postgres/pg_wal:
total 0
+ pg_ctl -D /dbdata/postgres -w start -o '-c listen_addresses='\'''\'' -p 5432'
waiting for server to start....2023-10-10 15:07:43.286 UTC [125] LOG: starting PostgreSQL 15.4 (Debian 15.4-2.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2023-10-10 15:07:43.289 UTC [125] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-10-10 15:07:43.294 UTC [128] LOG: database system was interrupted; last known up at 2023-10-10 15:07:37 UTC
2023-10-10 15:07:43.294 UTC [128] LOG: creating missing WAL directory "pg_wal/archive_status"
+ echo wal-g wal-fetch 00000002.history pg_wal/RECOVERYHISTORY
+ wal-g wal-fetch 00000002.history pg_wal/RECOVERYHISTORY
ERROR: 2023/10/10 15:07:43.448832 Archive '00000002.history' does not exist.
2023-10-10 15:07:43.451 UTC [128] LOG: starting point-in-time recovery to "2023-10-10 15:07:37"
+ echo wal-g wal-fetch 000000010000000000000006 pg_wal/RECOVERYXLOG
+ wal-g wal-fetch 000000010000000000000006 pg_wal/RECOVERYXLOG
2023-10-10 15:07:43.525 UTC [128] LOG: restored log file "000000010000000000000006" from archive
2023-10-10 15:07:43.540 UTC [128] LOG: redo starts at 0/6000028
+ echo wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
+ wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
INFO: 2023/10/10 15:07:43.555833 WAL-prefetch file: 000000010000000000000007
INFO: 2023/10/10 15:07:43.566613 WAL-prefetch file: 000000010000000000000008
ERROR: 2023/10/10 15:07:43.575270 Archive '000000010000000000000008' does not exist.
INFO: 2023/10/10 15:07:43.577595 WAL-prefetch file: 000000010000000000000009
ERROR: 2023/10/10 15:07:43.587269 Archive '000000010000000000000009' does not exist.
INFO: 2023/10/10 15:07:43.588298 WAL-prefetch file: 00000001000000000000000A
ERROR: 2023/10/10 15:07:43.596400 Archive '00000001000000000000000A' does not exist.
INFO: 2023/10/10 15:07:43.598420 WAL-prefetch file: 00000001000000000000000B
ERROR: 2023/10/10 15:07:43.605485 Archive '00000001000000000000000B' does not exist.
2023-10-10 15:07:43.607 UTC [128] LOG: restored log file "000000010000000000000007" from archive
INFO: 2023/10/10 15:07:43.608845 WAL-prefetch file: 00000001000000000000000C
ERROR: 2023/10/10 15:07:43.616956 Archive '00000001000000000000000C' does not exist.
INFO: 2023/10/10 15:07:43.619207 WAL-prefetch file: 00000001000000000000000D
ERROR: 2023/10/10 15:07:43.626840 Archive '00000001000000000000000D' does not exist.
INFO: 2023/10/10 15:07:43.630018 WAL-prefetch file: 00000001000000000000000E
+ echo wal-g wal-fetch 000000010000000000000008 pg_wal/RECOVERYXLOG
+ wal-g wal-fetch 000000010000000000000008 pg_wal/RECOVERYXLOG
ERROR: 2023/10/10 15:07:43.639201 Archive '00000001000000000000000E' does not exist.
INFO: 2023/10/10 15:07:43.640134 WAL-prefetch file: 00000001000000000000000F
INFO: 2023/10/10 15:07:43.640961 WAL-prefetch file: 000000010000000000000008
ERROR: 2023/10/10 15:07:43.647345 Archive '00000001000000000000000F' does not exist.
ERROR: 2023/10/10 15:07:43.649211 Archive '000000010000000000000008' does not exist.
INFO: 2023/10/10 15:07:43.650600 WAL-prefetch file: 000000010000000000000010
INFO: 2023/10/10 15:07:43.651082 WAL-prefetch file: 000000010000000000000009
ERROR: 2023/10/10 15:07:43.656872 Archive '000000010000000000000010' does not exist.
ERROR: 2023/10/10 15:07:43.657555 Archive '000000010000000000000009' does not exist.
INFO: 2023/10/10 15:07:43.661950 WAL-prefetch file: 00000001000000000000000A
ERROR: 2023/10/10 15:07:43.668230 Archive '00000001000000000000000A' does not exist.
INFO: 2023/10/10 15:07:43.672402 WAL-prefetch file: 00000001000000000000000B
ERROR: 2023/10/10 15:07:43.673422 Archive '000000010000000000000008' does not exist.
2023-10-10 15:07:43.677 UTC [128] LOG: consistent recovery state reached at 0/6000100
2023-10-10 15:07:43.677 UTC [128] LOG: recovery stopping at restore point "2023-10-10 15:07:37", time 2023-10-10 15:07:38.846288+00
2023-10-10 15:07:43.677 UTC [128] LOG: redo done at 0/7000028 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.13 s
2023-10-10 15:07:43.677 UTC [125] LOG: database system is ready to accept read-only connections
ERROR: 2023/10/10 15:07:43.678263 Archive '00000001000000000000000B' does not exist.
+ echo wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
+ wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
INFO: 2023/10/10 15:07:43.683397 WAL-prefetch file: 00000001000000000000000C
ERROR: 2023/10/10 15:07:43.690699 Archive '00000001000000000000000C' does not exist.
INFO: 2023/10/10 15:07:43.694149 WAL-prefetch file: 00000001000000000000000D
ERROR: 2023/10/10 15:07:43.700156 Archive '00000001000000000000000D' does not exist.
INFO: 2023/10/10 15:07:43.705238 WAL-prefetch file: 00000001000000000000000E
ERROR: 2023/10/10 15:07:43.712120 Archive '00000001000000000000000E' does not exist.
INFO: 2023/10/10 15:07:43.716212 WAL-prefetch file: 00000001000000000000000F
ERROR: 2023/10/10 15:07:43.722915 Archive '00000001000000000000000F' does not exist.
INFO: 2023/10/10 15:07:43.727287 WAL-prefetch file: 000000010000000000000010
ERROR: 2023/10/10 15:07:43.733704 Archive '000000010000000000000010' does not exist.
INFO: 2023/10/10 15:07:43.737884 WAL-prefetch file: 000000010000000000000011
done
server started
+ ls -l /dbdata/postgres
+ grep signal
-rw-r--r-- 1 postgres postgres 0 Oct 10 15:07 recovery.signal
+ echo 'YES SIGNAL2'
YES SIGNAL2
+ cat /dbdata/postgres/postgresql.conf
+ grep recovery_target_time
#recovery_target_time = '' # the time stamp up to which recovery will proceed
#recovery_target_timeline = 'latest' # 'current', 'latest', or timeline ID
+ grep e2
+ echo -e 'Line1\nLine2\n'
ERROR: 2023/10/10 15:07:43.745114 Archive '000000010000000000000011' does not exist.
Line2
+ sleep 5s
2023-10-10 15:07:43.754 UTC [128] LOG: restored log file "000000010000000000000007" from archive
+ echo wal-g wal-fetch 00000002.history pg_wal/RECOVERYHISTORY
+ wal-g wal-fetch 00000002.history pg_wal/RECOVERYHISTORY
INFO: 2023/10/10 15:07:43.784834 WAL-prefetch file: 000000010000000000000008
ERROR: 2023/10/10 15:07:43.794647 Archive '000000010000000000000008' does not exist.
INFO: 2023/10/10 15:07:43.795807 WAL-prefetch file: 000000010000000000000009
ERROR: 2023/10/10 15:07:43.803363 Archive '000000010000000000000009' does not exist.
INFO: 2023/10/10 15:07:43.806559 WAL-prefetch file: 00000001000000000000000A
ERROR: 2023/10/10 15:07:43.813320 Archive '00000001000000000000000A' does not exist.
ERROR: 2023/10/10 15:07:43.816576 Archive '00000002.history' does not exist.
INFO: 2023/10/10 15:07:43.817500 WAL-prefetch file: 00000001000000000000000B
2023-10-10 15:07:43.819 UTC [128] LOG: selected new timeline ID: 2
ERROR: 2023/10/10 15:07:43.824429 Archive '00000001000000000000000B' does not exist.
INFO: 2023/10/10 15:07:43.828646 WAL-prefetch file: 00000001000000000000000C
ERROR: 2023/10/10 15:07:43.837391 Archive '00000001000000000000000C' does not exist.
INFO: 2023/10/10 15:07:43.839443 WAL-prefetch file: 00000001000000000000000D
ERROR: 2023/10/10 15:07:43.847201 Archive '00000001000000000000000D' does not exist.
INFO: 2023/10/10 15:07:43.850294 WAL-prefetch file: 00000001000000000000000E
+ echo wal-g wal-fetch 00000001.history pg_wal/RECOVERYHISTORY
+ wal-g wal-fetch 00000001.history pg_wal/RECOVERYHISTORY
ERROR: 2023/10/10 15:07:43.858171 Archive '00000001000000000000000E' does not exist.
INFO: 2023/10/10 15:07:43.861360 WAL-prefetch file: 00000001000000000000000F
ERROR: 2023/10/10 15:07:43.869013 Archive '00000001000000000000000F' does not exist.
INFO: 2023/10/10 15:07:43.872483 WAL-prefetch file: 000000010000000000000010
ERROR: 2023/10/10 15:07:43.879430 Archive '000000010000000000000010' does not exist.
INFO: 2023/10/10 15:07:43.883651 WAL-prefetch file: 000000010000000000000011
ERROR: 2023/10/10 15:07:43.890594 Archive '000000010000000000000011' does not exist.
ERROR: 2023/10/10 15:07:43.894272 Archive '00000001.history' does not exist.
2023-10-10 15:07:43.899 UTC [128] LOG: archive recovery complete
2023-10-10 15:07:43.900 UTC [126] LOG: checkpoint starting: end-of-recovery immediate wait
2023-10-10 15:07:43.909 UTC [126] LOG: checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.004 s, sync=0.001 s, total=0.011 s; sync files=2, longest=0.001 s, average=0.001 s; distance=16384 kB, estimate=16384 kB
2023-10-10 15:07:43.913 UTC [125] LOG: database system is ready to accept connections
+ echo wal-g wal-push pg_wal/00000002.history
+ wal-g wal-push pg_wal/00000002.history
INFO: 2023/10/10 15:07:43.961691 FILE PATH: 00000002.history.lz4
+ cat /backup/restore.log
wal-g wal-fetch 00000002.history pg_wal/RECOVERYHISTORY
wal-g wal-fetch 000000010000000000000006 pg_wal/RECOVERYXLOG
wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
wal-g wal-fetch 000000010000000000000008 pg_wal/RECOVERYXLOG
wal-g wal-fetch 000000010000000000000007 pg_wal/RECOVERYXLOG
wal-g wal-fetch 00000002.history pg_wal/RECOVERYHISTORY
wal-g wal-fetch 00000001.history pg_wal/RECOVERYHISTORY
wal-g wal-push pg_wal/00000002.history
waiting for server to shut down...2023-10-10 15:07:48.758 UTC [125] LOG: received fast shutdown request
.2023-10-10 15:07:48.760 UTC [125] LOG: aborting any active transactions
2023-10-10 15:07:48.763 UTC [125] LOG: background worker "logical replication launcher" (PID 249) exited with exit code 1
2023-10-10 15:07:48.763 UTC [126] LOG: shutting down
2023-10-10 15:07:48.785 UTC [126] LOG: checkpoint starting: shutdown immediate
+ echo wal-g wal-push pg_wal/000000020000000000000007
+ wal-g wal-push pg_wal/000000020000000000000007
2023-10-10 15:07:48.796 UTC [126] LOG: checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.003 s, sync=0.001 s, total=0.013 s; sync files=0, longest=0.000 s, average=0.000 s; distance=16383 kB, estimate=16384 kB
INFO: 2023/10/10 15:07:48.846421 FILE PATH: 000000020000000000000007.lz4
2023-10-10 15:07:48.867 UTC [125] LOG: database system is shut down
done
server stopped
PostgreSQL init process complete; ready for start up.
2023-10-10 15:07:49.026 UTC [7] LOG: starting PostgreSQL 15.4 (Debian 15.4-2.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2023-10-10 15:07:49.026 UTC [7] LOG: listening on IPv4 address "0.0.0.0", port 5432
2023-10-10 15:07:49.026 UTC [7] LOG: listening on IPv6 address "::", port 5432
2023-10-10 15:07:49.032 UTC [7] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-10-10 15:07:49.037 UTC [279] LOG: database system was shut down at 2023-10-10 15:07:48 UTC
2023-10-10 15:07:49.041 UTC [7] LOG: database system is ready to accept connections
2023-10-10 15:12:49.061 UTC [277] LOG: checkpoint starting: time
2023-10-10 15:12:49.078 UTC [277] LOG: checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.007 s, sync=0.001 s, total=0.018 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB
