XFS filesystem errors after VM restore

robhost · Feb 16, 2021

Hello,

we're currently testing PBS with PVE. Backups works so far, but when restoring VMs with XFS the VM is unbootable (see attached image) and always needs a xfs_repair in rescue. This is reproducible with different VMs and backups.

With ext4 its fine and without errors.

The backup setting is "snapshot" and guest agent is inplace.

Is this a known limitation or a bug?

Thanks!

danielb · Feb 16, 2021

I've done quite a lot of restorations from PBS with guests using XFS (el7, el8) without issue, so, it doesn't look like a general problem

robhost · Feb 16, 2021

danielb said:
I've done quite a lot of restorations from PBS with guests using XFS (el7, el8) without issue, so, it doesn't look like a general problem

Ok, thanks! Which backup-settings did you use? Any special settings or something? Encryption?
We let PVE prune old backups and not PBS, maybe this causes a problem here?

Did you try restores also from "incremental" backups?

We're also using EL8.

danielb · Feb 16, 2021

Nothing fancy. Daily backups, no encryption, snapshot mode. PBS is responsible for pruning though. From incremental backups, if you mean fast incr using dirty-bitmaps : yes, we're using them, and I've tested several restorations successfuly

robhost · Feb 16, 2021

danielb said:
PBS is responsible for pruning though.

Maybe this is the cause, because on our site PVE does this? Will do some more tests.

robhost · Feb 16, 2021

Ok, tested further:
It does not depend or encryption or anything else. Even the first backup with PBS from a fresh deployed VM is broken after restore here with XFS

tom · Feb 16, 2021

please post your backup task log (and restore log).

robhost · Feb 16, 2021

Backup:

Code:

INFO: starting new backup job: vzdump 5480 --storage snap03 --mode snapshot --node hav301 --remove 0
INFO: Starting Backup of VM 5480 (qemu)
INFO: Backup started at 2021-02-16 17:36:02
INFO: status = running
INFO: VM Name: vs5480
INFO: include disk 'scsi0' 'ceph-vs:vm-5480-disk-0' 100G
INFO: backup mode: snapshot
INFO: bandwidth limit: 80000 KB/s
INFO: ionice priority: 7
INFO: creating Proxmox Backup Server archive 'vm/5480/2021-02-16T16:36:02Z'
INFO: issuing guest-agent 'fs-freeze' command
INFO: enabling encryption
INFO: issuing guest-agent 'fs-thaw' command
INFO: started backup task 'd6289662-1b1c-4c44-bd2f-8e87e07a8645'
INFO: resuming VM again
INFO: scsi0: dirty-bitmap status: created new
INFO:   0% (216.0 MiB of 100.0 GiB) in  3s, read: 72.0 MiB/s, write: 32.0 MiB/s
INFO:   1% (1.0 GiB of 100.0 GiB) in 15s, read: 69.0 MiB/s, write: 32.3 MiB/s
INFO:   2% (2.0 GiB of 100.0 GiB) in 32s, read: 59.8 MiB/s, write: 55.8 MiB/s
INFO:   3% (3.1 GiB of 100.0 GiB) in 50s, read: 60.2 MiB/s, write: 56.4 MiB/s
INFO:   4% (4.0 GiB of 100.0 GiB) in  1m  3s, read: 76.9 MiB/s, write: 0 B/s
INFO:   5% (5.0 GiB of 100.0 GiB) in  1m 16s, read: 76.6 MiB/s, write: 2.2 MiB/s
INFO:   6% (6.0 GiB of 100.0 GiB) in  1m 33s, read: 59.1 MiB/s, write: 58.6 MiB/s
INFO:   7% (7.1 GiB of 100.0 GiB) in  1m 47s, read: 77.1 MiB/s, write: 585.1 KiB/s
INFO:   8% (8.0 GiB of 100.0 GiB) in  2m  0s, read: 76.9 MiB/s, write: 945.2 KiB/s
INFO:   9% (9.0 GiB of 100.0 GiB) in  2m 13s, read: 76.9 MiB/s, write: 1.5 MiB/s
[ ... ]
INFO:  90% (90.1 GiB of 100.0 GiB) in 20m 16s, read: 77.1 MiB/s, write: 585.1 KiB/s
INFO:  91% (91.0 GiB of 100.0 GiB) in 20m 29s, read: 76.9 MiB/s, write: 630.2 KiB/s
INFO:  92% (92.0 GiB of 100.0 GiB) in 20m 42s, read: 76.9 MiB/s, write: 945.2 KiB/s
INFO:  93% (93.0 GiB of 100.0 GiB) in 20m 55s, read: 76.9 MiB/s, write: 630.2 KiB/s
INFO:  94% (94.1 GiB of 100.0 GiB) in 21m  9s, read: 77.1 MiB/s, write: 877.7 KiB/s
INFO:  95% (95.0 GiB of 100.0 GiB) in 21m 22s, read: 76.9 MiB/s, write: 945.2 KiB/s
INFO:  96% (96.0 GiB of 100.0 GiB) in 21m 35s, read: 76.9 MiB/s, write: 630.2 KiB/s
INFO:  97% (97.1 GiB of 100.0 GiB) in 21m 49s, read: 76.6 MiB/s, write: 877.7 KiB/s
INFO:  98% (98.0 GiB of 100.0 GiB) in 22m  2s, read: 77.5 MiB/s, write: 630.2 KiB/s
INFO:  99% (99.0 GiB of 100.0 GiB) in 22m 15s, read: 76.9 MiB/s, write: 630.2 KiB/s
INFO: 100% (100.0 GiB of 100.0 GiB) in 22m 29s, read: 72.0 MiB/s, write: 877.7 KiB/s
INFO: backup is sparse: 95.04 GiB (95%) total zero data
INFO: backup was done incrementally, reused 95.04 GiB (95%)
INFO: transferred 100.00 GiB in 1349 seconds (75.9 MiB/s)
INFO: Finished Backup of VM 5480 (00:22:30)
INFO: Backup finished at 2021-02-16 17:58:32
Using encryption key from file descriptor
INFO: Backup job finished successfully
TASK OK

