PG11 基于时间点恢复在时间线上无限循环

restore_command = '/usr/bin/lz4 -f -q -d /data/database/1/backup/%f.lz4 %p'
recovery_target_action = 'promote'
recovery_target_inclusive = false
recovery_target_time = '2021-10-24 17:19:00'

正常恢复完 wal 后

日志里不停循环
2021-10-24 22:30:41.733 CST [32146] LOG: restored log file "000003A9.history" from archive
/data/database/1/backup/000003AA.history.lz4: No such file or directory
2021-10-24 22:30:41.739 CST [32146] LOG: restored log file "000003AA.history" from archive
/data/database/1/backup/000003AB.history.lz4: No such file or directory
2021-10-24 22:30:41.745 CST [32146] LOG: restored log file "000003AB.history" from archive
/data/database/1/backup/000003AC.history.lz4: No such file or directory
2021-10-24 22:30:41.752 CST [32146] LOG: restored log file "000003AC.history" from archive
/data/database/1/backup/000003AD.history.lz4: No such file or directory
2021-10-24 22:30:41.758 CST [32146] LOG: restored log file "000003AD.history" from archive
/data/database/1/backup/000003AE.history.lz4: No such file or directory
2021-10-24 22:30:41.765 CST [32146] LOG: restored log file "000003AE.history" from archive

这啥问题啊,一晚上了没解决,要哭了呀

源数据没有启过新时间线,不知道为什么恢复的时候会无限寻找“下一个时间线”
升级到 11.13 也没用...感觉不找到最大时间线不停了....

lolizeppelin

2021-10-24 22:51:06 +08:00

debug5 级别日志

