Osterei: cache lookup failed for relation

Hallo zusammen,

der Osterhase hat mit ein schönes Ei ins Nest gelegt. Am 2.4. habe ich in meinem Protokoll folgendes stehen:

2010-04-02 02:17:34 CEST   LOG:  Systemlogger-Prozess (PID 31994) wurde von Signal 9 beendet
2010-04-02 02:17:34 CEST   LOG:  Background-Writer-Prozess (PID 31996) wurde von Signal 9 beendet
2010-04-02 02:17:34 CEST   LOG:  aktive Serverprozesse werden abgebrochen
2010-04-02 02:17:34 CEST   LOG:  alle Serverprozesse beendet; initialisiere neu
2010-04-02 02:18:03 CEST postgres postgres FATAL:  das Datenbanksystem startet
2010-04-02 02:18:03 CEST   LOG:  Datenbanksystem wurde am 2010-04-02 02:15:12 CEST unterbrochen
2010-04-02 02:18:03 CEST   LOG:  konnte Datei »pg_xlog/0000000100000009000000F6« nicht öffnen (Logdatei 9, Segment 246): Datei oder Verzeichnis nicht gefunden
2010-04-02 02:18:03 CEST   LOG:  ungültiger Checkpoint-Datensatz
2010-04-02 02:18:03 CEST   PANIK:  konnte den nötigen Checkpoint-Datensatz nicht finden
2010-04-02 02:18:03 CEST   TIPP:  Wenn Sie kein Backup wiederherstellen, versuchen Sie, die Datei »/var/lib/pgsql/data/backup_label« zu löschen.
2010-04-02 02:18:03 CEST   LOG:  Start-Prozess (PID 14209) wurde von Signal 6 beendet
2010-04-02 02:18:03 CEST   LOG:  Serverstart abgebrochen wegen Start-Prozess-Fehler
2010-04-02 02:18:28 CEST   FATAL:  Archivbefehl »test ! -f /var/lib/pgsql/archive/tx_log/000000010000000B0000001C && cp pg_xlog/000000010000000B0000001C /var/lib/pgsql/archive/tx_log/000000010000000B000001C« fehlgeschlagen: Fehlercode 3
2010-04-02 02:18:28 CEST   LOG:  Logger fährt herunter

Damit verbunden stand die DB - bis heute. Den Datenbankserver neu starten ging nicht, dann kam der hier:

2010-04-06 08:24:06 CEST   LOG:  Datenbanksystem wurde am 2010-04-02 02:15:12 CEST unterbrochen
2010-04-06 08:24:06 CEST   LOG:  konnte Datei »pg_xlog/0000000100000009000000F6« nicht öffnen (Logdatei 9, Segment 246): Datei oder Verzeichnis nicht gefunden
2010-04-06 08:24:06 CEST   LOG:  ungültiger Checkpoint-Datensatz
2010-04-06 08:24:06 CEST   PANIK:  konnte den nötigen Checkpoint-Datensatz nicht finden
2010-04-06 08:24:06 CEST   TIPP:  Wenn Sie kein Backup wiederherstellen, versuchen Sie, die Datei »/var/lib/pgsql/data/backup_label« zu löschen.
2010-04-06 08:24:06 CEST   LOG:  Start-Prozess (PID 31424) wurde von Signal 6 beendet
2010-04-06 08:24:06 CEST   LOG:  Serverstart abgebrochen wegen Start-Prozess-Fehler
2010-04-06 08:24:06 CEST   LOG:  Logger fährt herunter

Die fehlende Datei (eigentlich waren es zwei) habe ich aus dem Archiv zurückkopiert, dann ist der Server wieder gestartet, hatte aber folgendes bei INSERTs zu meckern:

2010-04-06 08:49:17 CEST mediweb mediweb FEHLER:  duplizierter Schlüssel verletzt Unique-Constraint »auth_user_pkey«

Da die Applikation bisher aber immer fehlerfrei lief, schließe ich die derzeit aus. Habe also versucht, ein VACUUM FULL zu machen. Das hat mir gesagt, geht nicht, da das tx_log nicht geschrieben werden kann:

2010-04-06 08:54:57 CEST   FEHLER:  xlog flush request A/910115D0 is not satisfied --- flushed only to 9/F8005FBC
2010-04-06 08:54:57 CEST   ZUSAMMENHANG:  schreibe Block 0 von Relation 1663/66156/75859

Das kam dann permantent:

