Problem with incremental backups Hyper-V Commercial

client
1

We are testing a new Server 2019 Hyper-V setup with ReFS and Dedup enabled on the VM storage. We have installed the commercial client version for Hyper-V. Full image backups work fine but we get error on incremental: “Exchanging data with client during image backup preparation failed. Connection to client broke”
Client: Server 2019 ReFS/Dedup. Version: 2.2.19-hyperv
Server: Server 2019 ReFS/Dedup. Version: 2.4.12

Here are the debug output from the client:

2020-03-02 20:35:06: Device D:\ isn’t NTFS formatted
2020-03-02 20:35:06: rc=0 hasError=true state=0
2020-03-02 20:35:06: Script “C:\Program Files\UrBackup\preimagebackup.bat” does not exist
2020-03-02 20:35:06: Creating shadowcopy of “hyperv://DHCP01/IDE:0:0”…
2020-03-02 20:35:06: FileSrv: Info: Window size=131072
2020-03-02 20:35:06: FileSrv: Received data…
2020-03-02 20:35:06: FileSrv: Received a Packet.
2020-03-02 20:35:06: FileSrv: Sending file (normal) urbackup/mbr_data_DHCP01–IDE_0_0.zip.err metadata_id=0
2020-03-02 20:35:06: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip.err
2020-03-02 20:35:06: FileSrv: Could not open file \?\C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip.err. The system cannot find the file specified. (code: 2)
2020-03-02 20:35:06: FileSrv: Received data…
2020-03-02 20:35:06: FileSrv: Received a Packet.
2020-03-02 20:35:06: Received flush.
2020-03-02 20:35:06: FileSrv: Received data…
2020-03-02 20:35:06: FileSrv: Received a Packet.
2020-03-02 20:35:06: FileSrv: Sending file (normal) urbackup/mbr_data_DHCP01–IDE_0_0.zip metadata_id=0
2020-03-02 20:35:06: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip
2020-03-02 20:35:06: FileSrv: Could not open file \?\C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip. The system cannot find the file specified. (code: 2)
2020-03-02 20:35:06: FileSrv: Received a Packet.
2020-03-02 20:35:06: Received flush.
2020-03-02 20:35:07: FileSrv: Received data…
2020-03-02 20:35:07: FileSrv: Received a Packet.
2020-03-02 20:35:07: FileSrv: Sending file (normal) urbackup/mbr_data_DHCP01–IDE_0_0.zip metadata_id=0
2020-03-02 20:35:07: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip
2020-03-02 20:35:07: FileSrv: Could not open file \?\C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip. The system cannot find the file specified. (code: 2)
2020-03-02 20:35:07: FileSrv: Received data…
2020-03-02 20:35:07: FileSrv: Received a Packet.
2020-03-02 20:35:07: Received flush.
2020-03-02 20:35:08: FileSrv: Received data…
2020-03-02 20:35:08: FileSrv: Received a Packet.
2020-03-02 20:35:08: FileSrv: Sending file (normal) urbackup/mbr_data_DHCP01–IDE_0_0.zip metadata_id=0
2020-03-02 20:35:08: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip
2020-03-02 20:35:08: FileSrv: Could not open file \?\C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip. The system cannot find the file specified. (code: 2)
2020-03-02 20:35:08: FileSrv: Received data…
2020-03-02 20:35:08: FileSrv: Received a Packet.
2020-03-02 20:35:08: Received flush.
2020-03-02 20:35:09: FileSrv: Received data…
2020-03-02 20:35:09: FileSrv: Received a Packet.
2020-03-02 20:35:09: FileSrv: Sending file (normal) urbackup/mbr_data_DHCP01–IDE_0_0.zip metadata_id=0
2020-03-02 20:35:09: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip
2020-03-02 20:35:09: FileSrv: Could not open file \?\C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip. The system cannot find the file specified. (code: 2)
2020-03-02 20:35:09: FileSrv: Received data…
2020-03-02 20:35:09: FileSrv: Received a Packet.
2020-03-02 20:35:09: Received flush.
2020-03-02 20:35:09: FileSrv: Received data…
2020-03-02 20:35:09: FileSrv: Received a Packet.
2020-03-02 20:35:09: FileSrv: Sending file (normal) urbackup/mbr_data_DHCP01–IDE_0_0.zip.err metadata_id=0
2020-03-02 20:35:09: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip.err
2020-03-02 20:35:09: FileSrv: Could not open file \?\C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip.err. The system cannot find the file specified. (code: 2)
2020-03-02 20:35:09: FileSrv: Received a Packet.
2020-03-02 20:35:09: Received flush.
2020-03-02 20:35:11: done.
2020-03-02 20:35:13: Zeroing image hash data of volume hyperv://DHCP01/IDE:0:0…
2020-03-02 20:35:13: Zeroed 281 MB
2020-03-02 20:35:13: Hyper-V save_id 13
2020-03-02 20:35:16: ClientService cmd: #ILPYeoZRKxF97gGPzqA4l#2PING RUNNING pc_done=0&status_id=96&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=RhQbcOy5xZ7DaiSU6R0u4
2020-03-02 20:35:21: ClientService cmd: STATUS#pw=taPcpD07RxCEgvhVI5T8VcyJB0hwHw
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:25: ClientService cmd: PONG
2020-03-02 20:35:26: ClientService cmd: #ILPYeoZRKxF97gGPzqA4l#2PING RUNNING pc_done=0&status_id=96&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=RhQbcOy5xZ7DaiSU6R0u4
2020-03-02 20:35:29: FileSrv: Received data…
2020-03-02 20:35:29: FileSrv: Received a Packet.
2020-03-02 20:35:29: FileSrv: Sending file (normal) urbackup/mbr_data_DHCP01–IDE_0_0.zip metadata_id=0
2020-03-02 20:35:29: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip
2020-03-02 20:35:29: FileSrv: Reading last file part
2020-03-02 20:35:29: FileSrv: Info: File End
2020-03-02 20:35:29: FileSrv: Closed file.
2020-03-02 20:35:29: FileSrv: Received data…
2020-03-02 20:35:29: FileSrv: Received a Packet.
2020-03-02 20:35:29: Received flush.
2020-03-02 20:35:29: FileSrv: Received data…
2020-03-02 20:35:29: FileSrv: Received a Packet.
2020-03-02 20:35:29: FileSrv: Sending file (normal) urbackup/mbr_data_DHCP01–IDE_0_0.zip.save_id metadata_id=0
2020-03-02 20:35:29: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\mbr_data_DHCP01–IDE_0_0.zip.save_id
2020-03-02 20:35:29: FileSrv: Reading last file part
2020-03-02 20:35:29: FileSrv: Info: File End
2020-03-02 20:35:29: FileSrv: Closed file.
2020-03-02 20:35:29: FileSrv: Received data…
2020-03-02 20:35:29: FileSrv: Received a Packet.
2020-03-02 20:35:29: Received flush.
2020-03-02 20:35:29: FileSrv: Recv Error in RecvMessage
2020-03-02 20:35:29: FileSrv: Deleting Memory…
2020-03-02 20:35:29: FileSrv: done.
2020-03-02 20:35:29: ClientService cmd: #ILPYeoZRKxF97gGPzqA4l#INCR IMAGE letter=IDE:0:0&hashsize=7290912&token=RhQbcOy5xZ7DaiSU6R0u4&checksum=1&bitmap=1&clientsubname=DHCP01&status_id=96&running_jobs=0&shadowid=13&zero_skipped=1&cbitmapsize=3645484
2020-03-02 20:35:31: ClientService cmd: STATUS#pw=taPcpD07RxCEgvhVI5T8VcyJB0hwHw
2020-03-02 20:35:36: FileSrv: ClientThread deleted. 1024 KB Memory freed.
2020-03-02 20:35:36: ClientService cmd: #ILPYeoZRKxF97gGPzqA4l#2PING RUNNING pc_done=0&status_id=96&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=RhQbcOy5xZ7DaiSU6R0u4
2020-03-02 20:35:46: ClientService cmd: #ILPYeoZRKxF97gGPzqA4l#2PING RUNNING pc_done=0&status_id=96&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=RhQbcOy5xZ7DaiSU6R0u4
2020-03-02 20:35:56: ClientService cmd: #ILPYeoZRKxF97gGPzqA4l#2PING RUNNING pc_done=0&status_id=96&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=RhQbcOy5xZ7DaiSU6R0u4
2020-03-02 20:36:06: ClientService cmd: #ILPYeoZRKxF97gGPzqA4l#2PING RUNNING pc_done=0&status_id=96&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=RhQbcOy5xZ7DaiSU6R0u4
2020-03-02 20:36:16: ClientService cmd: #ILPYeoZRKxF97gGPzqA4l#2PING RUNNING pc_done=0&status_id=96&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=RhQbcOy5xZ7DaiSU6R0u4
2020-03-02 20:36:19: ClientService cmd: #ILPYeoZRKxF97gGPzqA4l#2LOGDATA 1583177778 0-1583177706-Starting unscheduled incremental image backup of volume “IDE:0:0”…
0-1583177706-Basing image backup on last full image backup
0-1583177706-Loading ZIP metadata from urbackup/mbr_data_DHCP01–IDE_0_0.zip
0-1583177706-VM22[DHCP01]: Loading MBR zip file…
0-1583177729-VM22[DHCP01]: Loaded MBR zip file (14.2832 KB)
2-1583177778-Exchanging data with client during image backup preparation failed. Connection to client broke.
0-1583177778-Time taken for backing up client VM22[DHCP01]: 1m 12s
2-1583177778-Backup failed

