S3 Datastore Garbage Collection Phase 2 schlägt fehlt (os error 2)

[zemaphore]

Hey PBS Team,

anbei ein Fehler-Report zu meinem Testing des S3 Datastore Features.

Seit heute schlägt die Garbage Collection leider fehl. Die Phase 1 des GC wird erfolgreich abgeschlossen, aber Phase 2 bricht mit dem folgenden Fehlerbild ab:

...
marked 100% (84 of 84 index files)
Start GC phase2 (sweep unused chunks)
queued notification (id=aa611254-a09a-4abf-91d9-f275745cf6d6)
TASK ERROR: No such file or directory (os error 2)
Error: task failed (status No such file or directory (os error 2))

Leider gibt es keine Details welche Datei hier fehlt.... Ein "strace" gegen den "proxmox-backup-proxy":

strace -ff   -e trace=open,openat,stat,lstat,rename,unlink,unlinkat   -s 2000   -p 654   -o /root/pbs-proxy.strace

Liefert folgende ENOENTs:

/root/pbs-proxy.strace.1351:324:openat(AT_FDCWD, "/mnt/hetzner-s3-cache/nbg1-pbsfra01/ns/cloud/ns", O_RDONLY) = -1 ENOENT (No such file or directory)
/root/pbs-proxy.strace.1351:30569:openat(AT_FDCWD, "/mnt/hetzner-s3-cache/nbg1-pbsfra01/ns/pve01.fra-daily/ns", O_RDONLY) = -1 ENOENT (No such file or directory)
/root/pbs-proxy.strace.1351:42357:openat(AT_FDCWD, "/mnt/hetzner-s3-cache/nbg1-pbsfra01/ns/pve01.fra-longterm/ns", O_RDONLY) = -1 ENOENT (No such file or directory)
/root/pbs-proxy.strace.1351:49232:openat(AT_FDCWD, "/mnt/hetzner-s3-cache/nbg1-pbsfra01/ns/pve01.fra-general/ns", O_RDONLY) = -1 ENOENT (No such file or directory)
/root/pbs-proxy.strace.1351:49246:unlink("/mnt/hetzner-s3-cache/nbg1-pbsfra01/.chunks/000a/000a05976e7a8bc21d9a2b7498c523c17b51eeef8415d9c3ff0a19aae78a873e.using") = -1 ENOENT (No such file or directory)
/root/pbs-proxy.strace.1351:49247:unlink("/mnt/hetzner-s3-cache/nbg1-pbsfra01/.chunks/000a/000a05976e7a8bc21d9a2b7498c523c17b51eeef8415d9c3ff0a19aae78a873e") = -1 ENOENT (No such file or directory)

Hier fehlen scheinbar erwartete chunks. Ich habe danach den S3 Cache sowie Datastore einmal komplett entfernt und aus dem S3 content wieder neu aufgebaut/eingehangen, aber das Problem besteht weiterhin. Gibt es einen Weg - über Modifikationen im S3 content oder im S3 Cache - den Store wieder zu reparieren?

Kernel

Linux pbs01 6.14.11-4-pve #1 SMP PREEMPT_DYNAMIC PMX 6.14.11-4 (2025-10-10T08:04Z) x86_64 GNU/Linux

PBS

proxmox-backup-server 4.0.20-1 running version: 4.0.20

 

[Chris]

Hallo,

was liefert ein stat /mnt/hetzner-s3-cache/nbg1-pbsfra01/.chunks/000a/ direkt nach der fehlgeschlagenen garbage collection? Bitte auch den output von ls -l /mnt/hetzner-s3-cache/nbg1-pbsfra01/.chunks/000a/ posten.

Edit: Welche schritte wurden gemacht um den store und die cache wiederherzustellen?

 

[zemaphore]

Hey Chris,

sehr gerne...

root@pbs01.fra: ~ stat /mnt/hetzner-s3-cache/nbg1-pbsfra01/.chunks/000a/
  File: /mnt/hetzner-s3-cache/nbg1-pbsfra01/.chunks/000a/
  Size: 4096          Blocks: 8          IO Block: 4096   directory
