WARNING: transaction log file could not be archived: too many failures

Hallo,

meine Logs sind voll mit folgender Fehlermeldung:
LOG: archive command “copy pg_xlog\00000001000000640000005C D:\BackUp_PostgreSql\WAL\00000001000000640000005C” failed: return code 1
2008-05-05 00:15:50 WARNING: transaction log file “00000001000000640000005C” could not be archived: too many failures

Der backup string lautet:
‘copy %p D:\BackUp_PostgreSql\WAL\%f’
Und funktioniert eigentlich auch soweit. Als der Fehler zum ersten Mal auftrat, wusste ich mir nicht zu helfen, und ich fuhr die Datenbank herunter, änderte die READY Datei zu Done, und machte so der Datenbanl glaubhaft, das sie die WAL-Files bereitsgesichter hatte.
Ich startete sie wieder, und alles war wieder in Ordnung. Natürlich hab ich sofort einen neuen Backup-Punkt gesetzt (SELECT pg_start_backup(‘label’) .

Aber irgendwann schleicht sich dann der Fehler wieder ein, und ich habe keinen Schimmer, wo durch dieser Fehler hervorgerufen wird.

Irgendwer eine Idee?

Welche Fehler mitten oder am Ende des Logs stehen, ist irrelevant. Wichtig ist der erste auftretende Fehler.

Andreas

Das ist kein PostgreSQL Fehler, das ist ein Fehler in deinem archive_command. Dieses liefert (warum, wirst du selbst herausfinden müssen) einen Fehlercode zurück - woraufhin PG annimmt, dass das entsprechende WAL Logfile nicht gesichert werden konnte.

Also, warum funktioniert dein copy Befehl nicht? Festplatte voll, Dateisystem nicht erreichbar? Dateisystem read-only? Verzeichnisname falsch? Gibt Dutzende Möglichkeiten.

In dem Backup Verzeichnis liegt diese Datei, und in dem pg_xlog ist sie schon gelöscht. Nur die Status-File ist noch auf “Ready” statt “Done”.

In den Server Logs steht erst ein Eintrag:
LOG: archived transaction log file “00000001000000640000005C”

Doch einige Zeit später, steht in den Logs, das es nicht geklappt hatte:

2008-04-30 05:32:55 LOG: archived transaction log file “00000001000000640000005C”
2008-04-30 05:33:42 LOG: archived transaction log file “00000001000000640000005D”
2008-04-30 05:33:51 LOG: archived transaction log file “00000001000000640000005E”
2008-04-30 05:33:57 LOG: archived transaction log file “00000001000000640000005F”
2008-04-30 05:34:03 LOG: archived transaction log file “000000010000006400000060”
2008-04-30 05:34:12 LOG: archived transaction log file “000000010000006400000061”
2008-04-30 05:34:21 LOG: archived transaction log file “000000010000006400000062”
2008-04-30 05:34:29 LOG: archived transaction log file “000000010000006400000063”
2008-04-30 05:34:37 LOG: archived transaction log file “000000010000006400000064”
2008-04-30 05:35:32 LOG: archived transaction log file “000000010000006400000065”
2008-04-30 05:35:38 LOG: archived transaction log file “000000010000006400000066”
2008-04-30 05:35:45 LOG: archived transaction log file “000000010000006400000067”
2008-04-30 05:35:53 LOG: archived transaction log file “000000010000006400000068”
2008-04-30 05:36:03 LOG: archived transaction log file “000000010000006400000069”
2008-04-30 05:36:11 LOG: archived transaction log file “00000001000000640000006A”
2008-04-30 05:36:18 LOG: archived transaction log file “00000001000000640000006B”
2008-04-30 05:36:28 LOG: archived transaction log file “00000001000000640000006C”
2008-04-30 05:37:21 LOG: archive command “copy pg_xlog\00000001000000640000005C D:\BackUp_PostgreSql\WAL\00000001000000640000005C” failed: return code 1
2008-04-30 05:37:22 LOG: archive command “copy pg_xlog\00000001000000640000005C D:\BackUp_PostgreSql\WAL\00000001000000640000005C” failed: return code 1
2008-04-30 05:37:22 LOG: archive command “copy pg_xlog\00000001000000640000005C D:\BackUp_PostgreSql\WAL\00000001000000640000005C” failed: return code 1
2008-04-30 05:37:22 WARNING: transaction log file “00000001000000640000005C” could not be archived: too many failures


Es scheint wirklich die Umbenennung der Status-File Probleme zu bereiten.
Unsere PostgreSQL Version ist 8.2.3.

Vielleicht sollte ich auf 8.2.7 wechseln. Muss ich bei diesem kleinen Versionschwenk ein Textdumpüberführung starten, oder kann der mit dem DATA-Verzeichnis umgehen?

Innerhalb von Minor Versionen ist kein Dump&Restore notwendig.
Genaueres dazu sagt jedoch das Changelog, dass man sich sowieso durchlesen sollte um Probleme mit der eigenen Applikation zu vermeiden.

So, ich hab es jetzt mal auf 8.2.7 ein Update vollzogen, und das Problem der schon existierenden Datei durch manuelles löschen behoben.

Er hat die ganzen WAL-Files nachkopiert und eine Weile schien es so, als wenn der Fehler weg sei.
Doch nun, ist er wieder da.

Immer wenn er eine Reihe von WAL-Files bei einer großen Transaktion (wie clustern nach index, oder große Veränderungen in der DB) in das Backup-Verzeichnis kopiert, dann klappt es bei einer nicht, und dann geht der Ärger los.

Als es das letzte Mal passiert ist, hab ich kurz vorher ein Vacuum Analyze abgebrochen, da dieser soviel Last verursachte, die zu der Tageszeit unerträglich war. Darf man das nicht abbrechen?

Warum nutzt Du nicht die Syntax laut Doku? Im Beispiel dort für Windows sieht das so aus:

archive_command = 'copy "%p" /mnt/server/archivedir/"%f"'  # Windows

Mit Google findet man für Windows auch:

archive_command = 'copy "%p" "D:/ProgramFiles/PostgreSQL/8.2/test_sabin/%f"' #in postgresql.conf

Abgesehen von den konkreten Verzeichnissen: dort stehen " mit dabei.

Ich weiß nicht wirklich, wie es unter Windows korrekt ist, die Tatsache, daß es wohl nur unter Last bei Dir nicht geht könnte 2 Dinge bedeuten:

  1. es ist erst einmal korrekt, was Du machst
  2. Dein OS macht beim COPY unter Last schlapp

Wie ads wohl schon schrieb: PG delegiert das an das OS und wertet den Rückgabestatus aus.

Was passiert, wenn Du händisch das kopieren aufrufst? Hast Du vielleicht ein Rechteproblem? Platte voll? Plattenschaden?
Ist D: eine eigene Platte oder nur eine weitere Partition? Falls Platte: separater Controller? Oder ist das ein entferntes Netz-Laufwerk?

Andreas

Das mit der anderen Syntax werd ich mal ausprobieren.

Wenn ich das Kommando manuell aufrufe kommen immer zwei mögliche Fehlermeldungen. Eine besagt, dass die Zieldatei bereits vorhanden ist, eine andere sagt, dass die Quelldatei nicht zu öffnen sei.

Welche kommt, ist unterschiedlich. Bei der ersten Fehlermeldung existiert die Datei tatsächlich schon im Backup-Ordner. Wenn ich sie dann lösche, behebt sich das Problem.

Wenn die zweite Fehlermeldung auftritt, dann reagiert die Quelldatei wirklich komisch. Wenn man die Eigenschaften von einer Datei öffnet, so hat man normalerweise 3 Tabs: Allgemein, Sicherheit und Dateiinfo. Bei dieser “gesperrten” Datei ist nur Allgemein zu sehen. Um dieses Problem zu lösen, bleibt mir nur noch ein Neustart der DB. Dazu muss ich aber auch sagen, dass ich erst einen normalen Shutdown initialisiere (pg_ctl STOP -m smart). Leider ist ein Client (wahrscheinlich unser OPC-Router) so frech und blockiert die Connection weiterhin. Er blockiert das aber nicht mit einer Transaktion. Wie er das macht, ist mir unklar. Nur mit Zwang (pg_ctl STOP -m fast) lässt sich die letzte Connection nun kappen.

Wer nicht weiß was ein OPC-Router ist: Dies ist ein Programm, das von einer SPS-Steuerung Werte zyklisch in die Datenbank pfeffert.
Also ein Stresstest für die DB :slight_smile:

Da haben wir es doch. Dein COPY schlägt fehl und petzt das an PG. Möglicherweise zeigt Dir die man-page zu COPY, wie man es zwingen kann, die Zieldatei zu überschreiben.

Den andere Fall, also Quelldatei nicht zu öffnen, schließe ich mal aus.

Andreas

Also liegt das Problem doch auf deiner Seite … und nicht bei PG.

Für eine Replikationslösung habe ich das Spiel etwas weitergetrieben und kopiere die Datei nicht nur sondern prüfe bei Vorhandensein auch, ob die Prüfsumme identisch ist (wenn ja, war das Kopieren früher schon mal erfolgreich und ich kann endgültig ein OK zurückliefern) oder ob es Unterschiede in Dateigröße oder Prüfsumme gibt (gab einen Fehler, also noch mal schreiben).

Das bekommt man aber nicht mit einem Windows Shell Befehl in den Griff … ich habe es in Perl gelöst.

Ich habe wohl zu früh geurteilt. Es lag nicht an dem OPC-Router, und auch nicht an PostgreSQL.

Es lag an mir :smiley:

Nach und nach habe ich alle Clients von der DB abgestöpselt, und bei einem Programm, das ich selber geschrieben habe, wurde die WAL-File freigegegen.

Das Programm habe ich in Java geschrieben, und bin scheinbar etwas nachlässig mit dem CLOSE Befehl umgegangen.

Die Lösung ist also, dass ich meinen eigenen Code überarbeite.

Sorry, war wohl viel Lärm um nichts. Trotzdem Danke für eure Anregungen!

Höh, was suchen deine Programme in den WAL-Logfiles?

Direkt nichts, aber bei Java erstellt man sich doch erst ein Connection Object und daraus holt man sich ein Statement Object. Später muss man beides schließen. Tut man das nicht, wird scheinbar eine WAL-File blockiert.

Ich kann dir nicht ganz folgen. Was haben deine Connections mit den WAL-Files zu tun? An sich nichts … jetzt müsstest du etwas deutlicher werden.

Hab ich da etwas nicht verstanden?

Ist es nicht so, dass begonnene Transaktionen in den WAL-Files geschrieben werden, und wenn sie commited werden, dann wird das in den WAL-Files verzeichnet, und im nachhinein in den Tablesspaces geschrieben?

Also bedeutet das doch, dass wenn ich mit dem jdbc-Treiber rumspiele, dass das in den WAL-Files Konsequenzen hat. Also kann es doch sein, dass nicht geschlossene Statements weiterhin die entsprechende WAL-File sperren.

Ich kann nur sagen, was meine Beobachtung ist, und die lautet:
Wenn ich das “unsauber” geschriebene Java-Programm beende, wird die WAL-File freigegeben.

Wenn ihr da einen anderen Zusammenhang seht, ich bin für Anregungen immer offen!


Zur Info:
Ich habe 12 checkpoint_segments á 16 MB, da ich sehr große Transaktionen habe.

Da wird eine Info im WAL Logfile abgelegt, dass die Transaktion gestartet wird. Ob und wann die geschlossen wird, ob sie zurückgerollt oder committed wird, muss nicht im gleichen Logfile stehen …

Wenn also bei dir WAL Logfiles aus irgendeinem Grund hängen bleiben, wäre das … interessant.

Am Besten ich warte mal ein paar Tage, und lasse ein paar riesige Transaktionen durchlaufen, und dann werden wir ja sehen, ob es mehr oder weniger Zufall war. Aber immerhin kann das Java-Programm die Datenbank vom runterfahren abhalten, was ich auch schon frech finde :slight_smile:

Bisher hat der Fehler nie lange auf sich warten lassen (bin selten länger als zwei Tage ohne Fehler ausgekommen).

Am Sonntag wäre der nächste 100%ige Belastungstest, da ich da immer die größten Tabellen nach einem Index clustere.

Werde euch auf dem laufenden halten.

Wie ist die Einstellung für ‘wal_buffers’ bei dir?

wall_buffers = 512Kb.

Zu wenig?

Setz das testweise mal so groß wie deine Transaktion ist (plus etwas Overhead). Allerdings glaube ich, dass mehr als 16 MB auch keinen Sinn machen, aber da bin ich mir gerade nicht sicher.