Full backups fail. Inc and Diff work OK.


Author
Message
MikePA24
MikePA24
New Member
New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)
Group: Forum Members
Posts: 20, Visits: 32
I have a long-standing and very irritating problem. 

When I take a FULL backup of the disk on my HP Laptop (saving the image across a network share to a desktop machine) the image is 99.9% complete but then the backup job fails. The failure comes right at the very end (either of the imaging itself, or of the auto-verification, if that is requested). 

So there lies the IRRITATION. In order to verify the image, it has already been saved to disk (I can see it as a 250GB file on the network share as the verification takes place, having been renamed from the .tmp version). 

It appears that, as Macrium Reflect is trying to "shut down" the completed backup (which has actually worked FINE!), something goes wrong as it tries to shut down VSS, such that the backup becomes (incorrectly) considered as FAILED. And Macrium Reflect proceeds to DELETE the (perfectly good) FULL image file, and sends me a failure notification email. 

This was SO irritating I just yesterday upgraded from version 6.x to version 7.2 (home edition 64-bit) at a cost of $70, hoping this would be cured in the newer version, But . . . the same problem occurs.

Occasionally, the FULL backup works (but most times it fails). Once I have a full backup, incremental and differential backups work just fine. 

My theory is that this is something to do with the time elapsed. The DIFF & INC are relatively quick to run (15 minutes to an hour). Whereas the full backup takes 7-8 hours (or more) to complete. Something about that long time-span seems to make the eventual VSS shutdown calls fail and trigger Reflect to consider the entire backup as failed. 

I can't stress enough, the failure comes always at the end of those 7-8 hours. That is what makes this such an irritating behavior. It takes so long every time to test any theories or workarounds. And reducing the size of the FULL backup (for testing purposes) would not yield a valid test, given the theory that time (or size) is the difference between success and failure. 

If someone can get this solved for me I would be very grateful. 

"Conceptually" if Reflect just ignored the shutdown VSS errors . . . . all would be well, and the full backup would be completed. I'll just reiterate, the FULL backup is visible as a 250GB file on the target folder during verification (if requested). When the ""failure"" occurs, Reflect, of course,  proceeds to delete it. 

Thanks,

Mike

