ATI 2019 incremental backup consistantly fails to Seagate 8Tb Backup Plus Hub
Creating the initial full back succeeds but subsequent incremental backups fail. ATI claims previous backup not found. The previous backup file is there at the same location where it was created.
If I switch to only doing full backups they succeed but if I try to mount or verify a tib file it often fails with an error indicating it fails to open the file.


- Log in to post comments

The external USB drive is always the same drive letter. Below is the log file from an attempt to do an incremental backup. It appears that it does this about every 10 minutes and it always fails.
6/20/2019 23:40:35: -04:00 17740 I00000000: -----
6/20/2019 23:40:35: -04:00 17740 I00000000: ATI Demon started. Version: 23.5.1.17750.
6/20/2019 23:40:35: -04:00 17740 I00640000: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
6/20/2019 23:40:35: -04:00 17740 I00640002: Operation ARUBA started by schedule.
6/20/2019 23:40:37: -04:00 17740 I00640000: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
6/20/2019 23:40:37: -04:00 17740 I013C0000: Operation: Backup
6/20/2019 23:40:37: -04:00 17740 I0064000B: Priority changed to Low.
6/20/2019 23:40:38: -04:00 17740 I00010400: Child process has exited with code '0'.
6/20/2019 23:40:38: -04:00 17740 I00640086: Execution of user command succeeded: C:/Users/Tom Demler/Documents/StartBackup.cmd
6/20/2019 23:40:38: -04:00 17740 E00040012: Error 0x40012: This is not the last volume of the backup archive.
| trace level: error
| line: 0x2ec441f255ed3661
| file: c:\bs_hudson\workspace\790\core\backup\archive_struct_helper.cpp:319
| function: backupmedia::CheckLastVolume
| line: 0x2ec441f255ed3661, c:\bs_hudson\workspace\790\core\backup\archive_struct_helper.cpp:319, backupmedia::CheckLastVolume
| $module: ti_demon_vs_17750
6/21/2019 09:15:13: -04:00 17740 E000B03E9: Error 0xb03e9: Cannot open the backup.
| trace level: error
| line: 0x65e40aa0b486f44
| file: c:\bs_hudson\workspace\790\products\imager\archive\impl\operations\archive_operation_backup.cpp:179
| function: TrueImage::Archive::BackupArchiveOperationImpl::DoPrepare
| line: 0x65e40aa0b486f44, c:\bs_hudson\workspace\790\products\imager\archive\impl\operations\archive_operation_backup.cpp:179, TrueImage::Archive::BackupArchiveOperationImpl::DoPrepare
| $module: ti_demon_vs_17750
|
| error 0x4000f: Canceled.
| line: 0x1d8eab676a3f690f
| file: c:\bs_hudson\workspace\790\products\imager\archive\impl\operations\archive_message_callback.cpp:742
| function: TrueImage::Archive::ArchiveMsgReadCallbackProcessor::ProcessOpenError
| line: 0x1d8eab676a3f690f, c:\bs_hudson\workspace\790\products\imager\archive\impl\operations\archive_message_callback.cpp:742, TrueImage::Archive::ArchiveMsgReadCallbackProcessor::ProcessOpenError
| $module: ti_demon_vs_17750
|
| error 0x40012: This is not the last volume of the backup archive.
| line: 0x2ec441f255ed3661
| file: c:\bs_hudson\workspace\790\core\backup\archive_struct_helper.cpp:319
| function: backupmedia::CheckLastVolume
| line: 0x2ec441f255ed3661, c:\bs_hudson\workspace\790\core\backup\archive_struct_helper.cpp:319, backupmedia::CheckLastVolume
| $module: ti_demon_vs_17750
6/21/2019 09:15:13: -04:00 17740 E013C0005: Error 0x13c0005: Operation has completed with errors.
| trace level: error
| line: 0x9f2c53c72e8bcec0
| file: c:\bs_hudson\workspace\790\products\imager\demon\main.cpp:714
| function: main
| line: 0x9f2c53c72e8bcec0, c:\bs_hudson\workspace\790\products\imager\demon\main.cpp:714, main
| $module: ti_demon_vs_17750
Start: 6/20/2019 23:40:35
Stop: 6/21/2019 09:15:13
Total Time: 09:34:38
- Log in to post comments

