Image backups succeed but marked as not complete

TomTomGo · September 20, 2017, 9:14am

Since 2 days we have a W2012R2 client with cbt which have a strange problem.
All images volumes backups (SYSVOL/C:/T:/F:) succeed without any errors but they are not marked as complete in backup_server.db / backups_images table, resulting in a backup “loop” while in backup window.
I test to set them to complete=1 and make a full restore, works well.
What should be the reason why it set backups incomplete ?
@Uroni I can provide logs and tables by PM if needed…

Edit : Server Debian 8 / ZFS layout / UrBackup Server 2.1.19 / client 2.1.19-cbt

Regards,

TomTomGo · September 20, 2017, 9:59am

Client’s log :


2017-09-19 09:14:09: Sending image done
2017-09-19 09:14:10: Deleting shadowcopy for path "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4\" -2
2017-09-19 09:14:11: ClientService cmd: #INm3VGsw0sSVUJpcFkeHR#2PING RUNNING pc_done=92&eta_ms=11201908&status_id=826&speed_bpms=130.941&total_bytes=24874319872&done_bytes=22911660032#token=5S3q2Dh7Dn1yKNA1k5sK
2017-09-19 09:14:12: Number of Writers: 16
2017-09-19 09:14:12: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer FSRM Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer SqlServerWriter has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer WIDWriter has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer IIS Metabase Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer DFS Replication service writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:12: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2017-09-19 09:14:13: Deleting Shadowcopy for dir "C:\"
2017-09-19 09:14:13: Service finished. Transferred 8.68151 GB
2017-09-19 09:14:13: Transferred uncompressed: 21.3982 GB (ratio: 2.4648)
2017-09-19 09:14:13: Average sent paket size: 336.931 MB
2017-09-19 09:14:13: SERVICE_COMMANDS finished
2017-09-19 09:14:21: ClientService cmd: #INm3VGsw0sSVUJpcFkeHR#2PING RUNNING pc_done=92&eta_ms=11191648&status_id=826&speed_bpms=130.941&total_bytes=24874319872&done_bytes=22913150976#token=5S3q2Dh7Dn1yKNA1k5sK
2017-09-19 09:14:30: rc=0 hasError=true state=3
2017-09-19 09:14:30: SERVICE_COMMANDS finished
2017-09-19 09:14:31: rc=0 hasError=true state=0
2017-09-19 09:14:31: SERVICE_COMMANDS finished

Server’s log :
2017-09-19 09:14:23: Trim beyond drivesize (drivesize: 128479395328 trim to 128479395840). Trimming less… 2017-09-19 09:14:23: Starting trimming image file (if possible) 2017-09-19 09:14:26: Trimmed 1.57812 GB 2017-09-19 09:14:27: Transferred 8.68151 GB - Average speed: 1.9685 MBit/s 2017-09-19 09:14:27: (Before compression: 21.3982 GB ratio: 2.4648) 2017-09-19 09:14:27: Script does not exist urbackup/post_incr_imagebackup 2017-09-19 09:14:27: Time taken for backing up client SV412: 10h 42m 7s 2017-09-19 09:14:27: Backup succeeded 2017-09-19 09:14:27: Updating statistics… 2017-09-19 09:14:27: Updating image stats… 2017-09-19 09:14:27: Updating file statistics… 2017-09-19 09:14:27: Done updating statistics. 2017-09-19 09:14:30: Stopping channel… 2017-09-19 09:14:30: Lost channel connection to SV412. has_error=true 2017-09-19 09:14:31: client_main Thread for client SV412 finished 2017-09-19 09:14:37: Authed+capa for client ‘SV404’ (compressed-v2, token auth) - 1 spare connections 2017-09-19 09:14:47: Authed+capa for client ‘SV412’ (compressed-v2, token auth) - 1 spare connections 2017-09-19 09:14:56: Client finished: SV412

EDIT : Not sure but “Stopping channel” and “rc=0 hasError=true state=3” seems not to be normal …

uroni · September 20, 2017, 10:24pm

Are you using any image backup groups?

TomTomGo · September 21, 2017, 8:32am

Yes, client configuration :


