Protocol cancelled?

[mhentrich]

Trying to backup a large VM with several disks. With fleecing off, the backup runs successfully (though the performance is so bad we normally have to cancel it). With fleecing on, it seems to cancel itself a couple of percent in. Here are the logs:

INFO: VM Name: QA-SQL
INFO: include disk 'virtio0' 'saprox-daily:vm-114-disk-0.qcow2' 250G
INFO: include disk 'virtio1' 'saprox-daily:vm-114-disk-1.qcow2' 4T
INFO: include disk 'virtio2' 'saprox-daily:vm-114-disk-3.qcow2' 500G
INFO: include disk 'virtio3' 'saprox-daily:vm-114-disk-4.qcow2' 2560G
INFO: include disk 'virtio4' 'saprox-daily:vm-114-disk-5.qcow2' 100G
INFO: include disk 'virtio5' 'saprox-daily:vm-114-disk-2.qcow2' 50G
INFO: include disk 'virtio6' 'saprox-daily:vm-114-disk-6.qcow2' 4608G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating Proxmox Backup Server archive 'vm/114/2026-03-26T07:35:25Z'
Formatting '/mnt/pve/fleece/images/114/vm-114-fleece-0.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off preallocation=metadata compression_type=zlib size=268435456000 lazy_refcounts=off refcount_bits=16
Formatting '/mnt/pve/fleece/images/114/vm-114-fleece-1.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off preallocation=metadata compression_type=zlib size=4398046511104 lazy_refcounts=off refcount_bits=16
Formatting '/mnt/pve/fleece/images/114/vm-114-fleece-2.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off preallocation=metadata compression_type=zlib size=536870912000 lazy_refcounts=off refcount_bits=16
Formatting '/mnt/pve/fleece/images/114/vm-114-fleece-3.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off preallocation=metadata compression_type=zlib size=2748779069440 lazy_refcounts=off refcount_bits=16
Formatting '/mnt/pve/fleece/images/114/vm-114-fleece-4.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off preallocation=metadata compression_type=zlib size=107374182400 lazy_refcounts=off refcount_bits=16
Formatting '/mnt/pve/fleece/images/114/vm-114-fleece-5.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off preallocation=metadata compression_type=zlib size=53687091200 lazy_refcounts=off refcount_bits=16
Formatting '/mnt/pve/fleece/images/114/vm-114-fleece-6.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off preallocation=metadata compression_type=zlib size=4947802324992 lazy_refcounts=off refcount_bits=16
INFO: drive-virtio0: attaching fleecing image fleece-local:114/vm-114-fleece-0.qcow2 to QEMU
INFO: drive-virtio1: attaching fleecing image fleece-local:114/vm-114-fleece-1.qcow2 to QEMU
INFO: drive-virtio2: attaching fleecing image fleece-local:114/vm-114-fleece-2.qcow2 to QEMU
INFO: drive-virtio3: attaching fleecing image fleece-local:114/vm-114-fleece-3.qcow2 to QEMU
INFO: drive-virtio4: attaching fleecing image fleece-local:114/vm-114-fleece-4.qcow2 to QEMU
INFO: drive-virtio5: attaching fleecing image fleece-local:114/vm-114-fleece-5.qcow2 to QEMU
INFO: drive-virtio6: attaching fleecing image fleece-local:114/vm-114-fleece-6.qcow2 to QEMU
INFO: issuing guest-agent 'fs-freeze' command
INFO: issuing guest-agent 'fs-thaw' command
INFO: started backup task '125b36c2-09dd-440e-817c-96bac3056734'
INFO: resuming VM again
INFO: virtio0: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: virtio1: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: virtio2: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: virtio3: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: virtio4: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: virtio5: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: virtio6: dirty-bitmap status: existing bitmap was invalid and has been cleared
INFO: 0% (564.0 MiB of 11.9 TiB) in 3s, read: 188.0 MiB/s, write: 165.3 MiB/s
INFO: 1% (121.7 GiB of 11.9 TiB) in 28m 11s, read: 73.5 MiB/s, write: 73.5 MiB/s
INFO: 1% (144.4 GiB of 11.9 TiB) in 33m 34s, read: 71.9 MiB/s, write: 71.9 MiB/s
ERROR: backup write data failed: command error: protocol canceled
INFO: aborting backup job
INFO: resuming VM again
INFO: removing (old) fleecing image 'fleece-local:114/vm-114-fleece-0.qcow2'
INFO: removing (old) fleecing image 'fleece-local:114/vm-114-fleece-1.qcow2'
INFO: removing (old) fleecing image 'fleece-local:114/vm-114-fleece-2.qcow2'
INFO: removing (old) fleecing image 'fleece-local:114/vm-114-fleece-3.qcow2'
INFO: removing (old) fleecing image 'fleece-local:114/vm-114-fleece-4.qcow2'
INFO: removing (old) fleecing image 'fleece-local:114/vm-114-fleece-5.qcow2'
INFO: removing (old) fleecing image 'fleece-local:114/vm-114-fleece-6.qcow2'
ERROR: Backup of VM 114 failed - backup write data failed: command error: protocol canceled
INFO: Failed at 2026-03-26 03:10:15

