PBS restored old snapshot instead of current VM disk

[mko]

We have PBS doing daily backups of all VMs in our PVE cluster, VMs are backed by ZFS storage. Yesterday we had a problem with one VM and restored the most recent PBS backup. When booting the newly restored VM, the data on the filesystem is back at a date of a ~7 month old manual snapshot that was still present instead of the current data at the time of the PBS backup.

Here is the original VM's task list, showing that a snapshot was taken Jun 14 (2021) 11:27:28 and stayed around until it was deleted on Jan 04 (2022):


The PBS restore was done via the PVE GUI and this is the command from the task log, showing the backup from 2022-01-04 was restored:

/usr/bin/pbs-restore --repository xxx@pbs@ip.ip.ip.ip:backup-vmdata1 vm/264/2022-01-04T08:31:36Z drive-scsi0.img.fidx /dev/zvol/ssd1/vmdata1/vm-301-disk-0 --verbose --format raw --skip-zero

Looking at data on the restored VM, some of the last timestamps are from Jun 14 2021 11:20:56 (~7 minutes before the manual snapshot) and then jumps to the current time on Jan 4 2022 when the VM was restored.

It appears that PBS has been backing up the old Jun 14, 2021 snapshot instead of the live VM disk, even though the backup log (below) says it is ignoring the snapshot. Restoring a different PBS backup date also restored the old June 14, 2021 snapshot instead of that day's backup.

Any ideas what might be causing this and should I file a bug report? We are on PBS 1.0-1 which is due for an upgrade, but I don't see anything similar in the release notes.

Thanks in advance.

Backup job log:

INFO: Starting Backup of VM 264 (qemu)
INFO: Backup started at 2022-01-04 02:31:36
INFO: status = stopped
INFO: backup mode: stop
INFO: ionice priority: 7
INFO: VM Name: vmname
INFO: include disk 'scsi0' 'vmdata1:vm-264-disk-0' 60G
INFO: snapshots found (not included into backup)
INFO: creating Proxmox Backup Server archive 'vm/264/2022-01-04T08:31:36Z'
INFO: starting kvm to execute backup task
INFO: started backup task 'c5355c6a-aa73-4ef1-846a-bdb56712a72b'
INFO: scsi0: dirty-bitmap status: created new
INFO:   1% (728.0 MiB of 60.0 GiB) in  3s, read: 242.7 MiB/s, write: 0 B/s
INFO:   2% (1.5 GiB of 60.0 GiB) in  6s, read: 269.3 MiB/s, write: 0 B/s
INFO:   6% (3.8 GiB of 60.0 GiB) in  9s, read: 784.0 MiB/s, write: 0 B/s
[...etc...]
INFO: 100% (60.0 GiB of 60.0 GiB) in  3m 14s, read: 560.0 MiB/s, write: 0 B/s
INFO: backup is sparse: 25.36 GiB (42%) total zero data
INFO: backup was done incrementally, reused 60.00 GiB (100%)
INFO: transferred 60.00 GiB in 194 seconds (316.7 MiB/s)
INFO: stopping kvm after backup task
INFO: Finished Backup of VM 264 (00:03:18)

 

[dcsapak]

how did you restore from backup? i can only see the 'rollback' task which is not the backup but the snapshot rollback
to restore the backup you have to go to the 'backup' tab and restore from there

 

[mko]

The PBS backup was restored by going to the PBS datastore on PVE, selecting the backup from 2022-01-04T08:31:36Z, clicking the "Restore" button, and restoring to a new VMID.

Here is the full restore log and task list of the new restored VM if it's helpful. Original VMID 264, new VMID 301.