update_freq_incr_def=-18000
update_freq_full=-2592000
update_freq_full_def=-2592000
update_freq_image_full=172800
update_freq_image_full_def=172800
update_freq_image_incr=51840
update_freq_image_incr_def=51840
max_file_incr=100
max_file_incr_def=100
min_file_incr=40
min_file_incr_def=40
max_file_full=10
max_file_full_def=10
min_file_full=2
min_file_full_def=2
min_image_incr=5
min_image_incr_def=5
max_image_incr=5
max_image_incr_def=5
min_image_full=6
min_image_full_def=6
max_image_full=6
max_image_full_def=6
startup_backup_delay=600
startup_backup_delay_def=600
backup_window_incr_file=
backup_window_incr_file_def=
backup_window_full_file=
backup_window_full_file_def=
backup_window_incr_image=Mon-Fri/22:30-24;Tue-Sat/0-8
backup_window_incr_image_def=Mon-Fri/22:30-24;Tue-Sat/0-8
backup_window_full_image=Sat/22:30-24;Sun/0-8
backup_window_full_image_def=Sat/22:30-24;Sun/0-8
exclude_files=
exclude_files_def=
include_files=
include_files_def=
default_dirs=
default_dirs_def=
allow_config_paths=false
allow_config_paths_def=false
allow_starting_full_file_backups=false
allow_starting_full_file_backups_def=false
allow_starting_incr_file_backups=false
allow_starting_incr_file_backups_def=false
allow_starting_full_image_backups=true
allow_starting_full_image_backups_def=true
allow_starting_incr_image_backups=true
allow_starting_incr_image_backups_def=true
allow_pause=false
allow_pause_def=false
allow_log_view=true
allow_log_view_def=true
allow_overwrite=false
allow_overwrite_def=false
allow_tray_exit=false
allow_tray_exit_def=false
image_letters=C;F;T
image_letters_def=C;F;T
internet_server=backup-2.local.lan
internet_server_def=backup-2.local.lan
internet_server_port=55415
internet_server_port_def=55415
internet_authkey=E7W9DwBWHj
internet_authkey_def=E7W9DwBWHj
internet_speed=1310720;262144@Mon-Fri/8-12:30;262144@Mon-Fri/13:30-18
internet_speed_def=1310720;262144@Mon-Fri/8-12:30;262144@Mon-Fri/13:30-18
local_speed=0
local_speed_def=0
internet_image_backups=true
internet_image_backups_def=true
internet_full_file_backups=false
internet_full_file_backups_def=false
internet_encrypt=false
internet_encrypt_def=false
internet_compress=true
internet_compress_def=true
internet_mode_enabled=true
internet_mode_enabled_def=true
silent_update=true
silent_update_def=true
client_quota=
client_quota_def=
local_full_file_transfer_mode=hashed
local_full_file_transfer_mode_def=hashed
internet_full_file_transfer_mode=hashed
internet_full_file_transfer_mode_def=hashed
local_incr_file_transfer_mode=hashed
local_incr_file_transfer_mode_def=hashed
internet_incr_file_transfer_mode=blockhash
internet_incr_file_transfer_mode_def=blockhash
local_image_transfer_mode=hashed
local_image_transfer_mode_def=hashed
internet_image_transfer_mode=hashed
internet_image_transfer_mode_def=hashed
end_to_end_file_backup_verification=false
end_to_end_file_backup_verification_def=false
internet_calculate_filehashes_on_client=true
internet_calculate_filehashes_on_client_def=true
image_file_format=cowraw
image_file_format_def=cowraw
internet_connect_always=false
internet_connect_always_def=false
server_url=http://backup-2.local.lan:55414/
server_url_def=http://backup-2.local.lan:55414/
verify_using_client_hashes=false
verify_using_client_hashes_def=false
internet_readd_file_entries=true
internet_readd_file_entries_def=true
background_backups=true
background_backups_def=true
local_incr_image_style=to-last
local_incr_image_style_def=to-last
local_full_image_style=synthetic
local_full_image_style_def=synthetic
internet_incr_image_style=to-last
internet_incr_image_style_def=to-last
internet_full_image_style=synthetic
internet_full_image_style_def=synthetic
create_linked_user_views=false
create_linked_user_views_def=false
max_running_jobs_per_client=3
max_running_jobs_per_client_def=3
cbt_volumes=ALL
cbt_volumes_def=ALL
cbt_crash_persistent_volumes=-
cbt_crash_persistent_volumes_def=-
ignore_disk_errors=false
ignore_disk_errors_def=false
vss_select_components=default=1
vss_select_components_def=default=1
allow_file_restore=false
allow_file_restore_def=false
allow_component_restore=false
allow_component_restore_def=false
allow_component_config=false
allow_component_config_def=false
file_snapshot_groups=
file_snapshot_groups_def=
image_snapshot_groups=ALL
image_snapshot_groups_def=ALL
internet_file_dataplan_limit=5242880000
internet_file_dataplan_limit_def=5242880000
internet_image_dataplan_limit=20971520000
internet_image_dataplan_limit_def=20971520000