Here is the pertinent bit of the log (I've obfuscated my email)

Volume Snapshots Created
Analyzing file system on volume
Analyzing file system on volume C:


--------------------------------------------------------------------------------
Saving Partition - SYSTEM
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - (CSmile
Reading File System Bitmap
Saving Partition
Gathering Windows Events - Please Wait


--------------------------------------------------------------------------------
Email Notifications
Recipients: &&&&
Email notification sent


--------------------------------------------------------------------------------
I/O Performance: Read 106.2 Mb/s - Write 87.8 Mb/s


--------------------------------------------------------------------------------
Backup aborted! - Unable to read from disk - Error Code 21 - The device is not ready. .

And here is complete VSS log.

(Gathering writer metadata...)
(Waiting for the asynchronous operation to finish...)
Initialize writer metadata ...
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
Discover directly excluded components ...
- Excluding writer '' since it has no selected components for restore.
- Excluding writer '' since it has no selected components for restore.
- Excluding writer 'Shadow Copy Optimization Writer' since it has no selected components for restore.
- Excluding writer 'BITS Writer' since it has no selected components for restore.
- Excluding writer 'MSSearch Service Writer' since it has no selected components for restore.
Discover components that reside outside the shadow set ...
Discover all excluded components ...
Discover excluded writers ...
Discover explicitly included components ...
Verifying explicitly specified writers/components ...
Select explicitly included components ...
* Writer 'Task Scheduler Writer':
 - Add component \TasksStore
* Writer 'VSS Metadata Store Writer':
 - Add component \WriterMetadataStore
* Writer 'Performance Counters Writer':
 - Add component \PerformanceCounters
* Writer 'Registry Writer':
 - Add component \Registry
* Writer 'COM+ REGDB Writer':
 - Add component \COM+ REGDB
* Writer 'WMI Writer':
 - Add component \WMI
Creating shadow set {42101dea-bec0-48af-a0da-e5eb67147a01} ...
- Adding volume \\?\Volume{10b5181d-9400-11e1-9a76-806e6f6e6963}\ [C:\] to the shadow set...
Preparing for backup ...
(Waiting for the asynchronous operation to finish...)
(Waiting for the asynchronous operation to finish...)
Creating the shadow (DoSnapshotSet) ...
(Waiting for the asynchronous operation to finish...)
(Waiting for the asynchronous operation to finish...)
Shadow copy set successfully created.
Saving the backup components document ...

List of created shadow copies:


Querying all shadow copies with the SnapshotSetID {42101dea-bec0-48af-a0da-e5eb67147a01} ...
* SNAPSHOT ID = {3301c5f4-8959-4fc9-a5ed-d4417e1cdb58} ...
 - Shadow copy Set: {42101dea-bec0-48af-a0da-e5eb67147a01}
 - Original count of shadow copies = 1
 - Original Volume name: \\?\Volume{10b5181d-9400-11e1-9a76-806e6f6e6963}\ [C:\]
 - Creation Time: 11/8/2018 4:58:53 PM
 - Shadow copy device name: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14
 - Originating machine: PAVILIONG7
 - Service machine: PAVILIONG7
 - Not Exposed
 - Provider id: {b5946137-7b9f-4925-af80-51abd60b20d5}
 - Attributes: Auto_Release Differential

Windows Events
*****************************
Date:  11/9/2018 2:57:10 AM
Type:  Error
Event:  12291
Source:  VSS
Volume Shadow Copy Service error: Error on creating/using the COM+ Writers publisher interface: BackupShutdown [0x80042302, A Volume Shadow Copy Service component encountered an unexpected error.
Check the Application event log for more information.
].

*****************************
Date:  11/9/2018 2:57:10 AM
Type:  Error
Event:  8193
Source:  VSS
Volume Shadow Copy Service error: Unexpected error calling routine IMultiInterfaceEventControl::GetSubscriptions. hr = 0x80010108, The object invoked has disconnected from its clients.
.

*****************************
Date:  11/8/2018 4:58:47 PM
Type:  Warning
Event:  12348
Source:  VSS
Volume Shadow Copy Service warning: VSS was denied access to the root of volume \\?\Volume{3d9c07e1-93cd-11e1-9adf-80c16e4b86d2}\. Denying administrators from accessing volume roots can cause many unexpected failures, and will prevent VSS from functioning properly. Check security on the volume, and try the operation again.

Operation:
 Removing auto-release shadow copies
 Loading provider
Context:
 Execution Context: System Provider  

Edited 9 November 2018 1:53 PM by MikePA24
MikePA24
MikePA24
New Member
New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)
Group: Forum Members
Posts: 20, Visits: 32
p.s. The backup in question was started at 4:58PM yesterday afternoon. And eventually failed about 10 hours later.

In this case I had NOT requested auto-verify, so the failure occurs directly after the image is completed. 
MikePA24
MikePA24
New Member
New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)
Group: Forum Members
Posts: 20, Visits: 32
p.p.s. I did try using a little program to repeatedly write a file to the target share folder (for the image file) on the desktop machine every 10 minutes, just in case something there was going to sleep. But this has not made any difference at all.
MikePA24
MikePA24
New Member
New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)
Group: Forum Members
Posts: 20, Visits: 32
By way of comparison, here are the run log and VSS log from a successful Incremental backup (again, some email details and folder names obfuscated).

Destination:
Backup Type: Incremental
File Name: Append to recent image in directory '\\Desktopsk\macrium images\'
Attempting to connect to: '\\Desktopsk\macrium images'
Successfully connected
\\Desktopsk\macrium images\1CA63C28841414DE-09-09.mrimg


--------------------------------------------------------------------------------
Operation 1 of 2
Hard Disk: 1
Drive Letter: N/A
File System: NTFS
Label: SYSTEM
Size: 199.0 MB
Free: 125.8 MB
Used: 73.2 MB


--------------------------------------------------------------------------------
Operation 2 of 2
Hard Disk: 1
Drive Letter: C
File System: NTFS
Label:
Size: 465.57 GB
Free: 100.70 GB
Used: 364.86 GB


