VSS failing with no VSS errors


#1

I have a simple setup: UrBackup Server 1.4.12 on a 2003 server with client on the same.

I show no VSS issues with vssadmin list writers.

But whenever I kick off the backup, I get an immediate failure “Request of image backup failed: Reason: Creating Shadow drive failed. Stopping.”

vssadmin still shows no issues.

I tried configuring both server and client services to run under the domain admin account, but I get the same result.

I uninstalled completely and reinstalled yesterday. I also scheduled a reboot at 3am this morning. Still no joy.

I can create a snapshot through Windows just fine.

Here are my logs:

2016-01-28 11:28:21: WARNING: Upgrading…
2016-01-28 11:28:21: WARNING: Converting database to journal mode…
2016-01-28 11:28:21: WARNING: Upgrading database to version 4
2016-01-28 11:28:21: WARNING: Upgrading database to version 5
2016-01-28 11:28:21: WARNING: Upgrading database to version 6
2016-01-28 11:28:21: WARNING: Upgrading database to version 7
2016-01-28 11:28:21: WARNING: Upgrading database to version 8
2016-01-28 11:28:21: WARNING: Upgrading database to version 9
2016-01-28 11:28:21: WARNING: Upgrading database to version 10
2016-01-28 11:28:21: WARNING: Upgrading database to version 11
2016-01-28 11:28:21: WARNING: Upgrading database to version 12
2016-01-28 11:28:21: WARNING: Upgrading database to version 13
2016-01-28 11:28:21: WARNING: Upgrading database to version 14
2016-01-28 11:28:22: WARNING: Upgrading database to version 15
2016-01-28 11:28:22: WARNING: Upgrading database to version 16
2016-01-28 11:28:22: WARNING: Upgrading database to version 17
2016-01-28 11:28:22: WARNING: Upgrading database to version 18
2016-01-28 11:28:22: WARNING: Upgrading database to version 19
2016-01-28 11:28:22: WARNING: Upgrading database to version 20
2016-01-28 11:28:22: WARNING: Upgrading database to version 21
2016-01-28 11:28:22: WARNING: Upgrading database to version 22
2016-01-28 11:28:22: WARNING: Upgrading database to version 23
2016-01-28 11:28:22: WARNING: Upgrading database to version 24
2016-01-28 11:28:22: WARNING: Upgrading database to version 25
2016-01-28 11:28:22: WARNING: Upgrading database to version 26
2016-01-28 11:28:22: WARNING: Upgrading database to version 27
2016-01-28 11:28:22: WARNING: Upgrading database to version 28
2016-01-28 11:28:23: WARNING: Upgrading database to version 29
2016-01-28 11:28:23: WARNING: Upgrading database to version 30
2016-01-28 11:28:23: WARNING: Upgrading database to version 31
2016-01-28 11:28:23: WARNING: Upgrading database to version 32
2016-01-28 11:28:23: WARNING: Upgrading database to version 33
2016-01-28 11:28:23: WARNING: Upgrading database to version 34
2016-01-28 11:28:23: WARNING: Upgrading database to version 35
2016-01-28 11:28:23: WARNING: Done.
2016-01-28 11:33:40: ERROR: Error getting Client settings of PROFITTECH3. Errorcode: FILE_DOESNT_EXIST (3)
2016-01-28 11:33:42: ERROR: Request of image backup failed. Reason: Creating Shadow drive failed. Stopping.
2016-01-28 11:33:42: ERROR: Backup failed
2016-01-28 11:33:42: WARNING: Exponential backoff: Waiting at least 40m before next image backup
2016-01-28 11:36:33: ERROR: Request of image backup failed. Reason: Creating Shadow drive failed. Stopping.
2016-01-28 11:36:34: ERROR: Backup failed
2016-01-28 11:36:34: WARNING: Exponential backoff: Waiting at least 1h 20m before next image backup
2016-01-28 18:00:25: ERROR: Request of image backup failed. Reason: Creating Shadow drive failed. Stopping.
2016-01-28 18:00:25: ERROR: Backup failed
2016-01-28 18:00:25: WARNING: Exponential backoff: Waiting at least 2h 40m before next image backup
2016-01-28 20:40:55: ERROR: Request of image backup failed. Reason: Creating Shadow drive failed. Stopping.
2016-01-28 20:40:56: ERROR: Backup failed
2016-01-28 20:40:56: WARNING: Exponential backoff: Waiting at least 5h 20m before next image backup
2016-01-29 10:16:13: ERROR: Request of image backup failed. Reason: Creating Shadow drive failed. Stopping.
2016-01-29 10:16:14: ERROR: Backup failed
2016-01-29 10:16:14: WARNING: Exponential backoff: Waiting at least 40m before next image backup
2016-01-29 10:24:20: ERROR: Request of image backup failed. Reason: Creating Shadow drive failed. Stopping.
2016-01-29 10:24:21: ERROR: Backup failed
2016-01-29 10:24:21: WARNING: Exponential backoff: Waiting at least 40m before next image backup