TomTomGo · September 21, 2017, 8:35am

Tonight’s backup works fine after :

removing ISO image from the VM CD Drive (D:)
restarting the service on the client
urbackup remove-unknown on the server

Don’t know which one do the trick, but now seuqence in client’s logfile is good

Before :
017-09-18 22:32:20: Started connection to SERVICE_COMMANDS 2017-09-18 22:32:21: Filesystem type is ntfs (\?\Volume{86f7e1fa-403d-11e5-80c2-806e6f6e6963}) 2017-09-18 22:32:21: TotalNumberOfClusters=89599 numberOfClusters=89599 n_clusters=11200 StartingLcn=0 BitmapSize=89599 r_bytes=11216 2017-09-18 22:32:21: FSINFO: blocksize=4096 size=367001088 has_error=false used_space=300220416 2017-09-18 22:42:38: Sending full image done 2017-09-18 22:42:38: Service finished. Transferred 249.651 MB 2017-09-18 22:42:38: Transferred uncompressed: 286.909 MB (ratio: 1.14924) 2017-09-18 22:42:38: Average sent paket size: 47.8182 MB 2017-09-18 22:42:38: SERVICE_COMMANDS finished 2017-09-18 22:42:40: Started connection to SERVICE_COMMANDS 2017-09-18 22:42:40: rc=0 hasError=true state=0 2017-09-18 22:42:40: SERVICE_COMMANDS finished 2017-09-18 22:42:40: Started connection to SERVICE_COMMANDS 2017-09-18 22:42:40: ERROR: Not found 2017-09-18 22:42:40: rc=0 hasError=true state=0 2017-09-18 22:42:40: SERVICE_COMMANDS finished 2017-09-18 22:42:40: Started connection to SERVICE_COMMANDS 2017-09-18 22:42:41: Started connection to SERVICE_COMMANDS 2017-09-18 22:42:41: rc=0 hasError=true state=0 2017-09-18 22:42:41: SERVICE_COMMANDS finished 2017-09-18 22:42:41: Started connection to SERVICE_COMMANDS 2017-09-18 22:42:41: Started connection to SERVICE_COMMANDS 2017-09-18 22:42:41: Script “C:\Program Files\UrBackup\preimagebackup.bat” does not exist 2017-09-18 22:42:41: Creating shadowcopy of “C:”… 2017-09-18 22:42:45: rc=0 hasError=true state=0 2017-09-18 22:42:45: SERVICE_COMMANDS finished 2017-09-18 22:42:49: Looking for old Sessions… 0 sessions 2017-09-18 22:42:50: rc=0 hasError=true state=0 2017-09-18 22:42:50: SERVICE_COMMANDS finished 2017-09-18 22:42:52: Number of Writers: 16 2017-09-18 22:42:52: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK. … 2017-09-18 22:43:59: Writer IIS Metabase Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK. 2017-09-18 22:43:59: Shadowcopy path: \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4 2017-09-18 22:43:59: Shadowcopy path: \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy5 2017-09-18 22:43:59: Shadowcopy path: \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy6 2017-09-18 22:43:59: done. 2017-09-18 22:43:59: Change block tracking reports 16 MB have changed on shadow copy \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4 2017-09-18 22:43:59: Change block tracking active on volume C: 2017-09-18 22:43:59: Bitmap urbackup\hdat_img_c_.cbt does not exist. Nothing to merge. 2017-09-18 22:43:59: Zeroing image hash data of volume C:… 2017-09-18 22:44:00: Change block tracking reports 3.5 MB have changed on shadow copy \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy5 2017-09-18 22:44:00: Change block tracking active on volume f: 2017-09-18 22:44:00: Bitmap urbackup\hdat_img_f_.cbt does not exist. Nothing to merge. 2017-09-18 22:44:00: Zeroing image hash data of volume f:… 2017-09-18 22:44:03: Change block tracking reports 3.5 MB have changed on shadow copy \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy6 2017-09-18 22:44:03: Change block tracking active on volume t: 2017-09-18 22:44:03: Bitmap urbackup\hdat_img_t_.cbt does not exist. Nothing to merge. 2017-09-18 22:44:03: Zeroing image hash data of volume t:… 2017-09-18 22:44:05: Filesystem type is ntfs (\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4) 2017-09-18 22:44:05: TotalNumberOfClusters=31366911 numberOfClusters=31366911 n_clusters=3920864 StartingLcn=0 BitmapSize=31366911 r_bytes=3920880 2017-09-18 22:44:05: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4\HIBERFIL.SYS from backup… 2017-09-18 22:44:05: Error opening file handle to \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4\HIBERFIL.SYS 2017-09-18 22:44:05: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4\pagefile.sys from backup… 2017-09-18 22:44:05: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4\swapfile.sys from backup… 2017-09-18 22:44:05: Error opening file handle to \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4\swapfile.sys 2017-09-18 22:44:05: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4\System Volume Information{3808876b-c176-4e48-b7ae-04046e6cc752} from backup… 2017-09-18 22:44:05: FSINFO: blocksize=4096 size=128478871040 has_error=false used_space=103631044608 2017-09-18 22:44:07: Started connection to SERVICE_COMMANDS 2017-09-18 22:44:07: rc=0 hasError=true state=0 2017-09-18 22:44:07: SERVICE_COMMANDS finished 2017-09-18 22:44:07: Started connection to SERVICE_COMMANDS 2017-09-18 22:44:07: Started connection to SERVICE_COMMANDS 2017-09-18 22:44:07: rc=0 hasError=true state=0 2017-09-18 22:44:07: SERVICE_COMMANDS finished 2017-09-18 22:44:07: Started connection to SERVICE_COMMANDS 2017-09-18 22:44:08: Started connection to SERVICE_COMMANDS 2017-09-18 22:44:08: Started connection to SERVICE_COMMANDS 2017-09-18 22:45:20: Filesystem type is ntfs (\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy5) 2017-09-18 22:45:20: TotalNumberOfClusters=39320831 numberOfClusters=39320831 n_clusters=4915104 StartingLcn=0 BitmapSize=39320831 r_bytes=4915120 2017-09-18 22:45:20: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy5\System Volume Information{3808876b-c176-4e48-b7ae-04046e6cc752} from backup… 2017-09-18 22:45:20: FSINFO: blocksize=4096 size=161058127360 has_error=false used_space=38556942336 2017-09-18 22:46:28: Filesystem type is ntfs (\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy6) 2017-09-18 22:46:28: TotalNumberOfClusters=26213631 numberOfClusters=26213631 n_clusters=3276704 StartingLcn=0 BitmapSize=26213631 r_bytes=3276720 2017-09-18 22:46:28: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy6\System Volume Information{3808876b-c176-4e48-b7ae-04046e6cc752} from backup… 2017-09-18 22:46:28: FSINFO: blocksize=4096 size=107371036160 has_error=false used_space=72881975296 2017-09-18 23:12:50: Looking for old Sessions… 0 sessions 2017-09-18 23:42:51: Looking for old Sessions… 0 sessions 2017-09-19 00:09:22: Started connection to SERVICE_COMMANDS 2017-09-19 00:09:22: rc=0 hasError=true state=0 2017-09-19 00:09:22: rc=0 hasError=true state=0 2017-09-19 00:09:22: SERVICE_COMMANDS finished 2017-09-19 00:09:22: rc=0 hasError=true state=0 2017-09-19 00:09:22: SERVICE_COMMANDS finished 2017-09-19 00:09:22: rc=0 hasError=true state=0 2017-09-19 00:09:22: SERVICE_COMMANDS finished 2017-09-19 00:09:22: Started connection to SERVICE_COMMANDS 2017-09-19 00:09:22: rc=0 hasError=true state=0 2017-09-19 00:09:22: SERVICE_COMMANDS finished 2017-09-19 00:09:24: Started connection to SERVICE_COMMANDS 2017-09-19 00:09:26: Started connection to SERVICE_COMMANDS 2017-09-19 00:12:07: Started connection to SERVICE_COMMANDS 2017-09-19 00:12:07: Started connection to SERVICE_COMMANDS 2017-09-19 00:12:07: rc=0 hasError=true state=0 2017-09-19 00:12:07: SERVICE_COMMANDS finished 2017-09-19 00:12:07: rc=0 hasError=true state=0 2017-09-19 00:12:07: SERVICE_COMMANDS finished 2017-09-19 00:12:07: rc=0 hasError=true state=0 2017-09-19 00:12:07: SERVICE_COMMANDS finished 2017-09-19 00:12:09: Started connection to SERVICE_COMMANDS 2017-09-19 00:12:52: Looking for old Sessions… 0 sessions 2017-09-19 00:12:55: Sending image done 2017-09-19 00:12:55: Deleting shadowcopy for path “f:” -2 2017-09-19 00:12:55: Deleting Shadowcopy for dir “f:” 2017-09-19 00:12:55: Service finished. Transferred 705.339 MB 2017-09-19 00:12:55: Transferred uncompressed: 814.867 MB (ratio: 1.15528) 2017-09-19 00:12:55: Average sent paket size: 61.6004 MB 2017-09-19 00:12:55: SERVICE_COMMANDS finished 2017-09-19 00:13:09: rc=0 hasError=true state=0 2017-09-19 00:13:09: SERVICE_COMMANDS finished 2017-09-19 01:22:00: Sending image done 2017-09-19 01:22:00: Deleting shadowcopy for path “t:” -2 2017-09-19 01:22:00: Deleting Shadowcopy for dir “t:” 2017-09-19 01:22:00: Service finished. Transferred 1.49967 GB 2017-09-19 01:22:00: Transferred uncompressed: 11.5635 GB (ratio: 7.71071) 2017-09-19 01:22:00: Average sent paket size: 223.239 MB 2017-09-19 01:22:00: SERVICE_COMMANDS finished 2017-09-19 01:22:18: rc=0 hasError=true state=0 2017-09-19 01:22:18: SERVICE_COMMANDS finished … 2017-09-19 07:12:54: rc=0 hasError=true state=9 … 2017-09-19 09:14:09: Sending image done 2017-09-19 09:14:10: Deleting shadowcopy for path “\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy4” -2 2017-09-19 09:14:12: Number of Writers: 16 2017-09-19 09:14:12: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer System Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer FSRM Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer SqlServerWriter has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer WIDWriter has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer IIS Metabase Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer DFS Replication service writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:12: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK. 2017-09-19 09:14:13: Deleting Shadowcopy for dir “C:” 2017-09-19 09:14:13: Service finished. Transferred 8.68151 GB 2017-09-19 09:14:13: Transferred uncompressed: 21.3982 GB (ratio: 2.4648) 2017-09-19 09:14:13: Average sent paket size: 336.931 MB 2017-09-19 09:14:13: SERVICE_COMMANDS finished 2017-09-19 09:14:30: rc=0 hasError=true state=3 2017-09-19 09:14:30: SERVICE_COMMANDS finished 2017-09-19 09:14:31: rc=0 hasError=true state=0 2017-09-19 09:14:31: SERVICE_COMMANDS finished

