Recovery doesn't pause during PITR

[Nikhil Shetty <nikhil.dba04@xxxxxxxxx>]

Hi Team,

I am trying to perform PITR using below settings in recovery.conf

restore_command = 'cp /opt/arch_bkp/%f %p'
recovery_target_time = '2021-03-31 05:49:10 UTC'
recovery_target_action = 'pause'

To test this I created a table after basebackup. I want the recovery to pause at the above specified time to check if the table is available. If the table is not available then I would like to extend the recovery_target_time and perform recovery again until my table is available.

In my case the database is not paused and it opens for r/w connections as seen from below logs:

2021-03-31 05:52:46.539 UTC [4577] LOG:  restored log file "00000001000000040000003C" from archive
2021-03-31 05:52:46.752 UTC [4577] LOG:  restored log file "00000001000000040000003D" from archive
2021-03-31 05:52:46.966 UTC [4577] LOG:  restored log file "00000001000000040000003E" from archive
2021-03-31 05:52:47.226 UTC [4577] LOG:  restored log file "00000001000000040000003F" from archive
2021-03-31 05:52:47.582 UTC [4577] LOG:  consistent recovery state reached at 4/3FE830C8
2021-03-31 05:52:47.582 UTC [4575] LOG:  database system is ready to accept read only connections
2021-03-31 05:52:47.612 UTC [4577] LOG:  restored log file "000000010000000400000040" from archive
2021-03-31 05:52:47.874 UTC [4577] LOG:  restored log file "000000010000000400000041" from archive
2021-03-31 05:52:48.150 UTC [4577] LOG:  restored log file "000000010000000400000042" from archive
2021-03-31 05:52:48.512 UTC [4577] LOG:  restored log file "000000010000000400000043" from archive
2021-03-31 05:52:48.782 UTC [4577] LOG:  restored log file "000000010000000400000044" from archive
2021-03-31 05:52:49.060 UTC [4577] LOG:  restored log file "000000010000000400000045" from archive
2021-03-31 05:52:49.399 UTC [4577] LOG:  restored log file "000000010000000400000046" from archive
2021-03-31 05:52:49.784 UTC [4577] LOG:  restored log file "000000010000000400000047" from archive
2021-03-31 05:52:50.146 UTC [4577] LOG:  restored log file "000000010000000400000048" from archive
2021-03-31 05:52:50.586 UTC [4577] LOG:  restored log file "000000010000000400000049" from archive
2021-03-31 05:52:50.882 UTC [4577] LOG:  restored log file "00000001000000040000004A" from archive
2021-03-31 05:52:51.320 UTC [4577] LOG:  restored log file "00000001000000040000004B" from archive
2021-03-31 05:52:51.656 UTC [4577] LOG:  restored log file "00000001000000040000004C" from archive
2021-03-31 05:52:52.037 UTC [4577] LOG:  restored log file "00000001000000040000004D" from archive
2021-03-31 05:52:52.454 UTC [4577] LOG:  restored log file "00000001000000040000004E" from archive
2021-03-31 05:52:52.959 UTC [4577] LOG:  restored log file "00000001000000040000004F" from archive
2021-03-31 05:52:53.299 UTC [4577] LOG:  restored log file "000000010000000400000050" from archive
2021-03-31 05:52:53.532 UTC [4577] LOG:  restored log file "000000010000000400000051" from archive
2021-03-31 05:52:53.691 UTC [4577] LOG:  restored log file "000000010000000400000052" from archive
2021-03-31 05:52:53.813 UTC [4577] LOG:  restored log file "000000010000000400000053" from archive
2021-03-31 05:52:53.935 UTC [4577] LOG:  restored log file "000000010000000400000054" from archive
2021-03-31 05:52:54.114 UTC [4577] LOG:  restored log file "000000010000000400000055" from archive
2021-03-31 05:52:54.272 UTC [4577] LOG:  restored log file "000000010000000400000056" from archive
2021-03-31 05:52:54.423 UTC [4577] LOG:  restored log file "000000010000000400000057" from archive
2021-03-31 05:52:54.560 UTC [4577] LOG:  restored log file "000000010000000400000058" from archive
2021-03-31 05:52:54.758 UTC [4577] LOG:  restored log file "000000010000000400000059" from archive
2021-03-31 05:52:54.949 UTC [4577] LOG:  restored log file "00000001000000040000005A" from archive
2021-03-31 05:52:55.074 UTC [4577] LOG:  restored log file "00000001000000040000005B" from archive
2021-03-31 05:52:55.298 UTC [4577] LOG:  restored log file "00000001000000040000005C" from archive
2021-03-31 05:52:55.413 UTC [4577] LOG:  restored log file "00000001000000040000005D" from archive
2021-03-31 05:52:55.578 UTC [4577] LOG:  restored log file "00000001000000040000005E" from archive
2021-03-31 05:52:55.839 UTC [4577] LOG:  restored log file "00000001000000040000005F" from archive
2021-03-31 05:52:55.999 UTC [4577] LOG:  restored log file "000000010000000400000060" from archive
2021-03-31 05:52:56.135 UTC [4577] LOG:  restored log file "000000010000000400000061" from archive
2021-03-31 05:52:56.261 UTC [4577] LOG:  restored log file "000000010000000400000062" from archive
2021-03-31 05:52:56.433 UTC [4577] LOG:  restored log file "000000010000000400000063" from archive
cp: cannot stat ‘/opt/arch_bkp/000000010000000400000064’: No such file or directory
2021-03-31 05:52:56.593 UTC [4577] LOG:  redo done at 4/63FFC750
2021-03-31 05:52:56.593 UTC [4577] LOG:  last completed transaction was at log time 2021-03-31 05:49:07.634527+00
2021-03-31 05:52:56.619 UTC [4577] LOG:  restored log file "000000010000000400000063" from archive
cp: cannot stat ‘/opt/arch_bkp/00000002.history’: No such file or directory
2021-03-31 05:52:56.701 UTC [4577] LOG:  selected new timeline ID: 2
2021-03-31 05:52:56.755 UTC [4577] LOG:  archive recovery complete
cp: cannot stat ‘/opt/arch_bkp/00000001.history’: No such file or directory
2021-03-31 05:52:56.762 UTC [4581] LOG:  checkpoint starting: end-of-recovery immediate wait
2021-03-31 05:52:57.541 UTC [4581] LOG:  checkpoint complete: wrote 16084 buffers (98.2%); 0 WAL file(s) added, 0 removed, 61 recycled; write=0.437 s, sync=0.273 s, total=0.779 s; sync files=20, longest=0.236 s, average=0.014 s; distance=1015800 kB, estimate=1015800 kB
2021-03-31 05:52:57.630 UTC [4575] LOG:  database system is ready to accept connections

PostgreSQL version: 11.11

I don't see any issue with my configuration. 

Thanks and Regards,

Nikhil