No image or files backup cause to VSS error. Logs attached

#1

Hello,

i’ve installed a new Urbackup Server on a Linux Centos 7.

I’ve many errors on a Windows Server backup files and image copy.

On files i get completed with errors. I understand that this message is probably caused by the VSS that giving errors and probably all files will be copied but i’ve to resolve the issue.
On images i get a complete fail.

I attached logs.

This is the most important server of this costumer and is the only that give this problem.

Server
OS: Centos7
VER URBACKUP: 2.4.13

Client
OS: Windows 2012 R2
VER URBACKUP: 1.4.11

LOG: https://we.tl/t-AfXAnFLbss

EDIT:
Same installation for all. I don’t undestand.
I’ve tried also doing a restart of the service Volume Shadow Copy, restart the entirely server, doing a sfc /scannow scan and no solution.

I’ve tested and with vssadmin list writers there are no errors
I’ve also tried to re register vss dlls like microsoft suggest and nothing

#2

I cannot edit the post now. This is the relevant LOG in the client:

2021-02-22 09:31:25: Loaded -fileserv- plugin
2021-02-22 09:31:25: Loaded -fsimageplugin- plugin
2021-02-22 09:31:25: Loaded -cryptoplugin- plugin
2021-02-22 09:31:25: SQLite: recovered 9458 frames from WAL file C:\Program Files\UrBackup\urbackup\backup_client.db-wal code: 283
2021-02-22 09:31:25: urbackupserver: Server started up successfully!
2021-02-22 09:31:25: FileSrv: Backup privileges set successfully
2021-02-22 09:31:25: FileSrv: Backup privileges set successfully (SE_SECURITY_NAME)
2021-02-22 09:31:25: FileSrv: Backup privileges set successfully (SE_RESTORE_NAME)
2021-02-22 09:31:25: FileSrv: Binding UDP socket at port 35622…
2021-02-22 09:31:25: FileSrv: done.
2021-02-22 09:31:25: FileSrv: Disabling new behavior…
2021-02-22 09:31:25: FileSrv: Binding ipv6 UDP socket at port 35622…
2021-02-22 09:31:25: FileSrv: done.
2021-02-22 09:31:25: FileSrv: Disabling new behavior…
2021-02-22 09:31:25: FileSrv: Servername: -Srv2012App-
2021-02-22 09:31:25: FileSrv: Server started up successfully
2021-02-22 09:31:25: FileSrv: UDP Thread started
2021-02-22 09:31:25: Started UrBackupClient Backend…
2021-02-22 09:31:25: Filesystem. Vol="\?\Volume{5a24496b-0a92-11e5-80b4-806e6f6e6963}" Name=“riservato per il sistema” Type=“ntfs” VPaths=0 Size=366997504
2021-02-22 09:31:25: Bootable flag set for volume
2021-02-22 09:31:25: Found potential candidate: \?\Volume{5a24496b-0a92-11e5-80b4-806e6f6e6963}\ Score: 3
2021-02-22 09:31:25: Filesystem. Vol="\?\Volume{d62aeccb-0760-11e8-80d5-52540024c49b}" Name=“dati” Type=“ntfs” VPaths=1 Size=644222021632
2021-02-22 09:31:25: Bootable flag not set for volume
2021-02-22 09:31:25: Filesystem. Vol="\?\Volume{9c80c37c-e878-463f-995f-f25f15dfd23c}" Name=“backup” Type=“ntfs” VPaths=1 Size=858856091648
2021-02-22 09:31:25: GPT formated hard disk encountered. No bootable flag. Attributes = 0
2021-02-22 09:31:25: Bootable flag not set for volume
2021-02-22 09:31:25: Filesystem. Vol="\?\Volume{5a24496c-0a92-11e5-80b4-806e6f6e6963}" Name="" Type=“ntfs” VPaths=1 Size=343215697920
2021-02-22 09:31:25: Filesystem is System partition. Skipping…
2021-02-22 09:31:25: Filesystem. Vol="\?\Volume{5a244970-0a92-11e5-80b4-806e6f6e6963}" Name=“ir3_sss_x64fre_it-it_dv9” Type=“udf” VPaths=1 Size=4591839232
2021-02-22 09:31:25: Bootable flag not set for volume
2021-02-22 09:31:25: Filesystem. Vol="\?\Volume{5a244971-0a92-11e5-80b4-806e6f6e6963}" Name=“cdrom” Type=“cdfs” VPaths=1 Size=69953536
2021-02-22 09:31:25: Bootable flag not set for volume
2021-02-22 09:31:25: Found potential candidate: \?\Volume{5a244971-0a92-11e5-80b4-806e6f6e6963}\ Score: 2
2021-02-22 09:31:25: Not on Physical Device ‘C’: \?\Volume{5a244971-0a92-11e5-80b4-806e6f6e6963} (E:)
2021-02-22 09:31:25: Selected volume \?\Volume{5a24496b-0a92-11e5-80b4-806e6f6e6963}
2021-02-22 09:31:25: System dir: C:\Windows
2021-02-22 09:31:25: Volpath: \.\C:
2021-02-22 09:31:25: Device is not GPT formatted (0)
2021-02-22 09:31:25: Found no EFI System Partition
2021-02-22 09:31:25: urbackupserver: No available slots… starting new Worker
2021-02-22 09:31:25: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:25: ClientService cmd: STATUS#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:25: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:26: ClientService cmd: STATUS#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:26: Looking for old Sessions… 0 sessions
2021-02-22 09:31:26: Internet only mode not enabled. Waiting for local server for 3:00…
2021-02-22 09:31:26: Final path: G:
2021-02-22 09:31:26: Final path: C:\Program Files (x86)\Dolphin\Stratega6
2021-02-22 09:31:26: Final path: V:
2021-02-22 09:31:26: Final path: C:\Program Files (x86)\Dolphin\XplodeIt
2021-02-22 09:31:26: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:27: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:28: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:29: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:30: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:31: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:32: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:33: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:34: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#1CHANNEL capa=1&token=Pf8vD5SC0W10kJ6XXgsU&restore_version=1&virtual_client=
2021-02-22 09:31:34: New channel: Number of Channels: 1
2021-02-22 09:31:34: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:35: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:36: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:37: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:38: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:39: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:40: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:41: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:42: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:43: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:44: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#MBR driveletter=SYSVOL&disk_path=SYSVOL&image_full=1&running_jobs=1&token=Pf8vD5SC0W10kJ6XXgsU
2021-02-22 09:31:44: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#2PING RUNNING pc_done=0&status_id=7&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=Pf8vD5SC0W10kJ6XXgsU
2021-02-22 09:31:44: rc=0 hasError=true state=0
2021-02-22 09:31:44: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#FULL IMAGE letter=SYSVOL&token=Pf8vD5SC0W10kJ6XXgsU&checksum=1&bitmap=1&status_id=7&running_jobs=1&zero_skipped=1
2021-02-22 09:31:44: Filesystem type is ntfs (\?\Volume{5a24496b-0a92-11e5-80b4-806e6f6e6963})
2021-02-22 09:31:44: TotalNumberOfClusters=89599 numberOfClusters=89599 n_clusters=11200 StartingLcn=0 BitmapSize=89599 r_bytes=11216
2021-02-22 09:31:44: FSINFO: blocksize=4096 size=367001088 has_error=false used_space=271380480
2021-02-22 09:31:44: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:45: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:46: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:47: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:48: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:49: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:50: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:51: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:52: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:53: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:53: Sending full image done
2021-02-22 09:31:53: Removing running process (1) id 1 server_id 7 token Pf8vD5SC0W10kJ6XXgsU action 3
2021-02-22 09:31:54: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#2PING RUNNING pc_done=100&status_id=7&speed_bpms=0&total_bytes=271380480&done_bytes=253657088&paused_fb=1#token=Pf8vD5SC0W10kJ6XXgsU
2021-02-22 09:31:54: Client timeout in ClientConnector::Run
2021-02-22 09:31:54: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:55: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:56: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#MBR driveletter=ESP&disk_path=ESP&image_full=1&running_jobs=1&token=Pf8vD5SC0W10kJ6XXgsU
2021-02-22 09:31:56: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#2PING RUNNING pc_done=0&status_id=8&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=Pf8vD5SC0W10kJ6XXgsU
2021-02-22 09:31:56: rc=0 hasError=true state=0
2021-02-22 09:31:56: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#FULL IMAGE letter=ESP&token=Pf8vD5SC0W10kJ6XXgsU&checksum=1&bitmap=1&status_id=8&running_jobs=1&zero_skipped=1
2021-02-22 09:31:56: ERROR: Not found
2021-02-22 09:31:56: rc=0 hasError=true state=0
2021-02-22 09:31:56: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:57: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#MBR driveletter=C&disk_path=C:&image_full=1&running_jobs=1&token=Pf8vD5SC0W10kJ6XXgsU
2021-02-22 09:31:57: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#2PING RUNNING pc_done=0&status_id=6&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=Pf8vD5SC0W10kJ6XXgsU
2021-02-22 09:31:57: rc=0 hasError=true state=0
2021-02-22 09:31:57: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#FULL IMAGE letter=C:&token=Pf8vD5SC0W10kJ6XXgsU&checksum=1&bitmap=1&status_id=6&running_jobs=1&zero_skipped=1
2021-02-22 09:31:57: Script “C:\Program Files\UrBackup\preimagebackup.bat” does not exist
2021-02-22 09:31:57: Creating shadowcopy of “C:”…
2021-02-22 09:31:57: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:58: ClientService cmd: STATUS#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:58: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:31:59: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:32:00: Number of Writers: 13
2021-02-22 09:32:00: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer SqlServerWriter has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer IIS Config Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Writer IIS Metabase Writer has failure state VSS_WS_STABLE with error S_OK.
2021-02-22 09:32:00: Preparing change block tracking reset for volume c: failed: Funzione non corretta. (code: 1)
2021-02-22 09:32:00: ERROR: backupcom->AddToSnapshotSet(&(Server->ConvertToWchar(selected_vols[i])[0]), GUID_NULL, &additional_refs[i].volid) failed. VSS error code VSS_E_UNEXPECTED_PROVIDER_ERROR
2021-02-22 09:32:00: ERROR: VSS provider information:
2021-02-22 09:32:00: ERROR: Nome provider: ‘Microsoft iSCSI Target VSS Hardware Provider’
2021-02-22 09:32:00: ERROR: Tipo provider: Hardware
2021-02-22 09:32:00: ERROR: ID provider: {3f900f90-00e9-440e-873a-96ca5eb079e5}
2021-02-22 09:32:00: ERROR: Versione: 6.3.9600.16384
2021-02-22 09:32:00: ERROR: Nome provider: ‘Microsoft File Share Shadow Copy provider’
2021-02-22 09:32:00: ERROR: Tipo provider: Condivisione file
2021-02-22 09:32:00: ERROR: ID provider: {89300202-3cec-4981-9171-19f59559e0f2}
2021-02-22 09:32:00: ERROR: Versione: 1.0.0.1
2021-02-22 09:32:00: ERROR: Nome provider: ‘Microsoft Software Shadow Copy provider 1.0’
2021-02-22 09:32:00: ERROR: Tipo provider: Sistema
2021-02-22 09:32:00: ERROR: ID provider: {b5946137-7b9f-4925-af80-51abd60b20d5}
2021-02-22 09:32:00: ERROR: Versione: 1.0.0.7
2021-02-22 09:32:00: done.
2021-02-22 09:32:00: Disabling CBT on volume “C:”
2021-02-22 09:32:00: ERROR: Creating shadowcopy of “C:” failed.
2021-02-22 09:32:00: ERROR: Creating shadow copy failed. See client log file for details.
2021-02-22 09:32:00: Sending full image done
2021-02-22 09:32:00: Removing running process (1) id 2 server_id 6 token Pf8vD5SC0W10kJ6XXgsU action 3
2021-02-22 09:32:00: ClientService cmd: STATUS DETAIL#pw=1LDFgdO5Q5cZ3vYK3cntwX2WsNCNVl
2021-02-22 09:32:01: ClientService cmd: #IiIq14yY0ATxnmbxl2t2j#2LOGDATA 1613982720 0-1613982704-Starting unscheduled full image backup of volume “C:”…
2-1613982720-Request of image backup failed. Reason: Creating shadow copy failed. See client log file for details.
0-1613982720-Transferred 205 bytes - Average speed: 456 Bit/s
0-1613982720-Time taken for backing up client Srv2012App: 16s
2-1613982720-Backup failed

