Restore von PBS schlägt fehl

[DasMoritz]

Hallo zusammen,

ich wollte gestern einen Restore von meinem Backup durchführen, leider lief das anscheinend auf einen Poller.

Situation:
Es wird eine VM auf der PVE Umgebung nächtlich auf den PBS gesichert, Job jeweils nachts um 04:00.
Gestern Abend habe ich dann den Restore durchführen wollen und komme zu diesem Ergebnis:

new volume ID is 'ZFS-Pool:vm-100-disk-0'
new volume ID is 'ZFS-Pool:vm-100-disk-1'
new volume ID is 'ZFS-Pool:vm-100-disk-2'
new volume ID is 'ZFS-Pool:vm-100-disk-3'
new volume ID is 'local-zfs:vm-100-disk-0'
restore proxmox backup image: /usr/bin/pbs-restore --repository root@pam@192.168.178.97:PBS-Store vm/100/2023-08-25T02:00:02Z drive-sata0.img.fidx /dev/zvol/ZFS-Pool/vm-100-disk-0 --verbose --format raw --skip-zero
connecting to repository 'root@pam@192.168.178.97:PBS-Store'
open block backend for target '/dev/zvol/ZFS-Pool/vm-100-disk-0'
starting to restore snapshot 'vm/100/2023-08-25T02:00:02Z'
download and verify backup index
progress 3% (read 4194304 bytes, zeroes = 0% (0 bytes), duration 0 sec)
progress 6% (read 8388608 bytes, zeroes = 0% (0 bytes), duration 0 sec)
progress 9% (read 12582912 bytes, zeroes = 0% (0 bytes), duration 0 sec)
progress 12% (read 16777216 bytes, zeroes = 0% (0 bytes), duration 0 sec)
progress 15% (read 20971520 bytes, zeroes = 0% (0 bytes), duration 0 sec)
progress 18% (read 25165824 bytes, zeroes = 0% (0 bytes), duration 0 sec)
progress 21% (read 29360128 bytes, zeroes = 0% (0 bytes), duration 0 sec)
progress 25% (read 33554432 bytes, zeroes = 0% (0 bytes), duration 1 sec)
progress 28% (read 37748736 bytes, zeroes = 0% (0 bytes), duration 1 sec)
progress 31% (read 41943040 bytes, zeroes = 0% (0 bytes), duration 1 sec)
progress 34% (read 46137344 bytes, zeroes = 0% (0 bytes), duration 1 sec)
progress 37% (read 50331648 bytes, zeroes = 0% (0 bytes), duration 1 sec)
progress 40% (read 54525952 bytes, zeroes = 0% (0 bytes), duration 1 sec)
progress 43% (read 58720256 bytes, zeroes = 0% (0 bytes), duration 1 sec)
progress 46% (read 62914560 bytes, zeroes = 0% (0 bytes), duration 2 sec)
progress 50% (read 67108864 bytes, zeroes = 0% (0 bytes), duration 2 sec)
progress 53% (read 71303168 bytes, zeroes = 0% (0 bytes), duration 2 sec)
progress 56% (read 75497472 bytes, zeroes = 0% (0 bytes), duration 2 sec)
progress 59% (read 79691776 bytes, zeroes = 0% (0 bytes), duration 2 sec)
progress 62% (read 83886080 bytes, zeroes = 5% (4194304 bytes), duration 2 sec)
progress 65% (read 88080384 bytes, zeroes = 4% (4194304 bytes), duration 2 sec)
progress 68% (read 92274688 bytes, zeroes = 9% (8388608 bytes), duration 2 sec)
progress 71% (read 96468992 bytes, zeroes = 8% (8388608 bytes), duration 2 sec)
progress 75% (read 100663296 bytes, zeroes = 12% (12582912 bytes), duration 2 sec)
progress 78% (read 104857600 bytes, zeroes = 12% (12582912 bytes), duration 2 sec)
progress 81% (read 109051904 bytes, zeroes = 15% (16777216 bytes), duration 2 sec)
progress 84% (read 113246208 bytes, zeroes = 14% (16777216 bytes), duration 2 sec)
progress 87% (read 117440512 bytes, zeroes = 17% (20971520 bytes), duration 2 sec)
progress 90% (read 121634816 bytes, zeroes = 17% (20971520 bytes), duration 2 sec)
progress 93% (read 125829120 bytes, zeroes = 20% (25165824 bytes), duration 2 sec)
progress 96% (read 130023424 bytes, zeroes = 19% (25165824 bytes), duration 2 sec)
progress 100% (read 134217728 bytes, zeroes = 21% (29360128 bytes), duration 2 sec)
restore image complete (bytes=134217728, duration=2.98s, speed=42.93MB/s)
restore proxmox backup image: /usr/bin/pbs-restore --repository root@pam@192.168.178.97:PBS-Store vm/100/2023-08-25T02:00:02Z drive-sata1.img.fidx /dev/zvol/ZFS-Pool/vm-100-disk-1 --verbose --format raw --skip-zero
connecting to repository 'root@pam@192.168.178.97:PBS-Store'
open block backend for target '/dev/zvol/ZFS-Pool/vm-100-disk-1'
starting to restore snapshot 'vm/100/2023-08-25T02:00:02Z'
download and verify backup index
progress 1% (read 343932928 bytes, zeroes = 4% (16777216 bytes), duration 10 sec)
progress 2% (read 687865856 bytes, zeroes = 2% (16777216 bytes), duration 21 sec)
[...]
progress 99% (read 34019999744 bytes, zeroes = 86% (29334962176 bytes), duration 128 sec)
progress 100% (read 34359738368 bytes, zeroes = 86% (29674700800 bytes), duration 128 sec)
restore image complete (bytes=34359738368, duration=128.34s, speed=255.32MB/s)
restore proxmox backup image: /usr/bin/pbs-restore --repository root@pam@192.168.178.97:PBS-Store vm/100/2023-08-25T02:00:02Z drive-sata2.img.fidx /dev/zvol/ZFS-Pool/vm-100-disk-2 --verbose --format raw --skip-zero
connecting to repository 'root@pam@192.168.178.97:PBS-Store'
open block backend for target '/dev/zvol/ZFS-Pool/vm-100-disk-2'
starting to restore snapshot 'vm/100/2023-08-25T02:00:02Z'
download and verify backup index
progress 1% (read 107374182400 bytes, zeroes = 1% (1518338048 bytes), duration 4123 sec)
progress 2% (read 214748364800 bytes, zeroes = 1% (2822766592 bytes), duration 8368 sec)
progress 3% (read 322122547200 bytes, zeroes = 1% (4232052736 bytes), duration 12615 sec)
progress 4% (read 429496729600 bytes, zeroes = 1% (5737807872 bytes), duration 16713 sec)
progress 5% (read 536870912000 bytes, zeroes = 1% (7168065536 bytes), duration 20759 sec)
progress 6% (read 644245094400 bytes, zeroes = 1% (8623489024 bytes), duration 24755 sec)
progress 7% (read 751619276800 bytes, zeroes = 1% (10175381504 bytes), duration 28834 sec)
progress 8% (read 858993459200 bytes, zeroes = 1% (11790188544 bytes), duration 33021 sec)
progress 9% (read 966367641600 bytes, zeroes = 1% (13258194944 bytes), duration 37479 sec)
progress 10% (read 1073741824000 bytes, zeroes = 1% (17364418560 bytes), duration 41755 sec)
restore failed: reading file "/.chunks/9176/9176d51b91eb4ca3eea38a99c81babd9f6e67a0525e11c612d45ff9c4f257f41" failed: Input/output error (os error 5)
temporary volume 'ZFS-Pool:vm-100-disk-3' sucessfuly removed
temporary volume 'ZFS-Pool:vm-100-disk-1' sucessfuly removed
temporary volume 'local-zfs:vm-100-disk-0' sucessfuly removed
temporary volume 'ZFS-Pool:vm-100-disk-2' sucessfuly removed
temporary volume 'ZFS-Pool:vm-100-disk-0' sucessfuly removed
error before or during data restore, some or all disks were not completely restored. VM 100 state is NOT cleaned up.
TASK ERROR: command '/usr/bin/pbs-restore --repository root@pam@192.168.178.97:PBS-Store vm/100/2023-08-25T02:00:02Z drive-sata2.img.fidx /dev/zvol/ZFS-Pool/vm-100-disk-2 --verbose --format raw --skip-zero' failed: exit code 255

