Error in DeviceIoControl during Hyper-V backups

jayb · March 14, 2019, 6:15am

Hi - thanks in advance for any help.

I have server installed on Server 2016 standard, backing up another Server 2016 Standard instance. The host has 8 x Server 2012R2 vm’s - some running, some not. 6 of the VM’s do image backups successfully without issues, 2 VM’s consistently fail. All VM’s have been ‘upgraded’ to the latest hardware/virtualisation version inside Hyper-V Manager.

On the client, I see the following in the log

2019-03-11 07:14:12: WARNING: Restarting shadow copy of hyperv://hodor.xxx.yyy.zzz/SCSI:0:0 because it was started by this server
2019-03-11 07:14:36: ERROR: Error in DeviceIoControl(IOCTL_DISK_GET_LENGTH_INFO)
2019-03-11 07:15:37: ERROR: Could not open path in os_get_final_path for “e:\Hyper-V\Snapshots\02A91E45-0C6C-4DEA-8EB9-B1648F388514.xml”
2019-03-11 07:15:37: ERROR: Could not open path in os_get_final_path for “e:\Hyper-V\Snapshots\479CA8C1-3A30-4E24-9645-057DE3B55F14.xml”
2019-03-11 07:15:37: ERROR: Could not open path in os_get_final_path for “e:\Hyper-V\Snapshots\4BF61647-7E8C-482E-BACF-9DCE6CED7335.xml”
2019-03-11 07:15:37: ERROR: Could not open path in os_get_final_path for “e:\Hyper-V\Snapshots\58588676-A469-409B-A007-DA73A1E178CA.xml”
2019-03-11 07:15:37: ERROR: Could not open path in os_get_final_path for “e:\Hyper-V\Snapshots\C33EBBC0-5BA3-4890-9242-C3B1405BC858.xml”
2019-03-11 07:15:37: ERROR: Could not open path in os_get_final_path for “e:\Hyper-V\Snapshots\F2CD29FB-24D0-428D-8735-F4CFD7F7A21C.xml”
2019-03-11 07:19:56: ERROR: Error opening vhd file. Errorcode: 2
2019-03-11 07:19:56: WARNING: FSPartitioned has error
2019-03-11 07:19:56: ERROR: Opening filesystem on device failed. Stopping.

On the server side logs I see:

019-03-11 07:14:05: WARNING: Error retrieving last image backup. Doing full image backup instead.
2019-03-11 07:14:31: ERROR: Client disconnected and image is not persistent (Timeout: false).
2019-03-11 07:14:31: ERROR: Backup failed
2019-03-11 07:14:32: WARNING: Exponential backoff: Waiting at least 3 days 13h 20m before next image backup
2019-03-11 07:14:43: WARNING: Connecting to ClientService of “hpv1-sbe[hodor.xxx.yyy.zzz]” failed: Sending logdata to client failed
2019-03-11 07:19:14: WARNING: Error retrieving last image backup. Doing full image backup instead.
2019-03-11 07:19:57: ERROR: Request of image backup failed. Reason: Opening filesystem on device failed. Stopping.
2019-03-11 07:19:57: ERROR: Backup failed
2019-03-11 07:19:58: WARNING: Exponential backoff: Waiting at least 3 days 13h 20m before next image backup
2019-03-12 03:33:02: WARNING: Deleting b:\UrBackup\hpv1-sbe[hodor.xxx.yyy.zzz]\190311-0714_Image_SCSI_0_0\Image_SCSI_0_0_190311-0714.vhd failed. The system cannot find the file specified. (code: 2)
2019-03-12 03:33:02: WARNING: Deleting b:\UrBackup\hpv1-sbe[hodor.xxx.yyy.zzz]\190311-0714_Image_SCSI_0_0\Image_SCSI_0_0_190311-0714.vhd.hash failed. The system cannot find the file specified. (code: 2)
2019-03-12 03:33:02: WARNING: Deleting b:\UrBackup\hpv1-sbe[hodor.xxx.yyy.zzz]\190311-0714_Image_SCSI_0_0\Image_SCSI_0_0_190311-0714.vhd.cbitmap failed. The system cannot find the file specified. (code: 2)
2019-03-12 03:33:02: WARNING: Deleting b:\UrBackup\hpv1-sbe[hodor.xxx.yyy.zzz]\190311-0714_Image_SCSI_0_0\Image_SCSI_0_0_190311-0714.vhd.sync failed. The system cannot find the file specified. (code: 2)
2019-03-12 03:33:02: WARNING: Deleting incomplete image “b:\UrBackup\hpv1-sbe[hodor.xxx.yyy.zzz]\190311-0714_Image_SCSI_0_0\Image_SCSI_0_0_190311-0714.vhd” failed.

