proxmox-file-restore failed: Error: starting VM timed out (500)

[KMJ]

I setup a Proxmox Backup Server to replace Veeam Backup and till now everything worked great.

- Storage is on a 40TB NAS connected to the Proxmox cluster with 10GB Network.
- PBS runs on a node of the cluster and backups all VM's to this 40TB Storage.

This works great for all VM's and since Updating to 7.1 single file restore works fine for zfs and lvm too.

The problem is one VM which has a 3TB Harddisk mounted on a FreeBSD/TrueNAS VM serving files to the net.

The Backup of it worked great and the backup is shown with 3.24TB on the PBS Storage. I do have other VM's having up to 650GB which opens fine in the File Restore Box which is opening after clicking on File Restore.

When I try to do a file restore on the 3.24 TB VM, i get:

proxmox-file-restore failed: Error: starting VM timed out (500)
which switches to
communication error (0) after some seconds.

My problem is, i need the file restore on this VM, so I am looking where to increase this timeout to be able to handle this huge VM.

Thank you for any hint,

Greetings,
Karl

 

[KMJ]

I already tried upgrading everything. Proxmox is 7.1 as of today and Backup Server is 2.1 on server and client side, as of today.

 

[dietmar]

The problem is one VM which has a 3TB Harddisk mounted on a FreeBSD/TrueNAS VM serving files to the net.

What kind of file system does this VM use exactly?

 

[KMJ]

The Storage NAS is ZFS, which is NFS mounted
The TrueNAS Fileserver uses the 3TB Harddisk as ZFS Pool too.

It worked till yesterday, where the TrueNAS VM had 85GB. The biggest VM is 650GB, backed up to the same PBS Storage and it works fine too.

I blowed up the TrueNAS Harddisk vom 85GB to 3TB to be able to go live, then retested everything that I do not fail when going live.

All other VMs can be opened fine with file restore, except the one with the 3TB runs into this timeout.

 

[KMJ]

Update: The incremental Backup works fine. But the incremental fails file restore with time out. I am in the bad situation that I will be forced to move back to VMWare/Veeam if I do not get this under control.

Any help with the timeout, even I have to change script/programs manually would be greatly appreciated. It would be really bad to see the new solution gone there only for one problem. everything else works like a charme and is tested.