Ich habe meinen PVE Host nun einmal neu gestartet und die restorte VM nun noch einmal gelöscht und den Restore-Task dann neu gestartet.

Kann mir jemand sagen, was hier die Ursache war / ist?

Danke,
Moritz

 

[Chris]

restore failed: reading file "/.chunks/9176/9176d51b91eb4ca3eea38a99c81babd9f6e67a0525e11c612d45ff9c4f257f41" failed: Input/output error (os error 5) temporary volume 'ZFS-Pool:vm-100-disk-3' sucessfuly removed

Hi,
sieht so aus als ob da ein chunk auf PBS Seite nicht lesbar ist. Ist dort ein verify job eingerichtet?

 

[DasMoritz]

Moin @Chris

Danke dir.
Also ich habe mal direkt auf meinem PBS geschaut, da finde ich nichts im Bereich der VerifyJobs.

Es kann aber nicht sein, dass das automatisierte Backup (welches der PVE von meinen VM's jede Nacht um 04:00 macht) da irgendwie was zerschießt? Zeitlich passt das jedoch nicht übereinander, da der Fehler gegen 08:20 (ca.) entstand.

 

[Chris]

Moin @Chris

Danke dir.
Also ich habe mal direkt auf meinem PBS geschaut, da finde ich nichts im Bereich der VerifyJobs.

Es kann aber nicht sein, dass das automatisierte Backup (welches der PVE von meinen VM's jede Nacht um 04:00 macht) da irgendwie was zerschießt? Zeitlich passt das jedoch nicht übereinander, da der Fehler gegen 08:20 (ca.) entstand.

Dann bitte zunächst einen verify job ausführen, der die konsistenz des backups prüft.

Input/output error (os error 5) deutet aber eher darauf hin, dass das filesystem am PBS den Inhalt der Datei nicht lesen konnte.

 

[DasMoritz]

Okay, ich habe mal einen Verify-Job angeschoben.
Gibt es eine grobe Aussage wie lange das ca. dauert?

Danke und Gruß,
Moritz

 

[Falk R.]

Okay, ich habe mal einen Verify-Job angeschoben.
Gibt es eine grobe Aussage wie lange das ca. dauert?

Danke und Gruß,
Moritz

Kommt auf die Datenmenge und die Performance der Disks an. Von wenigen Minuten bis viele Stunden ist da alles möglich.

 

[DasMoritz]

Moin,

so, der Verify-Job läuft noch, aber:

2023-08-30T14:44:24+02:00:   check drive-sata2.img.fidx
2023-08-30T21:34:38+02:00: can't verify chunk, load failed - store 'PBS-Store', unable to load chunk '9176d51b91eb4ca3eea38a99c81babd9f6e67a0525e11c612d45ff9c4f257f41' - Input/output error (os error 5)
2023-08-30T21:34:38+02:00: corrupted chunk renamed to "/.chunks/9176/9176d51b91eb4ca3eea38a99c81babd9f6e67a0525e11c612d45ff9c4f257f41.0.bad"
2023-08-30T21:34:38+02:00: chunk 9176d51b91eb4ca3eea38a99c81babd9f6e67a0525e11c612d45ff9c4f257f41 was marked as corrupt

Das scheint genau der Chunk zu sein, der das Problem verursacht hat.
Was bedeutet das nun für den Restore des Backups?
Ist das Backup damit korrupt oder kann dies noch verwendet werden?

Danke
Moritz

 

[Dunuin]

korrupt

Korrupt, sowie vielleicht auch viele andere Backups, da PBS ja dedupliziert und sich verschiedenste Backups und Backup Snapshots den selben Chunk teilen. Falls du einen Sync zu einem zweiten PBS hast könntest du damit versuchen die kaputten durch einen heilen Chunk auszutauschen. Oder nochmal ein Backup erstellen und hoffen, dass da der defekte Chunk noch im Gast existiert, dass da PVE einen heilen Chunk hochladen kann. Halt nur doof, wenn da der Chunk schon nicht mehr existiert.

 

[DasMoritz]

Moin,

okay, dass ist natürlich keine erfreuliche Nachricht.

Frage: Das Backup ist täglich erfolgt, macht es irgendwie Sinn nun weiter in die Vergangenheit zu gehen oder kann ich erkennen wann der Chunk „kaputt gegangen“ ist?

Einen zweiten PBS habe ich leider nicht.

Edit: Gesichert wurde übrigens eine VM auf Basis von XPENOLOGY, Dateisystem war / ist BTRFS. Kann das noch irgendwas helfen?

 

[Dunuin]

Frage: Das Backup ist täglich erfolgt, macht es irgendwie Sinn nun weiter in die Vergangenheit zu gehen oder kann ich erkennen wann der Chunk „kaputt gegangen“ ist?

Schwer zu sagen. Normal hat man da ein Verify-Job laufen der auch z.B. alle 60 Tage ein Full Re-Verify macht. Dann wüsste man z.B., dass wenigstens vor 60 Tagen noch alles heil war. Legst du da keinen entsprechenden Job an, schert sich PBS auch nicht darum, ob die Integrität deiner Backups noch gegeben ist und weiß dann auch von nichts.

Was hast du denn als Storage? ZFS würde ja z.B. auch noch zusätzlich auf Datenintegrität der Chunks prüfen und könnte dir beim Scrub auch die Chunks reparieren, sofern Paritätsdaten/Mirror-Laufwerke verfügbar sind.

 

[DasMoritz]

Moin,

sprich: Da hilft nur probieren?
Da das Backup auf den PBS erst seit ca. 50 Tagen aktiv ist und ich den VerifyJob natürlich auf 180 Tage stehen hatte (fail) bringt mir das nicht viel.

Aber ich könnte ja z.B. versuchen ein Backup von vor 25 Tagen zu nutzen, oder?

Irgendwo muss der Fehler ja rein gekommen sein, oder macht das keinen Sinn?

Edit: @Dunuin Auf dem PBS rennt ZFS als Filesystem, die Platten sind gespiegelt.

 

[Dunuin]

Das Problem ist die Deduplizierung. Sagen wir deine VM hat seit dem ersten Backup vor 50 Tagen eine Windows-Systemdatei und die wurde in den letzten 50 Tagen nicht verändert. Vor 10 Tagen ist dir ein Chunk, der Teil der Systemdatei ist, korrumpiert. Jetzt sind nicht nur die Backup Snapshots der letzten 10 Tage defekt, sondern aller 50 Tage. Weil jeder einzelne der Backup Snapshots halt den selben defekten Chunk referenziert. Am Ende hast du dann keinen einziges 100% integres Backup der VM mehr. Und wenn du Pech hast, hast du vielleicht noch andere Windows VMs die genau die gleiche Systemdatei gleich ausgerichtet benutzen. Dann wären auch diese Backups der anderen VMs noch betroffen.
Komplett heil wären nur alte Backup Snapshots, wenn der defekte Block z.B. erst vor 30 Tagen beschrieben wurde. Dann würden die Backups der ersten 20 Tage wenigstens noch gehen. Aber das hängt halt echt davon ab, welche Backup Snapshots seit wann und bis wann diesen Chunk referenzieren.

Wenn du da kein Backup deiner Backups hast (z.B. Sync zu zweiten PBS oder Sync zu zweitem lokalen Datastore) oder ein selbstheilendes Dateisystem wie ZFS mit raid1/10/5/6 dann sieht es da halt schlecht aus.

Falls der Chunk nicht wichtig war könntest du versuchen die VM per proxmox-backup-client wiederherzustellen. Da gab es glaube ich eine Option defekte Chunks mit Nullen zu füllen ohne den Restore abzubrechen. Dann wäre die VM wenigstens wiederherstellbar, wenn dann halt auch nicht mit voller Datenintegrität.

 

[Chris]

Moin,

sprich: Da hilft nur probieren?
Da das Backup auf den PBS erst seit ca. 50 Tagen aktiv ist und ich den VerifyJob natürlich auf 180 Tage stehen hatte (fail) bringt mir das nicht viel.

Aber ich könnte ja z.B. versuchen ein Backup von vor 25 Tagen zu nutzen, oder?

Irgendwo muss der Fehler ja rein gekommen sein, oder macht das keinen Sinn?

Edit: @Dunuin Auf dem PBS rennt ZFS als Filesystem, die Platten sind gespiegelt.

Also, wie @Dunuin bereits richtig vorgeschlagen hat, ist es nun (nach Abschluss des verify jobs) an der Zeit ein weiteres Backup durchzuführen. Denn: der verify job hat den chunk nun als defekt markiert und auch die Datei entsprechend umbenannt. Daher wird das Backup nun feststellen, dass es den chunk nicht gibt und dieses erneut hochladen (immer vorausgesetzt, dass es die Daten dieses chunks so noch am filesystem deinen Gastes gibt, und dieser daher ins Backup soll). Ist dies der Fall, dann sind auch alle bisherigen Backups wieder vollständing, da diese ja den selben chunk referenzieren. Falls die Daten am Gast seitdem aber modifiziert wurden, und daher einen anderen chunk hash (und somit einen anderen chunk) generieren, dann ist es nicht möglich diesen fehlerhaften chunk wiederherzustellen (wir kennen/haben ja die Daten nicht mehr), in diesem Fall sind die bisherigen Backups, welche diesen chunk referenzieren dann auch unbrauchbar (bis auf die oben genannten restore optionen).

Was die Backups betrifft, so solltest du anhand des verify status im Proxmox Backup Server WebUI erkennen, ob alle oder nur einige deiner Backups den bad chunk referenzieren.

Was mich ein bisschen wundert ist der IO error, bitte umbedingt auch ein zpool scrub <poolname> durchlaufen lassen und die SMART values der disks des pools prüfen.

 

[DasMoritz]

Moin,

erstmal ganz herzlichen Dank euch beiden @Dunuin und @Chris
Ich glaube ich konnte es lösen bzw. es wird gerade gelöst:

1.) Ich hatte noch ein XPenology / Synology Backup auf meine uralte Synology DS-211 (die ist schon 12 Jahre alt, neue Platten und rennt recht gut), da läuft gerade die Wiederherstellung.
2.) Ich habe dazu gelernt, dass ich den Verify-Job häufiger einplanen sollte
3.) PBS und PVE arbeiten zusammen super, ich habe vorhin einen Restore einer anderen VM durchgeführt, die läuft nun auch wieder.