#2

I think that error can also occur if the drive does not exists.Putting the client into debug log mode should give more details (see here on how to do that).


#3

Ok, I enabled debug logging and then attempted a full.

2016-01-29 12:21:59: Getting client settings...
2016-01-29 12:21:59: Sending backup incr intervall...
2016-01-29 12:22:21: Sending file "urbackup\www"
2016-01-29 12:22:21: Sending file: urbackup\www/index.htm
2016-01-29 12:22:21: Sending file: urbackup\www/index.htm done
2016-01-29 12:22:21: Sending file "urbackup\www/layout.css"
2016-01-29 12:22:21: Sending file: urbackup\www/layout.css
2016-01-29 12:22:21: Sending file: urbackup\www/layout.css done
2016-01-29 12:22:21: Sending file "urbackup\www/datatable.css"
2016-01-29 12:22:21: Sending file: urbackup\www/datatable.css
2016-01-29 12:22:21: Sending file: urbackup\www/datatable.css done
2016-01-29 12:22:21: Sending file "urbackup\www/jquery.jqplot.min.css"
2016-01-29 12:22:21: Sending file: urbackup\www/jquery.jqplot.min.css
2016-01-29 12:22:21: Sending file: urbackup\www/jquery.jqplot.min.css done
2016-01-29 12:22:21: Sending file "urbackup\www/dataTables.colVis.min.css"
2016-01-29 12:22:21: Sending file: urbackup\www/dataTables.colVis.min.css
2016-01-29 12:22:21: Sending file: urbackup\www/dataTables.colVis.min.css done
2016-01-29 12:22:21: Sending file "urbackup\www/dataTables.tableTools.min.css"
2016-01-29 12:22:21: Sending file: urbackup\www/dataTables.tableTools.min.css
2016-01-29 12:22:21: Sending file: urbackup\www/dataTables.tableTools.min.css done
2016-01-29 12:22:21: Sending file "urbackup\www/jquery.js"
2016-01-29 12:22:21: Sending file: urbackup\www/jquery.js
2016-01-29 12:22:21: Sending file: urbackup\www/jquery.js done
2016-01-29 12:22:21: Sending file "urbackup\www/jquery.dataTables.min.js"
2016-01-29 12:22:21: Sending file: urbackup\www/jquery.dataTables.min.js
2016-01-29 12:22:21: Sending file: urbackup\www/jquery.dataTables.min.js done
2016-01-29 12:22:21: Sending file "urbackup\www/dust-full.min.js"
2016-01-29 12:22:21: Sending file: urbackup\www/dust-full.min.js
2016-01-29 12:22:21: Sending file: urbackup\www/dust-full.min.js done
2016-01-29 12:22:21: Sending file "urbackup\www/jquery.jqplot.min.js"
2016-01-29 12:22:21: Sending file: urbackup\www/jquery.jqplot.min.js
2016-01-29 12:22:21: Sending file "urbackup\www/jqplot.pieRenderer.min.js"
2016-01-29 12:22:21: Sending file: urbackup\www/jquery.jqplot.min.js done
2016-01-29 12:22:21: Sending file: urbackup\www/jqplot.pieRenderer.min.js
2016-01-29 12:22:21: Sending file: urbackup\www/jqplot.pieRenderer.min.js done
2016-01-29 12:22:21: Sending file "urbackup\www/jqplot.barRenderer.min.js"
2016-01-29 12:22:21: Sending file: urbackup\www/jqplot.barRenderer.min.js
2016-01-29 12:22:21: Sending file: urbackup\www/jqplot.barRenderer.min.js done
2016-01-29 12:22:21: Sending file "urbackup\www/jqplot.dateAxisRenderer.min.js"
2016-01-29 12:22:21: Sending file: urbackup\www/jqplot.dateAxisRenderer.min.js
2016-01-29 12:22:21: Sending file: urbackup\www/jqplot.dateAxisRenderer.min.js done
2016-01-29 12:22:21: Sending file "urbackup\www/jqplot.highlighter.min.js"
2016-01-29 12:22:21: Sending file: urbackup\www/jqplot.highlighter.min.js
2016-01-29 12:22:21: Sending file: urbackup\www/jqplot.highlighter.min.js done
2016-01-29 12:22:21: Sending file "urbackup\www/templates.js"
2016-01-29 12:22:21: Sending file: urbackup\www/templates.js
2016-01-29 12:22:21: Sending file: urbackup\www/templates.js done
2016-01-29 12:22:21: Sending file "urbackup\www/urbackup_functions.js"
2016-01-29 12:22:21: Sending file: urbackup\www/urbackup_functions.js
2016-01-29 12:22:21: Sending file: urbackup\www/urbackup_functions.js done
2016-01-29 12:22:21: Sending file "urbackup\www/default_user_rights.js"
2016-01-29 12:22:21: Sending file: urbackup\www/default_user_rights.js
2016-01-29 12:22:21: Sending file: urbackup\www/default_user_rights.js done
2016-01-29 12:22:21: Sending file "urbackup\www/translation.js"
2016-01-29 12:22:21: Sending file: urbackup\www/translation.js
2016-01-29 12:22:21: Sending file: urbackup\www/translation.js done
2016-01-29 12:22:21: Sending file "urbackup\www/urbackup.js"
2016-01-29 12:22:21: Sending file: urbackup\www/urbackup.js
2016-01-29 12:22:21: Sending file: urbackup\www/urbackup.js done
2016-01-29 12:22:21: Sending file "urbackup\www/dataTables.colVis.min.js"
2016-01-29 12:22:21: Sending file: urbackup\www/dataTables.colVis.min.js
2016-01-29 12:22:21: Sending file: urbackup\www/dataTables.colVis.min.js done
2016-01-29 12:22:21: Sending file "urbackup\www/md5.js"
2016-01-29 12:22:21: Sending file: urbackup\www/md5.js
2016-01-29 12:22:21: Sending file: urbackup\www/md5.js done
2016-01-29 12:22:21: Sending file "urbackup\www/tabber-minimized.js"
2016-01-29 12:22:21: Sending file: urbackup\www/tabber-minimized.js
2016-01-29 12:22:21: Sending file: urbackup\www/tabber-minimized.js done
2016-01-29 12:22:21: Sending file "urbackup\www/dataTables.tableTools.min.js"
2016-01-29 12:22:21: Sending file: urbackup\www/dataTables.tableTools.min.js
2016-01-29 12:22:21: Sending file: urbackup\www/dataTables.tableTools.min.js done
2016-01-29 12:22:21: Sending file "urbackup\www/indicator.gif"
2016-01-29 12:22:21: Sending file: urbackup\www/indicator.gif
2016-01-29 12:22:21: Sending file: urbackup\www/indicator.gif done
2016-01-29 12:22:21: Sending file "urbackup\www/header.png"
2016-01-29 12:22:21: Sending file: urbackup\www/header.png
2016-01-29 12:22:21: Sending file: urbackup\www/header.png done
2016-01-29 12:22:21: Created new database connection for urbackup/backup_server.db
2016-01-29 12:22:21: Sending file "urbackup\www/favicon.ico"
2016-01-29 12:22:21: Sending file: urbackup\www/favicon.ico
2016-01-29 12:22:21: Sending file: urbackup\www/favicon.ico done
2016-01-29 12:22:21: Created new database connection for urbackup/backup_server.db
2016-01-29 12:22:24: Downloading version file...
2016-01-29 12:22:24: Downloading server version info...
2016-01-29 12:22:28: msg=START IMAGE FULL
2016-01-29 12:22:28: Starting full image backup...
2016-01-29 12:22:28: Backing up SYSVOL...
2016-01-29 12:22:28: Request of SYSVOL failed. Reason: Opening filesystem on device failed. Stopping.. This probably just means the Computer does not have a "System restore" volume which UrBackup can backup.
2016-01-29 12:22:28: Transferred 143 bytes - Average speed: 1.144 MBit/s
2016-01-29 12:22:28: Backing up SYSVOL done.
2016-01-29 12:22:28: Created new database connection for urbackup/backup_server.db
2016-01-29 12:22:30: ERROR: Request of image backup failed. Reason: Creating Shadow drive failed. Stopping.
2016-01-29 12:22:30: Transferred 132 bytes - Average speed: 600 Bit/s
2016-01-29 12:22:30: Time taken for creating image of client PROFITTECH3: 2s
2016-01-29 12:22:30: ERROR: Backup failed
2016-01-29 12:22:30: WARNING: Exponential backoff: Waiting at least 40m before next image backup
2016-01-29 12:22:39: Sending file "urbackup\www/arr.png"
2016-01-29 12:22:39: Sending file: urbackup\www/arr.png
2016-01-29 12:22:39: Sending file: urbackup\www/arr.png done