And restore from this one:

Code:

Using encryption key from file descriptor
Encryption key fingerprint: '7f:3e:01:43:04:83:2a:3f'
Using encryption key from file descriptor
Encryption key fingerprint: '7f:3e:01:43:04:83:2a:3f'
Using encryption key from file descriptor
Encryption key fingerprint: '7f:3e:01:43:04:83:2a:3f'
new volume ID is 'ceph-vs:vm-1337-disk-0'
restore proxmox backup image: /usr/bin/pbs-restore --repository hav3@pbs@snap03.robhost.de:local vm/5480/2021-02-16T16:36:02Z drive-scsi0.img.fidx 'rbd:rbd/vm-1337-disk-0:mon_host=10.11.3.1;10.11.3.2;10.11.3.3:auth_supported=cephx:id=hav3:keyring=/etc/pve/priv/ceph/ceph-vs.keyring' --verbose --format raw --keyfile /etc/pve/priv/storage/snap03.enc --skip-zero
connecting to repository 'hav3@pbs@snap03.robhost.de:local'
open block backend for target 'rbd:rbd/vm-1337-disk-0:mon_host=10.11.3.1;10.11.3.2;10.11.3.3:auth_supported=cephx:id=hav3:keyring=/etc/pve/priv/ceph/ceph-vs.keyring'
starting to restore snapshot 'vm/5480/2021-02-16T16:36:02Z'
download and verify backup index
progress 1% (read 1073741824 bytes, zeroes = 54% (583008256 bytes), duration 8 sec)
progress 2% (read 2147483648 bytes, zeroes = 30% (654311424 bytes), duration 18 sec)
progress 3% (read 3221225472 bytes, zeroes = 20% (654311424 bytes), duration 28 sec)
progress 4% (read 4294967296 bytes, zeroes = 40% (1723858944 bytes), duration 28 sec)
progress 5% (read 5368709120 bytes, zeroes = 51% (2789212160 bytes), duration 28 sec)
progress 6% (read 6442450944 bytes, zeroes = 43% (2797600768 bytes), duration 40 sec)
progress 7% (read 7516192768 bytes, zeroes = 51% (3862953984 bytes), duration 40 sec)
progress 8% (read 8589934592 bytes, zeroes = 57% (4924112896 bytes), duration 40 sec)
progress 9% (read 9663676416 bytes, zeroes = 61% (5976883200 bytes), duration 40 sec)
progress 10% (read 10737418240 bytes, zeroes = 65% (7042236416 bytes), duration 40 sec)
progress 11% (read 11811160064 bytes, zeroes = 68% (8103395328 bytes), duration 40 sec)
progress 12% (read 12884901888 bytes, zeroes = 70% (9147777024 bytes), duration 40 sec)
progress 13% (read 13958643712 bytes, zeroes = 73% (10204741632 bytes), duration 40 sec)
progress 14% (read 15032385536 bytes, zeroes = 74% (11261706240 bytes), duration 40 sec)
progress 15% (read 16106127360 bytes, zeroes = 76% (12322865152 bytes), duration 40 sec)
progress 16% (read 17179869184 bytes, zeroes = 77% (13384024064 bytes), duration 41 sec)
progress 17% (read 18253611008 bytes, zeroes = 79% (14449377280 bytes), duration 41 sec)
progress 18% (read 19327352832 bytes, zeroes = 80% (15510536192 bytes), duration 41 sec)
progress 19% (read 20401094656 bytes, zeroes = 81% (16575889408 bytes), duration 41 sec)
progress 20% (read 21474836480 bytes, zeroes = 82% (17620271104 bytes), duration 41 sec)
progress 21% (read 22548578304 bytes, zeroes = 82% (18681430016 bytes), duration 41 sec)
progress 22% (read 23622320128 bytes, zeroes = 83% (19738394624 bytes), duration 41 sec)
progress 23% (read 24696061952 bytes, zeroes = 84% (20803747840 bytes), duration 41 sec)
progress 24% (read 25769803776 bytes, zeroes = 84% (21827158016 bytes), duration 41 sec)
progress 25% (read 26843545600 bytes, zeroes = 85% (22888316928 bytes), duration 41 sec)
progress 26% (read 27917287424 bytes, zeroes = 85% (23949475840 bytes), duration 41 sec)
progress 27% (read 28991029248 bytes, zeroes = 86% (25010634752 bytes), duration 42 sec)
progress 28% (read 30064771072 bytes, zeroes = 86% (26075987968 bytes), duration 42 sec)
progress 29% (read 31138512896 bytes, zeroes = 87% (27141341184 bytes), duration 42 sec)
progress 30% (read 32212254720 bytes, zeroes = 87% (28206694400 bytes), duration 42 sec)
progress 31% (read 33285996544 bytes, zeroes = 87% (29272047616 bytes), duration 42 sec)
progress 32% (read 34359738368 bytes, zeroes = 88% (30337400832 bytes), duration 42 sec)
progress 33% (read 35433480192 bytes, zeroes = 88% (31398559744 bytes), duration 42 sec)
progress 34% (read 36507222016 bytes, zeroes = 88% (32463912960 bytes), duration 42 sec)
progress 35% (read 37580963840 bytes, zeroes = 89% (33516683264 bytes), duration 42 sec)
progress 36% (read 38654705664 bytes, zeroes = 89% (34573647872 bytes), duration 42 sec)
progress 37% (read 39728447488 bytes, zeroes = 89% (35630612480 bytes), duration 42 sec)
progress 38% (read 40802189312 bytes, zeroes = 89% (36695965696 bytes), duration 42 sec)
progress 39% (read 41875931136 bytes, zeroes = 90% (37761318912 bytes), duration 42 sec)
progress 40% (read 42949672960 bytes, zeroes = 90% (38826672128 bytes), duration 42 sec)
progress 41% (read 44023414784 bytes, zeroes = 90% (39887831040 bytes), duration 42 sec)
progress 42% (read 45097156608 bytes, zeroes = 90% (40948989952 bytes), duration 42 sec)
progress 43% (read 46170898432 bytes, zeroes = 90% (42014343168 bytes), duration 42 sec)
progress 44% (read 47244640256 bytes, zeroes = 91% (43079696384 bytes), duration 42 sec)
progress 45% (read 48318382080 bytes, zeroes = 91% (44140855296 bytes), duration 43 sec)
progress 46% (read 49392123904 bytes, zeroes = 91% (45206208512 bytes), duration 43 sec)
progress 47% (read 50465865728 bytes, zeroes = 91% (46267367424 bytes), duration 43 sec)
progress 48% (read 51539607552 bytes, zeroes = 91% (47328526336 bytes), duration 43 sec)
progress 49% (read 52613349376 bytes, zeroes = 91% (48385490944 bytes), duration 43 sec)
progress 50% (read 53687091200 bytes, zeroes = 92% (49450844160 bytes), duration 43 sec)
progress 51% (read 54760833024 bytes, zeroes = 92% (50507808768 bytes), duration 43 sec)
progress 52% (read 55834574848 bytes, zeroes = 92% (51573161984 bytes), duration 43 sec)
progress 53% (read 56908316672 bytes, zeroes = 92% (52550434816 bytes), duration 44 sec)
progress 54% (read 57982058496 bytes, zeroes = 92% (53607399424 bytes), duration 44 sec)
progress 55% (read 59055800320 bytes, zeroes = 92% (54626615296 bytes), duration 44 sec)
progress 56% (read 60129542144 bytes, zeroes = 92% (55683579904 bytes), duration 44 sec)
progress 57% (read 61203283968 bytes, zeroes = 92% (56732155904 bytes), duration 45 sec)
progress 58% (read 62277025792 bytes, zeroes = 92% (57797509120 bytes), duration 45 sec)
progress 59% (read 63350767616 bytes, zeroes = 92% (58862862336 bytes), duration 45 sec)
progress 60% (read 64424509440 bytes, zeroes = 93% (59924021248 bytes), duration 45 sec)
progress 61% (read 65498251264 bytes, zeroes = 93% (60985180160 bytes), duration 45 sec)
progress 62% (read 66571993088 bytes, zeroes = 93% (62046339072 bytes), duration 45 sec)
progress 63% (read 67645734912 bytes, zeroes = 93% (63107497984 bytes), duration 45 sec)
progress 64% (read 68719476736 bytes, zeroes = 93% (64172851200 bytes), duration 45 sec)
progress 65% (read 69793218560 bytes, zeroes = 93% (65238204416 bytes), duration 45 sec)
progress 66% (read 70866960384 bytes, zeroes = 93% (66299363328 bytes), duration 45 sec)
progress 67% (read 71940702208 bytes, zeroes = 93% (67364716544 bytes), duration 45 sec)
progress 68% (read 73014444032 bytes, zeroes = 93% (68430069760 bytes), duration 45 sec)
progress 69% (read 74088185856 bytes, zeroes = 93% (69495422976 bytes), duration 45 sec)
progress 70% (read 75161927680 bytes, zeroes = 93% (70552387584 bytes), duration 45 sec)
progress 71% (read 76235669504 bytes, zeroes = 93% (71617740800 bytes), duration 45 sec)
progress 72% (read 77309411328 bytes, zeroes = 94% (72683094016 bytes), duration 45 sec)
progress 73% (read 78383153152 bytes, zeroes = 94% (73731670016 bytes), duration 45 sec)
progress 74% (read 79456894976 bytes, zeroes = 94% (74797023232 bytes), duration 45 sec)
progress 75% (read 80530636800 bytes, zeroes = 94% (75853987840 bytes), duration 46 sec)
progress 76% (read 81604378624 bytes, zeroes = 94% (76915146752 bytes), duration 46 sec)
progress 77% (read 82678120448 bytes, zeroes = 94% (77980499968 bytes), duration 46 sec)
progress 78% (read 83751862272 bytes, zeroes = 94% (79041658880 bytes), duration 46 sec)
progress 79% (read 84825604096 bytes, zeroes = 94% (80107012096 bytes), duration 46 sec)
progress 80% (read 85899345920 bytes, zeroes = 94% (80937484288 bytes), duration 49 sec)
progress 81% (read 86973087744 bytes, zeroes = 94% (82002837504 bytes), duration 49 sec)
progress 82% (read 88046829568 bytes, zeroes = 94% (83068190720 bytes), duration 49 sec)
progress 83% (read 89120571392 bytes, zeroes = 94% (84133543936 bytes), duration 49 sec)
progress 84% (read 90194313216 bytes, zeroes = 94% (85194702848 bytes), duration 49 sec)
progress 85% (read 91268055040 bytes, zeroes = 94% (86247473152 bytes), duration 49 sec)
progress 86% (read 92341796864 bytes, zeroes = 94% (87224745984 bytes), duration 50 sec)
progress 87% (read 93415538688 bytes, zeroes = 94% (88290099200 bytes), duration 50 sec)
progress 88% (read 94489280512 bytes, zeroes = 94% (89355452416 bytes), duration 50 sec)
progress 89% (read 95563022336 bytes, zeroes = 94% (90349502464 bytes), duration 51 sec)
progress 90% (read 96636764160 bytes, zeroes = 94% (91414855680 bytes), duration 51 sec)
progress 91% (read 97710505984 bytes, zeroes = 94% (92480208896 bytes), duration 51 sec)
progress 92% (read 98784247808 bytes, zeroes = 94% (93541367808 bytes), duration 51 sec)
progress 93% (read 99857989632 bytes, zeroes = 94% (94606721024 bytes), duration 51 sec)
progress 94% (read 100931731456 bytes, zeroes = 94% (95667879936 bytes), duration 51 sec)
progress 95% (read 102005473280 bytes, zeroes = 94% (96729038848 bytes), duration 51 sec)
progress 96% (read 103079215104 bytes, zeroes = 94% (97794392064 bytes), duration 51 sec)
progress 97% (read 104152956928 bytes, zeroes = 94% (98855550976 bytes), duration 51 sec)
progress 98% (read 105226698752 bytes, zeroes = 94% (99920904192 bytes), duration 51 sec)
progress 99% (read 106300440576 bytes, zeroes = 95% (100986257408 bytes), duration 51 sec)
progress 100% (read 107374182400 bytes, zeroes = 95% (102047416320 bytes), duration 52 sec)
restore image complete (bytes=107374182400, duration=52.04s, speed=1967.78MB/s)
rescan volumes...
TASK OK