After :
2017-09-21 00:40:22: Started connection to SERVICE_COMMANDS 2017-09-21 00:40:22: rc=0 hasError=true state=0 2017-09-21 00:40:22: SERVICE_COMMANDS finished 2017-09-21 00:40:22: Internet server auth failed. Error: Token not found 2017-09-21 00:40:22: InternetClient: Had an auth error 2017-09-21 00:40:23: Started connection to SERVICE_COMMANDS 2017-09-21 00:40:24: Started connection to SERVICE_COMMANDS 2017-09-21 00:40:24: Filesystem type is ntfs (\?\Volume{86f7e1fa-403d-11e5-80c2-806e6f6e6963}) 2017-09-21 00:40:24: TotalNumberOfClusters=89599 numberOfClusters=89599 n_clusters=11200 StartingLcn=0 BitmapSize=89599 r_bytes=11216 2017-09-21 00:40:24: FSINFO: blocksize=4096 size=367001088 has_error=false used_space=300220416 2017-09-21 00:46:57: Looking for old Sessions… 0 sessions 2017-09-21 00:50:41: Sending full image done 2017-09-21 00:50:41: Service finished. Transferred 249.65 MB 2017-09-21 00:50:41: Transferred uncompressed: 286.909 MB (ratio: 1.14924) 2017-09-21 00:50:41: Average sent paket size: 47.8182 MB 2017-09-21 00:50:41: SERVICE_COMMANDS finished 2017-09-21 00:50:45: Started connection to SERVICE_COMMANDS 2017-09-21 00:50:45: rc=0 hasError=true state=0 2017-09-21 00:50:45: SERVICE_COMMANDS finished 2017-09-21 00:50:45: Started connection to SERVICE_COMMANDS 2017-09-21 00:50:45: ERROR: Not found 2017-09-21 00:50:45: rc=0 hasError=true state=0 2017-09-21 00:50:45: SERVICE_COMMANDS finished 2017-09-21 00:50:45: Started connection to SERVICE_COMMANDS 2017-09-21 00:50:46: Started connection to SERVICE_COMMANDS 2017-09-21 00:50:46: rc=0 hasError=true state=0 2017-09-21 00:50:46: SERVICE_COMMANDS finished 2017-09-21 00:50:46: Started connection to SERVICE_COMMANDS 2017-09-21 00:50:47: rc=0 hasError=true state=0 2017-09-21 00:50:47: SERVICE_COMMANDS finished 2017-09-21 00:50:48: Started connection to SERVICE_COMMANDS 2017-09-21 00:50:48: Script “C:\Program Files\UrBackup\preimagebackup.bat” does not exist 2017-09-21 00:50:48: Creating shadowcopy of “C:”… 2017-09-21 00:50:56: rc=0 hasError=true state=0 2017-09-21 00:50:56: SERVICE_COMMANDS finished 2017-09-21 00:50:57: Number of Writers: 16 … 2017-09-21 00:52:03: Writer IIS Metabase Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK. 2017-09-21 00:52:03: Shadowcopy path: \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14 2017-09-21 00:52:03: Shadowcopy path: \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy15 2017-09-21 00:52:03: Shadowcopy path: \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy16 2017-09-21 00:52:03: done. 2017-09-21 00:52:03: Change block tracking reports 17.5 MB have changed on shadow copy \?\GLOBALROOT\Device\HarddiskVol umeShadowCopy14 2017-09-21 00:52:03: Change block tracking active on volume C: 2017-09-21 00:52:04: Bitmap urbackup\hdat_img_c_.cbt does not exist. Nothing to merge. 2017-09-21 00:52:04: Zeroing image hash data of volume C:… 2017-09-21 00:52:04: Change block tracking reports 3.5 MB have changed on shadow copy \?\GLOBALROOT\Device\HarddiskVolu meShadowCopy15 2017-09-21 00:52:04: Change block tracking active on volume f: 2017-09-21 00:52:04: Bitmap urbackup\hdat_img_f_.cbt does not exist. Nothing to merge. 2017-09-21 00:52:04: Zeroing image hash data of volume f:… 2017-09-21 00:52:06: Change block tracking reports 3.5 MB have changed on shadow copy \?\GLOBALROOT\Device\HarddiskVolu meShadowCopy16 2017-09-21 00:52:06: Change block tracking active on volume t: 2017-09-21 00:52:06: Bitmap urbackup\hdat_img_t_.cbt does not exist. Nothing to merge. 2017-09-21 00:52:06: Zeroing image hash data of volume t:… 2017-09-21 00:52:07: Filesystem type is ntfs (\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14) 2017-09-21 00:52:07: TotalNumberOfClusters=31366911 numberOfClusters=31366911 n_clusters=3920864 StartingLcn=0 BitmapSiz e=31366911 r_bytes=3920880 2017-09-21 00:52:08: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14\HIBERFIL.SYS fr om backup… 2017-09-21 00:52:08: Error opening file handle to \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14\HIBERFIL.SYS 2017-09-21 00:52:08: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14\pagefile.sys fr om backup… 2017-09-21 00:52:08: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14\swapfile.sys fr om backup… 2017-09-21 00:52:08: Error opening file handle to \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14\swapfile.sys 2017-09-21 00:52:08: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14\System Volume I nformation{3808876b-c176-4e48-b7ae-04046e6cc752} from backup… 2017-09-21 00:52:08: FSINFO: blocksize=4096 size=128478871040 has_error=false used_space=102542503936 2017-09-21 00:52:10: Started connection to SERVICE_COMMANDS 2017-09-21 00:52:10: rc=0 hasError=true state=0 2017-09-21 00:52:10: SERVICE_COMMANDS finished 2017-09-21 00:52:10: Started connection to SERVICE_COMMANDS 2017-09-21 00:52:10: rc=0 hasError=true state=0 2017-09-21 00:52:10: SERVICE_COMMANDS finished 2017-09-21 00:52:10: Started connection to SERVICE_COMMANDS 2017-09-21 00:52:10: Started connection to SERVICE_COMMANDS 2017-09-21 00:52:11: Started connection to SERVICE_COMMANDS 2017-09-21 00:52:12: Started connection to SERVICE_COMMANDS 2017-09-21 00:52:33: Filesystem type is ntfs (\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy15) 2017-09-21 00:52:33: TotalNumberOfClusters=39320831 numberOfClusters=39320831 n_clusters=4915104 StartingLcn=0 BitmapSiz e=39320831 r_bytes=4915120 2017-09-21 00:52:33: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy15\System Volume I nformation{3808876b-c176-4e48-b7ae-04046e6cc752} from backup… 2017-09-21 00:52:33: FSINFO: blocksize=4096 size=161058127360 has_error=false used_space=40048025600 2017-09-21 00:52:39: Filesystem type is ntfs (\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy16) 2017-09-21 00:52:39: TotalNumberOfClusters=26213631 numberOfClusters=26213631 n_clusters=3276704 StartingLcn=0 BitmapSiz e=26213631 r_bytes=3276720 2017-09-21 00:52:39: Trying to exclude contents of file \?\GLOBALROOT\Device\HarddiskVolumeShadowCopy16\System Volume I nformation{3808876b-c176-4e48-b7ae-04046e6cc752} from backup… 2017-09-21 00:52:39: FSINFO: blocksize=4096 size=107371036160 has_error=false used_space=72853762048 2017-09-21 00:54:41: Sending image done 2017-09-21 00:54:41: Deleting shadowcopy for path “f:” -2 2017-09-21 00:54:41: Deleting Shadowcopy for dir “f:” 2017-09-21 00:54:41: Service finished. Transferred 22.0553 MB 2017-09-21 00:54:41: Transferred uncompressed: 52.8643 MB (ratio: 2.39689) 2017-09-21 00:54:41: Average sent paket size: 5.54311 MB 2017-09-21 00:54:41: SERVICE_COMMANDS finished 2017-09-21 00:54:50: Started connection to SERVICE_COMMANDS 0-1505947930-Image backup is being backed up in a snapshot group together with volumes C:, t: 0-1505947930-Basing image backup on last incremental or full image backup 0-1505947930-Creating writable snapshot of previous image backup… 0-1505947958-Change block tracking active. Max 65.5 MB have changed. 0-1505948089-Transferred 22.0553 MB - Average speed: 1.35293 MBit/s 0-1505948089-(Before compression: 52.8643 MB ratio: 2.39689) 0-1505948089-Time taken for backing up client SV412: 2m 39s 0-1505948089-Backup succeeded