--------------------------------------------------------------------------------
Starting Image - Thursday, November 08, 2018 10:05:58
Initializing
Destination Drive: Free Space 793.75 GB
Free space threshold: Delete oldest backup sets when free space is less than 500.00 GB

Creating Volume Snapshot - Please Wait
Volume Snapshots Created
Analyzing file system on volume
Analyzing file system on volume C:


--------------------------------------------------------------------------------
Saving Partition - SYSTEM
Reading File System Bitmap
Looking for changes
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - (CSmile
Reading File System Bitmap
Looking for changes
Saving Partition


--------------------------------------------------------------------------------
Saving Index
New File: 225 MB 1CA63C28841414DE-09-09.mrimg
Verifying '1CA63C28841414DE-09-09.mrimg'
Ok. Continuing...


--------------------------------------------------------------------------------
Email Notifications
Recipients: &&&
Email notification sent


--------------------------------------------------------------------------------
I/O Performance: Read 165.1 Mb/s - Write 85.8 Mb/s


--------------------------------------------------------------------------------
Image and Verification Completed Successfully in 00:09:07

VSS Log

(Gathering writer metadata...)
(Waiting for the asynchronous operation to finish...)
Initialize writer metadata ...
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
Discover directly excluded components ...
- Excluding writer '' since it has no selected components for restore.
- Excluding writer '' since it has no selected components for restore.
- Excluding writer 'Shadow Copy Optimization Writer' since it has no selected components for restore.
- Excluding writer 'MSSearch Service Writer' since it has no selected components for restore.
- Excluding writer 'BITS Writer' since it has no selected components for restore.
Discover components that reside outside the shadow set ...
Discover all excluded components ...
Discover excluded writers ...
Discover explicitly included components ...
Verifying explicitly specified writers/components ...
Select explicitly included components ...
* Writer 'Task Scheduler Writer':
 - Add component \TasksStore
* Writer 'VSS Metadata Store Writer':
 - Add component \WriterMetadataStore
* Writer 'Performance Counters Writer':
 - Add component \PerformanceCounters
* Writer 'Registry Writer':
 - Add component \Registry
* Writer 'COM+ REGDB Writer':
 - Add component \COM+ REGDB
* Writer 'WMI Writer':
 - Add component \WMI
Creating shadow set {83716749-b9ec-4037-b8fe-68147b1f15af} ...
- Adding volume \\?\Volume{10b5181d-9400-11e1-9a76-806e6f6e6963}\ [C:\] to the shadow set...
Preparing for backup ...
(Waiting for the asynchronous operation to finish...)
(Waiting for the asynchronous operation to finish...)
Creating the shadow (DoSnapshotSet) ...
(Waiting for the asynchronous operation to finish...)
(Waiting for the asynchronous operation to finish...)
Shadow copy set successfully created.
Saving the backup components document ...

List of created shadow copies:


Querying all shadow copies with the SnapshotSetID {83716749-b9ec-4037-b8fe-68147b1f15af} ...
* SNAPSHOT ID = {10461c21-ec9d-4fbc-9c08-69ca373220b9} ...
 - Shadow copy Set: {83716749-b9ec-4037-b8fe-68147b1f15af}
 - Original count of shadow copies = 1
 - Original Volume name: \\?\Volume{10b5181d-9400-11e1-9a76-806e6f6e6963}\ [C:\]
 - Creation Time: 11/8/2018 10:06:07 AM
 - Shadow copy device name: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy12
 - Originating machine: PAVILIONG7
 - Service machine: PAVILIONG7
 - Not Exposed
 - Provider id: {b5946137-7b9f-4925-af80-51abd60b20d5}
 - Attributes: Auto_Release Differential

Edited 9 November 2018 2:09 PM by MikePA24
jphughan
jphughan
Macrium Evangelist
Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)
Group: Forum Members
Posts: 3.8K, Visits: 28K
The VSS snapshot occurs before Reflect starts backing up any data, so it doesn't really matter how long the backup job takes after that point.  The only possible risk is there is that if so much data on your disk changes that the storage required to maintain the snapshot exceeds the storage allocated to VSS, Windows would delete the snapshot that Reflect was using to perform the backup, but in that case the backup would fail with an error that the snapshot was deleted.  IF there was some other problem with VSS, you would have seen a failure or at least a warning (depending on the issue) at the very beginning of the job, not a hang at the end.  Any chance you have third-party anti-virus installed?  If so, can you try running a Full with it disabled?  I'm wondering if anti-virus might be trying to do something with that Full file after it's created and is taking a lot longer to do whatever it's doing on a large Full than a much smaller Diff/Inc, hence the issue.

