File Backup Doesn't work on Windows Client / Ubuntu UrBackup server


#1

Hello Folks,

I have UrBackup Server installed Ubuntu
urbackup-server/xenial,now 2.2.11.2193-1ubuntu1~xenial amd64 [installed]

I have Urbackup windows client 2.2.6 installed on Windows Server 2012 R2.

While the image level backup works on windows client for disk (both incr & full)
The file backup fails to start…
Any help I can get on this is very much appreciated.

On the client, after enabling debugging, I see this messages -
I am attempting to do a full file backup on “C:\OS Images” which contains a few text files.

2018-11-12 13:45:18: rc=0 hasError=true state=0
2018-11-12 13:45:18: Internet mode not enabled
2018-11-12 13:45:19: FileSrv: Stopping CUPDThread...
2018-11-12 13:45:52: ClientService cmd: STATUS#pw=LumOOK06A5MLI8M9poS5CP5WfxtDoD
2018-11-12 13:46:09: CUDPThread exited.
2018-11-12 13:46:09: FileSrv: Backup privileges set successfully
2018-11-12 13:46:09: FileSrv: Backup privileges set successfully (SE_SECURITY_NAME)
2018-11-12 13:46:09: FileSrv: Backup privileges set successfully (SE_RESTORE_NAME)
2018-11-12 13:46:09: FileSrv: Binding UDP socket at port 35622...
2018-11-12 13:46:09: FileSrv: done.
2018-11-12 13:46:09: FileSrv: Disabling new behavior...
2018-11-12 13:46:09: FileSrv: Servername: -ps-dell-mgr-
2018-11-12 13:46:09: FileSrv: Server started up successfully
2018-11-12 13:46:09: FileSrv: UDP Thread startet
2018-11-12 13:46:09: Final path: C:\OS Images
2018-11-12 13:46:09: Final path: C:\Windows\System32\Tasks
2018-11-12 13:46:09: Final path: C:\Windows\Tasks
2018-11-12 13:46:09: Final path: C:\Windows\System32\inetsrv\config
2018-11-12 13:46:09: Final path: C:\Windows\System32\wbem\Repository
2018-11-12 13:46:19: FileSrv: Stopping CUPDThread...
2018-11-12 13:46:44: ClientService cmd: STATUS#pw=LumOOK06A5MLI8M9poS5CP5WfxtDoD
2018-11-12 13:47:09: CUDPThread exited.
2018-11-12 13:47:09: FileSrv: Backup privileges set successfully
2018-11-12 13:47:09: FileSrv: Backup privileges set successfully (SE_SECURITY_NAME)
2018-11-12 13:47:09: FileSrv: Backup privileges set successfully (SE_RESTORE_NAME)
2018-11-12 13:47:09: FileSrv: Binding UDP socket at port 35622...
2018-11-12 13:47:09: FileSrv: done.
2018-11-12 13:47:09: FileSrv: Disabling new behavior...
2018-11-12 13:47:09: FileSrv: Servername: -ps-dell-mgr-
2018-11-12 13:47:09: FileSrv: Server started up successfully
2018-11-12 13:47:09: FileSrv: UDP Thread startet
2018-11-12 13:47:09: Final path: C:\OS Images
2018-11-12 13:47:09: Final path: C:\Windows\System32\Tasks
2018-11-12 13:47:09: Final path: C:\Windows\Tasks
2018-11-12 13:47:09: Final path: C:\Windows\System32\inetsrv\config
2018-11-12 13:47:09: Final path: C:\Windows\System32\wbem\Repository
2018-11-12 13:47:11: Internet mode not enabled
2018-11-12 13:47:36: ClientService cmd: STATUS#pw=LumOOK06A5MLI8M9poS5CP5WfxtDoD
2018-11-12 13:48:28: ClientService cmd: STATUS#pw=LumOOK06A5MLI8M9poS5CP5WfxtDoD
2018-11-12 13:49:05: ClientService cmd: #ILPQixBlg6roBydtK8wKU#ADD IDENTITY
2018-11-12 13:49:05: rc=0 hasError=true state=0
2018-11-12 13:49:05: ClientService cmd: #ILPQixBlg6roBydtK8wKU#GET CHALLENGE
2018-11-12 13:49:05: rc=0 hasError=true state=0
2018-11-12 13:49:05: ClientService cmd: 
2018-11-12 13:49:05: rc=0 hasError=true state=0
2018-11-12 13:49:05: ClientService cmd: #Ifm8wHbE5tCO7gwoLDmuB#CAPA
2018-11-12 13:49:06: Cannot read data from device (D:\)
2018-11-12 13:49:06: Cannot read data from device (E:\)
2018-11-12 13:49:06: Device D:\ isn't NTFS formatted
2018-11-12 13:49:06: Device E:\ isn't NTFS formatted
2018-11-12 13:49:06: rc=0 hasError=true state=0
2018-11-12 13:49:06: FileSrv: Info: Window size=65536
2018-11-12 13:49:06: FileSrv: Received data...
2018-11-12 13:49:06: ClientService cmd: #Ifm8wHbE5tCO7gwoLDmuB#1CHANNEL capa=0&token=rxWKiaWFHGTFyKna4oW3&restore_version=1&virtual_client=
2018-11-12 13:49:06: FileSrv: Received a Packet.
2018-11-12 13:49:06: New channel: Number of Channels: 1
2018-11-12 13:49:06: FileSrv: Sending file (normal) urbackup/settings.cfg metadata_id=0
2018-11-12 13:49:06: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2018-11-12 13:49:06: FileSrv: Reading last file part
2018-11-12 13:49:06: FileSrv: Info: File End
2018-11-12 13:49:06: FileSrv: Closed file.
2018-11-12 13:49:06: FileSrv: Received data...
2018-11-12 13:49:06: FileSrv: Received a Packet.
2018-11-12 13:49:06: Received flush.
2018-11-12 13:49:06: FileSrv: Recv Error in RecvMessage
2018-11-12 13:49:06: FileSrv: Deleting Memory...
2018-11-12 13:49:06: FileSrv: done.
2018-11-12 13:49:06: ClientService cmd: #Ifm8wHbE5tCO7gwoLDmuB#SETTINGS update_freq_incr_def=18000
update_freq_full_def=2592000
update_freq_image_full_def=1209600
update_freq_image_incr_def=86400
max_file_incr_def=100
min_file_incr_def=40
max_file_full_def=10
min_file_full_def=2
min_image_incr_def=0
max_image_incr_def=14
min_image_full_def=0
max_image_full_def=1
startup_backup_delay_def=0
backup_window_incr_file_def=1-7/0-24
backup_window_full_file_def=1-7/0-24
backup_window_incr_image_def=1-7/0-24
backup_window_full_image_def=1-7/0-24
exclude_files_def=
include_files_def=
computername_def=ps-dell-mgr
virtual_clients_def=
default_dirs_def=C:\OS Images
allow_config_paths_def=true
allow_starting_full_file_backups_def=true
allow_starting_incr_file_backups_def=true
allow_starting_full_image_backups_def=true
allow_starting_incr_image_backups_def=true
allow_pause_def=true
allow_log_view_def=true
allow_overwrite_def=true
allow_tray_exit_def=true
image_letters_def=C
internet_server_def=
internet_server_port_def=55415
internet_authkey_def=S7E7xBn4iP
internet_speed_def=0
local_speed_def=0
internet_image_backups_def=false
internet_full_file_backups_def=false
internet_encrypt_def=true
internet_compress_def=true
internet_mode_enabled_def=false
silent_update_def=false
client_quota_def=
local_full_file_transfer_mode_def=hashed
internet_full_file_transfer_mode_def=raw
local_incr_file_transfer_mode_def=hashed
internet_incr_file_transfer_mode_def=blockhash
local_image_transfer_mode_def=hashed
internet_image_transfer_mode_def=raw
end_to_end_file_backup_verification_def=false
internet_calculate_filehashes_on_client_def=true
internet_parallel_file_hashing_def=false
image_file_format_def=vhd
internet_connect_always_def=false
server_url_def=
verify_using_client_hashes_def=false
internet_readd_file_entries_def=true
background_backups_def=true
local_incr_image_style_def=to-full
local_full_image_style_def=full
internet_incr_image_style_def=to-last
internet_full_image_style_def=synthetic
create_linked_user_views_def=false
max_running_jobs_per_client_def=1
cbt_volumes_def=ALL
cbt_crash_persistent_volumes_def=-
ignore_disk_errors_def=false
vss_select_components_def=
allow_file_restore_def=true
allow_component_restore_def=true
allow_component_config_def=true
file_snapshot_groups_def=
image_snapshot_groups_def=
internet_file_dataplan_limit_def=5242880000
internet_image_dataplan_limit_def=20971520000
alert_script_def=1
alert_params_def=

