Last backup has failed error
When I attempted an incremental backup today, I get the message:-
"The last backup has failed."
The backup drive is powered up and connected. I can see the files using WIndows Explorer.
So then I tried verifying the backup, it took almost 2 hours but it was successfull.
When I try to backup again, I get the same error.
I can see no log files under C:\ProgramData\Acronis\TrueImage apart from three old files with last years date.
How do I fix the problem?
Where do I find the logs?
They are not under C:\ProgramData\Acronis\TrueImage \Logs
Looks like the logs are in C:\ProgramData\Acronis\TrueImageHome\Logs
I can see three files with today as the modification date:-
NSB_2017-05-17-08-38-12.log
afcdpsrv.log
NSB_2017-06-10-12-03-12.log
The two NSB_xxxxx files don't contain much.
The last section of the afcdpsrv.log (i.e. the entries with today's date) is as follows:-
10-06-2017 07:59:34: tid=0x00000B14>Session change. Session logon. Session Id 35
10-06-2017 09:11:45: tid=0x00000B14>[Device]: New device arrived in system. : {\\?\STORAGE#Volume#{971dcfa8-4798-11e7-86ef-a434d9e383ab}#0000000008100000#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b}}
10-06-2017 09:11:46: Retreiving Fdisk ver1 disk set to Fdisk ver2c disk set...
10-06-2017 09:11:46: Fdisk2: Use Disk 3 host= 0 bus = 0 target = 0
10-06-2017 09:11:46: Fdisk2: Use Disk 5 host= 0 bus = 0 target = 0
10-06-2017 09:11:46: Fdisk2: Use Disk 9 host= 0 bus = 0 target = 0
10-06-2017 09:11:46: Refreshing Drivers...
10-06-2017 09:11:46: Enter to process disks in Mbr Driver (id = 276)
10-06-2017 09:11:46: Exit from process disks in Mbr Driver (id = 276)
10-06-2017 09:11:46: Enter to process disks in Gpt Driver (id = 277)
10-06-2017 09:11:46: Try to load Alternate Header from 500118191
10-06-2017 09:11:46: Gpt Disk 17A7370F-E3E5-4644-9DE9-205450384C7B LBA=500118191 ALBA=1
10-06-2017 09:11:46: try to loading Header from 1
10-06-2017 09:11:46: Gpt Disk 17A7370F-E3E5-4644-9DE9-205450384C7B LBA=1 ALBA=500118191
10-06-2017 09:11:46: Try to load Alternate Header from 9767541166
10-06-2017 09:11:46: Gpt Disk 745339F6-8041-4D8E-B4B6-B5B9DC3DDCCE LBA=9767541166 ALBA=1
10-06-2017 09:11:46: try to loading Header from 1
10-06-2017 09:11:46: Gpt Disk 745339F6-8041-4D8E-B4B6-B5B9DC3DDCCE LBA=1 ALBA=9767541166
10-06-2017 09:11:46: Exit from process disks in Gpt Driver (id = 277)
10-06-2017 09:11:47: LDM: New ProcessDisks(rawLayer, headLayer)
10-06-2017 09:11:47: ProcessDisks: One more disk to check
10-06-2017 09:11:47: ProcessDisks: One more disk to check
10-06-2017 09:11:47: ProcessDisks: One more disk to check
10-06-2017 09:11:47: Mark All groups as Root Like Dgs
10-06-2017 09:11:47: ------ Volumes Objects ------
10-06-2017 09:11:47: LDM initialization complete
10-06-2017 09:11:47: Retreiving Fdisk ver1 disk set to Fdisk ver2c disk set...
10-06-2017 09:11:47: Fdisk2: Use Disk 3 host= 0 bus = 0 target = 0
10-06-2017 09:11:47: Fdisk2: Use Disk 5 host= 0 bus = 0 target = 0
10-06-2017 09:11:47: Fdisk2: Use Disk 9 host= 0 bus = 0 target = 0
10-06-2017 09:11:47: Refreshing Drivers...
10-06-2017 09:11:47: Enter to process disks in Mbr Driver (id = 307)
10-06-2017 09:11:47: Exit from process disks in Mbr Driver (id = 307)
10-06-2017 09:11:47: Enter to process disks in Gpt Driver (id = 308)
10-06-2017 09:11:47: Try to load Alternate Header from 500118191
10-06-2017 09:11:47: Gpt Disk 17A7370F-E3E5-4644-9DE9-205450384C7B LBA=500118191 ALBA=1
10-06-2017 09:11:47: try to loading Header from 1
10-06-2017 09:11:47: Gpt Disk 17A7370F-E3E5-4644-9DE9-205450384C7B LBA=1 ALBA=500118191
10-06-2017 09:11:47: Try to load Alternate Header from 9767541166
10-06-2017 09:11:47: Gpt Disk 745339F6-8041-4D8E-B4B6-B5B9DC3DDCCE LBA=9767541166 ALBA=1
10-06-2017 09:11:47: try to loading Header from 1
10-06-2017 09:11:47: Gpt Disk 745339F6-8041-4D8E-B4B6-B5B9DC3DDCCE LBA=1 ALBA=9767541166
10-06-2017 09:11:47: Exit from process disks in Gpt Driver (id = 308)
10-06-2017 09:11:47: LDM: New ProcessDisks(rawLayer, headLayer)
10-06-2017 09:11:47: ProcessDisks: One more disk to check
10-06-2017 09:11:47: ProcessDisks: One more disk to check
10-06-2017 09:11:47: ProcessDisks: One more disk to check
10-06-2017 09:11:47: Mark All groups as Root Like Dgs
10-06-2017 09:11:47: ------ Volumes Objects ------
10-06-2017 09:11:47: LDM initialization complete
10-06-2017 09:11:47: Retreiving Fdisk ver1 disk set to Fdisk ver2c disk set...
10-06-2017 09:11:47: Fdisk2: Use Disk 3 host= 0 bus = 0 target = 0
10-06-2017 09:11:47: Fdisk2: Use Disk 5 host= 0 bus = 0 target = 0
10-06-2017 09:11:47: Fdisk2: Use Disk 9 host= 0 bus = 0 target = 0
10-06-2017 09:11:47: Refreshing Drivers...
10-06-2017 09:11:47: Enter to process disks in Mbr Driver (id = 338)
10-06-2017 09:11:47: Exit from process disks in Mbr Driver (id = 338)
10-06-2017 09:11:47: Enter to process disks in Gpt Driver (id = 339)
10-06-2017 09:11:47: Try to load Alternate Header from 500118191
10-06-2017 09:11:47: Gpt Disk 17A7370F-E3E5-4644-9DE9-205450384C7B LBA=500118191 ALBA=1
10-06-2017 09:11:47: try to loading Header from 1
10-06-2017 09:11:47: Gpt Disk 17A7370F-E3E5-4644-9DE9-205450384C7B LBA=1 ALBA=500118191
10-06-2017 09:11:47: Try to load Alternate Header from 9767541166
10-06-2017 09:11:47: Gpt Disk 745339F6-8041-4D8E-B4B6-B5B9DC3DDCCE LBA=9767541166 ALBA=1
10-06-2017 09:11:47: try to loading Header from 1
10-06-2017 09:11:47: Gpt Disk 745339F6-8041-4D8E-B4B6-B5B9DC3DDCCE LBA=1 ALBA=9767541166
10-06-2017 09:11:47: Exit from process disks in Gpt Driver (id = 339)
10-06-2017 09:11:47: LDM: New ProcessDisks(rawLayer, headLayer)
10-06-2017 09:11:47: ProcessDisks: One more disk to check
10-06-2017 09:11:47: ProcessDisks: One more disk to check
10-06-2017 09:11:47: ProcessDisks: One more disk to check
10-06-2017 09:11:47: Mark All groups as Root Like Dgs
10-06-2017 09:11:47: ------ Volumes Objects ------
10-06-2017 09:11:47: LDM initialization complete
10-06-2017 09:11:48: Retreiving Fdisk ver1 disk set to Fdisk ver2c disk set...
10-06-2017 09:11:48: Fdisk2: Use Disk 3 host= 0 bus = 0 target = 0
10-06-2017 09:11:48: Fdisk2: Use Disk 5 host= 0 bus = 0 target = 0
10-06-2017 09:11:48: Fdisk2: Use Disk 9 host= 0 bus = 0 target = 0
10-06-2017 09:11:48: Refreshing Drivers...
10-06-2017 09:11:48: Enter to process disks in Mbr Driver (id = 369)
10-06-2017 09:11:48: Exit from process disks in Mbr Driver (id = 369)
10-06-2017 09:11:48: Enter to process disks in Gpt Driver (id = 370)
10-06-2017 09:11:48: Try to load Alternate Header from 500118191
10-06-2017 09:11:48: Gpt Disk 17A7370F-E3E5-4644-9DE9-205450384C7B LBA=500118191 ALBA=1
10-06-2017 09:11:48: try to loading Header from 1
10-06-2017 09:11:48: Gpt Disk 17A7370F-E3E5-4644-9DE9-205450384C7B LBA=1 ALBA=500118191
10-06-2017 09:11:48: Try to load Alternate Header from 9767541166
10-06-2017 09:11:48: Gpt Disk 745339F6-8041-4D8E-B4B6-B5B9DC3DDCCE LBA=9767541166 ALBA=1
10-06-2017 09:11:48: try to loading Header from 1
10-06-2017 09:11:48: Gpt Disk 745339F6-8041-4D8E-B4B6-B5B9DC3DDCCE LBA=1 ALBA=9767541166
10-06-2017 09:11:48: Exit from process disks in Gpt Driver (id = 370)
10-06-2017 09:11:48: LDM: New ProcessDisks(rawLayer, headLayer)
10-06-2017 09:11:48: ProcessDisks: One more disk to check
10-06-2017 09:11:48: ProcessDisks: One more disk to check
10-06-2017 09:11:48: ProcessDisks: One more disk to check
10-06-2017 09:11:48: Mark All groups as Root Like Dgs
10-06-2017 09:11:48: ------ Volumes Objects ------
10-06-2017 09:11:48: LDM initialization complete
10-06-2017 09:11:48: Retreiving Fdisk ver1 disk set to Fdisk ver2c disk set...
10-06-2017 09:11:48: Fdisk2: Use Disk 3 host= 0 bus = 0 target = 0
10-06-2017 09:11:48: Fdisk2: Use Disk 5 host= 0 bus = 0 target = 0
10-06-2017 09:11:48: Fdisk2: Use Disk 9 host= 0 bus = 0 target = 0
10-06-2017 09:11:48: Refreshing Drivers...
10-06-2017 09:11:48: Enter to process disks in Mbr Driver (id = 400)
10-06-2017 09:11:48: Exit from process disks in Mbr Driver (id = 400)
10-06-2017 09:11:48: Enter to process disks in Gpt Driver (id = 401)
10-06-2017 09:11:48: Try to load Alternate Header from 500118191
10-06-2017 09:11:48: Gpt Disk 17A7370F-E3E5-4644-9DE9-205450384C7B LBA=500118191 ALBA=1
10-06-2017 09:11:48: try to loading Header from 1
10-06-2017 09:11:48: Gpt Disk 17A7370F-E3E5-4644-9DE9-205450384C7B LBA=1 ALBA=500118191
10-06-2017 09:11:48: Try to load Alternate Header from 9767541166
10-06-2017 09:11:48: Gpt Disk 745339F6-8041-4D8E-B4B6-B5B9DC3DDCCE LBA=9767541166 ALBA=1
10-06-2017 09:11:48: try to loading Header from 1
10-06-2017 09:11:48: Gpt Disk 745339F6-8041-4D8E-B4B6-B5B9DC3DDCCE LBA=1 ALBA=9767541166
10-06-2017 09:11:48: Exit from process disks in Gpt Driver (id = 401)
10-06-2017 09:11:48: LDM: New ProcessDisks(rawLayer, headLayer)
10-06-2017 09:11:48: ProcessDisks: One more disk to check
10-06-2017 09:11:48: ProcessDisks: One more disk to check
10-06-2017 09:11:48: ProcessDisks: One more disk to check
10-06-2017 09:11:48: Mark All groups as Root Like Dgs
10-06-2017 09:11:48: ------ Volumes Objects ------
10-06-2017 09:11:48: LDM initialization complete
10-06-2017 11:32:25: tid=0x00000B14>Session change. Session lock. Session Id 35
10-06-2017 12:01:33: tid=0x00000B14>Session change. Session unlock. Session Id 35
10-06-2017 12:02:18: tid=0x00000B14>Session change. Session logoff. Session Id 35
10-06-2017 12:02:18: tid=0x00000B14>System shutdown.
10-06-2017 12:02:18: tid=0x0000136C>Stopped driver manager with status 0x0
10-06-2017 12:02:18: Service has stopped.
Brian, if you use the Log Viewer, it will find them and show the path in the top panel.
Ok, so I installed the Log Viewer.
As far as I can see, there is no service log for today's failed backup.
What is the next step?
The last service log for the drive I am attempting to back up is dated 2017-03-27.
The last couple of entries are:-
id=11; level=2; module=100; code=0; date/time=27/03/2017 09:44:29
message=The following backups have been successfully created: L:\2TB Raid 1_inc_b2_s5_v1.tib
id=12; level=2; module=316; code=6; date/time=27/03/2017 09:44:29
message=Operation has succeeded.
Since then, I have carried out two further successfull incremental backups. These do not appear in any service logs.
There exist incremental backup files on the backup drive named:-
L:\2TB Raid 1_inc_b2_s6_v1.tib
L:\2TB Raid 1_inc_b2_s7_v1.tib
=====
I found this script file. Does this contain any clues?
Note the strange looking change that happens to the ids after L:\2TB Raid 1_inc_b2_s5_v1
<?xml version="1.0" encoding="UTF-8" ?>
<batch>
<version>1.0</version>
<uuid>20AB40A1-6645-4B11-A28C-F488AD6F4D70</uuid>
<display>2TB Raid 1</display>
<description>Cornwall Images</description>
<priority>low</priority>
<stage>
<before>
<user_command>
<command enabled="false" />
</user_command>
</before>
<operations>
<backup check_after="false" notarize_files="false">
<reserve_backup_copy format="tib" need_reserve_backup_copy="false">
<volume_location device_instance_id="" uri="" volume_id="0" />
</reserve_backup_copy>
<antivirus_check_common_options default_action="abort" enabled="false" scan_archives="false" scan_boot_records="true" scan_cookies="false" scan_mail="true" scan_no_heuristics="false" scan_not_recursive="false" scan_processes="true" scan_programs_only="false" scan_registry="false" try_update="false" />
<media_builder_options destination="" enabled="false" />
<archive_options check_network_timeout="false" computer_id="3F225AAF-543E-495F-A1D6-6C52B39727A6" id="11720978762458263412" network_timeout="0" split_archive="false">
<volumes_locations>
<volume_location device_instance_id="NULL" uri="L:\2TB Raid 1_full_b2_s1_v1.tib" volume_id="2341966341" />
<volume_location device_instance_id="NULL" uri="L:\2TB Raid 1_inc_b2_s2_v1.tib" volume_id="2888008791" />
<volume_location device_instance_id="NULL" uri="L:\2TB Raid 1_inc_b2_s3_v1.tib" volume_id="3908147850" />
<volume_location device_instance_id="NULL" uri="L:\2TB Raid 1_inc_b2_s4_v1.tib" volume_id="2338208798" />
<volume_location device_instance_id="NULL" uri="L:\2TB Raid 1_inc_b2_s5_v1.tib" volume_id="385326961" />
<volume_location device_instance_id="STORAGE\VOLUME\{AF4032E3-0A7C-11E7-86E6-A434D9E383AB}#0000000008100000" uri="L:\2TB Raid 1_inc_b2_s6_v1.tib" volume_id="2656118411" />
<volume_location device_instance_id="STORAGE\VOLUME\{AF4032E3-0A7C-11E7-86E6-A434D9E383AB}#0000000008100000" uri="L:\2TB Raid 1_inc_b2_s7_v1.tib" volume_id="4117232783" />
<volume_location device_instance_id="STORAGE\VOLUME\{AF4032E3-0A7C-11E7-86E6-A434D9E383AB}#0000000008100000" uri="L:\@task@.tib" volume_id="0" />
</volumes_locations>
</archive_options>
<common_options allow_multi_volume_snapshot="false" allow_reset_archive_bit="false" app_settings_backup="false" chassis="3" description="Cornwall Images" entire_pc="false" exclude_by_mask="true" exclude_hidden="false" exclude_system="false" execution_count="21" fast_incremental="true" ignore_encryption="false" increment_type="incremental" nonstop_backup="false" ocb="false" rotation_count="0" rotation_scheme="0" skip_security="false" smart_backup="false" snapshot_mode="vss">
<file_mask pattern="hiberfil.sys" />
<file_mask pattern="pagefile.sys" />
<file_mask pattern="$Recycle.Bin" />
<file_mask pattern="swapfile.sys" />
<file_mask pattern="System Volume Information" />
<file_mask pattern="*.tib" />
<file_mask pattern="*.tib.metadata" />
<file_mask pattern="*.~" />
<file_mask pattern="*.tmp" />
<file_mask pattern="C:\Users\Brian\AppData\Local\Temp" />
<file_mask pattern="C:\Users\Admin\AppData\Local\Temp" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Temp" />
<file_mask pattern="C:\Users\Brian\AppData\Local\Microsoft\Windows\INetCache" />
<file_mask pattern="C:\Users\Admin\AppData\Local\Microsoft\Windows\INetCache" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Microsoft\Windows\INetCache" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Google\Chrome\User Data\Default\Cache" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Opera Software" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Mozilla\Firefox\Profiles" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Google\Chrome\User Data\Default\Cache" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Opera Software" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Mozilla\Firefox\Profiles" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Google\Chrome\User Data\Default\Cache" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Opera Software" />
<file_mask pattern="C:\Users\Brian Keen\AppData\Local\Mozilla\Firefox\Profiles" />
<file_mask pattern="C:\Windows\CSC" />
<stream_options allow_silent_media="false" cache_network_write="false" compression_level="normal" encryption_algorithm="none" format="tib" freespace="0" ignore_bad_sectors="false" reattempt_count="5" reattempt_on="true" reattempt_pausesec="30" silent_asz_cleanup="true" silent_mode="false" type="disk" ver="1">
<net_speed_limit speed_limit_mode="absolute" value="0" />
<disk_speed_limit speed_limit_mode="absolute" value="0" />
<traffic_quota_limit traffic_quota_limit_period="month" value="0" />
<quota scheme_flags="2" type="0" />
</stream_options>
</common_options>
<disk_source has_asz_backup="false" sector_by_sector_backup="false" sector_by_sector_backup_unallocated="false">
<holder strid="\local\hd_sign(A8C7617F)" />
</disk_source>
</backup>
</operations>
<after>
<user_command>
<command enabled="false" />
</user_command>
</after>
<after>
<user_command>
<command enabled="false" />
</user_command>
</after>
</stage>
<silent-reboot>false</silent-reboot>
<common_options>
<silent_mode enabled="0" />
<notify>
<email address="" authentification="false" enabled="0" encryption-type="none" from="" long_format="1" pop-before-smtp="false" pop-server="" pop-server-port="0" server="" server-port="25" subject="%OPERATION_STATUS% - Acronis True Image notification from %COMPUTER_NAME%" user="">
<notify_mode full_log="true" operation_complete="true" operation_fail="true" operation_message="true" />
</email>
</notify>
<show_only_own_task enabled="0" />
<shutdown_after do="0" />
<force_shutdown do="1" />
</common_options>
</batch>
Brian, the text you posted is from the Scripts folder which is the XML configuration data for your backup task, this should be left alone and let the main GUI make any changes to this.
If you are concerned about the contents, then either create a new backup task (in the GUI) or use the option to 'Clone settings' for your task, and let this create a new Scripts .tib.tis configuration file.
ATIH 2017 does not use service_ log files anymore - these are the format used by ATIH 2016 & some earlier versions. For 2017 the files names are more convoluted as ti_demon_...
It is possible that the older backup task logs you have seen come from an earlier version of ATIH before you upgraded to 2017.
The MVP Log Viewer has a further option shown in the File menu for Log File Cleanup which can remove old log files based on age criteria, i.e. remove all logs older than 10 days.
Ok - so which log should I look at in the Log Viewer to locate the fault?
I've just discovered I had downloaded an older version of the Log Viewer.
Brian, the log viewer should normally open to the backup task logs - for ATIH 2017 these are shown as Log Type: TI-demon in the top menu bar.
So using the new Log Viewer, I get this:-
2017-06-10 14:07:36:724 6244 I00640000: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
2017-06-10 14:07:36:724 6244 I00640002: Operation 2TB Raid 1 started manually.
2017-06-10 14:07:36:724 6244 I00640000: Operation description: Cornwall Images.
2017-06-10 14:07:48:179 6244 I00640000: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
2017-06-10 14:07:48:194 6244 I013C0000: Operation: Backup
2017-06-10 14:07:48:194 6244 I0064000B: Priority changed to Low.
2017-06-10 14:07:48:194 6244 E000B007F: Error 0xb007f: The backup location was not found on the destination drive. Make sure the correct storage device is connected to the computer.
| trace level: error
| line: 0x65e40aa0b487143
| file: k:\8053\products\imager\archive\impl\operations\archive_operation_backup.cpp:690
| function: TrueImage::Archive::BackupArchiveOperationImpl::CheckLastVolumeDeviceIdMatch
| line: 0x65e40aa0b487143, k:\8053\products\imager\archive\impl\operations\archive_operation_backup.cpp:690, TrueImage::Archive::BackupArchiveOperationImpl::CheckLastVolumeDeviceIdMatch
| $module: ti_demon_vs_8053
2017-06-10 14:07:48:257 6244 E013C0005: Error 0x13c0005: Operation has completed with errors.
| trace level: error
| line: 0x9f2c53c72e8bcea1
| file: k:\8053\products\imager\demon\main.cpp:683
| function: main
| line: 0x9f2c53c72e8bcea1, k:\8053\products\imager\demon\main.cpp:683, main
| $module: ti_demon_vs_8053
I am none the wiser. The log is not even telling me the backup file name it was trying to find!
I had previously tried restarting the PC. It made no difference.
This time I shut the PC down, power cycled the external USB backup drive and then started the PC.
Now the backup operation appears to be working.
This is seems odd because previously, the verify operation completed successfully which indicates that ATI must have been able to see the files on the backup drive correctly.
Any suggestions?
Brian, the main error is as below:
2017-06-10 14:07:48:194 6244 E000B007F: Error 0xb007f: The backup location was not found on the destination drive. Make sure the correct storage device is connected to the computer.
When you look at your backup task in the ATIH GUI - what do you see as the destination drive location?
Is this the same destination drive that has always been used for this backup task, and does it still have the same drive letter allocated as shown in the GUI destination information?
Yes - I had already checked that. The external USB backup drive always appears as L: on my PC.
This was the case both before and after the reboot and backup drive power cycle. If it had changed, then I would not expect the 'Validate' operation to have worked.
Incidentally, the 'login' button on the ATI forum web pages does not work.
If you try logging in from the URL below, you will see what I mean:-
Brian, strange that the backup seems to be working after the second power cycle, including the external drive. There must have been some difference in the way that the drive presented or was seen to give this error, but what is anyones to guess at?
If I click on the forum login page it simply shows me that I am already logged in, so if you are having problems, it may be worth clearing your browser cache in case you have something stale stored there which is contributing to the login issue?
To try the login problem, you need to logout of the forum first, then try logging in using the button.
It's not a browser or cache issue: It's the same on both Firefox and IE.
When I try to login to the forum using the button, I see the account details of another user with initals 'rkh'!
Brian, there were some problems with user accounts being 'mixed up' after the new forum software was introduced, and it sounds like this is affecting your account too.
Please send a private message to Ekaterina who is the forum moderator and can resolve this for you.
The MVP's had the same problem with the new forum and this was resolved for us!