Nick
Nick
Macrium Representative
Macrium Representative (2.9K reputation)Macrium Representative (2.9K reputation)Macrium Representative (2.9K reputation)Macrium Representative (2.9K reputation)Macrium Representative (2.9K reputation)Macrium Representative (2.9K reputation)Macrium Representative (2.9K reputation)Macrium Representative (2.9K reputation)Macrium Representative (2.9K reputation)
Group: Administrators
Posts: 1.7K, Visits: 9.1K
MikePA24 - 9 November 2018 12:45 PM
I have a long-standing and very irritating problem. 

When I take a FULL backup of the disk on my HP Laptop (saving the image across a network share to a desktop machine) the image is 99.9% complete but then the backup job fails. The failure comes right at the very end (either of the imaging itself, or of the auto-verification, if that is requested). 

So there lies the IRRITATION. In order to verify the image, it has already been saved to disk (I can see it as a 250GB file on the network share as the verification takes place, having been renamed from the .tmp version). 

It appears that, as Macrium Reflect is trying to "shut down" the completed backup (which has actually worked FINE!), something goes wrong as it tries to shut down VSS, such that the backup becomes (incorrectly) considered as FAILED. And Macrium Reflect proceeds to DELETE the (perfectly good) FULL image file, and sends me a failure notification email. 

This was SO irritating I just yesterday upgraded from version 6.x to version 7.2 (home edition 64-bit) at a cost of $70, hoping this would be cured in the newer version, But . . . the same problem occurs.

Occasionally, the FULL backup works (but most times it fails). Once I have a full backup, incremental and differential backups work just fine. 

My theory is that this is something to do with the time elapsed. The DIFF & INC are relatively quick to run (15 minutes to an hour). Whereas the full backup takes 7-8 hours (or more) to complete. Something about that long time-span seems to make the eventual VSS shutdown calls fail and trigger Reflect to consider the entire backup as failed. 

I can't stress enough, the failure comes always at the end of those 7-8 hours. That is what makes this such an irritating behavior. It takes so long every time to test any theories or workarounds. And reducing the size of the FULL backup (for testing purposes) would not yield a valid test, given the theory that time (or size) is the difference between success and failure. 

If someone can get this solved for me I would be very grateful. 

"Conceptually" if Reflect just ignored the shutdown VSS errors . . . . all would be well, and the full backup would be completed. I'll just reiterate, the FULL backup is visible as a 250GB file on the target folder during verification (if requested). When the ""failure"" occurs, Reflect, of course,  proceeds to delete it. 

Thanks,

Mike