2018-11-12 13:49:06: rc=0 hasError=true state=0
2018-11-12 13:49:06: ClientService cmd: #Ifm8wHbE5tCO7gwoLDmuB#INCRINTERVALL "54003"
2018-11-12 13:49:06: rc=0 hasError=true state=0
2018-11-12 13:49:06: ClientService cmd: #Ifm8wHbE5tCO7gwoLDmuB#VERSION 207
2018-11-12 13:49:06: Server has new version 207 (client version: 0). Updating...
2018-11-12 13:49:06: rc=0 hasError=true state=0
2018-11-12 13:49:06: ClientService cmd: #Ifm8wHbE5tCO7gwoLDmuB#CAPA
2018-11-12 13:49:06: Device D:\ isn't NTFS formatted
2018-11-12 13:49:06: Device E:\ isn't NTFS formatted
2018-11-12 13:49:06: Device D:\ isn't NTFS formatted
2018-11-12 13:49:06: Device E:\ isn't NTFS formatted
2018-11-12 13:49:06: rc=0 hasError=true state=0
2018-11-12 13:49:06: ClientService cmd: #ILPQixBlg6roBydtK8wKU#GET CHALLENGE
2018-11-12 13:49:06: rc=0 hasError=true state=0
2018-11-12 13:49:06: ClientService cmd: 
2018-11-12 13:49:06: rc=0 hasError=true state=0
2018-11-12 13:49:06: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#2PING RUNNING pc_done=&status_id=2&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rxWKiaWFHGTFyKna4oW3
2018-11-12 13:49:06: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#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=2&async=1#token=rxWKiaWFHGTFyKna4oW3
2018-11-12 13:49:06: Async index 840751f300b42aa629725c04109b77fe
2018-11-12 13:49:06: rc=0 hasError=true state=0
2018-11-12 13:49:06: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#WAIT FOR INDEX async_id=840751f300b42aa629725c04109b77fe#token=rxWKiaWFHGTFyKna4oW3
2018-11-12 13:49:06: Wait for async index 840751f300b42aa629725c04109b77fe
2018-11-12 13:49:08: ClientService cmd: STATUS#pw=LumOOK06A5MLI8M9poS5CP5WfxtDoD
2018-11-12 13:49:16: FileSrv: ClientThread deleted. 1024 KB Memory freed.
2018-11-12 13:49:16: FileSrv: Stopping CUPDThread...
2018-11-12 13:49:16: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#2PING RUNNING pc_done=&status_id=2&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rxWKiaWFHGTFyKna4oW3
2018-11-12 13:49:25: ERROR: Recvfrom error in CUDPThread::UdpStep
2018-11-12 13:49:25: ERROR: Last error: 10058
2018-11-12 13:49:25: CUDPThread exited.
2018-11-12 13:49:25: FileSrv: Backup privileges set successfully
2018-11-12 13:49:25: FileSrv: Backup privileges set successfully (SE_SECURITY_NAME)
2018-11-12 13:49:25: FileSrv: Backup privileges set successfully (SE_RESTORE_NAME)
2018-11-12 13:49:25: FileSrv: Binding UDP socket at port 35622...
2018-11-12 13:49:25: FileSrv: done.
2018-11-12 13:49:25: FileSrv: Disabling new behavior...
2018-11-12 13:49:25: FileSrv: Servername: -ps-dell-mgr-
2018-11-12 13:49:25: FileSrv: Server started up successfully
2018-11-12 13:49:25: FileSrv: UDP Thread startet
2018-11-12 13:49:25: Final path: C:\OS Images
2018-11-12 13:49:25: Final path: C:\Windows\System32\Tasks
2018-11-12 13:49:25: Final path: C:\Windows\Tasks
2018-11-12 13:49:25: Final path: C:\Windows\System32\inetsrv\config
2018-11-12 13:49:25: Final path: C:\Windows\System32\wbem\Repository
2018-11-12 13:49:25: Removing VSS log data...
2018-11-12 13:49:25: Final path: C:\OS Images
2018-11-12 13:49:25: Final path: C:\Windows\System32\Tasks
2018-11-12 13:49:25: Final path: C:\Windows\Tasks
2018-11-12 13:49:25: Final path: C:\Windows\System32\inetsrv\config
2018-11-12 13:49:25: Final path: C:\Windows\System32\wbem\Repository
2018-11-12 13:49:25: Script list at "C:\Program Files\UrBackup\backup_scripts\list.bat" does not exist. Skipping.
2018-11-12 13:49:25: Deleting files... doing full index...
2018-11-12 13:49:25: Final path: C:\OS Images
2018-11-12 13:49:25: Final path: C:\Windows\System32\Tasks
2018-11-12 13:49:25: Final path: C:\Windows\Tasks
2018-11-12 13:49:25: Final path: C:\Windows\System32\inetsrv\config
2018-11-12 13:49:25: Final path: C:\Windows\System32\wbem\Repository
2018-11-12 13:49:25: Removing deleted directories from index...
2018-11-12 13:49:25: Removing unconfirmed VSS path ".symlink_Task Scheduler Writer_{D61D61C8-D73A-4EEE-8CDD-F6F9786B7124}_TasksStore_files00000000" to "C:\Windows\System32\Tasks
2018-11-12 13:49:25: Removing unconfirmed VSS path ".symlink_Task Scheduler Writer_{D61D61C8-D73A-4EEE-8CDD-F6F9786B7124}_TasksStore_files00000001" to "C:\Windows\Tasks
2018-11-12 13:49:25: Removing unconfirmed VSS path ".symlink_IIS Config Writer_{2A40FD15-DFCA-4AA8-A654-1F8C654603F6}_IISCONFIG_files00000000" to "C:\Windows\System32\inetsrv\config
2018-11-12 13:49:25: Removing unconfirmed VSS path ".symlink_WMI Writer_{A6AD56C2-B509-4E6C-BB19-49D8F43532F0}_WMI_files00000000" to "C:\Windows\System32\wbem\Repository
2018-11-12 13:49:25: Creating shadowcopy of "OS Images" in indexDirs()
2018-11-12 13:49:26: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#2PING RUNNING pc_done=&status_id=2&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rxWKiaWFHGTFyKna4oW3
2018-11-12 13:49:26: Number of Writers: 12
2018-11-12 13:49:26: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:26: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:26: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:26: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:26: Writer SqlServerWriter has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:26: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:26: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:26: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:26: Writer IIS Config Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:26: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:26: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:26: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:26: Preparing change block tracking reset for volume c: failed: Incorrect function. (code: 1)
2018-11-12 13:49:27: Number of Writers: 12
2018-11-12 13:49:27: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer SqlServerWriter has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:27: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:34: Number of Writers: 12
2018-11-12 13:49:35: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:35: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:35: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:35: Writer System Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:35: Writer SqlServerWriter has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:35: Writer ASR Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:35: Writer COM+ REGDB Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:35: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:35: Writer IIS Config Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:35: Writer BITS Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:35: Writer Registry Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:35: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:49:35: Shadowcopy path: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy32
2018-11-12 13:49:35: done.
2018-11-12 13:49:35: Disabling CBT on volume "C:"
2018-11-12 13:49:35: Indexing "OS Images"...
2018-11-12 13:49:35: Indexing of "OS Images" done. 1 filesystem lookups 0 db lookups and 0 db updates
2018-11-12 13:49:35: Deleting backup of changed dirs...
2018-11-12 13:49:35: Script "C:\Program Files\UrBackup\postfileindex.bat" does not exist
2018-11-12 13:49:35: Async index 840751f300b42aa629725c04109b77fe finished with "done"
2018-11-12 13:49:35: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#GET VSSLOG
2018-11-12 13:49:35: VSS logdata - 775 bytes
2018-11-12 13:49:35: rc=0 hasError=true state=0
2018-11-12 13:49:35: rc=0 hasError=true state=0
2018-11-12 13:49:35: FileSrv: Info: Window size=65536
2018-11-12 13:49:35: FileSrv: Received data...
2018-11-12 13:49:35: FileSrv: Received a Packet.
2018-11-12 13:49:35: FileSrv: Sending file (normal) urbackup/filelist.ub metadata_id=0
2018-11-12 13:49:35: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\filelist.ub
2018-11-12 13:49:35: FileSrv: Reading last file part
2018-11-12 13:49:35: FileSrv: Info: File End
2018-11-12 13:49:35: FileSrv: Closed file.
2018-11-12 13:49:35: FileSrv: Received data...
2018-11-12 13:49:35: FileSrv: Received a Packet.
2018-11-12 13:49:35: Received flush.
2018-11-12 13:49:36: FileSrv: Received data...
2018-11-12 13:49:36: FileSrv: Received a Packet.
2018-11-12 13:49:36: FileSrv: Sending file (normal) urbackup/tokens_rxWKiaWFHGTFyKna4oW3.properties metadata_id=0
2018-11-12 13:49:36: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\tokens_rxWKiaWFHGTFyKna4oW3.properties
2018-11-12 13:49:36: FileSrv: Reading last file part
2018-11-12 13:49:36: FileSrv: Info: File End
2018-11-12 13:49:36: FileSrv: Closed file.
2018-11-12 13:49:36: FileSrv: Received data...
2018-11-12 13:49:36: FileSrv: Received a Packet.
2018-11-12 13:49:36: Received flush.
2018-11-12 13:49:36: FileSrv: Recv Error in RecvMessage
2018-11-12 13:49:36: FileSrv: Deleting Memory...
2018-11-12 13:49:36: FileSrv: done.
2018-11-12 13:49:36: rc=0 hasError=true state=0
2018-11-12 13:49:37: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#2LOGDATA 1542048576 0-1542048546-Starting scheduled full file backup...
0-1542048576-Removing unconfirmed VSS path ".symlink_Task Scheduler Writer_{D61D61C8-D73A-4EEE-8CDD-F6F9786B7124}_TasksStore_files00000000" to "C:\Windows\System32\Tasks
0-1542048576-Removing unconfirmed VSS path ".symlink_Task Scheduler Writer_{D61D61C8-D73A-4EEE-8CDD-F6F9786B7124}_TasksStore_files00000001" to "C:\Windows\Tasks
0-1542048576-Removing unconfirmed VSS path ".symlink_IIS Config Writer_{2A40FD15-DFCA-4AA8-A654-1F8C654603F6}_IISCONFIG_files00000000" to "C:\Windows\System32\inetsrv\config
0-1542048576-Removing unconfirmed VSS path ".symlink_WMI Writer_{A6AD56C2-B509-4E6C-BB19-49D8F43532F0}_WMI_files00000000" to "C:\Windows\System32\wbem\Repository
0-1542048576-Indexing of "OS Images" done. 1 filesystem lookups 0 db lookups and 0 db updates
0-1542048576-ps-dell-mgr: Loading file list...
2-1542048576-Error creating clientlist for client ps-dell-mgr
2-1542048576-Backup had an early error. Deleting partial backup.