robhost · Feb 16, 2021

FYI: Same happens with CentOS 8 when using ext4!

@danielb Are you using LVM (we do)?

hermelin · Feb 17, 2021

Do you use qemu-guest-agent ? https://pve.proxmox.com/wiki/Qemu-guest-agent

robhost · Feb 17, 2021

hermelin said:
Do you use qemu-guest-agent ? https://pve.proxmox.com/wiki/Qemu-guest-agent

As mentioned in the first post, yes.

You can also see this in the logs provided earlier:

Code:

INFO: issuing guest-agent 'fs-freeze' command
INFO: enabling encryption
INFO: issuing guest-agent 'fs-thaw' command

hermelin · Feb 17, 2021

robhost said:
As mentioned in the first post, yes.

You can also see this in the logs provided earlier:

Code:

INFO: issuing guest-agent 'fs-freeze' command INFO: enabling encryption INFO: issuing guest-agent 'fs-thaw' command

and is something info about fs-freeze in logs on VM

robhost · Feb 17, 2021

hermelin said:
and is something info about fs-freeze in logs on VM

Sure:

Code:

Feb 16 17:36:03 vs5480 qemu-ga[842]: info: guest-fsfreeze called
Feb 16 17:36:03 vs5480 host qemu-ga[842]: info: executing fsfreeze hook with arg 'freeze'
Feb 16 17:36:03 vs5480 qemu-ga[842]: info: executing fsfreeze hook with arg 'thaw'