#4

Could you do that with the client please?


#5

Hmmm… As soon as I set that to debug and restarted the service it now says, "Could not start backup, because no backup server was found’ when I try to kick off a backup from the client. That said, here is the log from the client:

2016-01-28 11:32:50: WARNING: Upgrading...
2016-01-28 11:32:50: ERROR: Error preparing Query [SELECT tvalue FROM misc WHERE tkey='db_version']: no such table: misc
2016-01-28 11:32:52: ERROR: Error preparing Query [DROP INDEX filehashes_idx]: no such index: filehashes_idx
2016-01-28 11:32:52: ERROR: GPT formated hard disk encountered. UrBackup does not support GPT formated hard disks! (Volume=\\?\Volume{51535365-151c-497a-8931-2f9c45ab3505})
2016-01-28 11:33:42: ERROR: backupcom->AddToSnapshotSet(volume_path, GUID_NULL, &dir->ref->ssetid) failed: EC=VSS_E_UNEXPECTED_PROVIDER_ERROR
2016-01-28 11:33:42: ERROR: Creating shadowcopy of "C:" failed.
2016-01-28 11:33:42: ERROR: Creating Shadow drive failed. Stopping.
2016-01-28 11:36:33: ERROR: backupcom->AddToSnapshotSet(volume_path, GUID_NULL, &dir->ref->ssetid) failed: EC=VSS_E_UNEXPECTED_PROVIDER_ERROR
2016-01-28 11:36:33: ERROR: Creating shadowcopy of "C:" failed.
2016-01-28 11:36:33: ERROR: Creating Shadow drive failed. Stopping.
2016-01-28 18:00:25: ERROR: backupcom->AddToSnapshotSet(volume_path, GUID_NULL, &dir->ref->ssetid) failed: EC=VSS_E_UNEXPECTED_PROVIDER_ERROR
2016-01-28 18:00:25: ERROR: Creating shadowcopy of "C:" failed.
2016-01-28 18:00:25: ERROR: Creating Shadow drive failed. Stopping.
2016-01-28 20:40:55: ERROR: backupcom->AddToSnapshotSet(volume_path, GUID_NULL, &dir->ref->ssetid) failed: EC=VSS_E_UNEXPECTED_PROVIDER_ERROR
2016-01-28 20:40:55: ERROR: Creating shadowcopy of "C:" failed.
2016-01-28 20:40:55: ERROR: Creating Shadow drive failed. Stopping.
2016-01-29 03:06:10: ERROR: GPT formated hard disk encountered. UrBackup does not support GPT formated hard disks! (Volume=\\?\Volume{51535365-151c-497a-8931-2f9c45ab3505})
2016-01-29 10:16:13: ERROR: backupcom->AddToSnapshotSet(volume_path, GUID_NULL, &dir->ref->ssetid) failed: EC=VSS_E_UNEXPECTED_PROVIDER_ERROR
2016-01-29 10:16:13: ERROR: Creating shadowcopy of "C:" failed.
2016-01-29 10:16:13: ERROR: Creating Shadow drive failed. Stopping.
2016-01-29 10:23:19: ERROR: GPT formated hard disk encountered. UrBackup does not support GPT formated hard disks! (Volume=\\?\Volume{51535365-151c-497a-8931-2f9c45ab3505})
2016-01-29 10:24:20: ERROR: backupcom->AddToSnapshotSet(volume_path, GUID_NULL, &dir->ref->ssetid) failed: EC=VSS_E_UNEXPECTED_PROVIDER_ERROR
2016-01-29 10:24:20: ERROR: Creating shadowcopy of "C:" failed.
2016-01-29 10:24:20: ERROR: Creating Shadow drive failed. Stopping.
2016-01-29 10:32:57: ERROR: backupcom->AddToSnapshotSet(volume_path, GUID_NULL, &dir->ref->ssetid) failed: EC=VSS_E_UNEXPECTED_PROVIDER_ERROR
2016-01-29 10:32:58: ERROR: Creating shadowcopy of "C:" failed.
2016-01-29 10:32:58: ERROR: Creating Shadow drive failed. Stopping.
2016-01-29 12:21:16: ERROR: GPT formated hard disk encountered. UrBackup does not support GPT formated hard disks! (Volume=\\?\Volume{51535365-151c-497a-8931-2f9c45ab3505})
2016-01-29 12:22:30: ERROR: backupcom->AddToSnapshotSet(volume_path, GUID_NULL, &dir->ref->ssetid) failed: EC=VSS_E_UNEXPECTED_PROVIDER_ERROR
2016-01-29 12:22:30: ERROR: Creating shadowcopy of "C:" failed.
2016-01-29 12:22:30: ERROR: Creating Shadow drive failed. Stopping.
2016-01-29 12:25:16: Loaded -fileserv- plugin
2016-01-29 12:25:16: Loaded -fsimageplugin- plugin
2016-01-29 12:25:16: Loaded -cryptoplugin- plugin
2016-01-29 12:25:17: Loading DLL "urbackup.dll" failed. Error Code: 127
2016-01-29 12:25:17: ERROR: Loading urbackup.dll failed
2016-01-29 12:25:17: Looking for old Sessions... 0 sessions
2016-01-29 12:26:37: Loaded -fileserv- plugin
2016-01-29 12:26:37: Loaded -fsimageplugin- plugin
2016-01-29 12:26:37: Loaded -cryptoplugin- plugin
2016-01-29 12:26:37: Loading DLL "urbackup.dll" failed. Error Code: 127
2016-01-29 12:26:37: ERROR: Loading urbackup.dll failed
2016-01-29 12:26:37: Looking for old Sessions... 0 sessions
2016-01-29 12:28:38: Loaded -fileserv- plugin
2016-01-29 12:28:38: Loaded -fsimageplugin- plugin
2016-01-29 12:28:38: Loaded -cryptoplugin- plugin
2016-01-29 12:28:38: Loading DLL "urbackup.dll" failed. Error Code: 127
2016-01-29 12:28:38: ERROR: Loading urbackup.dll failed
2016-01-29 12:28:38: Looking for old Sessions... 0 sessions
2016-01-29 12:30:36: ERROR: GPT formated hard disk encountered. UrBackup does not support GPT formated hard disks! (Volume=\\?\Volume{51535365-151c-497a-8931-2f9c45ab3505})
2016-01-29 12:31:07: Loaded -fileserv- plugin
2016-01-29 12:31:07: Loaded -fsimageplugin- plugin
2016-01-29 12:31:07: Loaded -cryptoplugin- plugin
2016-01-29 12:31:07: Created new database connection for urbackup/backup_client.db
2016-01-29 12:31:07: urbackupserver: Server started up sucessfully!
2016-01-29 12:31:07: FileSrv: Backup privileges set successfully
2016-01-29 12:31:07: FileSrv: Info: retval 0
2016-01-29 12:31:07: FileSrv: Info: retval 0
2016-01-29 12:31:07: FileSrv: Info: Window size=524288
2016-01-29 12:31:07: FileSrv: Binding udp socket at port 35622...
2016-01-29 12:31:07: FileSrv: done.
2016-01-29 12:31:07: FileSrv: Disabling new behavior...
2016-01-29 12:31:07: FileSrv: Servername: -PROFITTECH3-
2016-01-29 12:31:07: Started UrBackupClient Backend...
2016-01-29 12:31:07: FileSrv: Server started up sucessfully
2016-01-29 12:31:07: FileSrv: UDP Thread startet
2016-01-29 12:31:07: Filesystem. Vol="\\?\Volume{1320550f-4fc8-11df-bcf4-806e6f6e6963}\" Name="sysdrive" Type="ntfs" VPaths=1 Size=107372802048
2016-01-29 12:31:07: Filesystem is System partition. Skipping...
2016-01-29 12:31:07: Filesystem. Vol="\\?\Volume{1320550c-4fc8-11df-bcf4-806e6f6e6963}\" Name="datadrv" Type="ntfs" VPaths=1 Size=1142376202240
2016-01-29 12:31:07: Bootable flag not set for volume
2016-01-29 12:31:07: Filesystem. Vol="\\?\Volume{51535365-151c-497a-8931-2f9c45ab3505}\" Name="backupdrv" Type="ntfs" VPaths=1 Size=5999831220224
2016-01-29 12:31:07: ERROR: GPT formated hard disk encountered. UrBackup does not support GPT formated hard disks! (Volume=\\?\Volume{51535365-151c-497a-8931-2f9c45ab3505})
2016-01-29 12:31:07: Bootable flag not set for volume
2016-01-29 12:31:07: Filesystem. Vol="\\?\Volume{13205507-4fc8-11df-bcf4-806e6f6e6963}\" Name="" Type="" VPaths=1 Size=-1
2016-01-29 12:31:07: Bootable flag not set for volume
2016-01-29 12:31:08: Internet only mode not enabled. Waiting for local server for 3:00...
2016-01-29 12:31:08: Looking for old Sessions... 0 sessions
2016-01-29 12:31:08: Created new database connection for urbackup/backup_client.db
2016-01-29 12:31:08: Created new database connection for urbackup/backup_client.db
2016-01-29 12:31:08: Filesystem. Vol="\\?\Volume{13205506-4fc8-11df-bcf4-806e6f6e6963}\" Name="" Type="" VPaths=1 Size=-1
2016-01-29 12:31:08: Error reading partition information for bootable flag (Volume=\\?\Volume{13205506-4fc8-11df-bcf4-806e6f6e6963})
2016-01-29 12:31:08: Bootable flag not set for volume
2016-01-29 12:31:08: Filesystem. Vol="\\?\Volume{3523942c-ad7d-11e0-9fac-001b214e31aa}\" Name="ptc_archive1" Type="ntfs" VPaths=1 Size=2000396288000
2016-01-29 12:31:08: Bootable flag not set for volume
2016-01-29 12:31:08: Filesystem. Vol="\\?\Volume{c4d8c080-4ff1-11df-a6f7-97c6adad7545}\" Name="ptc_archive2" Type="ntfs" VPaths=1 Size=2000396288000
2016-01-29 12:31:08: Bootable flag not set for volume
2016-01-29 12:31:08: Filesystem. Vol="\\?\Volume{4a5a2406-abc9-11e0-9c21-001b214e31aa}\" Name="ptc_archive4" Type="ntfs" VPaths=1 Size=2000396288000
2016-01-29 12:31:08: Bootable flag not set for volume
2016-01-29 12:31:08: Filesystem. Vol="\\?\Volume{2c7994f5-e705-11e1-a7dc-001b214e31aa}\" Name="ptc_archive3" Type="ntfs" VPaths=1 Size=2000396288000
2016-01-29 12:31:08: Bootable flag not set for volume
2016-01-29 12:31:08: Found no SYSVOL on the same physical device as 'C'.
2016-01-29 12:31:10: FileSrv: UDP: PING received... sending PONG. Delay=172ms
2016-01-29 12:31:10: FileSrv: UDP: PING received... sending PONG. Delay=79ms
2016-01-29 12:31:10: urbackupserver: No available slots... starting new Worker
2016-01-29 12:31:10: ClientService cmd: GET LOGPOINTS#pw=lXE1xy0XCBPdKPcbMI7rLpH5eMXk6m
2016-01-29 12:31:10: Created new database connection for urbackup/backup_client.db
2016-01-29 12:31:10: rc=0 hasError=true state=0
2016-01-29 12:31:12: ClientService cmd: GET LOGDATA#pw=lXE1xy0XCBPdKPcbMI7rLpH5eMXk6m&logid=8&loglevel=0
2016-01-29 12:31:12: rc=0 hasError=true state=0
2016-01-29 12:31:16: ClientService cmd: START IMAGE FULL#pw=Q5Iboh5LdjRtVA9wVFYByrtcC2bR4k
2016-01-29 12:31:16: rc=0 hasError=true state=0
2016-01-29 12:31:25: ClientService cmd: START IMAGE FULL#pw=Q5Iboh5LdjRtVA9wVFYByrtcC2bR4k
2016-01-29 12:31:25: rc=0 hasError=true state=0
2016-01-29 12:31:40: ClientService cmd: #InVMtcYEayraSEeDmnA8Q#ADD IDENTITY
2016-01-29 12:31:40: rc=0 hasError=true state=0
2016-01-29 12:31:40: ClientService cmd: #InVMtcYEayraSEeDmnA8Q#GET CHALLENGE
2016-01-29 12:31:40: rc=0 hasError=true state=0
2016-01-29 12:31:40: ClientService cmd: #InVMtcYEayraSEeDmnA8Q#SIGNATURE#pubkey=MIIBtzCCASsGByqGSM44BAEwggEeAoGBAM2hQXsw+lesvHxwsaMTKcqKrDX4mh02jXtlg0xdsWoxqRP+8WbCx8e6YN44cL+Vkc+DRYsVIqMIuOLW6z9v57nz+Akicd6FkzgPviLRHDN1zCsgtyAnWz081SmkQ0tGP4RjPgs+4AbzAe+hd2IvsuuWqb2WtLhIpOKk7hO0iPeHAhUA/FZKOb8RtqjTZ6rxOXc/3htCT20CgYALbIbJHO4Jwi21yP0cKaBxcU46yycw3iIMG2wmv7/+LmI44/CGLo6Uz+MRNR5BVOyPH+BpmX52V9BxMZl/A1EwLRgjJLLqbGD51hNQ1+R7d2E8n8Z91NDzU3jzDdRyYrSCKalMDWgUMndiZFyPQnm1Kvisxydbe7slvr+Zy3D4agOBhQACgYEAq7OEOBF8fizfE3SpkUx/FQEEyRzOH3YdVQnKyRJ216hGzi691ItaSR+ZMKKndH3CiWXzs13Tx9EC9OuTLv4H6YO9rMzPFKr5XwBDFfC1wsFXKFZEAnuw7xCwYuHX4THKoOiLH53rhzveYzgSdn9zp3unC2z1ApCZX+isPEjDM/A-&signature=q9wjCUIMjYs3kZvGf1/1KUJUdzAdkJsGg8XvZ6ttdQNm1IuTAAdHYw--&session_identity=lIujrVoIlEp6fPxPdEPO
2016-01-29 12:31:40: rc=0 hasError=true state=0
2016-01-29 12:31:40: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#CAPA
2016-01-29 12:31:42: Cannot read data from device (E:\)
2016-01-29 12:31:43: Cannot read data from device (A:\)
2016-01-29 12:31:51: Device E:\ isn't NTFS formatted
2016-01-29 12:31:51: Device A:\ isn't NTFS formatted
2016-01-29 12:31:51: Device G:\ is connected via USB
2016-01-29 12:31:51: Device H:\ is connected via USB
2016-01-29 12:31:51: Device J:\ is connected via USB
2016-01-29 12:31:51: Device I:\ is connected via USB
2016-01-29 12:31:51: Client timeout in ClientConnector::Run
2016-01-29 12:31:51: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#CAPA
2016-01-29 12:31:51: Device E:\ isn't NTFS formatted
2016-01-29 12:31:51: Device A:\ isn't NTFS formatted
2016-01-29 12:31:51: Device E:\ isn't NTFS formatted
2016-01-29 12:31:51: Device A:\ isn't NTFS formatted
2016-01-29 12:31:51: Device G:\ is connected via USB
2016-01-29 12:31:51: Device H:\ is connected via USB
2016-01-29 12:31:51: Device J:\ is connected via USB
2016-01-29 12:31:51: Device I:\ is connected via USB
2016-01-29 12:31:51: rc=0 hasError=true state=0
2016-01-29 12:31:52: FileSrv: Info: Window size=524288
2016-01-29 12:31:52: FileSrv: Received data...
2016-01-29 12:31:52: FileSrv: Received a Packet.
2016-01-29 12:31:52: FileSrv: Sending file (normal) urbackup/settings.cfg
2016-01-29 12:31:52: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\settings.cfg
2016-01-29 12:31:52: FileSrv: Reading last file part
2016-01-29 12:31:52: FileSrv: Info: File End
2016-01-29 12:31:52: FileSrv: Closed file.
2016-01-29 12:31:52: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#1CHANNEL capa=0
2016-01-29 12:31:52: New channel: Number of Channels: 1
2016-01-29 12:31:52: FileSrv: Recv Error in RecvMessage
2016-01-29 12:31:52: FileSrv: Deleting Memory...
2016-01-29 12:31:52: FileSrv: done.
2016-01-29 12:31:52: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#SETTINGS update_freq_incr_def=18000
update_freq_full_def=2592000
update_freq_image_full_def=604800
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=7
max_image_incr_def=30
min_image_full_def=2
max_image_full_def=4
startup_backup_delay_def=0
backup_window_incr_file_def=Mon-Thu/18-22;Fri/18-24;Sat/0-24
backup_window_full_file_def=Mon-Thu/18-22;Fri/18-24;Sat/0-24
backup_window_incr_image_def=Mon-Thu/18-22;Fri/18-24;Sat/0-24
backup_window_full_image_def=Mon-Thu/18-22;Fri/18-24;Sat/0-24
exclude_files_def=
include_files_def=
default_dirs_def=
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,D
internet_server_def=
internet_server_port_def=55415
internet_authkey_def=9rzb3SNMEX
internet_speed_def=-1
local_speed_def=-1
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=hashed
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=hashed
file_hash_collect_amount_def=1000
file_hash_collect_timeout_def=10000
file_hash_collect_cachesize_def=40960
end_to_end_file_backup_verification_def=false
internet_calculate_filehashes_on_client_def=true
image_file_format_def=vhd
internet_connect_always_def=false
verify_using_client_hashes_def=false
internet_readd_file_entries_def=true
background_backups_def=true
follow_symlinks_def=true

