Nightly backup fails every time, but then succeeds 30 seconds later on retry
I didn't even realize this was happening until I was playing with the "MVP Log Viewer" and saw this bizarre pattern.
Every night's backup failed with
Error 0xb0428: The backup location was not found on the destination drive. Make sure the correct storage device is connected to the computer.
But since I had the default "Error handling" option set to retry after 30 seconds, the second attempt always worked perfectly, which is why I never noticed the failures.
What in the world is going on here?
Some peculiar aspects of my process might be behind it, although another Win10 machine with the same configuration behaves normally.
The backup is done to a USB removable external drive that is normally unmounted and powered off. The "pre-backup" commands power up the drive and mount it prior to the backup. I've directed the output of the pre-backup command batch file and see that the drive is properly mounted and readable before the initial backup starts.
The backup drive was previously used to back up this machine's predecessor, so maybe the drive is slightly haunted by it.
In order to get the output of the pre-backup commands re-directed to a file, I had to use a two-step process. The batch file that is directly called by TI is this:
cmd /k c:\bin\prebackupcommands >> d:\downloads\prebackuptrace.txt 2>&1 exit
It calls the actual batch file with the pre-backup commands. The /k option causes it to wait for completion of the commands, as TI requires.
Here's a annotated sample of the pre-backup batch file, showing both attempts. I added the long waits just to see if this was all a timing problem, but they didn't help.
C:\BIN>echo on
C:\BIN>time /t
08:32 PM
C:\BIN>c:/bin/waitforprocesstoend avp.com // Wait for A/V scan to end
C:\BIN>time /t
08:32 PM
C:\BIN>diskpowertcp on 10 // Power up drive
C:\BIN>time /t
08:32 PM
C:\BIN>waitforme 20 // Wait 20 seconds for drive to come to speed
20000
C:\BIN>time /t
08:32 PM
C:\BIN>mountvol h:\ \\?\Volume{3e12cce7-0000-0000-007e-000000000000}\ // Mount drive
C:\BIN>time /t
08:32 PM
C:\BIN>waitforme 5 // Wait 5 seconds, just because
5000
C:\BIN>time /t
08:32 PM
C:\BIN>sync64 h: // Access the drive to be sure it's really there
Sync v2.2 - Flush cached data to disk.
Copyright (C) 2016 Mark Russinovich
Sysinternals - www.sysinternals.com
Flushing: H
C:\BIN>time /t
08:32 PM
C:\BIN>waitforme 60 // Wait an entire minute, just because
60000
C:\BIN>time /t
08:33 PM
C:\BIN>dir h: // Access the drive again to be sure it's really there
Volume in drive H is BackupDrive
Volume Serial Number is 3CC3-9516
Directory of H:\
05/21/2019 11:48 AM <DIR> Acronis
04/12/2018 10:35 AM 21,286 Book Club membership list and book list 4-12-2018.docx
02/01/2014 11:13 AM 14,236 Book Club membership list and book list Feb 2014.docx
02/01/2014 11:15 AM 185,875 Book Club membership list and book list Feb 2014.pdf
06/27/2019 10:43 AM 21,545 Book Club membership list and book list Jan. 2019.docx
06/04/2018 07:31 PM 21,461 Book Club membership list and book list May 31-2018.docx
08/11/2015 02:42 PM <DIR> Certificate Backups
07/02/2019 08:58 AM <DIR> Dellbox-II-Hold
07/10/2019 08:36 PM <DIR> Dellbox-IV
07/04/2019 12:27 PM 45,888 Susan's Diary.docx
6 File(s) 310,291 bytes
4 Dir(s) 614,609,117,184 bytes free
C:\BIN>time /t
08:33 PM
C:\BIN>exit // Exit pre-backup commands
C:\BIN>echo on // And here, it starts all over again
C:\BIN>time /t
08:34 PM
C:\BIN>c:/bin/waitforprocesstoend avp.com
C:\BIN>time /t
08:34 PM
C:\BIN>diskpowertcp on 10
C:\BIN>time /t
08:34 PM
C:\BIN>waitforme 20
20000
C:\BIN>time /t
08:35 PM
C:\BIN>mountvol h:\ \\?\Volume{3e12cce7-0000-0000-007e-000000000000}\
The directory is not empty.
C:\BIN>time /t
08:35 PM
C:\BIN>waitforme 5
5000
C:\BIN>time /t
08:35 PM
C:\BIN>sync64 h:
Sync v2.2 - Flush cached data to disk.
Copyright (C) 2016 Mark Russinovich
Sysinternals - www.sysinternals.com
Flushing: H
C:\BIN>time /t
08:35 PM
C:\BIN>waitforme 60
60000
C:\BIN>time /t
08:36 PM
C:\BIN>dir h:
Volume in drive H is BackupDrive
Volume Serial Number is 3CC3-9516
Directory of H:\
05/21/2019 11:48 AM <DIR> Acronis
04/12/2018 10:35 AM 21,286 Book Club membership list and book list 4-12-2018.docx
02/01/2014 11:13 AM 14,236 Book Club membership list and book list Feb 2014.docx
02/01/2014 11:15 AM 185,875 Book Club membership list and book list Feb 2014.pdf
06/27/2019 10:43 AM 21,545 Book Club membership list and book list Jan. 2019.docx
06/04/2018 07:31 PM 21,461 Book Club membership list and book list May 31-2018.docx
08/11/2015 02:42 PM <DIR> Certificate Backups
07/02/2019 08:58 AM <DIR> Dellbox-II-Hold
07/10/2019 08:36 PM <DIR> Dellbox-IV
07/04/2019 12:27 PM 45,888 Susan's Diary.docx
6 File(s) 310,291 bytes
4 Dir(s) 614,609,117,184 bytes free
C:\BIN>time /t
08:36 PM
C:\BIN>exit
Where is the script located - different disk or network share than what is needing to be backed up it sounds like, right?
If so, I'd try moving the actual pre-script to the backup disk and running it from there. If the disk needs time to spin up completely so the pre-script can run, then this should signal the PC to wake up the drive, and once available, then it should run fine if timing is the issue.
Pretty sure the disk is completely spun up when the backup tries to access it. That's why I added a "dir" command to the pre-backup script to really prove it. The "dir" command is able to read the drive on both the first failing backup attempt and the second.
Also, I think the error message means something other than the drive not being accessible. I dummied up a backup script that dismounted the drive in the pre-backup script, after manually mounting it before starting the backup. That produced this error:
E000B042F: Error 0xb042f: Destination is unavailable
which is different from what I see in the real backup:
E000B0428: Error 0xb0428: The backup location was not found on the destination drive. Make sure the correct storage device is connected to the computer.
I think this error is saying that the drive is there and readable, but the chain of backups that it wants to reference isn't there, so it tells me to make sure I'm using the right device. Somehow, it finds it on the next go around.
Quite a conundrum.
I've decided to resurrect this thread to ask a question about the failure, which is still happening even though I started a fresh full backup on a brand new external backup drive. I've tried changing the name of the backup and the name of the directory on the backup drive.
I still see the error
2019-08-16T20:33:18:152-05:00 13708 E000B0428: Error 0xb0428: The backup location was not found on the destination drive. Make sure the correct storage device is connected to the computer.
in the log, but switching the MVP Log Viewer from "short" to "regular" log view, I see this too:
line: 0x4d3f22948e29f37e, c:\bs_hudson\workspace\790\products\ imager\archive\impl\utils.cpp:679, TrueImage::Archive:: CheckVolumeDeviceIdMatch | Path: H: | ExpectedId: \local\hd_ev\vol_guid(5B98B8B24464BF1E862B06BC71135AA7) | ActualId:
The "vol_guid" did change though. This is with the old backup drive:
"ExpectedId: \local\hd_sign(3E12CCE7)\part_sn(3CC39516803CC3A5) start(63)
What, exactly, is it looking for and not finding, and where is it looking? Unlikely that I'm going to be the guy to fix this problem, but I'm really curious what's going on just on this one machine, when the one sitting next to it is OK.
Bert, my understanding is that Acronis use a combination of drive letter and volume GUID to ensure that the correct backup drive is available for a task. In this way a change of drive letter could still be handled provided the volume GUID remains the same.
This information is stored in the backup task script .tib.tis file (in the C:\ProgramData\Acronis\TrueImageHome\Scripts folder) where you should see mentions of both volume GUID's and Disk ID's within the XML data for the task.
Acronis have moved to using the Volume GUID because this should not change even though a different drive letter may be used. These unique ID's are normally set when the drive is formatted and volumes created for the drive.
I had this same exact error occur in ATI 2020 beta 2. It just happened once.
Thought I'd drop in on this thread again because I'm now having the exact same pattern of error followed immediately with success on another PC that had been running TI 2019 without incident. The problem started showing up when I replaced the external USB backup drive with a larger one. Nothing changed except the drive's volume ID in the "mountvol" command in the pre-backup script.
Fortunately, just like before, the re-try after 5 seconds always works.
Bert wrote:Thought I'd drop in on this thread again because I'm now having the exact same pattern of error followed immediately with success on another PC that had been running TI 2019 without incident. The problem started showing up when I replaced the external USB backup drive with a larger one. Nothing changed except the drive's volume ID in the "mountvol" command in the pre-backup script.
Fortunately, just like before, the re-try after 5 seconds always works.
It seems very strange that a problem caused by a Volume GUID mismatch would first fail and then succeed 5 seconds later. I would have expected that the replacement of a target drive with a different drive would require you to change the backup task before it would work. Strange.
Are your multiple PCs using the same backup task name and writing to the same directory on the drive? I would expect this to cause problems but I wouldn't expect the symptoms you are seeing.
One more comment on this bizarre problem.
I just looked at the logs for the first time in a while and found that on April 29, 2020 the problem apparently healed itself. The backup fail/succeed problem occurred on 4/28 but not on 4/29 nor on any night since.
The problem that I'd been seeing since last July is simply gone.
Other than the OS changes that Microsoft keeps pounding me with, there have been no intentional changes to the system.
The problem is still occurring on my other Windows 10 PC however.
[I'll be moving up to TI 2021 as soon as it's released; curious to see if the problem goes away altogether.]