danielb · Feb 17, 2021

robhost said:
FYI: Same happens with CentOS 8 when using ext4!

@danielb Are you using LVM (we do)?

Most of my VM are not using LVM, but some of them are. For information, what storage are your VM using ? I had this kind of FS corruption not because of PBS, but because of some iSCSI command responses when LIO was reprovisionned (I was using ZFS over iSCSI with LIO backend, switched to NFS with a ZFS backstore for now because of that)

robhost · Feb 17, 2021

danielb said:
For information, what storage are your VM using ?

Storage is Ceph in this case. Will test with local storage also now.

robhost · Feb 17, 2021

Figured it out:

When restoring any VM to Ceph storage, the FS is broken. When restoring to local disk it's fine.
So it seems to be a problem with the restore from PBS to Ceph storage!

tom · Feb 17, 2021

robhost said:
Storage is Ceph

Please add details regarding your Ceph storage.

robhost · Feb 17, 2021

Hi @tom

What do you want to know exactly? It's a separate Ceph cluster (not running on the PVE nodes) running this version:

> ceph version 15.2.8 (bdf3eebcd22d7d0b3dd4d5501bee5bac354d5b55) octopus (stable)

robhost · Feb 17, 2021

When using a "classic" .vma backup from the same VM, restore to the same Ceph storage works fine.
So the problem is definitly PBS related here in some way.

So that is the sitation (all with the same VM):

Backup VM with PBS and restore to Ceph: FS broken
Backup VM with PBS and restore to local HDD: FS ok
Backup VM with PVE vzdump and restore to Ceph or local HDD: FS ok

dcsapak · Feb 17, 2021

i tested here with a backed up debian onto a up-todate pbs, restored to my test ceph cluster (15.2.8) and had no problems whatsoever
so it's at least not a general problem

can you post the versions of pve and pbs ?
are there any errors in the syslog/journal of either pbs/pve or the ceph nodes?

XFS filesystem errors after VM restore

Active Member

Attachments

Renowned Member

Active Member

Renowned Member

Active Member

Active Member

Proxmox Staff Member

Active Member

Active Member

Attachments

Renowned Member

Active Member

Renowned Member

Active Member

Renowned Member

Active Member

Active Member

Proxmox Staff Member

Active Member

Active Member

Proxmox Staff Member