+ '[' -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