new volume ID is 'vmdata1:vm-301-disk-0'
restore proxmox backup image: /usr/bin/pbs-restore --repository xxx@pbs@ip.ip.ip.ip:backup-vmdata1 vm/264/2022-01-04T08:31:36Z drive-scsi0.img.fidx /dev/zvol/ssd1/vmdata1/vm-301-disk-0 --verbose --format raw --skip-zero
connecting to repository 'xxx@pbs@ip.ip.ip.ip:backup-vmdata1'
open block backend for target '/dev/zvol/ssd1/vmdata1/vm-301-disk-0'
starting to restore snapshot 'vm/264/2022-01-04T08:31:36Z'
download and verify backup index
progress 1% (read 645922816 bytes, zeroes = 22% (142606336 bytes), duration 12 sec)
progress 2% (read 1291845632 bytes, zeroes = 29% (381681664 bytes), duration 24 sec)
progress 3% (read 1933574144 bytes, zeroes = 38% (750780416 bytes), duration 29 sec)
progress 4% (read 2579496960 bytes, zeroes = 45% (1170210816 bytes), duration 33 sec)
progress 5% (read 3221225472 bytes, zeroes = 53% (1719664640 bytes), duration 35 sec)
progress 6% (read 3867148288 bytes, zeroes = 60% (2357198848 bytes), duration 36 sec)
progress 7% (read 4513071104 bytes, zeroes = 66% (2994733056 bytes), duration 36 sec)
progress 8% (read 5154799616 bytes, zeroes = 70% (3632267264 bytes), duration 36 sec)
progress 9% (read 5800722432 bytes, zeroes = 73% (4273995776 bytes), duration 36 sec)
progress 10% (read 6442450944 bytes, zeroes = 75% (4877975552 bytes), duration 36 sec)
progress 11% (read 7088373760 bytes, zeroes = 77% (5490343936 bytes), duration 38 sec)
progress 12% (read 7734296576 bytes, zeroes = 74% (5779750912 bytes), duration 47 sec)
progress 13% (read 8376025088 bytes, zeroes = 76% (6404702208 bytes), duration 47 sec)
progress 14% (read 9021947904 bytes, zeroes = 77% (7029653504 bytes), duration 47 sec)
progress 15% (read 9663676416 bytes, zeroes = 79% (7667187712 bytes), duration 47 sec)
progress 16% (read 10309599232 bytes, zeroes = 80% (8308916224 bytes), duration 47 sec)
progress 17% (read 10955522048 bytes, zeroes = 81% (8950644736 bytes), duration 47 sec)
progress 18% (read 11597250560 bytes, zeroes = 82% (9588178944 bytes), duration 48 sec)
progress 19% (read 12243173376 bytes, zeroes = 83% (10229907456 bytes), duration 48 sec)
progress 20% (read 12884901888 bytes, zeroes = 81% (10473177088 bytes), duration 63 sec)
progress 21% (read 13530824704 bytes, zeroes = 77% (10489954304 bytes), duration 87 sec)
progress 22% (read 14176747520 bytes, zeroes = 74% (10506731520 bytes), duration 111 sec)
progress 23% (read 14818476032 bytes, zeroes = 71% (10666115072 bytes), duration 124 sec)
progress 24% (read 15464398848 bytes, zeroes = 71% (11072962560 bytes), duration 128 sec)
progress 25% (read 16106127360 bytes, zeroes = 70% (11362369536 bytes), duration 138 sec)
progress 26% (read 16752050176 bytes, zeroes = 67% (11362369536 bytes), duration 151 sec)
progress 27% (read 17397972992 bytes, zeroes = 65% (11366563840 bytes), duration 163 sec)
progress 28% (read 18039701504 bytes, zeroes = 63% (11383341056 bytes), duration 176 sec)
progress 29% (read 18685624320 bytes, zeroes = 61% (11400118272 bytes), duration 193 sec)
progress 30% (read 19327352832 bytes, zeroes = 59% (11416895488 bytes), duration 208 sec)
progress 31% (read 19973275648 bytes, zeroes = 57% (11433672704 bytes), duration 223 sec)
progress 32% (read 20619198464 bytes, zeroes = 55% (11446255616 bytes), duration 237 sec)
progress 33% (read 21260926976 bytes, zeroes = 53% (11463032832 bytes), duration 250 sec)
progress 34% (read 21906849792 bytes, zeroes = 52% (11479810048 bytes), duration 264 sec)
progress 35% (read 22548578304 bytes, zeroes = 50% (11496587264 bytes), duration 277 sec)
progress 36% (read 23194501120 bytes, zeroes = 49% (11513364480 bytes), duration 287 sec)
progress 37% (read 23840423936 bytes, zeroes = 48% (11525947392 bytes), duration 295 sec)
progress 38% (read 24482152448 bytes, zeroes = 47% (11542724608 bytes), duration 303 sec)
progress 39% (read 25128075264 bytes, zeroes = 45% (11555307520 bytes), duration 311 sec)
progress 40% (read 25769803776 bytes, zeroes = 44% (11572084736 bytes), duration 321 sec)
progress 41% (read 26415726592 bytes, zeroes = 43% (11588861952 bytes), duration 335 sec)
progress 42% (read 27061649408 bytes, zeroes = 42% (11605639168 bytes), duration 347 sec)
progress 43% (read 27703377920 bytes, zeroes = 41% (11622416384 bytes), duration 369 sec)
progress 44% (read 28349300736 bytes, zeroes = 41% (11639193600 bytes), duration 389 sec)
progress 45% (read 28991029248 bytes, zeroes = 40% (11655970816 bytes), duration 398 sec)
progress 46% (read 29636952064 bytes, zeroes = 39% (11672748032 bytes), duration 407 sec)
progress 47% (read 30282874880 bytes, zeroes = 38% (11689525248 bytes), duration 415 sec)
progress 48% (read 30924603392 bytes, zeroes = 37% (11706302464 bytes), duration 423 sec)
progress 49% (read 31570526208 bytes, zeroes = 37% (11723079680 bytes), duration 432 sec)
progress 50% (read 32212254720 bytes, zeroes = 36% (11739856896 bytes), duration 440 sec)
progress 51% (read 32858177536 bytes, zeroes = 35% (11756634112 bytes), duration 448 sec)
progress 52% (read 33504100352 bytes, zeroes = 35% (11773411328 bytes), duration 457 sec)
progress 53% (read 34145828864 bytes, zeroes = 34% (11777605632 bytes), duration 465 sec)
progress 54% (read 34791751680 bytes, zeroes = 33% (11790188544 bytes), duration 477 sec)
progress 55% (read 35433480192 bytes, zeroes = 33% (11806965760 bytes), duration 484 sec)
progress 56% (read 36079403008 bytes, zeroes = 32% (11823742976 bytes), duration 492 sec)
progress 57% (read 36725325824 bytes, zeroes = 32% (11840520192 bytes), duration 504 sec)
progress 58% (read 37367054336 bytes, zeroes = 31% (11857297408 bytes), duration 516 sec)
progress 59% (read 38012977152 bytes, zeroes = 31% (11869880320 bytes), duration 527 sec)
progress 60% (read 38654705664 bytes, zeroes = 30% (11886657536 bytes), duration 538 sec)
progress 61% (read 39300628480 bytes, zeroes = 30% (11899240448 bytes), duration 549 sec)
progress 62% (read 39946551296 bytes, zeroes = 29% (11916017664 bytes), duration 560 sec)
progress 63% (read 40588279808 bytes, zeroes = 29% (11928600576 bytes), duration 571 sec)
progress 64% (read 41234202624 bytes, zeroes = 28% (11945377792 bytes), duration 583 sec)
progress 65% (read 41875931136 bytes, zeroes = 28% (11962155008 bytes), duration 592 sec)
progress 66% (read 42521853952 bytes, zeroes = 28% (11978932224 bytes), duration 601 sec)
progress 67% (read 43167776768 bytes, zeroes = 27% (11995709440 bytes), duration 612 sec)
progress 68% (read 43809505280 bytes, zeroes = 27% (12012486656 bytes), duration 621 sec)
progress 69% (read 44455428096 bytes, zeroes = 27% (12029263872 bytes), duration 632 sec)
progress 70% (read 45097156608 bytes, zeroes = 26% (12046041088 bytes), duration 644 sec)
progress 71% (read 45743079424 bytes, zeroes = 26% (12062818304 bytes), duration 655 sec)
progress 72% (read 46389002240 bytes, zeroes = 26% (12146704384 bytes), duration 666 sec)
progress 73% (read 47030730752 bytes, zeroes = 26% (12331253760 bytes), duration 676 sec)
progress 74% (read 47676653568 bytes, zeroes = 27% (12905873408 bytes), duration 677 sec)
progress 75% (read 48318382080 bytes, zeroes = 27% (13417578496 bytes), duration 680 sec)
progress 76% (read 48964304896 bytes, zeroes = 28% (14021558272 bytes), duration 681 sec)
progress 77% (read 49610227712 bytes, zeroes = 29% (14663286784 bytes), duration 681 sec)
progress 78% (read 50251956224 bytes, zeroes = 30% (15246295040 bytes), duration 683 sec)
progress 79% (read 50897879040 bytes, zeroes = 31% (15888023552 bytes), duration 683 sec)
progress 80% (read 51539607552 bytes, zeroes = 32% (16525557760 bytes), duration 683 sec)
progress 81% (read 52185530368 bytes, zeroes = 32% (17167286272 bytes), duration 683 sec)
progress 82% (read 52831453184 bytes, zeroes = 33% (17737711616 bytes), duration 684 sec)
progress 83% (read 53473181696 bytes, zeroes = 34% (18375245824 bytes), duration 684 sec)
progress 84% (read 54119104512 bytes, zeroes = 35% (19016974336 bytes), duration 684 sec)
progress 85% (read 54760833024 bytes, zeroes = 35% (19654508544 bytes), duration 684 sec)
progress 86% (read 55406755840 bytes, zeroes = 36% (20292042752 bytes), duration 685 sec)
progress 87% (read 56052678656 bytes, zeroes = 37% (20933771264 bytes), duration 685 sec)
progress 88% (read 56694407168 bytes, zeroes = 38% (21554528256 bytes), duration 685 sec)
progress 89% (read 57340329984 bytes, zeroes = 38% (21990735872 bytes), duration 687 sec)
progress 90% (read 57982058496 bytes, zeroes = 37% (22007513088 bytes), duration 699 sec)
progress 91% (read 58627981312 bytes, zeroes = 37% (22024290304 bytes), duration 709 sec)
progress 92% (read 59273904128 bytes, zeroes = 37% (22187868160 bytes), duration 717 sec)
progress 93% (read 59915632640 bytes, zeroes = 38% (22808625152 bytes), duration 717 sec)
progress 94% (read 60561555456 bytes, zeroes = 38% (23450353664 bytes), duration 717 sec)
progress 95% (read 61203283968 bytes, zeroes = 39% (24087887872 bytes), duration 717 sec)
progress 96% (read 61849206784 bytes, zeroes = 39% (24729616384 bytes), duration 717 sec)
progress 97% (read 62495129600 bytes, zeroes = 40% (25333596160 bytes), duration 718 sec)
progress 98% (read 63136858112 bytes, zeroes = 41% (25950158848 bytes), duration 718 sec)
progress 99% (read 63782780928 bytes, zeroes = 41% (26591887360 bytes), duration 718 sec)
progress 100% (read 64424509440 bytes, zeroes = 42% (27225227264 bytes), duration 718 sec)
restore image complete (bytes=64424509440, duration=718.91s, speed=85.46MB/s)
rescan volumes...
TASK OK

 