2021-10-24 22:49:09.874 CST [4514] LOG: database system was shut down in recovery at 2021-10-24 22:30:59 CST
2021-10-24 22:49:09.874 CST [4514] DEBUG: restore_command = '/usr/bin/lz4 -f -q -d /data/database/1/backup/%f.lz4 %p'
2021-10-24 22:49:09.874 CST [4514] DEBUG: recovery_target_action = 'promote'
2021-10-24 22:49:09.874 CST [4514] DEBUG: recovery_target_inclusive = false
2021-10-24 22:49:09.875 CST [4514] DEBUG: recovery_target_time = '2021-10-24 17:19:00+08'
2021-10-24 22:49:09.875 CST [4514] LOG: starting point-in-time recovery to 2021-10-24 17:19:00+08
2021-10-24 22:49:09.875 CST [4514] DEBUG: executing restore command "/usr/bin/lz4 -f -q -d /data/database/1/backup/000000010000000200000023.lz4 pg_wal/RECOVERYXLOG"
2021-10-24 22:49:09.910 CST [4514] LOG: restored log file "000000010000000200000023" from archive
2021-10-24 22:49:09.912 CST [4514] DEBUG: got WAL segment from archive
2021-10-24 22:49:09.912 CST [4514] DEBUG: checkpoint record is at 2/23001C18
2021-10-24 22:49:09.913 CST [4514] DEBUG: redo record is at 2/23001BE0; shutdown false
2021-10-24 22:49:09.913 CST [4514] DEBUG: next transaction ID: 0:4735090; next OID: 34298
2021-10-24 22:49:09.913 CST [4514] DEBUG: next MultiXactId: 1; next MultiXactOffset: 0
2021-10-24 22:49:09.913 CST [4514] DEBUG: oldest unfrozen transaction ID: 562, in database 1
2021-10-24 22:49:09.913 CST [4514] DEBUG: oldest MultiXactId: 1, in database 1
2021-10-24 22:49:09.913 CST [4514] DEBUG: commit timestamp Xid oldest/newest: 0/0
2021-10-24 22:49:09.913 CST [4514] DEBUG: transaction ID wrap limit is 2147484209, limited by database with OID 1
2021-10-24 22:49:09.913 CST [4514] DEBUG: MultiXactId wrap limit is 2147483648, limited by database with OID 1
2021-10-24 22:49:09.913 CST [4514] DEBUG: starting up replication slots
2021-10-24 22:49:09.913 CST [4514] DEBUG: starting up replication origin progress state
2021-10-24 22:49:09.914 CST [4514] DEBUG: resetting unlogged relations: cleanup 1 init 0
2021-10-24 22:49:09.916 CST [4514] DEBUG: initializing for hot standby
2021-10-24 22:49:09.916 CST [4514] DEBUG: my backend ID is 1
2021-10-24 22:49:09.916 CST [4514] LOG: redo starts at 2/23001BE0
2021-10-24 22:49:09.916 CST [4514] DEBUG: prune KnownAssignedXids to 4735090
2021-10-24 22:49:09.916 CST [4514] CONTEXT: WAL redo at 2/23001BE0 for Standby/RUNNING_XACTS: nextXid 4735090 latestCompletedXid 4735089 oldestRunningXid 4735090
2021-10-24 22:49:09.916 CST [4514] DEBUG: 0 KnownAssignedXids (num=0 tail=0 head=0)
2021-10-24 22:49:09.916 CST [4514] CONTEXT: WAL redo at 2/23001BE0 for Standby/RUNNING_XACTS: nextXid 4735090 latestCompletedXid 4735089 oldestRunningXid 4735090
2021-10-24 22:49:09.916 CST [4514] DEBUG: recovery snapshots are now enabled
2021-10-24 22:49:09.916 CST [4514] CONTEXT: WAL redo at 2/23001BE0 for Standby/RUNNING_XACTS: nextXid 4735090 latestCompletedXid 4735089 oldestRunningXid 4735090
2021-10-24 22:49:09.916 CST [4514] DEBUG: prune KnownAssignedXids to 4735090
2021-10-24 22:49:09.916 CST [4514] CONTEXT: WAL redo at 2/23001C88 for Standby/RUNNING_XACTS: nextXid 4735090 latestCompletedXid 4735089 oldestRunningXid 4735090
2021-10-24 22:49:09.916 CST [4514] DEBUG: record known xact 4735090 latestObservedXid 4735089
2021-10-24 22:49:09.916 CST [4514] CONTEXT: WAL redo at 2/23001CC0 for Heap/DELETE: off 2 KEYS_UPDATED
2021-10-24 22:49:09.917 CST [4514] LOG: consistent recovery state reached at 2/230029E8
2021-10-24 22:49:09.917 CST [4514] LOG: recovery stopping before commit of transaction 4735090, time 2021-10-24 17:44:51.300459+08
2021-10-24 22:49:09.917 CST [4514] LOG: redo done at 2/230029E8
2021-10-24 22:49:09.917 CST [4514] DEBUG: resetting unlogged relations: cleanup 0 init 1
2021-10-24 22:49:09.918 CST [4512] LOG: database system is ready to accept read only connections
2021-10-24 22:49:09.918 CST [4516] DEBUG: checkpointer updated shared memory configuration values
2021-10-24 22:49:09.919 CST [4514] DEBUG: executing restore command "/usr/bin/lz4 -f -q -d /data/database/1/backup/00000002.history.lz4 pg_wal/RECOVERYHISTORY"
/data/database/1/backup/00000002.history.lz4: No such file or directory
2021-10-24 22:49:09.926 CST [4514] LOG: restored log file "00000002.history" from archive
2021-10-24 22:49:09.926 CST [4514] DEBUG: executing restore command "/usr/bin/lz4 -f -q -d /data/database/1/backup/00000003.history.lz4 pg_wal/RECOVERYHISTORY"
/data/database/1/backup/00000003.history.lz4: No such file or directory
2021-10-24 22:49:09.933 CST [4514] LOG: restored log file "00000003.history" from archive
2021-10-24 22:49:09.933 CST [4514] DEBUG: executing restore command "/usr/bin/lz4 -f -q -d /data/database/1/backup/00000004.history.lz4 pg_wal/RECOVERYHISTORY"

后面就是无限循环找时间线....orz