2017-09-21 00:54:51: rc=0 hasError=true state=0

2017-09-21 00:54:51: SERVICE_COMMANDS finished

2017-09-21 00:54:57: rc=0 hasError=true state=0

2017-09-21 00:54:57: SERVICE_COMMANDS finished

2017-09-21 01:16:58: Looking for old Sessions… 0 sessions

2017-09-21 01:36:16: Sending image done

2017-09-21 01:36:16: Deleting shadowcopy for path “t:” -2

2017-09-21 01:36:16: Deleting Shadowcopy for dir “t:”

2017-09-21 01:36:16: Service finished. Transferred 546.742 MB

2017-09-21 01:36:16: Transferred uncompressed: 3.45188 GB (ratio: 6.46507)

2017-09-21 01:36:16: Average sent paket size: 320.486 MB

2017-09-21 01:36:16: SERVICE_COMMANDS finished

2017-09-21 01:36:27: Started connection to SERVICE_COMMANDS

0-1505947930-Image backup is being backed up in a snapshot group together with volumes C:, f:

0-1505947930-Basing image backup on last incremental or full image backup

0-1505947931-Creating writable snapshot of previous image backup…

0-1505947962-Change block tracking active. Max 3.90088 GB have changed.

0-1505950586-Transferred 546.742 MB - Average speed: 1.74465 MBit/s