Tom, the log tells a different story here!
Error 0x40012: This is not the last volume of the backup archive.
Error 0xb03e9: Cannot open the backup.
I would recommend that you run a Validation for your backup task and check to see what errors this brings up related to the above error that the backup archive is incomplete?
- Log in to post comments

I modified the backup scheme to do a full followed by 5 incremental. The full and first incremental succeeded. The second incremental failed. That failure was followed by 5 additional failed attempts at 10 minute intervals. See the attached log data. The full backup can be mounted. The first incremental fails to mount; "Failed to open backup E:\Backups\Aruba_inc_b19_s2-v1. Make sure the backup location is accessible and contains all versions of the backup."
Attachment | Size |
---|---|
504494-169841.log | 4.19 KB |
504494-169844.log | 9.62 KB |
504494-169847.log | 22.37 KB |
- Log in to post comments

Tom, the new log files show the following issues:
7/15/2019 01:30:53: The following backups have been successfully created: E:\Backups\ARUBA_full_b19_s1_v1.tib
7/15/2019 01:30:54: Consolidate Backup Archive
Location: E:\Backups\ARUBA_full_b19_s1_v1.tib
Destination: E:\Backups\ARUBA_full_b19_s1_v1_A0B8E52F-E28B-4F1C-B826-AC3A0F94E684.tib
7/15/2019 01:30:54: Error 0x1e50015:
Failed to open backup E:\Backups\ARUBA_full_b10_s1_v1.tib.
Make sure the backup location is accessible and contains all versions of the backup.
7/15/2019 01:40:54: Error 0xb03e9: Failed to open data stream.
7/15/2019 01:40:54: Error 0x1ef0029: An error occurred during the backup consolidation.
7/15/2019 23:35:21: The following backups have been successfully created: E:\Backups\ARUBA_inc_b19_s2_v1.tib
7/15/2019 23:35:21: Consolidate Backup Archive
Location: E:\Backups\ARUBA_inc_b19_s2_v1.tib
Destination: E:\Backups\ARUBA_inc_b19_s2_v1_AEAA54E2-1B62-4EBB-B75A-39EE9AFE1A99.tib
7/15/2019 23:35:21: Error 0xb03e9: Failed to open data stream.
7/15/2019 23:35:21: Deleting backup file with path E:\Backups\ARUBA_full_b10_s1_v1.tib.
7/15/2019 23:35:21: Error 0xb03e9: Failed to open data stream.
7/15/2019 23:35:21: Deleting backup file with path E:\Backups\ARUBA_full_b11_s1_v1.tib.
7/15/2019 23:35:21: Deleting backup file with path E:\Backups\ARUBA_full_b12_s1_v1.tib.
7/15/2019 23:35:21: Deleting backup file with path E:\Backups\ARUBA_full_b13_s1_v1.tib.
7/15/2019 23:35:21: Error 0xb03e9: Failed to open data stream.
7/15/2019 23:35:21: Deleting backup file with path E:\Backups\ARUBA_full_b14_s1_v1.tib.
7/16/2019 23:30:04: Error 0x40011: The specified file does not exist.
7/16/2019 23:40:04: Error 0x1e50023: The specified file does not exist: E:\Backups\ARUBA_inc_b19_s2_v11.tib.
7/16/2019 23:40:04: Error 0x13c0005: Operation has completed with errors.
The main issue above has been during automatic cleanup operations (shown as consolidation) apart from the last log where again a file could not be found, but given the _v11.tib ending, this is telling a story that it could be a credentials issue for which such issues have given rise to _v11 file references.
So, is E:\Backups actually a Windows mapped drive to a network location / drive?
- Log in to post comments

The errors logged about missing backup are expected. Those were old backups that could not be mounted. I deleted them manually. I believe that the backup being created at that time succeeded and that success appears in the log. The E:\Backups location is on the USB connected 8Tb Seagate Backup Plus hub device.
- Log in to post comments

Tom, if you delete any backup files manually, then it is strongly recommended to run a validation for the task that created the deleted files if it is still shown in the main ATI GUI - this will help clean up the information held for the task in the internal Acronis database. A pop up error panel will be shown for each missing / deleted file to which you should take the Ignore option if shown or else the Cancel option.
The E:\Backups location is on the USB connected 8Tb Seagate Backup Plus hub device.
Please check your Power Options with regards to how USB devices are handled, i.e. is USB selective suspend enabled? Are you connecting the Seagate drive to a USB 3 port?
- Log in to post comments