Any idea what would cause this? The fleecing disk is 3.84 TB.

Thanks,
Matt H

 

[bitranox]

any reason why the data sits IN the vm ? usually You put the data seperated and mount it into the vm.
But maybe I got smth wrong here ?

 

[niteshadow]

I see VM is resuming after backup was aborted.
Can you confirm the status of the guest-agent (seems not present) ?
I was expecting something like this (files system freeze and snapshoted, VM resumes, then backup of snapshot):

INFO: Starting Backup of VM 610 (qemu)
INFO: Backup started at 2026-03-26 03:00:03
INFO: status = running
INFO: VM Name: emh-vm1
INFO: include disk 'scsi0' 'data:vm-610-disk-0' 128G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: snapshots found (not included into backup)
INFO: creating Proxmox Backup Server archive 'vm/610/2026-03-26T07:00:03Z'
INFO: issuing guest-agent 'fs-freeze' command
INFO: issuing guest-agent 'fs-thaw' command
INFO: started backup task 'e539d4b4-191d-4719-93d6-3c8557c18793'
INFO: resuming VM again
INFO: scsi0: dirty-bitmap status: OK (7.2 GiB of 128.0 GiB dirty)
INFO: using fast incremental mode (dirty-bitmap), 7.2 GiB dirty of 128.0 GiB total
INFO: 10% (768.0 MiB of 7.2 GiB) in 3s, read: 256.0 MiB/s, write: 238.7 MiB/s
INFO: 18% (1.3 GiB of 7.2 GiB) in 6s, read: 194.7 MiB/s, write: 146.7 MiB/s
INFO: 26% (1.9 GiB of 7.2 GiB) in 9s, read: 190.7 MiB/s, write: 150.7 MiB/s
INFO: 35% (2.6 GiB of 7.2 GiB) in 12s, read: 245.3 MiB/s, write: 140.0 MiB/s
INFO: 49% (3.6 GiB of 7.2 GiB) in 15s, read: 342.7 MiB/s, write: 120.0 MiB/s
INFO: 63% (4.6 GiB of 7.2 GiB) in 18s, read: 325.3 MiB/s, write: 149.3 MiB/s
INFO: 73% (5.3 GiB of 7.2 GiB) in 21s, read: 252.0 MiB/s, write: 132.0 MiB/s
INFO: 87% (6.3 GiB of 7.2 GiB) in 24s, read: 346.7 MiB/s, write: 141.3 MiB/s
INFO: 100% (7.2 GiB of 7.2 GiB) in 27s, read: 312.0 MiB/s, write: 141.3 MiB/s
INFO: Waiting for server to finish backup validation...
INFO: backup is sparse: 1.88 GiB (26%) total zero data
INFO: backup was done incrementally, reused 124.02 GiB (96%)
INFO: transferred 7.22 GiB in 28 seconds (264.1 MiB/s)
INFO: adding notes to backup
INFO: Finished Backup of VM 610 (00:00:31)
INFO: Backup finished at 2026-03-26 03:00:34