0-1505950586-(Before compression: 3.45188 GB ratio: 6.46507)

0-1505950586-Time taken for backing up client SV412: 44m 16s

0-1505950586-Backup succeeded
2017-09-21 01:36:28: rc=0 hasError=true state=0

2017-09-21 01:36:28: SERVICE_COMMANDS finished

2017-09-21 01:36:30: rc=0 hasError=true state=0

2017-09-21 01:36:30: SERVICE_COMMANDS finished

2017-09-21 01:46:59: Looking for old Sessions… 0 sessions

2017-09-21 02:17:00: Looking for old Sessions… 0 sessions

2017-09-21 02:47:01: Looking for old Sessions… 0 sessions

2017-09-21 03:01:28: Started connection to SERVICE_COMMANDS

2017-09-21 03:01:28: Server has new version 190 (client version: 0). Updating…

2017-09-21 03:01:29: rc=0 hasError=true state=0

2017-09-21 03:01:29: SERVICE_COMMANDS finished

2017-09-21 03:17:02: Looking for old Sessions… 0 sessions

2017-09-21 03:47:03: Looking for old Sessions… 0 sessions

2017-09-21 03:55:26: Sending image done

2017-09-21 03:55:26: Deleting shadowcopy for path “\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14” -2

2017-09-21 03:55:28: rc=0 hasError=true state=4