Folgende Fragen habe ich:
1.) Gibt es ein Tutorial oder einen Guide um PVE und PBS gemeinsam bestmöglich sicher zu betreiben bzw. was sollte man beachten?

Aktuell:
PVE Host mit 2x SSD (für PVE OS) und 2x HDD für VM's, jeweils im RAID1 betrieben, ZFS.
PBS Host mit 2x HDD (für PVE OS und VM), RAID 1, ZFS (räumlich getrennt im Gartenhaus aber auf dem gleichen Grundstück)

2.) Gibt es irgendwie einen Job oder ähnliches um die Gesundheit der Systeme regelmäßig zu prüfen und ggf. per Nachricht (Email) informiert zu werden? Der Kram läuft so gut, dass ich da eher selten rein schaue.

Danke,
Moritz

 

[Dunuin]

2.) Gibt es irgendwie einen Job oder ähnliches um die Gesundheit der Systeme regelmäßig zu prüfen und ggf. per Nachricht (Email) informiert zu werden? Der Kram läuft so gut, dass ich da eher selten rein schaue.

Da müsstest du dir schon Monitoring Software wie z.B. Zabbix als VM/LXC aufsetzen, wenn du mehr als nur fehlgeschlagene Backups, Verifies oder defekte ZFS Pools überwachen willst. Für letzteres müsstest du Postfix auf den PVE/PBS hosts einrichten, damit die Main-Benachrichtigungen von PVE/PBS klappen können.