On Wed, 2018-10-10 at 11:24 +0800, magodo wrote:
> Hello,
>
> I'm figuring out how to do PITR on a HA setup for postgres 9.6. I
> almost manage to do it, while I faced following issue:
>
>
> [1. create basebackup]
>
> [2. insert 2 rows]
>
> on both primary and standby's pg_xlog
>
> 000000010000000000000005
>
> rmgr: Transaction len (rec/tot): 34/ 34, tx: 633, lsn:
> 0/05016120, prev 0/050160E0, desc: COMMIT 2018-10-10 03:04:58.459754
> UTC - insert 1 (before: 2018-10-10 11:05:04 +08:00)
>
> rmgr: Transaction len (rec/tot): 34/ 34, tx: 634, lsn:
> 0/05016188, prev 0/05016148, desc: COMMIT 2018-10-10 03:05:07.010478
> UTC - insert 2 (before: 2018-10-10 11:05:09 +08:00)
>
> [3. failover and promote the standby]
>
> 000000010000000000000005 been archived as
> 000000010000000000000005.partial, and a new wal is switched out
> named:
> 000000020000000000000005, which contains above two commits.
>
> [4. recover to "after insert 1st row"]
>
> Stop new standby(the rewinded primary), and on the new
> primary(promoted
> standby), do following:
>
> 1. stop DB
> 2. sync $PGDATA against basebackup
> 3. create a recovery.conf with following content:
>
> restore_command = 'cp /var/lib/pgsql/9.6/data/archive/%f %p'
> recovery_target_timeline = 2
> recovery_target_time = '2018-10-10 11:05:04 +08:00'
>
> 4. stat DB
>
> Then I expect server is recovered to the time before insert 2nd row
> but
> after insert 1st row. The result is as I expected, but it is in a
> "read-only transaction". The log shows following:
>
> < 2018-10-10 03:09:56.790 UTC > LOG: database system was
> interrupted;
> last known up at 2018-10-10 02:57:59 UTC
> < 2018-10-10 03:09:56.931 UTC > DEBUG: restore_command = 'cp
> /var/lib/pgsql/9.6/data/archive/%f %p'
> < 2018-10-10 03:09:56.931 UTC > DEBUG: recovery_target_timeline = 2
> < 2018-10-10 03:09:56.931 UTC > DEBUG: recovery_target_time = '2018-
> 10-10 03:05:04+00'
> < 2018-10-10 03:09:56.934 UTC > LOG: restored log file
> "00000002.history" from archive
> < 2018-10-10 03:09:56.934 UTC > LOG: starting point-in-time recovery
> to 2018-10-10 03:05:04+00
> < 2018-10-10 03:09:56.936 UTC > LOG: restored log file
> "00000002.history" from archive
> cp: cannot stat
> '/var/lib/pgsql/9.6/data/archive/000000020000000000000004': No such
> file or directory
> < 2018-10-10 03:09:56.941 UTC > DEBUG: could not restore file
> "000000020000000000000004" from archive: child process exited with
> exit
> code
> 1
>
>
> < 2018-10-10 03:09:56.952 UTC > LOG: restored log file
> "000000010000000000000004" from archive
> < 2018-10-10 03:09:57.012 UTC > DEBUG: got WAL segment from archive
> < 2018-10-10 03:09:57.013 UTC > DEBUG: checkpoint record is at
> 0/4000060
> < 2018-10-10 03:09:57.013 UTC > DEBUG: redo record is at 0/4000028;
> shutdown FALSE
> < 2018-10-10 03:09:57.013 UTC > DEBUG: next transaction ID: 0:632;
> next OID: 16385
> < 2018-10-10 03:09:57.013 UTC > DEBUG: next MultiXactId: 1; next
> MultiXactOffset: 0
> < 2018-10-10 03:09:57.013 UTC > DEBUG: oldest unfrozen transaction
> ID:
> 623, in database 1
> < 2018-10-10 03:09:57.013 UTC > DEBUG: oldest MultiXactId: 1, in
> database 1
> < 2018-10-10 03:09:57.013 UTC > DEBUG: commit timestamp Xid
> oldest/newest: 0/0
> < 2018-10-10 03:09:57.013 UTC > DEBUG: transaction ID wrap limit is
> 2147484270, limited by database with OID 1
> < 2018-10-10 03:09:57.013 UTC > DEBUG: MultiXactId wrap limit is
> 2147483648, limited by database with OID 1
> < 2018-10-10 03:09:57.013 UTC > DEBUG: starting up replication slots
> < 2018-10-10 03:09:57.013 UTC > DEBUG: restoring replication slot
> from
> "pg_replslot/repl_slot/state"
> < 2018-10-10 03:09:57.015 UTC > DEBUG: starting up replication
> origin
> progress state
> < 2018-10-10 03:09:57.020 UTC > DEBUG: resetting unlogged relations:
> cleanup 1 init 0
> < 2018-10-10 03:09:57.021 UTC > DEBUG: initializing for hot standby
> < 2018-10-10 03:09:57.021 UTC > LOG: redo starts at 0/4000028
> < 2018-10-10 03:09:57.021 UTC > DEBUG: recovery snapshots are now
> enabled
> < 2018-10-10 03:09:57.021 UTC > CONTEXT: xlog redo at 0/4000028 for
> Standby/RUNNING_XACTS: nextXid 632 latestCompletedXid 631
> oldestRunningXid
> 632
>
>
> < 2018-10-10 03:09:57.021 UTC > DEBUG: end of backup reached
> < 2018-10-10 03:09:57.021 UTC > CONTEXT: xlog redo at 0/40000D0 for
> XLOG/BACKUP_END: 0/4000028
> < 2018-10-10 03:09:57.022 UTC > LOG: consistent recovery state
> reached
> at 0/40000F8
> < 2018-10-10 03:09:57.023 UTC > DEBUG: checkpointer updated shared
> memory configuration values
> < 2018-10-10 03:09:57.024 UTC > LOG: database system is ready to
> accept read only connections
> < 2018-10-10 03:09:57.028 UTC > DEBUG: archived transaction log file
> "000000010000000000000004"
> < 2018-10-10 03:09:57.035 UTC > DEBUG: archived transaction log file
> "00000002.history"
> < 2018-10-10 03:09:57.056 UTC > LOG: restored log file
> "000000020000000000000005" from archive
> < 2018-10-10 03:09:57.116 UTC > DEBUG: got WAL segment from archive
> < 2018-10-10 03:09:57.117 UTC > LOG: recovery stopping before commit
> of transaction 634, time 2018-10-10 03:05:07.010478+00
> < 2018-10-10 03:09:57.117 UTC > LOG: recovery has paused
> < 2018-10-10 03:09:57.117 UTC > HINT: Execute
> pg_xlog_replay_resume()
> to continue.
> < 2018-10-10 03:09:57.119 UTC > DEBUG: archived transaction log file
> "000000020000000000000005"
> < 2018-10-10 03:09:57.759 UTC > DEBUG: forked new backend, pid=254
> socket=11
> < 2018-10-10 03:09:57.771 UTC > DEBUG: server process (PID 254)
> exited
> with exit code 0
>
> And I have to execute `pg_xlog_replay_resume()` on the new primary so
> that it will branch out to new timeline 3 and work normally...
>
> Would anyone please tell me what's going on here? How can I avoid
> doing
> a manual resume?
>
> ---
> Magodo
I realized that because the basebackup is made from a hot standby, in
which the `hot_standby = on` is set in *postgresql.conf*.
From reference manual:
> ... This parameter can only be set at server start. It only has
effect during archive recovery or in standby mode.
So the primary after PITR has become a hot standby... Then I tried a
`pg_ctl promote` on it, but nothing happened.. Why?
---
Magodo