[dcsapak]

ok so from what i can see (from the task and backup log) is that the last time the vm was started before the backup on jan 04 was on june 14, but at the start of the backup the vm was stopped. so the vm stopped running sometime between june 14 and jan 04, and my guess is that this is the last state that was backed up...

 

[mko]

That "status = stopped" in the backup log is indeed interesting. This is one of our most important VMs so it was definitely running at the time of the Jan 4 and Dec 31 PBS backups that were restored and had old data from Jun 14.

The task log shows the VM Start on Jun 14 (2021) but no stop/shutdown tasks. On Jan 4 (2022) we did a graceful shutdown within the guest itself, took a snapshot while offline, and then started it back up, so I believe that is why there is no Stop event.

Any ideas what might have caused the backup log to show it "stopped" when it was for sure running? Just want to understand what happened here to avoid this on any other VMs in the future.

 

[dcsapak]

mhmm.. are you sure that this is the correct vm (vmid 264) ?
can you post the vm config and the journal from the time of the backup and maybe longer filtered by the vmid ?

if pve thought the vm was stopped, it would have started it again (for the backup) and used the disks in the config. so if the vm was really running it would have backed up some data that was written to disk (but corrupted the disk while doing so since two qemu processes would have accessed it...)

can you tell me what kind of vm this is (os/application/etc.) ?