+ (( 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 $