2018-11-12 13:49:37: rc=0 hasError=true state=0
2018-11-12 13:49:45: FileSrv: ClientThread deleted. 1024 KB Memory freed.
2018-11-12 13:49:57: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#2PING RUNNING pc_done=&status_id=4&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rxWKiaWFHGTFyKna4oW3
2018-11-12 13:49:57: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#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=4&async=1#token=rxWKiaWFHGTFyKna4oW3
2018-11-12 13:49:57: Async index 581f658e82761fbc92b274b328f307ee
2018-11-12 13:49:57: Removing VSS log data...
2018-11-12 13:49:57: rc=0 hasError=true state=0
2018-11-12 13:49:57: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#WAIT FOR INDEX async_id=581f658e82761fbc92b274b328f307ee#token=rxWKiaWFHGTFyKna4oW3
2018-11-12 13:49:57: Wait for async index 581f658e82761fbc92b274b328f307ee
2018-11-12 13:49:57: Final path: C:\OS Images
2018-11-12 13:49:57: Script list at "C:\Program Files\UrBackup\backup_scripts\list.bat" does not exist. Skipping.
2018-11-12 13:49:57: Deleting files... doing full index...
2018-11-12 13:49:57: Final path: C:\OS Images
2018-11-12 13:49:57: Removing deleted directories from index...
2018-11-12 13:49:57: Creating shadowcopy of "OS Images" in indexDirs()
2018-11-12 13:49:57: WARNING: Restarting shadow copy of C:\ because it was started by this server
2018-11-12 13:49:57: Releasing OS Images orig_target=C:\OS Images target=\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy32\OS Images
2018-11-12 13:49:57: Deleting shadowcopy for path "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy32\OS Images" -2
2018-11-12 13:49:58: Number of Writers: 12
2018-11-12 13:49:58: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer SqlServerWriter has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:58: Deleting Shadowcopy for dir "C:\"
2018-11-12 13:49:59: ClientService cmd: STATUS#pw=LumOOK06A5MLI8M9poS5CP5WfxtDoD
2018-11-12 13:49:59: Number of Writers: 12
2018-11-12 13:49:59: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer SqlServerWriter has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:49:59: Preparing change block tracking reset for volume c: failed: Incorrect function. (code: 1)
2018-11-12 13:50:00: Number of Writers: 12
2018-11-12 13:50:00: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer SqlServerWriter has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:00: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:04: Number of Writers: 12
2018-11-12 13:50:05: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:05: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:05: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2018-11-12 13:50:05: Writer System Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:50:05: Writer SqlServerWriter has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:50:06: Writer BITS Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:50:06: Writer ASR Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:50:06: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:50:06: Writer COM+ REGDB Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:50:06: Writer IIS Config Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:50:06: Writer Registry Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:50:06: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2018-11-12 13:50:06: Shadowcopy path: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy33
2018-11-12 13:50:06: done.
2018-11-12 13:50:06: Disabling CBT on volume "C:"
2018-11-12 13:50:06: Indexing "OS Images"...
2018-11-12 13:50:06: Indexing of "OS Images" done. 1 filesystem lookups 0 db lookups and 0 db updates
2018-11-12 13:50:06: Deleting backup of changed dirs...
2018-11-12 13:50:06: ClientService cmd: PONG
2018-11-12 13:50:06: rc=0 hasError=true state=3
2018-11-12 13:50:06: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#1CHANNEL capa=0&token=rxWKiaWFHGTFyKna4oW3&restore_version=1&virtual_client=
2018-11-12 13:50:06: New channel: Number of Channels: 1
2018-11-12 13:50:06: Script "C:\Program Files\UrBackup\postfileindex.bat" does not exist
2018-11-12 13:50:06: Async index 581f658e82761fbc92b274b328f307ee finished with "done"
2018-11-12 13:50:06: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#GET VSSLOG
2018-11-12 13:50:06: VSS logdata - 189 bytes
2018-11-12 13:50:06: rc=0 hasError=true state=0
2018-11-12 13:50:06: rc=0 hasError=true state=0
2018-11-12 13:50:06: FileSrv: Info: Window size=65536
2018-11-12 13:50:06: FileSrv: Received data...
2018-11-12 13:50:06: FileSrv: Received a Packet.
2018-11-12 13:50:06: FileSrv: Sending file (normal) urbackup/filelist.ub metadata_id=0
2018-11-12 13:50:06: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\filelist.ub
2018-11-12 13:50:06: FileSrv: Reading last file part
2018-11-12 13:50:06: FileSrv: Info: File End
2018-11-12 13:50:06: FileSrv: Closed file.
2018-11-12 13:50:06: FileSrv: Received data...
2018-11-12 13:50:06: FileSrv: Received a Packet.
2018-11-12 13:50:06: Received flush.
2018-11-12 13:50:06: FileSrv: Received data...
2018-11-12 13:50:06: FileSrv: Received a Packet.
2018-11-12 13:50:06: FileSrv: Sending file (normal) urbackup/tokens_rxWKiaWFHGTFyKna4oW3.properties metadata_id=0
2018-11-12 13:50:06: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\tokens_rxWKiaWFHGTFyKna4oW3.properties
2018-11-12 13:50:06: FileSrv: Reading last file part
2018-11-12 13:50:06: FileSrv: Info: File End
2018-11-12 13:50:06: FileSrv: Closed file.
2018-11-12 13:50:06: FileSrv: Received data...
2018-11-12 13:50:06: FileSrv: Received a Packet.
2018-11-12 13:50:06: Received flush.
2018-11-12 13:50:06: FileSrv: Recv Error in RecvMessage
2018-11-12 13:50:06: FileSrv: Deleting Memory...
2018-11-12 13:50:06: FileSrv: done.
2018-11-12 13:50:07: rc=0 hasError=true state=0
2018-11-12 13:50:08: ClientService cmd: #I6UEXOn4Ay0WDsY2cXdDD#2LOGDATA 1542048607 0-1542048597-Starting unscheduled full file backup...
1-1542048606-Restarting shadow copy of C:\ because it was started by this server
0-1542048606-Indexing of "OS Images" done. 1 filesystem lookups 0 db lookups and 0 db updates
0-1542048606-ps-dell-mgr: Loading file list...
2-1542048606-Error creating clientlist for client ps-dell-mgr
2-1542048607-Backup had an early error. Deleting partial backup.