Any ideas?

Regards
Jens

2

No, could you send/post the server debug log – maybe that has a hint? Thanks!

Btw. are you backing up to vhd or raw files? Backing up to raw files is problematic in combination with dedup (last time I looked).

3

Sorry here are the debu glog from the server. We use Compressed VHD in the settings.

2020-03-02 23:03:06: Loaded -url- plugin
2020-03-02 23:03:06: Loaded -fsimageplugin- plugin
2020-03-02 23:03:06: Starting HTTP-Server on port 55414
2020-03-02 23:03:06: HTTP: Server started up successfully!
2020-03-02 23:03:06: Loaded -cryptoplugin- plugin
2020-03-02 23:03:06: Loaded -fileserv- plugin
2020-03-02 23:03:06: Loaded -luaplugin- plugin
2020-03-02 23:03:06: FileSrv: Backup privileges set successfully
2020-03-02 23:03:06: FileSrv: Backup privileges set successfully (SE_SECURITY_NAME)
2020-03-02 23:03:06: FileSrv: Backup privileges set successfully (SE_RESTORE_NAME)
2020-03-02 23:03:06: SQLite: recovered 1452 frames from WAL file C:\Program Files\UrBackupServer\urbackup\backup_server.db-wal code: 283
2020-03-02 23:03:06: SQLite: recovered 46325 frames from WAL file C:\Program Files\UrBackupServer\urbackup\backup_server_files.db-wal code: 283
2020-03-02 23:03:06: SQLite: recovered 4 frames from WAL file C:\Program Files\UrBackupServer\urbackup\backup_server_link_journal.db-wal code: 283
2020-03-02 23:03:06: SQLite: recovered 68 frames from WAL file C:\Program Files\UrBackupServer\urbackup\backup_server_settings.db-wal code: 283
2020-03-02 23:03:06: SQLite: recovered 1452 frames from WAL file C:\Program Files\UrBackupServer\urbackup\backup_server.db-wal code: 283
2020-03-02 23:03:06: SQLite: recovered 68 frames from WAL file C:\Program Files\UrBackupServer\urbackup\backup_server_settings.db-wal code: 283
2020-03-02 23:03:07: SQLite: recovered 46325 frames from WAL file C:\Program Files\UrBackupServer\urbackup\backup_server_files.db-wal code: 283
2020-03-02 23:03:07: SQLite: recovered 4 frames from WAL file C:\Program Files\UrBackupServer\urbackup\backup_server_link_journal.db-wal code: 283
2020-03-02 23:03:07: Started UrBackup…
2020-03-02 23:03:07: Removing temporary files…
2020-03-02 23:03:07: Recreating temporary folder…
2020-03-02 23:03:07: Image mounting disabled. Install ImDisk to enable image mounting.
2020-03-02 23:03:07: Testing if backup destination can handle subvolumes and snapshots…
2020-03-02 23:03:07: Backup destination cannot handle subvolumes and snapshots. Snapshots disabled.
2020-03-02 23:03:07: Testing if backup destination can handle filesystem transactions…
2020-03-02 23:03:07: Testing for hardlinks in backup destination…
2020-03-02 23:03:07: Could not create hardlink at backup destination. Hardlinks disabled. The request is not supported. (code: 50)
2020-03-02 23:03:07: Testing for reflinks in backup destination…
2020-03-02 23:03:07: Could create reflink at backup destination. Reflinks enabled.
2020-03-02 23:03:07: UrBackup Server start up complete.
2020-03-02 23:03:07: Looking for old Sessions… 0 sessions
2020-03-02 23:03:07: Server started up successfully!
2020-03-02 23:03:07: Did not find backup suitable for archiving with backup_type=3 image=false letter=
2020-03-02 23:03:07: Did not find backup suitable for archiving with backup_type=3 image=false letter=
2020-03-02 23:03:07: Did not find backup suitable for archiving with backup_type=3 image=false letter=
2020-03-02 23:03:07: Did not find backup suitable for archiving with backup_type=3 image=false letter=
2020-03-02 23:03:09: Downloading version file…
2020-03-02 23:03:09: Broadcasting on interface IPv4 192.168.0.219
2020-03-02 23:03:09: Broadcasting on interface IPv6 ::1
2020-03-02 23:03:09: Downloading version file…
2020-03-02 23:03:09: Downloading server version info…
2020-03-02 23:03:10: Downloading dataplan database…
2020-03-02 23:03:10: ERROR: Sending broadcast failed! (ipv6)
2020-03-02 23:03:16: HTTP: No available slots… starting new Worker