1926: 2021-12-22 01:00:06 INFO: Starting Backup of VM 1926 (qemu)
1926: 2021-12-22 01:00:06 INFO: status = running
1926: 2021-12-22 01:00:06 INFO: VM Name: fs01.hq.mydomain.tld
1926: 2021-12-22 01:00:06 INFO: include disk 'scsi0' 'NFSDATA:1926/vm-1926-disk-0.raw' 16G
1926: 2021-12-22 01:00:06 INFO: include disk 'scsi1' 'NFSDATA:1926/vm-1926-disk-1.raw' 3000G
1926: 2021-12-22 01:00:06 INFO: backup mode: snapshot
1926: 2021-12-22 01:00:06 INFO: ionice priority: 7
1926: 2021-12-22 01:00:06 INFO: creating Proxmox Backup Server archive 'vm/1926/2021-12-22T00:00:06Z'
1926: 2021-12-22 01:00:09 INFO: started backup task '87c7e364-c552-4d6b-9295-563ca6547b5b'
1926: 2021-12-22 01:00:09 INFO: resuming VM again
1926: 2021-12-22 01:00:09 INFO: scsi0: dirty-bitmap status: OK (84.0 MiB of 16.0 GiB dirty)
1926: 2021-12-22 01:00:09 INFO: scsi1: dirty-bitmap status: OK (4.3 GiB of 2.9 TiB dirty)
1926: 2021-12-22 01:00:09 INFO: using fast incremental mode (dirty-bitmap), 4.4 GiB dirty of 2.9 TiB total
1926: 2021-12-22 01:00:12 INFO: 6% (312.0 MiB of 4.4 GiB) in 3s, read: 104.0 MiB/s, write: 104.0 MiB/s
1926: 2021-12-22 01:00:15 INFO: 12% (568.0 MiB of 4.4 GiB) in 6s, read: 85.3 MiB/s, write: 85.3 MiB/s
1926: 2021-12-22 01:00:18 INFO: 19% (856.0 MiB of 4.4 GiB) in 9s, read: 96.0 MiB/s, write: 96.0 MiB/s
1926: 2021-12-22 01:00:21 INFO: 24% (1.1 GiB of 4.4 GiB) in 12s, read: 85.3 MiB/s, write: 85.3 MiB/s
1926: 2021-12-22 01:00:24 INFO: 30% (1.3 GiB of 4.4 GiB) in 15s, read: 82.7 MiB/s, write: 82.7 MiB/s
1926: 2021-12-22 01:00:27 INFO: 37% (1.6 GiB of 4.4 GiB) in 18s, read: 102.7 MiB/s, write: 102.7 MiB/s
1926: 2021-12-22 01:00:30 INFO: 42% (1.9 GiB of 4.4 GiB) in 21s, read: 85.3 MiB/s, write: 85.3 MiB/s
1926: 2021-12-22 01:00:33 INFO: 49% (2.2 GiB of 4.4 GiB) in 24s, read: 104.0 MiB/s, write: 104.0 MiB/s
1926: 2021-12-22 01:00:36 INFO: 54% (2.4 GiB of 4.4 GiB) in 27s, read: 76.0 MiB/s, write: 76.0 MiB/s
1926: 2021-12-22 01:00:39 INFO: 60% (2.7 GiB of 4.4 GiB) in 30s, read: 88.0 MiB/s, write: 88.0 MiB/s
1926: 2021-12-22 01:00:42 INFO: 66% (2.9 GiB of 4.4 GiB) in 33s, read: 90.7 MiB/s, write: 90.7 MiB/s
1926: 2021-12-22 01:00:45 INFO: 73% (3.2 GiB of 4.4 GiB) in 36s, read: 97.3 MiB/s, write: 97.3 MiB/s
1926: 2021-12-22 01:00:48 INFO: 80% (3.5 GiB of 4.4 GiB) in 39s, read: 101.3 MiB/s, write: 101.3 MiB/s
1926: 2021-12-22 01:00:51 INFO: 86% (3.8 GiB of 4.4 GiB) in 42s, read: 88.0 MiB/s, write: 88.0 MiB/s
1926: 2021-12-22 01:00:54 INFO: 92% (4.1 GiB of 4.4 GiB) in 45s, read: 96.0 MiB/s, write: 96.0 MiB/s
1926: 2021-12-22 01:00:57 INFO: 98% (4.3 GiB of 4.4 GiB) in 48s, read: 90.7 MiB/s, write: 88.0 MiB/s
1926: 2021-12-22 01:00:59 INFO: 100% (4.4 GiB of 4.4 GiB) in 50s, read: 34.0 MiB/s, write: 26.0 MiB/s
1926: 2021-12-22 01:00:59 INFO: backup was done incrementally, reused 2.94 TiB (99%)
1926: 2021-12-22 01:00:59 INFO: transferred 4.38 GiB in 50 seconds (89.8 MiB/s)
1926: 2021-12-22 01:00:59 INFO: Finished Backup of VM 1926 (00:00:53)

 

[KMJ]

Update: The incremental Backup works fine. But the incremental fails file restore with time out. I am in the bad situation that I will be forced to move back to VMWare/Veeam if I do not get this under control.

Any help with the timeout, even I have to change script/programs manually would be greatly appreciated. It would be really bad to see the new solution gone there only for one problem. everything else works like a charme and is tested.