LIST PROVIDERS:
Nome provider: ‘Microsoft iSCSI Target VSS Hardware Provider’
Tipo provider: Hardware
ID provider: {3f900f90-00e9-440e-873a-96ca5eb079e5}
Versione: 6.3.9600.16384

Nome provider: ‘Microsoft File Share Shadow Copy provider’
Tipo provider: Condivisione file
ID provider: {89300202-3cec-4981-9171-19f59559e0f2}
Versione: 1.0.0.1

Nome provider: ‘Microsoft Software Shadow Copy provider 1.0’
Tipo provider: Sistema
ID provider: {b5946137-7b9f-4925-af80-51abd60b20d5}
Versione: 1.0.0.7

Any help?

#3

Ok i’ve probably solved after like 1 million tries.

Solution:
Delete the regkey of iSCSI VSS using AdvanceRun of Nirsoft:
AdvancedRun.exe /EXEFilename “c:\windows\system32\cmd.exe” /RunAs 8 /Run
And starting regedit i delete the key (Previously backup it obviously)

[HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\VSS\Providers{3f900f90-00e9-440e-873a-96ca5eb079e5}]
@=“Microsoft iSCSI Target VSS Hardware Provider”

Restarting Volume Shadow Copy now image copy works!

But I would like to ask a question if anyone knows.
Is this problem due to some limitation of UrBackup not being able to use other VSS providers or what can it be? Currently the image works for me and is copying now. I have yet to test the files of V: and G:
partitions (not included in the image) that are actually on an iSCSI connection and removing the provider I have some doubts that it does not give errors.