USB selective suspend is enabled. I believe it is connected to a USB 3 port - not sure how to check. Whay would that matter? The Seagate Backup plus hub is exactly that - it contains a USB hub and other USB devices can be connected to it - though none are.
- Log in to post comments

Tom Demler wrote:USB selective suspend is enabled. I believe it is connected to a USB 3 port - not sure how to check. Why would that matter? The Seagate Backup plus hub is exactly that - it contains a USB hub and other USB devices can be connected to it - though none are.
USB selective suspend allows the OS to suspend the drive when it deems that it may be idle or not using resources etc. This has been associated with numerous issues with backing up to USB drives here in the forums.
The type of port can matter because the power draw of USB 3 is almost double that of USB 2 but in your case, I understand that the Seagate drive / hub is powered independently so should not be drawing any power from the port, so the only impact of connecting a USB 3 device to a USB 2 port would be to limit performance to only USB 2 transfer rates.
- Log in to post comments

Are you suggesting that I disable USB selective suspend?
I effectively disconnect the Seagate drive when the backup is complete - by turning off the power to it via a post-backup command. I turn it on before the backup using a pre-backup command. The pre-backup command turn on power AND waits until the drive is visible to the OS.
- Log in to post comments

Tom, see the following:
Forum topic: True Image 2018 - constantly fails to recognize external USB Hard Drive
Forum topic: True Image cannot find the external backup drive
Forum topic: Acronis' USB drive occasionally opens up in file explorer then closes in a few moments
- Log in to post comments

Just an aside, I have never had such problems with my 6TB Backup Plus drive (other than the power supply dying - US power supply was shorted by the US to Australia adapter - fortunately the power supply was the same as another Seagate drive).
- Log in to post comments

Tom Demler wrote:USB selective suspend is enabled. I believe it is connected to a USB 3 port - not sure how to check. Whay would that matter? The Seagate Backup plus hub is exactly that - it contains a USB hub and other USB devices can be connected to it - though none are.
The USB suspend was an additional suggestion to provide better reliabilty for ensuring the USB is powered up when scheduled tasks occur. I imagine that there is no power issue here since most drives 6TB and larger have their own power supply.
Did you check Steve's other note first - that is more likely the key to this. Whenever you manually delete or move files outside of Acronis you essentially break the backup task when it comes time to restore or validate. If you run a manual validation, it is going to throw up error prompts stating that files are missing and ask you to locate them or ignore them. If you deleted them, then you must "ignore" each one that pops up until no more warnings appear. In the future, please use the ATI GUI to either "move" or "cleanup" unwanted versions of backups.
Steve Smith wrote:
Tom, if you delete any backup files manually, then it is strongly recommended to run a validation for the task that created the deleted files if it is still shown in the main ATI GUI - this will help clean up the information held for the task in the internal Acronis database. A pop up error panel will be shown for each missing / deleted file to which you should take the Ignore option if shown or else the Cancel option.
- Log in to post comments

