File backup status is "ok" but it contains no files (0 bytes)

alexxboo · March 29, 2018, 11:49am

Hi there,

after resolving the prefilebackup script issue unfortunately I ran into another problem.

I’m trying to do a full file backup of my Windows 10 machine. The image-Backup runs fine. The filebackup however spends some time indexing and then abruptly finishes (100%, status ok) with no files being transferred to the backup server.

Any help would be highly appreciated

Following are the client logs:

2018-03-29 13:18:09: ClientService cmd: START BACKUP FULL#pw=eyG<...>euu
2018-03-29 13:18:09: rc=0 hasError=true state=0
2018-03-29 13:18:10: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:10: ClientService cmd: #IOf<..>8hh#2PING RUNNING pc_done=&status_id=11&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=JEr<...>WCl
2018-03-29 13:18:10: ClientService cmd: #IOf<..>8hh#3START FULL BACKUP group=0&running_jobs=1&sha=528&with_permissions=1&with_scripts=1&with_orig_path=1&with_sequence=1&with_proper_symlinks=1&status_id=11&async=1#token=JEr<...>WCl
2018-03-29 13:18:10: Async index 85f<...>aa3
2018-03-29 13:18:10: rc=0 hasError=true state=0
2018-03-29 13:18:10: ClientService cmd: #IOf<..>8hh#WAIT FOR INDEX async_id=85f<...>aa3#token=JEr<...>WCl
2018-03-29 13:18:10: Wait for async index 85f<...>aa3
2018-03-29 13:18:11: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:11: ClientService cmd: STATUS#pw=eyG<...>euu
2018-03-29 13:18:12: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:13: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:14: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:15: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:15: ERROR: Recvfrom error in CUDPThread::UdpStep
2018-03-29 13:18:15: ERROR: Last error: 10058
2018-03-29 13:18:15: CUDPThread exited.
2018-03-29 13:18:15: FileSrv: Backup privileges set successfully
2018-03-29 13:18:15: FileSrv: Backup privileges set successfully (SE_SECURITY_NAME)
2018-03-29 13:18:15: FileSrv: Backup privileges set successfully (SE_RESTORE_NAME)
2018-03-29 13:18:15: FileSrv: Binding UDP socket at port 35622...
2018-03-29 13:18:15: FileSrv: done.
2018-03-29 13:18:15: FileSrv: Disabling new behavior...
2018-03-29 13:18:15: Final path: D:\tmp
2018-03-29 13:18:15: Removing VSS log data...
2018-03-29 13:18:15: FileSrv: Servername: -Quboid-
2018-03-29 13:18:15: FileSrv: Server started up successfully
2018-03-29 13:18:15: FileSrv: UDP Thread startet
2018-03-29 13:18:15: Final path: D:\tmp
2018-03-29 13:18:15: Script list at "C:\Program Files\UrBackup\backup_scripts\list.bat" does not exist. Skipping.
2018-03-29 13:18:15: Deleting files... doing full index...
2018-03-29 13:18:16: Script "C:\Program Files\UrBackup\prefilebackup.bat" does not exist
2018-03-29 13:18:16: Final path: D:\tmp
2018-03-29 13:18:16: Removing deleted directories from index...
2018-03-29 13:18:16: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:17: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:17: Selected no components to backup
2018-03-29 13:18:17: Creating shadowcopy of "tmp" in indexDirs()
2018-03-29 13:18:18: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:19: ClientService cmd: PONG
2018-03-29 13:18:19: Number of Writers: 12
2018-03-29 13:18:19: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer MSSearch Service Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer MSMQ Writer (MSMQ) has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Preparing change block tracking reset for volume d: failed: Unzulässige Funktion. (code: 1)
2018-03-29 13:18:19: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:19: Number of Writers: 12
2018-03-29 13:18:19: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer MSSearch Service Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer MSMQ Writer (MSMQ) has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:19: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:20: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:20: ClientService cmd: #IOf<..>8hh#2PING RUNNING pc_done=&eta_ms=61000&status_id=11&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=JEr<...>WCl
2018-03-29 13:18:21: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:22: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:23: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:24: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:25: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:26: Number of Writers: 12
2018-03-29 13:18:26: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:26: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:26: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:26: Writer System Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-03-29 13:18:26: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-03-29 13:18:26: Writer ASR Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-03-29 13:18:26: Writer IIS Config Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-03-29 13:18:26: Writer Registry Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-03-29 13:18:26: Writer MSSearch Service Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-03-29 13:18:26: Writer COM+ REGDB Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-03-29 13:18:26: Writer MSMQ Writer (MSMQ) has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-03-29 13:18:26: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-03-29 13:18:26: Shadowcopy path: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11
2018-03-29 13:18:26: done.
2018-03-29 13:18:26: Disabling CBT on volume "D:"
2018-03-29 13:18:26: Indexing "tmp"...
2018-03-29 13:18:26: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:27: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:28: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:29: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:29: Indexing of "tmp" done. 4 filesystem lookups 0 db lookups and 0 db updates
2018-03-29 13:18:29: Deleting backup of changed dirs...
2018-03-29 13:18:29: Script "C:\Program Files\UrBackup\postfileindex.bat" does not exist
2018-03-29 13:18:29: Async index 85f<...>aa3 finished with "done"
2018-03-29 13:18:29: ClientService cmd: #IOf<..>8hh#GET VSSLOG
2018-03-29 13:18:29: VSS logdata - 148 bytes
2018-03-29 13:18:29: rc=0 hasError=true state=0
2018-03-29 13:18:29: rc=0 hasError=true state=0
2018-03-29 13:18:29: FileSrv: Info: Window size=65536
2018-03-29 13:18:29: FileSrv: Received data...
2018-03-29 13:18:29: FileSrv: Received a Packet.
2018-03-29 13:18:29: FileSrv: Sending file (normal) urbackup/filelist.ub metadata_id=0
2018-03-29 13:18:29: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\filelist.ub
2018-03-29 13:18:29: FileSrv: Reading last file part
2018-03-29 13:18:29: FileSrv: Info: File End
2018-03-29 13:18:29: FileSrv: Closed file.
2018-03-29 13:18:29: FileSrv: Received data...
2018-03-29 13:18:29: FileSrv: Received a Packet.
2018-03-29 13:18:29: Received flush.
2018-03-29 13:18:29: FileSrv: Received data...
2018-03-29 13:18:29: FileSrv: Received a Packet.
2018-03-29 13:18:29: FileSrv: Sending file (normal) urbackup/tokens_JEr<...>WCl.properties metadata_id=0
2018-03-29 13:18:29: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\tokens_JEr<...>WCl.properties
2018-03-29 13:18:29: FileSrv: Reading last file part
2018-03-29 13:18:29: FileSrv: Info: File End
2018-03-29 13:18:29: FileSrv: Closed file.
2018-03-29 13:18:29: FileSrv: Received data...
2018-03-29 13:18:29: FileSrv: Received a Packet.
2018-03-29 13:18:29: Received flush.
2018-03-29 13:18:29: FileSrv: Info: Window size=65536
2018-03-29 13:18:29: FileSrv: Received data...
2018-03-29 13:18:29: FileSrv: Received a Packet.
2018-03-29 13:18:29: FileSrv: Sending script output (normal) urbackup/FILE_METADATA|JEr<...>WCl|4 metadata_id=0
2018-03-29 13:18:29: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\FILE_METADATA|JEr<...>WCl|4
2018-03-29 13:18:29: ClientService cmd: #IOf<..>8hh#START SC "tmp"#token=JEr<...>WCl
2018-03-29 13:18:29: orig_target=D:\tmp volpath=\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11
2018-03-29 13:18:29: Shadowcopy already present.
2018-03-29 13:18:29: Disabling CBT on volume "D:"
2018-03-29 13:18:29: rc=0 hasError=true state=0
2018-03-29 13:18:29: FileSrv: Received data...
2018-03-29 13:18:29: FileSrv: Received a Packet.
2018-03-29 13:18:29: FileSrv: Sending meta data of JEr<...>WCl|tmp metadata_id=2
2018-03-29 13:18:29: FileSrv: Mapped name: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11\tmp
2018-03-29 13:18:29: FileSrv: Received data...
2018-03-29 13:18:29: FileSrv: Received a Packet.
2018-03-29 13:18:29: Received flush.
2018-03-29 13:18:29: ClientService cmd: #IOf<..>8hh#STOP SC "tmp"#token=JEr<...>WCl
2018-03-29 13:18:29: Deleting shadowcopy for path "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11\tmp" -2
2018-03-29 13:18:30: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:30: ClientService cmd: #IOf<..>8hh#2PING RUNNING pc_done=100&status_id=11&speed_bpms=0&total_bytes=0&done_bytes=0&paused_fb=1#token=JEr<...>WCl
2018-03-29 13:18:31: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:31: Number of Writers: 12
2018-03-29 13:18:31: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer MSSearch Service Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer MSMQ Writer (MSMQ) has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2018-03-29 13:18:31: Deleting Shadowcopy for dir "D:\"
2018-03-29 13:18:31: rc=0 hasError=true state=0
2018-03-29 13:18:31: FileSrv: Received data...
2018-03-29 13:18:31: FileSrv: Received a Packet.
2018-03-29 13:18:31: ClientService cmd: #IOf<..>8hh#2DID BACKUP status_id=11&server_token=JEr<...>WCl&group=0
2018-03-29 13:18:31: rc=0 hasError=true state=0
2018-03-29 13:18:31: FileSrv: Sending script urbackup/FILE_METADATA|JEr<...>WCl|4 not finished yet
2018-03-29 13:18:31: FileSrv: Info: Window size=65536
2018-03-29 13:18:31: FileSrv: Recv Error in RecvMessage
2018-03-29 13:18:31: FileSrv: Deleting Memory...
2018-03-29 13:18:31: FileSrv: done.
2018-03-29 13:18:31: FileSrv: Received data...
2018-03-29 13:18:31: FileSrv: Received a Packet.
2018-03-29 13:18:31: FileSrv: Sending script output (normal) urbackup/FILE_METADATA|JEr<...>WCl|4 metadata_id=0
2018-03-29 13:18:31: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\FILE_METADATA|JEr<...>WCl|4
2018-03-29 13:18:31: FileSrv: Sent script urbackup/FILE_METADATA|JEr<...>WCl|4
2018-03-29 13:18:31: FileSrv: Received data...
2018-03-29 13:18:31: FileSrv: Received a Packet.
2018-03-29 13:18:31: Received flush.
2018-03-29 13:18:31: FileSrv: Received data...
2018-03-29 13:18:31: FileSrv: Received a Packet.
2018-03-29 13:18:31: FileSrv: Finishing script urbackup/FILE_METADATA|JEr<...>WCl|4
2018-03-29 13:18:31: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\FILE_METADATA|JEr<...>WCl|4
2018-03-29 13:18:31: Removing pipe file urbackup/FILE_METADATA|JEr<...>WCl|4
2018-03-29 13:18:31: Pipe file has exit code 0
2018-03-29 13:18:31: ClientService cmd: STATUS#pw=eyG<...>euu
2018-03-29 13:18:32: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:32: ClientService cmd: STATUS#pw=eyG<...>euu
2018-03-29 13:18:33: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:34: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:35: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:36: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:37: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:38: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:39: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:40: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:40: ClientService cmd: #IOf<..>8hh#2PING RUNNING pc_done=100&status_id=11&speed_bpms=0&total_bytes=0&done_bytes=0&paused_fb=1#token=JEr<...>WCl
2018-03-29 13:18:41: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:41: FileSrv: ClientThread deleted. 1024 KB Memory freed.
2018-03-29 13:18:42: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:43: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:44: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:45: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:46: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu
2018-03-29 13:18:47: ClientService cmd: STATUS DETAIL#pw=eyG<...>euu

alexxboo · April 5, 2018, 9:49am

Seems that I found a solution to the problem myself. (And maybe a client-bug?):

During installation I selected the second file-backup option from the dialog, which would include all Windows users folders. That resulted in the preferences include-setting to contain the default string C:\Users\:\Documents\*;C:\Users\:\Pictures\*;C:\Users\:\Music\*;C:\Users\:\Videos\*;C:\Users\:\Desktop\*. I then also added custom paths on another harddisk via the clients status tray icon context menu (i.e. D:\Work).

This obviously led to the 0 byte backup, because after I removed the default string from the preferences the file backup actually stored the configured files from the second drive.

I’m not sure if this is the intended behavior.
Hope this helps.