Hello,
I am currently testing the PBS backup solution, but I quickly encountered an issue with backup verifications. My backups worked well in a cron from Thursday to Sunday, but the one from Monday morning had a verification issue due to a Garbage Collect. Below, I have included the logs of the various issues:
Log Garbage Collect :
log erreur vérification :
Backup log :
Thanks for help
I am currently testing the PBS backup solution, but I quickly encountered an issue with backup verifications. My backups worked well in a cron from Thursday to Sunday, but the one from Monday morning had a verification issue due to a Garbage Collect. Below, I have included the logs of the various issues:
Log Garbage Collect :
2024-10-21T00:00:00+02:00: starting garbage collection on store Synology
2024-10-21T00:00:00+02:00: task triggered by schedule 'daily'
2024-10-21T00:00:00+02:00: Start GC phase1 (mark used chunks)
2024-10-21T00:00:34+02:00: WARN: warning: unable to access non-existent chunk 0dea469cae845d1e3323574defeeb5e85e9db795433ad7e6352b7a03ff186d80, required by "/mnt/backup_servers/vm/100/2024-10-17T13:39:04Z/drive-sata2.img.fidx"
2024-10-21T00:01:13+02:00: marked 6% (1 of 15 index files)
2024-10-21T00:01:19+02:00: WARN: warning: unable to access non-existent chunk 110495c662ca722f4e8818a14278d44dbd5d44145fdd17961133362cc8639497, required by "/mnt/backup_servers/vm/100/2024-10-17T13:39:04Z/drive-sata1.img.fidx"
2024-10-21T00:01:46+02:00: marked 13% (2 of 15 index files)
2024-10-21T00:01:46+02:00: marked 20% (3 of 15 index files)
2024-10-21T00:02:06+02:00: WARN: warning: unable to access non-existent chunk 0dea469cae845d1e3323574defeeb5e85e9db795433ad7e6352b7a03ff186d80, required by "/mnt/backup_servers/vm/100/2024-10-17T23:00:00Z/drive-sata2.img.fidx"
2024-10-21T00:02:42+02:00: marked 26% (4 of 15 index files)
2024-10-21T00:02:48+02:00: WARN: warning: unable to access non-existent chunk 110495c662ca722f4e8818a14278d44dbd5d44145fdd17961133362cc8639497, required by "/mnt/backup_servers/vm/100/2024-10-17T23:00:00Z/drive-sata1.img.fidx"
2024-10-21T00:03:13+02:00: marked 33% (5 of 15 index files)
2024-10-21T00:03:13+02:00: marked 40% (6 of 15 index files)
2024-10-21T00:03:35+02:00: WARN: warning: unable to access non-existent chunk 0dea469cae845d1e3323574defeeb5e85e9db795433ad7e6352b7a03ff186d80, required by "/mnt/backup_servers/vm/100/2024-10-18T08:40:53Z/drive-sata2.img.fidx"
2024-10-21T00:04:12+02:00: marked 46% (7 of 15 index files)
2024-10-21T00:04:19+02:00: WARN: warning: unable to access non-existent chunk 110495c662ca722f4e8818a14278d44dbd5d44145fdd17961133362cc8639497, required by "/mnt/backup_servers/vm/100/2024-10-18T08:40:53Z/drive-sata1.img.fidx"
2024-10-21T00:04:45+02:00: marked 53% (8 of 15 index files)
2024-10-21T00:04:45+02:00: marked 60% (9 of 15 index files)
2024-10-21T00:05:06+02:00: WARN: warning: unable to access non-existent chunk 0dea469cae845d1e3323574defeeb5e85e9db795433ad7e6352b7a03ff186d80, required by "/mnt/backup_servers/vm/100/2024-10-18T23:00:01Z/drive-sata2.img.fidx"
2024-10-21T00:05:44+02:00: marked 66% (10 of 15 index files)
2024-10-21T00:05:50+02:00: WARN: warning: unable to access non-existent chunk 110495c662ca722f4e8818a14278d44dbd5d44145fdd17961133362cc8639497, required by "/mnt/backup_servers/vm/100/2024-10-18T23:00:01Z/drive-sata1.img.fidx"
2024-10-21T00:06:16+02:00: marked 73% (11 of 15 index files)
2024-10-21T00:06:16+02:00: marked 80% (12 of 15 index files)
2024-10-21T00:06:36+02:00: WARN: warning: unable to access non-existent chunk 0dea469cae845d1e3323574defeeb5e85e9db795433ad7e6352b7a03ff186d80, required by "/mnt/backup_servers/vm/100/2024-10-19T23:00:06Z/drive-sata2.img.fidx"
2024-10-21T00:07:13+02:00: marked 86% (13 of 15 index files)
2024-10-21T00:07:19+02:00: WARN: warning: unable to access non-existent chunk 110495c662ca722f4e8818a14278d44dbd5d44145fdd17961133362cc8639497, required by "/mnt/backup_servers/vm/100/2024-10-19T23:00:06Z/drive-sata1.img.fidx"
2024-10-21T00:07:44+02:00: marked 93% (14 of 15 index files)
2024-10-21T00:07:44+02:00: marked 100% (15 of 15 index files)
2024-10-21T00:07:44+02:00: Start GC phase2 (sweep unused chunks)
2024-10-21T00:07:46+02:00: processed 1% (480 chunks)
2024-10-21T00:07:47+02:00: processed 2% (929 chunks)
2024-10-21T00:07:48+02:00: processed 3% (1382 chunks)
2024-10-21T00:07:50+02:00: processed 4% (1840 chunks)
2024-10-21T00:07:51+02:00: processed 5% (2297 chunks)
2024-10-21T00:07:52+02:00: processed 6% (2754 chunks)
2024-10-21T00:07:53+02:00: processed 7% (3180 chunks)
2024-10-21T00:07:55+02:00: processed 8% (3612 chunks)
2024-10-21T00:07:56+02:00: processed 9% (4043 chunks)
2024-10-21T00:07:57+02:00: processed 10% (4515 chunks)
2024-10-21T00:07:59+02:00: processed 11% (5013 chunks)
2024-10-21T00:08:00+02:00: processed 12% (5431 chunks)
2024-10-21T00:08:01+02:00: processed 13% (5896 chunks)
2024-10-21T00:08:02+02:00: processed 14% (6359 chunks)
2024-10-21T00:08:04+02:00: processed 15% (6829 chunks)
2024-10-21T00:08:05+02:00: processed 16% (7245 chunks)
2024-10-21T00:08:06+02:00: processed 17% (7668 chunks)
2024-10-21T00:08:07+02:00: processed 18% (8098 chunks)
2024-10-21T00:08:09+02:00: processed 19% (8555 chunks)
2024-10-21T00:08:10+02:00: processed 20% (9006 chunks)
2024-10-21T00:08:11+02:00: processed 21% (9472 chunks)
2024-10-21T00:08:13+02:00: processed 22% (9948 chunks)
2024-10-21T00:08:14+02:00: processed 23% (10400 chunks)
2024-10-21T00:08:15+02:00: processed 24% (10807 chunks)
2024-10-21T00:08:17+02:00: processed 25% (11234 chunks)
2024-10-21T00:08:18+02:00: processed 26% (11671 chunks)
2024-10-21T00:08:19+02:00: processed 27% (12115 chunks)
2024-10-21T00:08:20+02:00: processed 28% (12545 chunks)
2024-10-21T00:08:22+02:00: processed 29% (13025 chunks)
2024-10-21T00:08:23+02:00: processed 30% (13503 chunks)
2024-10-21T00:08:24+02:00: processed 31% (13974 chunks)
2024-10-21T00:08:26+02:00: processed 32% (14414 chunks)
2024-10-21T00:08:27+02:00: processed 33% (14845 chunks)
2024-10-21T00:08:28+02:00: processed 34% (15303 chunks)
2024-10-21T00:08:30+02:00: processed 35% (15709 chunks)
2024-10-21T00:08:31+02:00: processed 36% (16146 chunks)
2024-10-21T00:08:32+02:00: processed 37% (16601 chunks)
2024-10-21T00:08:34+02:00: processed 38% (17079 chunks)
2024-10-21T00:08:35+02:00: processed 39% (17560 chunks)
2024-10-21T00:08:37+02:00: processed 40% (18005 chunks)
2024-10-21T00:08:38+02:00: processed 41% (18449 chunks)
2024-10-21T00:08:39+02:00: processed 42% (18904 chunks)
2024-10-21T00:08:41+02:00: processed 43% (19351 chunks)
2024-10-21T00:08:42+02:00: processed 44% (19791 chunks)
2024-10-21T00:08:44+02:00: processed 45% (20241 chunks)
2024-10-21T00:08:45+02:00: processed 46% (20676 chunks)
2024-10-21T00:08:47+02:00: processed 47% (21116 chunks)
2024-10-21T00:08:48+02:00: processed 48% (21555 chunks)
2024-10-21T00:08:49+02:00: processed 49% (21997 chunks)
2024-10-21T00:08:51+02:00: processed 50% (22444 chunks)
2024-10-21T00:08:52+02:00: processed 51% (22892 chunks)
2024-10-21T00:08:53+02:00: processed 52% (23355 chunks)
2024-10-21T00:08:55+02:00: processed 53% (23783 chunks)
2024-10-21T00:08:56+02:00: processed 54% (24244 chunks)
2024-10-21T00:08:57+02:00: processed 55% (24689 chunks)
2024-10-21T00:08:59+02:00: processed 56% (25114 chunks)
2024-10-21T00:09:00+02:00: processed 57% (25562 chunks)
2024-10-21T00:09:01+02:00: processed 58% (26008 chunks)
2024-10-21T00:09:02+02:00: processed 59% (26486 chunks)
2024-10-21T00:09:03+02:00: processed 60% (26938 chunks)
2024-10-21T00:09:05+02:00: processed 61% (27388 chunks)
2024-10-21T00:09:06+02:00: processed 62% (27822 chunks)
2024-10-21T00:09:07+02:00: processed 63% (28245 chunks)
2024-10-21T00:09:08+02:00: processed 64% (28685 chunks)
2024-10-21T00:09:09+02:00: processed 65% (29141 chunks)
2024-10-21T00:09:11+02:00: processed 66% (29584 chunks)
2024-10-21T00:09:12+02:00: processed 67% (30008 chunks)
2024-10-21T00:09:13+02:00: processed 68% (30402 chunks)
2024-10-21T00:09:14+02:00: processed 69% (30819 chunks)
2024-10-21T00:09:15+02:00: processed 70% (31272 chunks)
2024-10-21T00:09:17+02:00: processed 71% (31710 chunks)
2024-10-21T00:09:18+02:00: processed 72% (32145 chunks)
2024-10-21T00:09:19+02:00: processed 73% (32624 chunks)
2024-10-21T00:09:20+02:00: processed 74% (33065 chunks)
2024-10-21T00:09:21+02:00: processed 75% (33524 chunks)
2024-10-21T00:09:22+02:00: processed 76% (33978 chunks)
2024-10-21T00:09:24+02:00: processed 77% (34455 chunks)
2024-10-21T00:09:25+02:00: processed 78% (34896 chunks)
2024-10-21T00:09:26+02:00: processed 79% (35276 chunks)
2024-10-21T00:09:27+02:00: processed 80% (35707 chunks)
2024-10-21T00:09:28+02:00: processed 81% (36122 chunks)
2024-10-21T00:09:29+02:00: processed 82% (36566 chunks)
2024-10-21T00:09:31+02:00: processed 83% (37034 chunks)
2024-10-21T00:09:32+02:00: processed 84% (37470 chunks)
2024-10-21T00:09:33+02:00: processed 85% (37895 chunks)
2024-10-21T00:09:34+02:00: processed 86% (38302 chunks)
2024-10-21T00:09:35+02:00: processed 87% (38755 chunks)
2024-10-21T00:09:37+02:00: processed 88% (39187 chunks)
2024-10-21T00:09:38+02:00: processed 89% (39637 chunks)
2024-10-21T00:09:39+02:00: processed 90% (40088 chunks)
2024-10-21T00:09:40+02:00: processed 91% (40546 chunks)
2024-10-21T00:09:41+02:00: processed 92% (41007 chunks)
2024-10-21T00:09:42+02:00: processed 93% (41433 chunks)
2024-10-21T00:09:43+02:00: processed 94% (41887 chunks)
2024-10-21T00:09:45+02:00: processed 95% (42326 chunks)
2024-10-21T00:09:46+02:00: processed 96% (42745 chunks)
2024-10-21T00:09:47+02:00: processed 97% (43235 chunks)
2024-10-21T00:09:48+02:00: processed 98% (43661 chunks)
2024-10-21T00:09:50+02:00: processed 99% (44085 chunks)
2024-10-21T00:09:51+02:00: Removed garbage: 0 B
2024-10-21T00:09:51+02:00: Removed chunks: 0
2024-10-21T00:09:51+02:00: Original data usage: 1.416 TiB
2024-10-21T00:09:51+02:00: On-Disk usage: 122.173 GiB (8.43%)
2024-10-21T00:09:51+02:00: On-Disk chunks: 44504
2024-10-21T00:09:51+02:00: Deduplication factor: 11.87
2024-10-21T00:09:51+02:00: Average chunk size: 2.811 MiB
2024-10-21T00:09:51+02:00: TASK WARNINGS: 10
log erreur vérification :
2024-10-21T01:01:45+02:00: Automatically verifying newly added snapshot
2024-10-21T01:01:45+02:00: verify Synology:vm/100/2024-10-20T23:00:00Z
2024-10-21T01:01:45+02:00: check qemu-server.conf.blob
2024-10-21T01:01:45+02:00: check drive-sata2.img.fidx
2024-10-21T01:34:14+02:00: can't verify chunk, load failed - store 'Synology', unable to load chunk '0dea469cae845d1e3323574defeeb5e85e9db795433ad7e6352b7a03ff186d80' - No such file or directory (os error 2)
2024-10-21T01:34:14+02:00: verified 71182.39/75300.00 MiB in 1949.08 seconds, speed 36.52/38.63 MiB/s (1 errors)
2024-10-21T01:34:14+02:00: verify Synology:vm/100/2024-10-20T23:00:00Z/drive-sata2.img.fidx failed: chunks could not be verified
2024-10-21T01:34:14+02:00: check drive-sata1.img.fidx
2024-10-21T01:47:13+02:00: can't verify chunk, load failed - store 'Synology', unable to load chunk '41b15145167e238b7ae15fa53b8669154a707771c6ba688ccd757c276534ec29' - No such file or directory (os error 2)
2024-10-21T01:47:13+02:00: can't verify chunk, load failed - store 'Synology', unable to load chunk '3336dc535303472d640310e9257b5aa2c6148fa62b7a4f7c8217713e9e3ca035' - No such file or directory (os error 2)
2024-10-21T01:47:13+02:00: can't verify chunk, load failed - store 'Synology', unable to load chunk '110495c662ca722f4e8818a14278d44dbd5d44145fdd17961133362cc8639497' - No such file or directory (os error 2)
2024-10-21T01:47:13+02:00: verified 25685.77/50816.00 MiB in 779.79 seconds, speed 32.94/65.17 MiB/s (3 errors)
2024-10-21T01:47:13+02:00: verify Synology:vm/100/2024-10-20T23:00:00Z/drive-sata1.img.fidx failed: chunks could not be verified
2024-10-21T01:47:13+02:00: check drive-efidisk0.img.fidx
2024-10-21T01:47:13+02:00: verified 0.00/0.12 MiB in 0.01 seconds, speed 0.38/22.59 MiB/s (0 errors)
2024-10-21T01:47:13+02:00: TASK ERROR: verification failed - please check the log for details
Backup log :
INFO: starting new backup job: vzdump 100 --storage PBS36 --mailnotification always --mailto backup.info@domain.com --quiet 1 --mode snapshot --fleecing 0 --notes-template '{{guestname}}'
INFO: Starting Backup of VM 100 (qemu)
INFO: Backup started at 2024-10-21 01:00:00
INFO: status = running
INFO: VM Name: SRVTEST-DATA
INFO: include disk 'sata1' 'local-lvm:vm-100-disk-1' 90G
INFO: include disk 'sata2' 'local-lvm:vm-100-disk-2' 200G
INFO: include disk 'efidisk0' 'local-lvm:vm-100-disk-0' 4M
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating Proxmox Backup Server archive 'vm/100/2024-10-20T23:00:00Z'
INFO: started backup task 'd361dddd-fc64-41a9-a805-1b0d89820163'
INFO: resuming VM again
INFO: efidisk0: dirty-bitmap status: OK (drive clean)
INFO: sata1: dirty-bitmap status: OK (14.3 GiB of 90.0 GiB dirty)
INFO: sata2: dirty-bitmap status: OK (36.0 MiB of 200.0 GiB dirty)
INFO: using fast incremental mode (dirty-bitmap), 14.3 GiB dirty of 290.0 GiB total
INFO: 3% (532.0 MiB of 14.3 GiB) in 3s, read: 177.3 MiB/s, write: 169.3 MiB/s
INFO: 7% (1.0 GiB of 14.3 GiB) in 6s, read: 176.0 MiB/s, write: 157.3 MiB/s
INFO: 10% (1.5 GiB of 14.3 GiB) in 9s, read: 174.7 MiB/s, write: 174.7 MiB/s
INFO: 14% (2.1 GiB of 14.3 GiB) in 12s, read: 188.0 MiB/s, write: 176.0 MiB/s
INFO: 18% (2.6 GiB of 14.3 GiB) in 15s, read: 168.0 MiB/s, write: 166.7 MiB/s
INFO: 21% (3.1 GiB of 14.3 GiB) in 18s, read: 169.3 MiB/s, write: 166.7 MiB/s
INFO: 25% (3.6 GiB of 14.3 GiB) in 21s, read: 176.0 MiB/s, write: 169.3 MiB/s
INFO: 28% (4.1 GiB of 14.3 GiB) in 24s, read: 173.3 MiB/s, write: 172.0 MiB/s
INFO: 31% (4.5 GiB of 14.3 GiB) in 27s, read: 137.3 MiB/s, write: 137.3 MiB/s
INFO: 34% (4.9 GiB of 14.3 GiB) in 30s, read: 141.3 MiB/s, write: 134.7 MiB/s
INFO: 37% (5.4 GiB of 14.3 GiB) in 33s, read: 152.0 MiB/s, write: 148.0 MiB/s
INFO: 40% (5.8 GiB of 14.3 GiB) in 36s, read: 142.7 MiB/s, write: 142.7 MiB/s
INFO: 43% (6.2 GiB of 14.3 GiB) in 39s, read: 137.3 MiB/s, write: 137.3 MiB/s
INFO: 47% (6.7 GiB of 14.3 GiB) in 42s, read: 185.3 MiB/s, write: 184.0 MiB/s
INFO: 50% (7.2 GiB of 14.3 GiB) in 45s, read: 149.3 MiB/s, write: 132.0 MiB/s
INFO: 53% (7.6 GiB of 14.3 GiB) in 48s, read: 158.7 MiB/s, write: 136.0 MiB/s
INFO: 54% (7.9 GiB of 14.3 GiB) in 52s, read: 57.0 MiB/s, write: 52.0 MiB/s
INFO: 58% (8.4 GiB of 14.3 GiB) in 55s, read: 180.0 MiB/s, write: 177.3 MiB/s
INFO: 62% (8.9 GiB of 14.3 GiB) in 58s, read: 184.0 MiB/s, write: 182.7 MiB/s
INFO: 65% (9.4 GiB of 14.3 GiB) in 1m 1s, read: 145.3 MiB/s, write: 145.3 MiB/s
INFO: 67% (9.7 GiB of 14.3 GiB) in 1m 4s, read: 112.0 MiB/s, write: 112.0 MiB/s
INFO: 70% (10.1 GiB of 14.3 GiB) in 1m 7s, read: 128.0 MiB/s, write: 126.7 MiB/s
INFO: 72% (10.4 GiB of 14.3 GiB) in 1m 10s, read: 128.0 MiB/s, write: 125.3 MiB/s
INFO: 75% (10.8 GiB of 14.3 GiB) in 1m 13s, read: 112.0 MiB/s, write: 109.3 MiB/s
INFO: 77% (11.1 GiB of 14.3 GiB) in 1m 16s, read: 130.7 MiB/s, write: 128.0 MiB/s
INFO: 80% (11.5 GiB of 14.3 GiB) in 1m 19s, read: 133.3 MiB/s, write: 129.3 MiB/s
INFO: 83% (11.9 GiB of 14.3 GiB) in 1m 22s, read: 121.3 MiB/s, write: 109.3 MiB/s
INFO: 85% (12.3 GiB of 14.3 GiB) in 1m 25s, read: 142.7 MiB/s, write: 142.7 MiB/s
INFO: 88% (12.6 GiB of 14.3 GiB) in 1m 28s, read: 117.3 MiB/s, write: 114.7 MiB/s
INFO: 90% (13.0 GiB of 14.3 GiB) in 1m 31s, read: 125.3 MiB/s, write: 121.3 MiB/s
INFO: 93% (13.4 GiB of 14.3 GiB) in 1m 34s, read: 122.7 MiB/s, write: 108.0 MiB/s
INFO: 95% (13.7 GiB of 14.3 GiB) in 1m 37s, read: 112.0 MiB/s, write: 85.3 MiB/s
INFO: 97% (13.9 GiB of 14.3 GiB) in 1m 40s, read: 81.3 MiB/s, write: 34.7 MiB/s
INFO: 100% (14.3 GiB of 14.3 GiB) in 1m 43s, read: 129.3 MiB/s, write: 129.3 MiB/s
INFO: backup was done incrementally, reused 276.36 GiB (95%)
INFO: transferred 14.32 GiB in 104 seconds (141.0 MiB/s)
INFO: adding notes to backup
INFO: Finished Backup of VM 100 (00:01:46)
INFO: Backup finished at 2024-10-21 01:01:46
INFO: Backup job finished successfully
INFO: notified via target `<backup.info@domain.com>`
TASK OK
Thanks for help