2020-03-02 23:06:34: msg=START IMAGE INCR
2020-03-02 23:06:34: Cannot do image backup because internet_no_images=true
2020-03-02 23:06:35: Starting unscheduled incremental image backup of volume “IDE:0:0”…
2020-03-02 23:06:35: Basing image backup on last full image backup
2020-03-02 23:06:35: Loading ZIP metadata from urbackup/mbr_data_DHCP01–IDE_0_0.zip
2020-03-02 23:06:35: VM22[DHCP01]: Loading MBR zip file…
2020-03-02 23:06:35: Flushing FileClient…
2020-03-02 23:06:35: Server timeout (2) in FileClient
2020-03-02 23:06:41: Reconnected successfully,
2020-03-02 23:06:41: Reconnected successfully,
2020-03-02 23:06:41: Flushing FileClient…
2020-03-02 23:06:41: Flushing FileClient…
2020-03-02 23:06:41: Server timeout (2) in FileClient
2020-03-02 23:06:41: Reconnected successfully,
2020-03-02 23:06:41: Flushing FileClient…
2020-03-02 23:06:41: Server timeout (2) in FileClient
2020-03-02 23:06:41: Server timeout (2) in FileClient
2020-03-02 23:07:25: ERROR: Sending broadcast failed! (ipv6)
2020-03-02 23:07:25: Reconnected successfully,
2020-03-02 23:07:25: Flushing FileClient…
2020-03-02 23:07:25: Server timeout (2) in FileClient
2020-03-02 23:07:33: Reconnected successfully,
2020-03-02 23:07:33: Flushing FileClient…
2020-03-02 23:07:33: Server timeout (2) in FileClient
2020-03-02 23:08:16: ERROR: Sending broadcast failed! (ipv6)
2020-03-02 23:08:17: Reconnected successfully,
2020-03-02 23:08:17: Flushing FileClient…
2020-03-02 23:08:17: Server timeout (2) in FileClient
2020-03-02 23:08:24: Reconnected successfully,
2020-03-02 23:08:24: Flushing FileClient…
2020-03-02 23:08:24: Server timeout (2) in FileClient
2020-03-02 23:09:06: ERROR: Sending broadcast failed! (ipv6)
2020-03-02 23:09:08: Reconnected successfully,
2020-03-02 23:09:08: Flushing FileClient…
2020-03-02 23:09:08: Reconnected successfully,
2020-03-02 23:09:08: Flushing FileClient…
2020-03-02 23:09:08: Sending backup incr interval…
2020-03-02 23:09:08: Reconnected successfully,
2020-03-02 23:09:08: Flushing FileClient…
2020-03-02 23:09:10: Reconnected successfully,
2020-03-02 23:09:10: Flushing FileClient…
2020-03-02 23:09:10: Flushing FileClient…
2020-03-02 23:09:12: Sending backup incr interval…
2020-03-02 23:09:14: Reconnected successfully,
2020-03-02 23:09:14: Flushing FileClient…
2020-03-02 23:09:14: Sending backup incr interval…
2020-03-02 23:09:23: Flushing FileClient…
2020-03-02 23:09:24: Flushing FileClient…
2020-03-02 23:09:25: Flushing FileClient…
2020-03-02 23:09:25: Flushing FileClient…
2020-03-02 23:09:45: Flushing FileClient…
2020-03-02 23:09:45: Server timeout (2) in FileClient
2020-03-02 23:09:57: ERROR: Sending broadcast failed! (ipv6)
2020-03-02 23:09:59: Reconnected successfully,
2020-03-02 23:09:59: Flushing FileClient…
2020-03-02 23:09:59: Server timeout (2) in FileClient
2020-03-02 23:10:02: HTTP: No available slots… starting new Worker
2020-03-02 23:10:08: Reconnected successfully,
2020-03-02 23:10:48: ERROR: Sending broadcast failed! (ipv6)
2020-03-02 23:10:50: Reconnected successfully,
2020-03-02 23:10:50: Flushing FileClient…
2020-03-02 23:10:50: VM22[DHCP01]: Loaded MBR zip file (14.2861 KB)
2020-03-02 23:10:50: Flushing FileClient…
2020-03-02 23:11:39: ERROR: Sending broadcast failed! (ipv6)
2020-03-02 23:11:58: Sending file data failed
2020-03-02 23:11:58: ERROR: Exchanging data with client during image backup preparation failed. Connection to client broke.
2020-03-02 23:11:58: Time taken for backing up client VM22[DHCP01]: 5m 23s
2020-03-02 23:11:58: ERROR: Backup failed

Regards
Jens