0

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:

  1. Extract from base.tar
  2. Copy configuration files (including recovery.conf) into the extract folder
  3. Stop Postgres
  4. Delete data folder
  5. Copy extract into data folder
  6. Grant write access to data folder
  7. Start Progress
  8. 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

3
  • You should upgrade PostgreSQL. In your question, you were too short in the description of what you did. How exactly did you "re-run the recovery"? Created another recovery.conf file and restarted? Restored the base backup again? Please describe the exact steps, and add the contents of the log file. Mar 9 at 8:09
  • Was that log from the broken restore, or the correct restore? Which it was, please show the logs from the other one as well.
    – jjanes
    Mar 9 at 13:18
  • Tried to answer your points by adding more information to original question
    – Arpad
    Mar 9 at 15:08

0

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.