Here is the pertinent bit of the log (I've obfuscated my email)

Volume Snapshots Created
Analyzing file system on volume
Analyzing file system on volume C:


--------------------------------------------------------------------------------
Saving Partition - SYSTEM
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - (CSmile
Reading File System Bitmap
Saving Partition
Gathering Windows Events - Please Wait


--------------------------------------------------------------------------------
Email Notifications
Recipients: &&&&
Email notification sent


--------------------------------------------------------------------------------
I/O Performance: Read 106.2 Mb/s - Write 87.8 Mb/s


--------------------------------------------------------------------------------
Backup aborted! - Unable to read from disk - Error Code 21 - The device is not ready. .

And here is complete VSS log.

(Gathering writer metadata...)
(Waiting for the asynchronous operation to finish...)
Initialize writer metadata ...
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
Discover directly excluded components ...
- Excluding writer '' since it has no selected components for restore.
- Excluding writer '' since it has no selected components for restore.
- Excluding writer 'Shadow Copy Optimization Writer' since it has no selected components for restore.
- Excluding writer 'BITS Writer' since it has no selected components for restore.
- Excluding writer 'MSSearch Service Writer' since it has no selected components for restore.
Discover components that reside outside the shadow set ...
Discover all excluded components ...
Discover excluded writers ...
Discover explicitly included components ...
Verifying explicitly specified writers/components ...
Select explicitly included components ...
* Writer 'Task Scheduler Writer':
 - Add component \TasksStore
* Writer 'VSS Metadata Store Writer':
 - Add component \WriterMetadataStore
* Writer 'Performance Counters Writer':
 - Add component \PerformanceCounters
* Writer 'Registry Writer':
 - Add component \Registry
* Writer 'COM+ REGDB Writer':
 - Add component \COM+ REGDB
* Writer 'WMI Writer':
 - Add component \WMI
Creating shadow set {42101dea-bec0-48af-a0da-e5eb67147a01} ...
- Adding volume \\?\Volume{10b5181d-9400-11e1-9a76-806e6f6e6963}\ [C:\] to the shadow set...
Preparing for backup ...
(Waiting for the asynchronous operation to finish...)
(Waiting for the asynchronous operation to finish...)
Creating the shadow (DoSnapshotSet) ...
(Waiting for the asynchronous operation to finish...)
(Waiting for the asynchronous operation to finish...)
Shadow copy set successfully created.
Saving the backup components document ...

List of created shadow copies:


Querying all shadow copies with the SnapshotSetID {42101dea-bec0-48af-a0da-e5eb67147a01} ...
* SNAPSHOT ID = {3301c5f4-8959-4fc9-a5ed-d4417e1cdb58} ...
 - Shadow copy Set: {42101dea-bec0-48af-a0da-e5eb67147a01}
 - Original count of shadow copies = 1
 - Original Volume name: \\?\Volume{10b5181d-9400-11e1-9a76-806e6f6e6963}\ [C:\]
 - Creation Time: 11/8/2018 4:58:53 PM
 - Shadow copy device name: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14
 - Originating machine: PAVILIONG7
 - Service machine: PAVILIONG7
 - Not Exposed
 - Provider id: {b5946137-7b9f-4925-af80-51abd60b20d5}
 - Attributes: Auto_Release Differential

Windows Events
*****************************
Date:  11/9/2018 2:57:10 AM
Type:  Error
Event:  12291
Source:  VSS
Volume Shadow Copy Service error: Error on creating/using the COM+ Writers publisher interface: BackupShutdown [0x80042302, A Volume Shadow Copy Service component encountered an unexpected error.
Check the Application event log for more information.
].

*****************************
Date:  11/9/2018 2:57:10 AM
Type:  Error
Event:  8193
Source:  VSS
Volume Shadow Copy Service error: Unexpected error calling routine IMultiInterfaceEventControl::GetSubscriptions. hr = 0x80010108, The object invoked has disconnected from its clients.
.

*****************************
Date:  11/8/2018 4:58:47 PM
Type:  Warning
Event:  12348
Source:  VSS
Volume Shadow Copy Service warning: VSS was denied access to the root of volume \\?\Volume{3d9c07e1-93cd-11e1-9adf-80c16e4b86d2}\. Denying administrators from accessing volume roots can cause many unexpected failures, and will prevent VSS from functioning properly. Check security on the volume, and try the operation again.

Operation:
 Removing auto-release shadow copies
 Loading provider
Context:
 Execution Context: System Provider  

Thanks for posting.

The error is a Read error from drive C:.  Windows has temporarily taken the disk offline during the read operation. It's possibly a bad sector though that will normally be reported as a CRC error by the controller.  The reason why an Inc or Diff isn't failing is because it isn't reading that part of the disk. 

It's also worth noting that the read performance is very low at 106.2 Mb/s

Try running 'chkdsk c: /r from an elevated command prompt and allowing the chkdsk to complete on reboot.

Kind Regards

Nick - Macrium Support

MikePA24
MikePA24
New Member
New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)
Group: Forum Members
Posts: 20, Visits: 32
Nick - 9 November 2018 3:42 PM
MikePA24 - 9 November 2018 12:45 PM
I have a long-standing and very irritating problem. 

When I take a FULL backup of the disk on my HP Laptop (saving the image across a network share to a desktop machine) the image is 99.9% complete but then the backup job fails. The failure comes right at the very end (either of the imaging itself, or of the auto-verification, if that is requested). 

So there lies the IRRITATION. In order to verify the image, it has already been saved to disk (I can see it as a 250GB file on the network share as the verification takes place, having been renamed from the .tmp version). 

It appears that, as Macrium Reflect is trying to "shut down" the completed backup (which has actually worked FINE!), something goes wrong as it tries to shut down VSS, such that the backup becomes (incorrectly) considered as FAILED. And Macrium Reflect proceeds to DELETE the (perfectly good) FULL image file, and sends me a failure notification email. 

This was SO irritating I just yesterday upgraded from version 6.x to version 7.2 (home edition 64-bit) at a cost of $70, hoping this would be cured in the newer version, But . . . the same problem occurs.

Occasionally, the FULL backup works (but most times it fails). Once I have a full backup, incremental and differential backups work just fine. 

My theory is that this is something to do with the time elapsed. The DIFF & INC are relatively quick to run (15 minutes to an hour). Whereas the full backup takes 7-8 hours (or more) to complete. Something about that long time-span seems to make the eventual VSS shutdown calls fail and trigger Reflect to consider the entire backup as failed. 

I can't stress enough, the failure comes always at the end of those 7-8 hours. That is what makes this such an irritating behavior. It takes so long every time to test any theories or workarounds. And reducing the size of the FULL backup (for testing purposes) would not yield a valid test, given the theory that time (or size) is the difference between success and failure. 

If someone can get this solved for me I would be very grateful. 

"Conceptually" if Reflect just ignored the shutdown VSS errors . . . . all would be well, and the full backup would be completed. I'll just reiterate, the FULL backup is visible as a 250GB file on the target folder during verification (if requested). When the ""failure"" occurs, Reflect, of course,  proceeds to delete it. 

Thanks,

Mike

Here is the pertinent bit of the log (I've obfuscated my email)

Volume Snapshots Created
Analyzing file system on volume
Analyzing file system on volume C:


--------------------------------------------------------------------------------
Saving Partition - SYSTEM
Reading File System Bitmap
Saving Partition


--------------------------------------------------------------------------------
Saving Partition - (CSmile
Reading File System Bitmap
Saving Partition
Gathering Windows Events - Please Wait


--------------------------------------------------------------------------------
Email Notifications
Recipients: &&&&
Email notification sent


--------------------------------------------------------------------------------
I/O Performance: Read 106.2 Mb/s - Write 87.8 Mb/s


--------------------------------------------------------------------------------
Backup aborted! - Unable to read from disk - Error Code 21 - The device is not ready. .

And here is complete VSS log.

(Gathering writer metadata...)
(Waiting for the asynchronous operation to finish...)
Initialize writer metadata ...
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get exclude files
- Enumerate components
- Get file list descriptors
- Get database descriptors
- Get log descriptors
Discover directly excluded components ...
- Excluding writer '' since it has no selected components for restore.
- Excluding writer '' since it has no selected components for restore.
- Excluding writer 'Shadow Copy Optimization Writer' since it has no selected components for restore.
- Excluding writer 'BITS Writer' since it has no selected components for restore.
- Excluding writer 'MSSearch Service Writer' since it has no selected components for restore.
Discover components that reside outside the shadow set ...
Discover all excluded components ...
Discover excluded writers ...
Discover explicitly included components ...
Verifying explicitly specified writers/components ...
Select explicitly included components ...
* Writer 'Task Scheduler Writer':
 - Add component \TasksStore
* Writer 'VSS Metadata Store Writer':
 - Add component \WriterMetadataStore
* Writer 'Performance Counters Writer':
 - Add component \PerformanceCounters
* Writer 'Registry Writer':
 - Add component \Registry
* Writer 'COM+ REGDB Writer':
 - Add component \COM+ REGDB
* Writer 'WMI Writer':
 - Add component \WMI
Creating shadow set {42101dea-bec0-48af-a0da-e5eb67147a01} ...
- Adding volume \\?\Volume{10b5181d-9400-11e1-9a76-806e6f6e6963}\ [C:\] to the shadow set...
Preparing for backup ...
(Waiting for the asynchronous operation to finish...)
(Waiting for the asynchronous operation to finish...)
Creating the shadow (DoSnapshotSet) ...
(Waiting for the asynchronous operation to finish...)
(Waiting for the asynchronous operation to finish...)
Shadow copy set successfully created.
Saving the backup components document ...

List of created shadow copies:


Querying all shadow copies with the SnapshotSetID {42101dea-bec0-48af-a0da-e5eb67147a01} ...
* SNAPSHOT ID = {3301c5f4-8959-4fc9-a5ed-d4417e1cdb58} ...
 - Shadow copy Set: {42101dea-bec0-48af-a0da-e5eb67147a01}
 - Original count of shadow copies = 1
 - Original Volume name: \\?\Volume{10b5181d-9400-11e1-9a76-806e6f6e6963}\ [C:\]
 - Creation Time: 11/8/2018 4:58:53 PM
 - Shadow copy device name: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy14
 - Originating machine: PAVILIONG7
 - Service machine: PAVILIONG7
 - Not Exposed
 - Provider id: {b5946137-7b9f-4925-af80-51abd60b20d5}
 - Attributes: Auto_Release Differential

Windows Events
*****************************
Date:  11/9/2018 2:57:10 AM
Type:  Error
Event:  12291
Source:  VSS
Volume Shadow Copy Service error: Error on creating/using the COM+ Writers publisher interface: BackupShutdown [0x80042302, A Volume Shadow Copy Service component encountered an unexpected error.
Check the Application event log for more information.
].

*****************************
Date:  11/9/2018 2:57:10 AM
Type:  Error
Event:  8193
Source:  VSS
Volume Shadow Copy Service error: Unexpected error calling routine IMultiInterfaceEventControl::GetSubscriptions. hr = 0x80010108, The object invoked has disconnected from its clients.
.

*****************************
Date:  11/8/2018 4:58:47 PM
Type:  Warning
Event:  12348
Source:  VSS
Volume Shadow Copy Service warning: VSS was denied access to the root of volume \\?\Volume{3d9c07e1-93cd-11e1-9adf-80c16e4b86d2}\. Denying administrators from accessing volume roots can cause many unexpected failures, and will prevent VSS from functioning properly. Check security on the volume, and try the operation again.

Operation:
 Removing auto-release shadow copies
 Loading provider
Context:
 Execution Context: System Provider  

Thanks for posting.

The error is a Read error from drive C:.  Windows has temporarily taken the disk offline during the read operation. It's possibly a bad sector though that will normally be reported as a CRC error by the controller.  The reason why an Inc or Diff isn't failing is because it isn't reading that part of the disk. 

It's also worth noting that the read performance is very low at 106.2 Mb/s

Try running 'chkdsk c: /r from an elevated command prompt and allowing the chkdsk to complete on reboot.

I will try that and report back. Thank you.

But just in clarification, does that tie in with the observation I made that the image file is saved (and, from the size, is a complete image) and then the lengthy verification process gone through BEFORE the job terminates in error?

I also wonder whether I should try my little "keepalive" program on the laptop C drive. It is noteworthy that the only time I have had success with FULL backups (not always, but sometimes) is when I haave run them manually during the day when I am using the laptop, versus when scheduled (as normal) in the overnight. 

This is an older laptop, and it is possible the drive is ailing, although no other unusual errors or blue screens. 

As I mentioned, unfortunately, it will take a while to test any hypothesis as it is about a 12-hour stint for each try, and it still might fail after 11 hours 59 minutes.

Thanks for the reply. Will be in touch.
MikePA24
MikePA24
New Member
New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)
Group: Forum Members
Posts: 20, Visits: 32
jphughan - 9 November 2018 3:30 PM
The VSS snapshot occurs before Reflect starts backing up any data, so it doesn't really matter how long the backup job takes after that point.  The only possible risk is there is that if so much data on your disk changes that the storage required to maintain the snapshot exceeds the storage allocated to VSS, Windows would delete the snapshot that Reflect was using to perform the backup, but in that case the backup would fail with an error that the snapshot was deleted.  IF there was some other problem with VSS, you would have seen a failure or at least a warning (depending on the issue) at the very beginning of the job, not a hang at the end.  Any chance you have third-party anti-virus installed?  If so, can you try running a Full with it disabled?  I'm wondering if anti-virus might be trying to do something with that Full file after it's created and is taking a lot longer to do whatever it's doing on a large Full than a much smaller Diff/Inc, hence the issue.

That's a good idea. There is Av on both the laptop being imaged and on the image file target machine. I will go back and check, but I believe I excluded the directory from av on the desktop. 

Incidentally you did  see in the VSS log a WARNING at the outset, and then two ERRORS when the job failed, 10 hours later? And that the WARNING did not exist in the VSS log for the successful incremental. 

I will try some things along the lines suggested and report back.

Thank you.
jphughan
jphughan
Macrium Evangelist
Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)Macrium Evangelist (5.6K reputation)
Group: Forum Members
Posts: 3.8K, Visits: 28K
MikePA24 - 9 November 2018 3:59 PM
Incidentally you did  see in the VSS log a WARNING at the outset, and then two ERRORS when the job failed, 10 hours later? And that the WARNING did not exist in the VSS log for the successful incremental. 

Thank you.

I did, and the fact that it mentions denied access reinforced my suspicion that anti-virus may be interfering somehow.  Reflect only ever creates temporary VSS snapshots (as opposed to permanent snapshots meant to enable features like System Restore), so it would delete that snapshot when the backup is complete, and perhaps that's responsible for the error at that point.  But since Nick from Macrium has weighed in, I'd follow his suggestions first.

MikePA24
MikePA24
New Member
New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)New Member (28 reputation)
Group: Forum Members
Posts: 20, Visits: 32
I may owe all who responded an apology.