Device: 8,17    Inode: 262158      Links: 2
Access: (0750/drwxr-x---)  Uid: (   34/  backup)   Gid: (   34/  backup)
Access: 2025-11-22 09:12:01.563617721 +0000
Modify: 2025-11-22 09:11:59.128458830 +0000
Change: 2025-11-22 09:11:59.128458830 +0000
 Birth: 2025-11-22 07:21:59.137748758 +0000

root@pbs01.fra: ~ ls -l /mnt/hetzner-s3-cache/nbg1-pbsfra01/.chunks/000a/
total 0

 

[Chris]

Okay, ich kann das problem reproduzieren, scheint dann aufzutreten wenn ein chunk zwar am object store vorhanden, jedoch von keinem backup index file mehr verwendet wird. Ein einmaliges

touch /mnt/hetzner-s3-cache/nbg1-pbsfra01/.chunks/000a/000a05976e7a8bc21d9a2b7498c523c17b51eeef8415d9c3ff0a19aae78a873e

sollte als workaround reichen bis ein fix verfügbar ist (auch für andere chunks falls dies bei weiteren auftritt).

 

[zemaphore]

Das ging extrem schnell, Chris. Vielen Dank schon mal.

Ich versuche mich mal mit strace an den Chunks fort zu hangeln. Der erste touch hat geholfen, aber jetzt fehlt der nächste chunk. Für die Zukunft wäre es eventuell auch hilfreich, wenn der GC task selbst die vermisste Datei im Log reporten könnte.

Schönes Wochenende wünsch ich noch

 

[Chris]

Das ging extrem schnell, Chris. Vielen Dank schon mal.

Vielen Dank noch für den Report!

Ich versuche mich mal mit strace an den Chunks fort zu hangeln. Der erste touch hat geholfen, aber jetzt fehlt der nächste chunk. Für die Zukunft wäre es eventuell auch hilfreich, wenn der GC task selbst die vermisste Datei im Log reporten könnte.

Ja, in der tat braucht es hier noch an Verbesserungen beim error logging. Für den Bug selbst gibt es nun einen bugfix patch auf der developer mailing list https://lore.proxmox.com/pbs-devel/20251122104118.205994-1-c.ebner@proxmox.com/T/

Schönes Wochenende wünsch ich noch

Danke, ebenso!

 

[zemaphore]

Hatte gesehen du hast im Patch geschrieben:

This should not happen under
normal datastore operation anyways, most likely to appear after
re-creation of the datastore from existing bucket contents containing
such unreferenced chunks.

Vielleicht noch als Hintergrund wie die Situation entstanden ist. Ich hab nach den fehlenden Chunks in den letzten Backup Logs gesucht und ein fehlgeschlagenes Backup gefunden.

Dort sieht man:

2025-11-22T03:14:02+00:00: Upload new chunk 000a05976e7a8bc21d9a2b7498c523c17b51eeef8415d9c3ff0a19aae78a873e

2025-11-22T03:14:35+00:00: Caching of chunk 000a05976e7a8bc21d9a2b7498c523c17b51eeef8415d9c3ff0a19aae78a873e

Und etwas später Upload-Fehler in den S3 Bucket die zum Abbruch des Backups führen.

2025-11-22T03:17:21+00:00: backup ended and finish failed: backup ended but finished state is not set.
2025-11-22T03:17:21+00:00: removing unfinished backup
2025-11-22T03:17:23+00:00: removing backup snapshot "/mnt/hetzner-s3-cache/nbg1-pbsfra01/ns/pve01.fra-general/vm/107/2025-11-22T03:10:53Z"
2025-11-22T03:17:23+00:00: TASK ERROR: backup ended but finished state is not set.

Das erklärt wieso die Chunks im Bucket liegen und eventuell im Cache verworfen wurden.

 

[Chris]

Das erklärt wieso die Chunks im Bucket liegen und eventuell im Cache verworfen wurden.

Ein Abbruch des backup jobs kann sicher dazu geführt haben, dass der chunk am s3 hochgeladen und nicht referenziert wird. Jedoch sollte dennoch der marker im local store cache vorhanden sein. Erst durch das neu erstellen der cache sollte dieser lokal nicht mehr vorhanden sein und daher zum genannten Fehlverhalten führen.

 

[zemaphore]

Ein Abbruch des backup jobs kann sicher dazu geführt haben, dass der chunk am s3 hochgeladen und nicht referenziert wird. Jedoch sollte dennoch der marker im local store cache vorhanden sein. Erst durch das neu erstellen der cache sollte dieser lokal nicht mehr vorhanden sein und daher zum genannten Fehlverhalten führen.