2010-04-06 09:30:43 CEST   FEHLER:  xlog flush request A/39067B04 is not satisfied --- flushed only to A/31D47E24
2010-04-06 09:30:43 CEST   ZUSAMMENHANG:  schreibe Block 216201 von Relation 1663/66156/91817
2010-04-06 09:30:43 CEST   WARNUNG:  konnte Block 216201 von 1663/66156/91817 nicht schreiben
2010-04-06 09:30:43 CEST   DETAIL:  Mehrere Fehlschläge --- Schreibfehler ist möglicherweise dauerhaft.

Ich habe dann mit

pg_resetxlog -f /var/lib/pgsql/data

das Transaktionslog resettet… Und nun kann ich eine der DBs gar nicht mehr verbinden:

2010-04-06 09:57:12 CEST mediweb postgres FATAL:  XX000: cache lookup failed for relation 2659
2010-04-06 09:57:12 CEST mediweb postgres ORT:  RelationCacheInitializePhase2, relcache.c:2433

Das System ist ein SLES 10 mit PG 8.2.

Hat jemand eine Idee?

murphy

Ja, spiel das letzte Backup wieder ein, ist der einfachste Weg.

Das Verzeichnis sieht so aus, als wäre es mittels Online Backup erstellt worden, allerdings fehlen zwingend notwendige Transaktionslogs und ein Recovery beim Anfahren wurde wohl auch nicht durchgeführt.

Doch, habe ich gerade gefunden:

postgresql-2010-04-06_084454.log:2010-04-06 08:44:55 CEST   LOG:  Datenbanksystem wurde während der Wiederherstellung am 2010-04-06 08:43:26 CEST unterbrochen
postgresql-2010-04-06_084454.log:2010-04-06 08:44:55 CEST   TIPP:  Das bedeutet wahrscheinlich, dass einige Daten verfälscht sind und Sie die letzte Datensicherung zur Wiederherstellung verwenden müssen.
postgresql-2010-04-06_084454.log:2010-04-06 08:44:55 CEST   LOG:  Datenbanksystem wurde nicht richtig heruntergefahren; automatische Wiederherstellung läuft

Ich wollte PITR schon immer mal wieder machen :wink:

Ich hätte es vorher mal getestet und mich nicht einfach so drauf verlassen :wink:

Hab ich ja (selbstverständlich :-))… Die Betonung lag auf “wieder”.
Geht jetzt auch wieder, aber weiß jemand, was die Meldung “cache lookup failed” heißen soll?

Andere Frage: wieso wurde die DB eigentlich mit -9 gekillt?

So, zu deiner Frage: diese Relation kann nicht gefunden werden, nicht im Cache (RAM) und nicht auf der Platte.

Das kann nur durch das OS erfolgt sein oder den DB-Server selbst. Um 2.18 Uhr sitzt hier niemand und schießt Datenbanken ab (hoffe ich). Kann PG so etwas verursachen, wenn die TX-Logs nicht weggeschrieben werden können oder so…? Nee, oder?

So, zu deiner Frage: diese Relation kann nicht gefunden werden, nicht im Cache (RAM) und nicht auf der Platte.

Kann das auf falsche permissions zurückzuführen sein, sodass Teile der DB nicht gelesen werden können?

Ich habe einmal das Basisbackup eingespielt und die logs bis zum Ende abgespielt, dann hatte ich den Fehler wieder/immernoch. Beim zweiten mal habe ich den Wiederherstellungslauf am 2.4.10 um 2.15 Uhr stoppen lassen, jetzt ist alles klar. Da die DB ja solange nicht lief, hat sich auch nichts geändert… Aber merkwürdig ist das schon!

Bleibt die Frage, warum das Ding mit -9 stirbt? Im /var/log/messages steht nichts.

Die Datenbank killt sich nicht selbst mit -9. Das muss von außen verursacht worden sein.

Die “xlog flush requests” würden mir zu denken geben. Ist die Hardware in Ordnung? Gibt es ev. im Syslog Probleme beim Schreiben oder Lesen der Platte?

Wie gesagt, im /var/log/messages gibt es keinen relevanten Eintrag und auch “dmesg” gibt nur irgendwelchen Firewallkram aus. Nichts plattentechnisches… kene I/O-Fehler oder so. Ich befürchte, hier ist nichts mehr zu machen.

Aber: das Signal -9 und die xlog-flush-requests stehen ja auch nicht unbedingt in einem logischen Zusammenhang.