Run into a strange issue using PostgreSQL 9.6 database on Windows OS
Using the recovery process with WAL files. Everything works fine - database starts up properly after recovery, no error message
BUT... if I re-run the recovery, in 90% of the cases the result is matching with the latest WAL file, but in 10% of the cases the recovery stops earlier than the latest WAL file, and Postgres starts up with a past stage.
No error message, it just says "consistent stage reached", without reading all WALs. It happens randomly.
Running restore on same WAL files could end up different result.
How to "re-run" recovery, extact steps:
- Extract from
base.tar
- Copy configuration files (including
recovery.conf
) into the extract folder - Stop Postgres
- Delete data folder
- Copy extract into data folder
- Grant write access to data folder
- Start Progress
- Wait until the recovery process completes and the service starts up
If I repeat this process several times, in 90% of the cases the database will be consistent of latest WAL, in 10% of the cases it won't.
What I tried:
- Added the Postgres and WAL folders as exception to the antivirus -> the issue still happens
base.tar
is not broken, because the bad recovery is started from same base file as good recovery- No error message in
pg_log
- Checked Windows log but not found anything related to the bad run (good run and bad run produces exact same Windows log)
recovery.conf
:
restore_command = 'copy "C:\\Source\\WAL\\%f" "%p"'
recovery_target_action = 'promote'
recovery_target_timeline = 'latest'
Using this command to start the recovery process:
net start postgresql-x64-9.6
pg_log
of a bad run - exactly same as pg_log
from good run, except few of WAL files not processed and last completed transaction timestamp is incorrect (no error message or anything)
2023-03-02 14:31:08 CET LOG: restored log file "000000010000164B0000003D" from archive
2023-03-02 14:31:08 CET LOG: restored log file "000000010000164B0000003E" from archive
2023-03-02 14:31:09 CET LOG: restored log file "000000010000164B0000003F" from archive
2023-03-02 14:31:09 CET LOG: redo done at 164B/3EFFEA88
2023-03-02 14:31:09 CET LOG: last completed transaction was at log time 2023-03-02 03:53:11.915884+01
2023-03-02 14:31:09 CET LOG: restored log file "000000010000164B0000003E" from archive
2023-03-02 14:31:09 CET LOG: selected new timeline ID: 2
2023-03-02 14:31:09 CET LOG: archive recovery complete
Please do not suggest upgrading Postgres, it is not an available option due to the application using the database
Some ideas:
Maybe the WAL files somehow locked or corrupted
Antivirus ignores the exception setting
Something in Windows impacts the recovery process
Disk error
I do something incorrectly...
The VM messing up something
The backup process in VM messing up something
recovery.conf
file and restarted? Restored the base backup again? Please describe the exact steps, and add the contents of the log file.