PITR findet keinen konsistenten Zeitpunkt!!!

Hallo Postgresgemeinde,


folgendes Problem habe ich beim durchführen von Point in Time Recovery:


PITR beendet immer mit der Fehlermeldung “FATAL: requested recovery stop point is before consistent recovery point”


Folgendes ist konfiguriert:
Alle Server Laufen auf CentOS und PostgreSQL 9.0


Ein Server läuft als Master und ein zweiter als Standby, der sowohl Streaming Replication als auch WAL-Shipping durchführt.
Wird ein Backup gebraucht soll der Standby-Server gestoppt werden und das PITR durchgeführt werden, um diesen Server dann zu einer beliebigen Zeit als Master hochfahren zu können.


Das WAL-Shipping kopiert alle WAL-Dateien in den Ordner pg_xlog_archive auf dem Slave. Von da aus werden sie dann eingespielt.


So wie ich bis jetzt gelesen habe, tritt dieser Fehler auf, wenn man versucht zu einem Zeitpunkt zurück zu springen, der älter ist, als der Zeitpunkt an dem man das initiale Basebackup beendet hat.
Deswegen habe ich hier auch mal die logdatei des Basebackups angefügt. Gleich danach die recovery config mit recovery_target_time die äter ist als die STOP TIME.


Wie unter log zu sehen ist bekomme ich trotzdem die oben genannte Fehlermeldung.
Was ich nun etwas eigenartig finde ist (siehe log…), dass ich zwar einen Zeitpunkt um 17:35 anfordere, postgresql jedoch bei der datei 47/A7 anfängt (redo starts at…). Diese Datei wurde erst viel später um 17:42 erstellt.
Beendet wird das ganze dann noch ein paar Transaktionen später bei der Datei 47/A8.


Um meinen gewünschten Zeitpunkt zu erreichen hätte ich jetzt erwartet, dass Postgres früher anfängt. irgendwo bei Datei 47/A5 und irgendwo bei A6 endet. Dort müsste sich ja irgendwo mein gewünter Transaktionszeitpunkt befinden.


Hat jemand eine Idee woran es liegen könnte?


Grüße, Max


-----Anhang--------------------------------------------------------------->






backup


START WAL LOCATION: 47/A2000020 (file 0000000500000047000000A2)
STOP WAL LOCATION: 47/A20000D8 (file 0000000500000047000000A2)
CHECKPOINT LOCATION: 47/A2000058
START TIME: 2012-01-10 17:17:43 CET
LABEL: basebackup
STOP TIME: 2012-01-10 17:17:44 CET




recovery.conf


restore_command = ‘cp /var/lib/pgsql/9.0/data/pg_xlog_archive/%f %p’
recovery_target_time = ‘2012-01-10 17:35:00 CET’




log Slave Server auf dem PITR durchgeführt wurde


Jan 10 17:47:53 db-3 pgsql_postgresql-9.0: Starting postgresql-9.0 service:
Jan 10 17:47:54 db-3 pgsql_postmaster[25740]: [1-1] @/LOG: database system was shut down in recovery at 2012-01-10 17:44:50 CET
Jan 10 17:47:54 db-3 pgsql_postmaster[25740]: [2-1] @/LOG: restored log file “00000005.history” from archive
Jan 10 17:47:54 db-3 pgsql_postmaster[25740]: [3-1] @/LOG: starting point-in-time recovery to 2012-01-10 17:35:00+01
Jan 10 17:47:54 db-3 pgsql_postmaster[25740]: [4-1] @/LOG: restored log file “0000000500000047000000A8” from archive
Jan 10 17:47:54 db-3 pgsql_postmaster[25740]: [5-1] @/LOG: restored log file “0000000500000047000000A7” from archive
Jan 10 17:47:54 db-3 pgsql_postmaster[25740]: [6-1] @/LOG: redo starts at 47/A7040AE0
Jan 10 17:47:54 db-3 pgsql_postmaster[25740]: [7-1] @/LOG: restored log file “0000000500000047000000A8” from archive
Jan 10 17:47:54 db-3 pgsql_postmaster[25740]: [8-1] @/LOG: recovery stopping before commit of transaction 61328, time 2012-01-10 17:42:46.440899+01
Jan 10 17:47:54 db-3 pgsql_postmaster[25740]: [9-1] @/LOG: redo done at 47/A8004640
Jan 10 17:47:54 db-3 pgsql_postmaster[25740]: [10-1] @/FATAL: requested recovery stop point is before consistent recovery point
Jan 10 17:47:54 db-3 pgsql_postmaster[25738]: [1-1] @/LOG: startup process (PID 25740) exited with exit code 1
Jan 10 17:47:54 db-3 pgsql_postmaster[25738]: [2-1] @/LOG: terminating any other active server processes




WAL-Files


-rw------- 1 postgres postgres 16777216 Jan 10 17:17 0000000500000047000000A2
-rw------- 1 postgres postgres 249 Jan 10 17:17 0000000500000047000000A2.00000020.backup
-rw------- 1 postgres postgres 16777216 Jan 10 17:22 0000000500000047000000A3
-rw------- 1 postgres postgres 16777216 Jan 10 17:27 0000000500000047000000A4
-rw------- 1 postgres postgres 16777216 Jan 10 17:32 0000000500000047000000A5
-rw------- 1 postgres postgres 16777216 Jan 10 17:37 0000000500000047000000A6
-rw------- 1 postgres postgres 16777216 Jan 10 17:42 0000000500000047000000A7
-rw------- 1 postgres postgres 16777216 Jan 10 17:47 0000000500000047000000A8
-rw------- 1 postgres postgres 16777216 Jan 10 17:52 0000000500000047000000A9