Yesterday, after my post, I did two things. (1) I ran a chkdsk c: /r for a few hours (it did not complete Stage 5, as I needed to work on the laptop and it still had hours to run); and (2) decided to look at windows events more closely around the time of the backup failure at 02:57:10AM.

Now, I did say this was a long-standing problem (FULL backups failing). This also means I have made any number of tweaks and attempts to troubleshoot and get the thing solved.

Originally, all my backups were running at 3AM, but they were all failing with a similar error. So I put together a little bat file, which I ran as a Scheduled Task at 02:57:00AM.

This is the bat content:

cd /d %windir%\system32
net stop vss
net stop swprv
regsvr32 /s ole32.dll
regsvr32 /s oleaut32.dll
regsvr32 /s vss_ps.dll
vssvc /register
regsvr32 /s /i swprv.dll
regsvr32 /s /i eventcls.dll
regsvr32 /s es.dll
regsvr32 /s stdprov.dll
regsvr32 /s vssui.dll
regsvr32 /s msxml.dll
regsvr32 /s msxml3.dll
regsvr32 /s msxml4.dll
vssvc /register
net start swprv
net start vss
ping www.google.com

I have changed the scheduling since then such that the FULL starts at 6PM once a month, and the DIFF and INC at 8PM weekly, and daily respectively. But I forgot about the scheduled task!!! So the FULL backup, in this instance, was killed off via this bat file which I created and scheduled! This only became clear when I selected a 30-second sample of Windows events and saw the bat file being run 10 seconds before the backup failed.

THE DIFF & INC, of course, were never affected as they complete at around 9PM the previous evening. .
 
Now, I think the original problem may have been related to the actions of the AV on the target machine, and putting in an exclusion for the backup’s target folder seems to have cured that.

All in all (while it’s possible the CHKDSK cured it, or that this time I just “got lucky”) I may well have run a false flag of distress up the pole, and sorry for that.if so. 

I can’t say for sure until the regularly scheduled FULL, DIFF, INCs have run, on their schedules for a few weeks without incident. I may initiate a manual few FULL backups to see that they are consistently running to successful completion now.

If the problem resurfaces, I will post an update. I just wanted to add this very pertinent info to the thread in the meantime.

Your point about slow disk read is well taken, although the network transfer speed might be the limiting factor there(?) Is it simply throttling its input read based on constraints of the network output (?) 



VSS LOG is now ultra clean.

- Not Exposed
 - Provider id: {b5946137-7b9f-4925-af80-51abd60b20d5}
 - Attributes: Auto_Release Differential

Thank you. 
Mike

GO

Merge Selected

Merge into selected topic...



Merge into merge target...



Merge into a specific topic ID...




Similar Topics

Reading This Topic

Login

Explore
Messages
Mentions
Search