The server is version 2.3.7, the client is a trial version of 2.2.13-hyperv. Intention is that this server/client combo is our proof of concept. If it all works, will purchase upwards of 30 licenses.

The client periodically crashes the urbackup service, with this in the event log:
Faulting application name: UrBackupClientBackend.exe, version: 0.0.0.0, time stamp: 0x5c4a5a8b
Faulting module name: ntdll.dll, version: 10.0.14393.2608, time stamp: 0x5bd133d4
Exception code: 0xc0000374
Fault offset: 0x00000000000f7b43
Faulting process id: 0x14e4
Faulting application start time: 0x01d4d504bef5fb0c
Faulting application path: C:\Program Files\UrBackup\UrBackupClientBackend.exe
Faulting module path: C:\Windows\SYSTEM32\ntdll.dll
Report Id: fd24fce4-6417-4b83-898c-81f86fe87b42
Faulting package full name:
Faulting package-relative application ID:

There is no consistency though between timestamps of when the service crashes and backups fail. Sometimes they align, most of the time they do not.

Thanks for any help or advice

uroni · March 14, 2019, 1:36pm

Thanks for trying.
It would be helpful, if you run the client in debug logging mode (like described in Having problems with UrBackup? Please read before posting) – that would give more context for the errors.

The Error in DeviceIoControl(IOCTL_DISK_GET_LENGTH_INFO) issue might be caused by the disk file extension being unrecognized. You are using vhd(x) (or do you have raw disks attached)?

W.r.t. the crash, a crash dump would be most helpful. Normally it creates one and puts the location where into the log.

jayb · March 14, 2019, 11:01pm

Thanks for the advice. I have enabled the debug logging and it’s running against one of the failed servers now. Should be able to provide log exports sometime in the next 1-2 hours.

With regards to crashdumps. Every time the client crashes the service with a ntdll.dll faulting module, there is an entry in the urbackup client log of “2019-03-08 15:13:24: ERROR: Error in DeviceIoControl(IOCTL_DISK_GET_LENGTH_INFO)”. Nothing else - just the single line. If it is supposed to be dumping to a file and recording that I can’t see it.

[edit]
Apologies - missed the question about disk type.

Hyper-V has VM files as vhdx format on the storage. UrBackup server is saving image files as VHD format.

jayb · March 14, 2019, 11:04pm

export of the log files attached

uroni · March 14, 2019, 11:30pm

Thanks for the log files. I removed them after download.

uroni · March 14, 2019, 11:56pm

Could you try if the 2.2.14 version at https://cbt.urbackup.com/2bd39cce-d4ab-4555-90f2-cc4b14ff80fc fixes the issue now?

jayb · March 15, 2019, 1:55am

Updated version installed, backup is progressing. It’s gotten further than it ever has before which is a huge positive. I will let you know success/failure.

Thanks for your help and efforts.

jayb · March 18, 2019, 11:26pm

Backups are still progressing and haven’t failed yet - it has made it to 80 odd percent out of 700GB. Looks like the change made to the new version has been successful. I’ll provide a further update in another day and a bit if it finishes uploading over the 10mb link.

UPDATE
1st of the VM’s that previously failed has completed successfully. It is now progressing through the 2nd of the failed VM’s. It will take another 2-3 days to complete. But at this point I am very close to saying the 2.2.13 to 2.2.14 client upgrade has resolved the problem. Thank you Uroni for your help and whatever updates to code you made.

UPDATE #2

All backups have completed successfully. The patch to 2.2.14 has resolved the issue experienced. Thanks Uroni for all your help - much appreciated.