Was steht denn in der “5.history” und der “20.backup” Datei drin?

in 20.backup hab ich unter Anhang als backup angehängt:

START WAL LOCATION: 47/A2000020 (file 0000000500000047000000A2)
STOP WAL LOCATION: 47/A20000D8 (file 0000000500000047000000A2)
CHECKPOINT LOCATION: 47/A2000058
START TIME: 2012-01-10 17:17:43 CET
LABEL: basebackup
STOP TIME: 2012-01-10 17:17:44 CET

In der 5.history steht folgendes:



2 00000002000000250000005E no recovery target specified


3 00000003000000470000008E before 2000-01-01 01:00:00+01


4 00000004000000470000008F before 2000-01-01 01:00:00+01


Was ist denn da in der dritten spalte mit “before …Datum…” gemeint? Der Server ist auf keinen Fall 12 Jahre alt :slight_smile:

Ah, ich sehe jetzt erst, das du einen bestimmten Zeitpunkt als Recovery Stop angegeben hast.
Du kannst nur einen Zeitpunkt angeben der sich nach dem Stop des Backups befindet.

Das ist auch die Antwort die ich überall im Internet und auch von Postgres-Team direkt bekommen habe.

Mein Backup wurde aber um 17:17 gestoppt: STOP TIME: 2012-01-10 17:17:44 CET
Mein geforderter Zeitpunkt ist jedoch 17:35: recovery_target_time = ‘2012-01-10 17:35:00 CET’
Eigentlich müsste das funktionieren oder sehe ich das falsch?

Wenn du genauer hinschaust, dann siehst du, das da etwas durcheinander gerät.
Dein Backup ist tatsächlich von 17:17 Uhr und im Logfile A2.

Aber das Restore startet aber schon in Logfile A8 - kann es sein, das du von einem anderen Backup startest?

Ja, das ist mir auch aufgefallen. Ich will ja eigentlich bis A6 wiederherstellen.
Was ich eben nur nicht verstehe, wieso er mit A8 anfängt.
Ich habe bei dem Versuch extra sichergestellt, dass niemand sonst einen basebackup durchführt.
Habe extra drauf geachtet, dass alles in der richtigen Reihenfolge geschieht.
Erst Basebackup, dann habe ich etwas gewartet und den recovery-target nach dem basebackup stop gelegt.
Es ist ja nicht so, dass es ein Betriebsunfall und zufällig was durcheinander geraten ist :slight_smile:
Ich mache das alles in einer Testumgebung und habe diesen Versuch mehrfach durchgeführt. Jedes mal genaustens drauf geachtet mir bekannte Fehlerquellen auszuschließen und trotzdem wiederholt sich der Fehler jedes mal genau so.

Hast du eine Erklärung dafür wieso er erst mit A8 anfängt?

Gibt es noch andere .backup und .history Dateien im Verzeichnis?
Vielleicht könntest du vor dem Test mal mit einem leeren Verzeichnis für die WAL anfangen - um diese Fehlerquelle auszuschließen.

Auf dem Slave habe ich vor dem Test sowohl pg_xlog als auch pg_xlog_archive geleert. Im Anhang sind auch alle Dateien in pg_xlog_archive aufgelistet. Es sind wirklich nur wenige Dateien und nur eine mit der Endung .backup

Die Systemzeiten auf beiden Rechnern geprüft?
Ansonsten fällt mir mit den Informationen nichts mehr ein. Müsste man sich direkt mal anschauen.

Die Zeiten waren es auch nicht.Ich glaube das Problem gefunden zu haben. Es war mein Fehler in der Konzeption. Für alle die ein ähnliches Problem haben hier eine kleine Beschreibung.Ausschlaggebend für das Problem war, dass Postgresql versehentlich WAL-Dateien aus dem Archiv eingespielt hat. Es wurden zwar WAL-Dateien der letzten 24 h aufgehoben und zuvor ein konsistentes Basebackup gemacht. Jedoch wurde Postgresql in der Zwischenzeit als Standby hochgefahren und hat die hälfte der WAL-Dateien aus dem Archiv eingespielt.Obwohl nun noch alle WAL-Dateien der letzten 24 h vorhanden sind, ist es dann nicht mehr möglich zu einem früheren Zeitpunkt zu springen als die zuletzt eingespielte WAL-Datei. Sprich wenn 20 der 24h wieder eingespielt wurden, kann man nur zurück zu den letzten 4 Stunden springen.Das sollte auch für ein Point in time Recovery gelten, wo man den Zeitpunkt versehentlich zu spät gewählt hat. Ich hab bis jetzt keine Möglichkeit gefunden mittels PITR trotzdem einen noch älteren Zeitpunkt wieder her zu stellen.Lösung somit simple: Vor dem PITR auf jeden Fall ein Backup vom Postgresql Datenordner machen.Bitte korrigiert mich wenn ich da falsch liege und es doch eine Möglichkeit gibt ein zweiter PITR zu einem noch früheren Zeitpunkt wieder her zu stellen.Und schon mal danke an ads für seine Tipps bei der Fehlersuche.

Nun, einfach nicht den Standby hoch fahren …
Und nein, es gibt keine Möglichkeit, auf einen früheren Zeitpunkt zurück zu springen.