2018-11-12 13:50:08: rc=0 hasError=true state=0
2018-11-12 13:50:16: FileSrv: ClientThread deleted. 1024 KB Memory freed.
2018-11-12 13:50:51: ClientService cmd: STATUS#pw=LumOOK06A5MLI8M9poS5CP5WfxtDoD
2018-11-12 13:51:06: ClientService cmd: PONG

On the server, I see these errors -

2018-11-13 09:52:47: Starting scheduled full file backup...
2018-11-13 09:52:47: ps-dell-mgr: Connecting for filelist...
2018-11-13 09:52:47: ps-dell-mgr: Waiting for filelist
2018-11-13 09:52:47: ps-dell-mgr: Connecting for filelist (async)...
2018-11-13 09:53:02: Indexing of "OS Images" done. 1 filesystem lookups 0 db lookups and 0 db updates
2018-11-13 09:53:02: ps-dell-mgr: Doing backup with hashed transfer...
2018-11-13 09:53:02: ps-dell-mgr: Loading file list...
2018-11-13 09:53:02: Flushing FileClient...
2018-11-13 09:53:02: Flushing FileClient...
2018-11-13 09:53:02: ERROR: Error creating clientlist for client ps-dell-mgr
2018-11-13 09:53:07: ERROR: Backup had an early error. Deleting partial backup.
2018-11-13 09:53:08: msg=WAKEUP
2018-11-13 09:53:08: WARNING: Exponential backoff: Waiting at least 21h 20m before next file backup
2018-11-13 09:53:08: server_prepare_hash Thread finished (exit)
2018-11-13 09:53:08: server_hash Thread finished - normal

#2

What storage are you using as the backup store ?


#3

For some reason the server cannot create files like /var/urbackup/clientlist_b_123.ub. Check permissions, free space etc…


#4

@uroni, thank you so much, the file permission on the directory was not correct. This was not due to default installation outcome but rather due to directories being mapped against different zfs datasets manually after installation.

P.S - Thank you for developing this product, UrBackup + Zfs is a wonderful solution for medium sized businesses.


#5

@dewitpj, the backend storage is zfs, the issue appeared to be a file permission issue on the server which @uroni correctly pointed out.