1926: 2021-12-22 01:00:06 INFO: Starting Backup of VM 1926 (qemu)
1926: 2021-12-22 01:00:06 INFO: status = running
1926: 2021-12-22 01:00:06 INFO: VM Name: fs01.hq.mydomain.tld
1926: 2021-12-22 01:00:06 INFO: include disk 'scsi0' 'NFSDATA:1926/vm-1926-disk-0.raw' 16G
1926: 2021-12-22 01:00:06 INFO: include disk 'scsi1' 'NFSDATA:1926/vm-1926-disk-1.raw' 3000G
1926: 2021-12-22 01:00:06 INFO: backup mode: snapshot
1926: 2021-12-22 01:00:06 INFO: ionice priority: 7
1926: 2021-12-22 01:00:06 INFO: creating Proxmox Backup Server archive 'vm/1926/2021-12-22T00:00:06Z'
1926: 2021-12-22 01:00:09 INFO: started backup task '87c7e364-c552-4d6b-9295-563ca6547b5b'
1926: 2021-12-22 01:00:09 INFO: resuming VM again
1926: 2021-12-22 01:00:09 INFO: scsi0: dirty-bitmap status: OK (84.0 MiB of 16.0 GiB dirty)
1926: 2021-12-22 01:00:09 INFO: scsi1: dirty-bitmap status: OK (4.3 GiB of 2.9 TiB dirty)
1926: 2021-12-22 01:00:09 INFO: using fast incremental mode (dirty-bitmap), 4.4 GiB dirty of 2.9 TiB total
1926: 2021-12-22 01:00:12 INFO: 6% (312.0 MiB of 4.4 GiB) in 3s, read: 104.0 MiB/s, write: 104.0 MiB/s
1926: 2021-12-22 01:00:15 INFO: 12% (568.0 MiB of 4.4 GiB) in 6s, read: 85.3 MiB/s, write: 85.3 MiB/s
1926: 2021-12-22 01:00:18 INFO: 19% (856.0 MiB of 4.4 GiB) in 9s, read: 96.0 MiB/s, write: 96.0 MiB/s
1926: 2021-12-22 01:00:21 INFO: 24% (1.1 GiB of 4.4 GiB) in 12s, read: 85.3 MiB/s, write: 85.3 MiB/s
1926: 2021-12-22 01:00:24 INFO: 30% (1.3 GiB of 4.4 GiB) in 15s, read: 82.7 MiB/s, write: 82.7 MiB/s
1926: 2021-12-22 01:00:27 INFO: 37% (1.6 GiB of 4.4 GiB) in 18s, read: 102.7 MiB/s, write: 102.7 MiB/s
1926: 2021-12-22 01:00:30 INFO: 42% (1.9 GiB of 4.4 GiB) in 21s, read: 85.3 MiB/s, write: 85.3 MiB/s
1926: 2021-12-22 01:00:33 INFO: 49% (2.2 GiB of 4.4 GiB) in 24s, read: 104.0 MiB/s, write: 104.0 MiB/s
1926: 2021-12-22 01:00:36 INFO: 54% (2.4 GiB of 4.4 GiB) in 27s, read: 76.0 MiB/s, write: 76.0 MiB/s
1926: 2021-12-22 01:00:39 INFO: 60% (2.7 GiB of 4.4 GiB) in 30s, read: 88.0 MiB/s, write: 88.0 MiB/s
1926: 2021-12-22 01:00:42 INFO: 66% (2.9 GiB of 4.4 GiB) in 33s, read: 90.7 MiB/s, write: 90.7 MiB/s
1926: 2021-12-22 01:00:45 INFO: 73% (3.2 GiB of 4.4 GiB) in 36s, read: 97.3 MiB/s, write: 97.3 MiB/s
1926: 2021-12-22 01:00:48 INFO: 80% (3.5 GiB of 4.4 GiB) in 39s, read: 101.3 MiB/s, write: 101.3 MiB/s
1926: 2021-12-22 01:00:51 INFO: 86% (3.8 GiB of 4.4 GiB) in 42s, read: 88.0 MiB/s, write: 88.0 MiB/s
1926: 2021-12-22 01:00:54 INFO: 92% (4.1 GiB of 4.4 GiB) in 45s, read: 96.0 MiB/s, write: 96.0 MiB/s
1926: 2021-12-22 01:00:57 INFO: 98% (4.3 GiB of 4.4 GiB) in 48s, read: 90.7 MiB/s, write: 88.0 MiB/s
1926: 2021-12-22 01:00:59 INFO: 100% (4.4 GiB of 4.4 GiB) in 50s, read: 34.0 MiB/s, write: 26.0 MiB/s
1926: 2021-12-22 01:00:59 INFO: backup was done incrementally, reused 2.94 TiB (99%)
1926: 2021-12-22 01:00:59 INFO: transferred 4.38 GiB in 50 seconds (89.8 MiB/s)
1926: 2021-12-22 01:00:59 INFO: Finished Backup of VM 1926 (00:00:53)

I need to come back to this one, currently I am toasted. :-(

I tried to not beeing forced to move back to Veeam and reduced the size of the disks and made 165, 400,200,400 GB on this System so File Restore worked fine. To bad I was forced to add another 400GB disk and now I run into this timeout again.

Please! Is there any setting to increase the timeout? Any hint which program does file restore and where it gets the timeout?

Backup, everything works great and now I am finally with the back against the wall.

Thank you for any hint!

 

[dcsapak]

mhmm looking at the code, the timeout is currently hardcoded in and it waits up to 12 seconds after the vm has started to connect to it... in theory that should be plenty of time, but i guess we could increase the timeout...
could you please open a bug here: https://bugzilla.proxmox.com

EDIT: sorry i misread the source, its up to 120+12 seconds...

 

[KMJ]

Good Morning Dominik,

i updated Server and CLient from 2.1-2 to 2.1-3 yesterday and retested things:

- Click on the NFSPBS Store shows the backup list after 1-2 seconds
- Entering 1926 (VMID) in the search shows the backups immediately
- Clicking File Restore on the Backup with 446GB and a later one with 1.09 TB and 4 disks shows things after around 10-15 seconds
- Clicking File Restore on the Backup with 1.5TB, 5 disks, shows the error after 17-18 seconds.

I will file the bug as mentioned and hope for a solution because I am already live :-(

Greetings;

Karl

 

[KMJ]

https://bugzilla.proxmox.com/show_bug.cgi?id=3836