2017-09-21 03:55:31: Number of Writers: 16

2017-09-21 03:55:31: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer FSRM Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer SqlServerWriter has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer WIDWriter has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer IIS Metabase Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer DFS Replication service writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:31: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.

2017-09-21 03:55:32: Deleting Shadowcopy for dir “C:”

2017-09-21 03:55:32: Service finished. Transferred 3.80213 GB

2017-09-21 03:55:32: Transferred uncompressed: 11.4694 GB (ratio: 3.01656)

2017-09-21 03:55:32: Average sent paket size: 902.57 MB

2017-09-21 03:55:32: SERVICE_COMMANDS finished

2017-09-21 03:55:32: Started connection to SERVICE_COMMANDS

0-1505947846-Basing image backup on last incremental or full image backup

0-1505947846-Creating writable snapshot of previous image backup…

0-1505947930-Change block tracking active. Max 12.7432 GB have changed.

0-1505947930-Image backup is being backed up in a snapshot group together with volumes f:, t:

0-1505958931-Transferred 3.80213 GB - Average speed: 2.95078 MBit/s

0-1505958931-(Before compression: 11.4694 GB ratio: 3.01656)

0-1505958931-Time taken for backing up client SV412: 3h 15m 9s

0-1505958931-Backup succeeded

2017-09-21 03:55:32: rc=0 hasError=true state=0 2017-09-21 03:55:32: SERVICE_COMMANDS finished 2017-09-21 03:55:35: rc=0 hasError=true state=0 2017-09-21 03:55:35: SERVICE_COMMANDS finished 2017-09-21 04:17:04: Looking for old Sessions… 0 sessions

Regards,

reine · November 3, 2017, 12:20pm

In most cases with vss error it has the help to remove all but microsofts vss providers

this have work for me no garant

To resolve this issue, you need to determine what unnecessary VSS providers are present, remove them and revert to the previous status (if necessary).

Open an elevated Command Prompt and type

vssadmin list providers

After you get the list of providers, identify the unnecessary ones. now go to the Registry

Open Regedit
Browse to HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\VSS\Providers\
Expand Providers and you should see three keys: Enum, and two GUID’s (Long strings of letters and numbers).
Click on the top GUID in the list and in the right-hand pane the Default string should have the name of the provider. If not check the other GUID.
Once you find the right GUID export the whole GUID and export it so you can revert the operation if needed.
Delete the unnecessary provider GUID subkey and close the registry
Open Windows services and reboot the “Volume Shadow Copy” service. It may be stopped to begin with, that’s okay.
Check and see if the provider is gone from: vssadmin list providers
(if needed) Reboot the server when next possible.
(if needed) If for some reason you need to revert to the initial state, import the previously exported registry subkey and bounce the Volume Shadow Copy service