Hey Chris, ich wünschte es wäre so. Hab es jetzt die letzten Tage mit den daily Backups beobachtet. Einen Tag ging alles gut, dann hatte ich wieder ein Backup was mit einem Upload Error bei einem Chunk abgebrochen hat. Im Anschluss schlägt GC jetzt wieder in Phase 2 fehl und vermisst chunks im local cache. Habe mir daraufhin mal die Logs vom Backup angesehen und festgestellt, dass es für den fehlenden Chunk ein Upload Eintrag gibt aber keinen Caching Eintrag bevor das Gesamtbackup abbricht. Eventuell liegt da das Problem... es wird im S3 ein chunk abgelegt, aber das wirkliche Caching im local cache nicht mehr durchgeführt, weil das Backup schon abgebrochen wurde.

Das ist der betroffene Chunk und das Backup-Log hab ich angehangen...

2025-11-24T22:01:20+00:00: Upload new chunk 025142b658902251a5e6b95a914ab6f2c286c9dc14be2525b79c28e57002ca0a

Eventuell hilft es ja mögliche Edge-Cases beim eigentlich Backup-Vorgang zu identifizieren.

P.S.: Diesmal habe ich nichts ausgehangen, gelöscht oder neu aufgebaut .

 

[Chris]

Bitte mit proxmox-backup-server in version 4.0.22-1 testen, tritt damit der Fehler in GC immer noch auf? Der fehlende lokale marker bei Backup-Abbruch sollte damit auch kein Problem mehr sein.

 

[zemaphore]

Bitte mit proxmox-backup-server in version 4.0.22-1 testen, tritt damit der Fehler in GC immer noch auf? Der fehlende lokale marker bei Backup-Abbruch sollte damit auch kein Problem mehr sein.

Ziehe gerade das Update auf 4.0.22-1, teste dann die nächsten Tage und melde mich.

Danke Dir

 

[zemaphore]

Bitte mit proxmox-backup-server in version 4.0.22-1 testen, tritt damit der Fehler in GC immer noch auf? Der fehlende lokale marker bei Backup-Abbruch sollte damit auch kein Problem mehr sein.

Sieht alles gut aus. GC Phase 2 Probleme sind mit 4.0.22-1 behoben. Danke für den Support... jetzt häng ich zwar bei Phase 3, aber dafür mach ich ein neues Topic auf.
Denke dieses hier ist jetzt geschlossen.

 

[Chris]

Das können wir auch gleich hier debuggen, woran hackt es in phase 3?

 

[zemaphore]

Klasse,

folgendes persistentes Fehlerbild:

...
2025-11-25T09:28:01+00:00: marked 100% (110 of 110 index files)
2025-11-25T09:28:01+00:00: Start GC phase2 (sweep unused chunks)
2025-11-25T09:28:03+00:00: processed 15562 total chunks
2025-11-25T09:28:03+00:00: Start GC phase3 (sweep unused chunk markers)
2025-11-25T09:28:03+00:00: queued notification (id=2a90091a-ca14-441b-9b82-d9c721673498)
2025-11-25T09:28:03+00:00: TASK ERROR: Invalid string length

 

[Chris]

Was liefert ein find .chunks/ -type f -name '*.using' -print im datastore folder? Beinhaltet das chunk folder oder dessen subfolder files welche nicht einem chunk digest entsprechen?

 

[Chris]

Aja, kann reproduzieren und hab auch schon den Fehler gefunden.

 

[zemaphore]

Was liefert ein find .chunks/ -type f -name '*.using' -print im datastore folder? Beinhaltet das chunk folder oder dessen subfolder files welche nicht einem chunk digest entsprechen?

Ich habe gerade ein Backup laufen, aber ein Scan mit deinem Script sowie einer angepassten Variante die mir alle Files mit Filename-Länge != 64 zeigt, hat mir ausschließlich und viele *.using Dateien gezeigt.

Aber wenn du es eh schon selbst hast...

 

[Chris]

Das bedeutet im Umkehrschluss aber es gibt chunks welche erwartet werden, jedoch nicht am S3 object store vorhanden sind. Es empfiehlt sich also eine Verifizierung aller snapshots.