I cloned the backup configuration and then deleted the original and all the backup files in the USB drive. I then ran a backup which created ARUBA_full_b1_s1_v1.tib. Here is what appears in the log:
7/18/2019 08:37:54: -04:00 21164 I00000000: -----
7/18/2019 08:37:54: -04:00 21164 I00000000: ATI Demon started. Version: 23.5.1.17750.
7/18/2019 08:37:54: -04:00 21164 I00640000: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
7/18/2019 08:37:54: -04:00 21164 I00640002: Operation ARUBA started manually.
7/18/2019 08:37:56: -04:00 21164 I00640000: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
7/18/2019 08:37:56: -04:00 21164 I013C0000: Operation: Backup
7/18/2019 08:37:56: -04:00 21164 I0064000B: Priority changed to Low.
7/18/2019 08:37:58: -04:00 21164 I00010400: Child process has exited with code '0'.
7/18/2019 08:37:58: -04:00 21164 I00640086: Execution of user command succeeded: C:/Users/Tom Demler/Documents/StartBackup.cmd
7/18/2019 08:37:58: -04:00 21164 I000B03F0: Create Backup Archive From: To file: E:\Backups\ARUBA.tib Compression: Normal Exclude: Files matching mask Match criterion: hiberfil.sys, pagefile.sys, $Recycle.Bin, swapfile.sys, System Volume Information, *.tib, *.tib.metadata, *.~, *.tmp, C:\Users\defaultuser0\AppData\Local\Temp, C:\Users\Tom Demler\AppData\Local\Temp, C:\Users\defaultuser0\AppData\Local\Microsoft\Windows\INetCache, C:\Users\defaultuser0\AppData\Local\Mozilla\Firefox\Profiles\*\cache2, C:\Users\defaultuser0\AppData\Local\Mozilla\Firefox\Profiles\*\OfflineCache, C:\Users\defaultuser0\AppData\Local\Opera Software\Opera Stable\Cache, C:\Users\defaultuser0\AppData\Local\Opera Software\Opera Stable\Media Cache, C:\Users\defaultuser0\AppData\Local\Google\Chrome\User Data\Default\Cache, C:\Users\Tom Demler\AppData\Local\Mozilla\Firefox\Profiles\*\cache2, C:\Users\Tom Demler\AppData\Local\Mozilla\Firefox\Profiles\*\OfflineCache, C:\Users\Tom Demler\AppData\Local\Opera Software\Opera Stable\Cache, C:\Users\Tom Demler\AppData\Local\Opera Software\Opera Stable\Media Cache, C:\Users\Tom Demler\AppData\Local\Google\Chrome\User Data\Default\Cache, C:\WINDOWS\CSC
7/18/2019 08:37:59: -04:00 21164 I000101F8: Pending operation 173 started: 'Creating partition image'.
7/18/2019 08:37:59: -04:00 21164 I000101F8: Pending operation 173 started: 'Creating partition image'.
7/18/2019 08:38:00: -04:00 17336 I00640000: Writing full version to file: ARUBA_full_b1_s1_v1.tib
7/18/2019 08:38:00: -04:00 21164 I000101F8: Pending operation 173 started: 'Creating partition image'.
7/18/2019 08:55:39: -04:00 21164 I000101F8: Pending operation 173 started: 'Creating partition image'.
7/18/2019 08:55:43: -04:00 21164 I000101F8: Pending operation 173 started: 'Creating partition image'.
7/18/2019 08:57:21: -04:00 21164 I000101F8: Pending operation 173 started: 'Creating partition image'.
7/18/2019 10:38:32: -04:00 21164 I000101F8: Pending operation 173 started: 'Creating partition image'.
7/18/2019 10:38:32: -04:00 21164 I000101F8: Pending operation 173 started: 'Creating partition image'.
7/18/2019 10:38:32: -04:00 21164 I00640000: The following backups have been successfully created: E:\Backups\ARUBA_full_b1_s1_v1.tib
7/18/2019 11:43:38: -04:00 21164 I00010400: Child process has exited with code '0'.
7/18/2019 11:43:38: -04:00 21164 I00640086: Execution of user command succeeded: C:/Users/Tom Demler/Documents/FinishBackup.cmd
7/18/2019 11:43:39: -04:00 21164 I013C0006: Operation has succeeded.
Start: 7/18/2019 08:37:54
Stop: 7/18/2019 11:43:39
Total Time: 03:05:45
However after re-applying power to the USB drive and attempting to mount the backupI get the error about failing to open the backup.
- Log in to post comments

Tom, simple test for you to try. Remove your Pre & Post Commands from the task and leave the USB drive to be managed just by Windows rather than powering it down via these commands.
Test your backup task and then check that you can mount the backup without any error?
Use the MVP Log Viewer to check the TibMounter logs created by ATI when using the Mount option which should show similar to below for a successful .tib mount operation.
18/07/2019 18:30:16 :597 [T] build: 2677; process: 7216; 'C:\Program Files (x86)\Common Files\Acronis\TibMounter\tib_mounter_monitor.exe'
18/07/2019 18:30:16 :598 [T] 2019.07.18 17:30:16 UTC
18/07/2019 18:30:16 :598 [T] 2019.07.18 18:30:16 LOCAL
18/07/2019 18:30:16 :619 [T] vbInit status 0x0
18/07/2019 18:30:16 :655 [T] Notifier initialize status 0x00000000
18/07/2019 18:30:16 :663 [T] vbSubscribeForVolumeNotifications status 0x0 (46 ms)
18/07/2019 18:30:16 :669 [T] BusInfo: 0 devices { }
18/07/2019 18:30:16 :669 [T] vbGetBusInfo status 0x0
18/07/2019 18:31:51 :063 [T] [OnVolumeMounted]: volume O: mounted
18/07/2019 18:34:20 :906 [T] [OnVolumeMounted]: volume P: mounted
- Log in to post comments