2016-01-29 12:31:52: rc=0 hasError=true state=0
2016-01-29 12:31:52: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#INCRINTERVALL "18000"
2016-01-29 12:31:52: rc=0 hasError=true state=0
2016-01-29 12:31:52: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#VERSION 101
2016-01-29 12:31:52: rc=0 hasError=true state=0
2016-01-29 12:32:00: FileSrv: UDP: PING received... sending PONG. Delay=165ms
2016-01-29 12:32:00: FileSrv: UDP: PING received... sending PONG. Delay=396ms
2016-01-29 12:32:02: FileSrv: ClientThread deleted. 1024 KB Memory freed.
2016-01-29 12:32:11: ClientService cmd: STATUS#pw=Q5Iboh5LdjRtVA9wVFYByrtcC2bR4k
2016-01-29 12:32:11: rc=0 hasError=true state=0
2016-01-29 12:32:13: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#FULL IMAGE letter=SYSVOL&token=wYgIVUA5SXI6ll8KPZF2&checksum=1
2016-01-29 12:32:13: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#PING RUNNING --#token=wYgIVUA5SXI6ll8KPZF2
2016-01-29 12:32:13: rc=0 hasError=true state=0
2016-01-29 12:32:13: Opening filesystem on device failed. Stopping.
2016-01-29 12:32:13: Device file: ""
2016-01-29 12:32:13: Sending full image done
2016-01-29 12:32:13: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#MBR driveletter=SYSVOL
2016-01-29 12:32:13: rc=0 hasError=true state=0
2016-01-29 12:32:13: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#FULL IMAGE letter=C:&token=wYgIVUA5SXI6ll8KPZF2&checksum=1
2016-01-29 12:32:13: Creating shadowcopy of "C:"...
2016-01-29 12:32:13: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#MBR driveletter=C
2016-01-29 12:32:13: rc=0 hasError=true state=0
2016-01-29 12:32:15: Number of Writers: 12
2016-01-29 12:32:15: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer SqlServerWriter has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer MSDEWriter has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer Event Log Writer has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer IIS Metabase Writer has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer TermServLicensing has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer NTDS has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer WINS Jet Writer has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: Writer FRS Writer has failure state VSS_WS_STABLE with error S_OK.
2016-01-29 12:32:15: ERROR: backupcom->AddToSnapshotSet(volume_path, GUID_NULL, &dir->ref->ssetid) failed: EC=VSS_E_UNEXPECTED_PROVIDER_ERROR
2016-01-29 12:32:15: done.
2016-01-29 12:32:15: ERROR: Creating shadowcopy of "C:" failed.
2016-01-29 12:32:15: ERROR: Creating Shadow drive failed. Stopping.
2016-01-29 12:32:15: Sending full image done
2016-01-29 12:32:15: rc=0 hasError=true state=4
2016-01-29 12:32:15: Deleting Shadowcopy for dir "C:\"
2016-01-29 12:32:16: ClientService cmd: #IlIujrVoIlEp6fPxPdEPO#2LOGDATA 1454088736 0-1454088733-Starting full image backup...
0-1454088733-Request of SYSVOL failed. Reason: Opening filesystem on device failed. Stopping.. This probably just means the Computer does not have a "System restore" volume which UrBackup can backup.
0-1454088733-Transferred 143 bytes - Average speed: 1.144 MBit/s
2-1454088735-Request of image backup failed. Reason: Creating Shadow drive failed. Stopping.
0-1454088735-Transferred 132 bytes - Average speed: 576 Bit/s
0-1454088736-Time taken for creating image of client PROFITTECH3: 3s
2-1454088736-Backup failed
1-1454088736-Exponential backoff: Waiting at least 40m before next image backup

2016-01-29 12:32:16: rc=0 hasError=true state=0

#6

Also, I only have the server configured to backup C and D volumes. The others are external drives, so they are excluded.


#7

Ok, so you should probably google for VSS_E_UNEXPECTED_PROVIDER_ERROR. Other backup software vendors have instructions for how to fix this :wink:


#8

Ahhh… This makes sense. I just disabled ShadowProtect since the BDR hardware had failed. Following the steps on https://www.veeam.com/kb1785 showed me that the VSS writer was still there. I was not seeing that by just running vssadmin list writers. It’s a provider thing!

Now it’s working fine. Thank you for the help!


#9

I Just fixed this problem.
just right click to the Drive that you want to fix, click on “configure shadow copies”, in the next windows select the letter that you want to fix them click on setting button finally mark “no limit” and ok.

If you need more details send me an email.
I hope you enjoy this solution.