Failed to restore using pitr recoveryTargetTime

General Discussions
#1

We use wal-g to sync WAL to object storage. I tried to test recovery to point-in-time using command

stolonctl init --cluster-name=cluster --store-backend=consul --store-endpoints=consul-server.consul:8500 --store-prefix=cluster '{ "initMode": "pitr", "pitrConfig": { "recoveryTargetSettings": {"recoveryTargetTime": "2021-05-12 10:23:30"}, "dataRestoreCommand": "wal-g backup-fetch %d LATEST", "archiveRecoverySettings": { "restoreCommand": "wal-g wal-fetch \"%f\" \"%p\"" }}}'

I checked WAL files exists. recovery.conf looks fine

restore_command = ‘wal-g wal-fetch “%f” “%p”’
recovery_target_time = ‘2021-05-12 10:23:30’
recovery_target_action = ‘promote’

I added column and added some records inside table, but I see content of full backup instead without column and data.

#2

2021-05-12T10:37:13.400Z INFO cmd/keeper.go:1218 restoring the database cluster
2021-05-12T10:37:13.479Z INFO postgresql/postgresql.go:384 stopping database
2021-05-12 10:37:13.763 UTC [3320] FATAL: the database system is shutting down
2021-05-12T10:37:13.763Z ERROR cmd/keeper.go:720 cannot get configured pg parameters {“error”: “pq: the database system is shutting down”}
INFO: 2021/05/12 10:37:14.572194 FILE PATH: 0000000D0000000000000023.lz4
waiting for server to shut down… done
server stopped
2021-05-12T10:37:14.863Z INFO cmd/keeper.go:1243 executing DataRestoreCommand
INFO: 2021/05/12 10:37:15.483457 LATEST backup is: ‘base_00000008000000000000001F’
INFO: 2021/05/12 10:37:15.837171 Finished extraction of part_003.tar.lz4
INFO: 2021/05/12 10:37:15.837263 Finished decompression of part_003.tar.lz4
INFO: 2021/05/12 10:37:21.123568 Finished extraction of part_001.tar.lz4
INFO: 2021/05/12 10:37:21.123618 Finished decompression of part_001.tar.lz4
INFO: 2021/05/12 10:37:21.132384 Finished decompression of pg_control.tar.lz4
INFO: 2021/05/12 10:37:21.132416 Finished extraction of pg_control.tar.lz4
INFO: 2021/05/12 10:37:21.132439
Backup extraction complete.
2021-05-12T10:37:21.169Z INFO postgresql/postgresql.go:319 starting database
2021-05-12 10:37:21.362 UTC [3353] FATAL: the database system is starting up
2021-05-12T10:37:21.363Z ERROR cmd/keeper.go:720 cannot get configured pg parameters {“error”: “pq: the database system is starting up”}
2021-05-12T10:37:21.371Z INFO cmd/keeper.go:1265 waiting for recovery to be completed
2021-05-12T10:37:21.458Z INFO cmd/keeper.go:1270 recovery completed
2021-05-12 10:37:21.460 UTC [3355] FATAL: the database system is starting up
2021-05-12 10:37:21.663 UTC [3356] FATAL: the database system is starting up
2021-05-12 10:37:21.866 UTC [3357] FATAL: the database system is starting up
2021-05-12 10:37:22.068 UTC [3370] FATAL: the database system is starting up
2021-05-12 10:37:22.271 UTC [3376] FATAL: the database system is starting up
2021-05-12 10:37:22.474 UTC [3379] FATAL: the database system is starting up
2021-05-12 10:37:22.677 UTC [3381] FATAL: the database system is starting up
2021-05-12 10:37:22.879 UTC [3399] FATAL: the database system is starting up
2021-05-12 10:37:23.082 UTC [3402] FATAL: the database system is starting up
2021-05-12 10:37:23.287 UTC [3405] FATAL: the database system is starting up
2021-05-12 10:37:23.557 UTC [3406] FATAL: the database system is starting up
2021-05-12 10:37:23.760 UTC [3407] FATAL: the database system is starting up
2021-05-12 10:37:23.955 UTC [3408] FATAL: the database system is starting up
2021-05-12T10:37:23.955Z ERROR cmd/keeper.go:720 cannot get configured pg parameters {“error”: “pq: the database system is starting up”}
2021-05-12 10:37:23.963 UTC [3409] FATAL: the database system is starting up
2021-05-12 10:37:24.166 UTC [3410] FATAL: the database system is starting up
2021-05-12 10:37:24.371 UTC [3423] FATAL: the database system is starting up
2021-05-12T10:37:25.155Z INFO postgresql/postgresql.go:384 stopping database
waiting for server to shut down… done
server stopped
2021-05-12T10:37:25.498Z INFO cmd/keeper.go:1505 our db requested role is master
2021-05-12T10:37:25.598Z INFO postgresql/postgresql.go:319 starting database
2021-05-12 10:37:25.821 UTC [3470] FATAL: the database system is starting up
2021-05-12 10:37:26.058 UTC [3489] FATAL: the database system is starting up
2021-05-12 10:37:26.260 UTC [3490] FATAL: the database system is starting up
2021-05-12 10:37:26.459 UTC [3494] FATAL: the database system is starting up
2021-05-12T10:37:26.459Z ERROR cmd/keeper.go:720 cannot get configured pg parameters {“error”: “pq: the database system is starting up”}
2021-05-12 10:37:26.463 UTC [3496] FATAL: the database system is starting up
2021-05-12 10:37:26.665 UTC [3514] FATAL: the database system is starting up
2021-05-12 10:37:26.868 UTC [3517] FATAL: the database system is starting up
2021-05-12 10:37:27.155 UTC [3519] FATAL: the database system is starting up
2021-05-12 10:37:27.358 UTC [3520] FATAL: the database system is starting up
2021-05-12 10:37:27.561 UTC [3522] FATAL: the database system is starting up
2021-05-12 10:37:27.764 UTC [3524] FATAL: the database system is starting up
2021-05-12T10:37:28.258Z INFO cmd/keeper.go:1537 promoting to master
2021-05-12T10:37:28.258Z INFO postgresql/postgresql.go:532 promoting database
ERROR: 2021/05/12 10:37:33.109374 Archive ‘000000080000000000000021’ does not exist.
ERROR: 2021/05/12 10:37:43.364107 Archive ‘0000000E.history’ does not exist.
waiting for server to promote… done
server promoted

#3

If I don’t specify recoveryTargetTime, db is restored to latest state before removal, so it applies both base backup + WALs