Backup will not run consistently
I am running Acronis 2019 on Win 10. I have 5 backup jobs (C, D, E, F, X), scheduled to start every day at staggered times between 3:30 AM and 4:00 AM. Each job backs up a single partition on a SSD on the same computer. Each job runs a full backup once per week, and runs incremental backups the other 6 days. Each job runs its full backup on a different day.
Other than the start time and the day for full backup, the scheduling of all of the jobs is identical. I can look at the jobs and see the they are scheduled to run the next morning.
Jobs C, D, F, and X start and run to completion every morning without exception.
Job E sometimes runs, and sometimes doesn't. When it doesn't start, there are no error messages. It just doesn't start. It fails to start about 3 times/week. Note that the other jobs are scheduled to start both before and after E, and they all work fine. The computer is awake. I've looked and looked at this job, and I can't see anything weird about it. I've looked through the Windows logs and I can't see anything suspicious there. The E partition is on the same SSD as the D partition, so I don't think it's a disk failure.
I've noticed that the jobs don't always start when they are scheduled to start. For example, yesterday the C job, which is scheduled for 3:30 am, didn't start until 4:18 am. This seems to happen mostly on Friday, so I suspect Windows is doing something. This delay is not consistent with when E doesn't run. Sometimes E runs on Friday, and sometimes it doesn't.
I'm not sure where else to start to troubleshoot this, but I'm open to suggestions.
I downloaded the tool and looked at the logs. The delay in scheduling is caused by the weekly full backup for C, which runs longer than the other tasks. So no problem there. We can drop that question.
But there is no log for E on the days that it doesn't trigger. Sometimes it's on the day when C does a full, but sometimes it's not. There's no consistency there. On the days that E does not run, I can't find any mention of it in the logs. Assuming that queued tasks are run in the order they are scheduled, the order is C-D-E-F-X, so E should run after D and before F. It's just not there.
Next suggestion?
I poked through further logs and found the below in log type Schedul2 on a day when E did not run. What does "failed because of: MUTEXES" mean?
7/12/2019 3:40:00 AM: 00001E60 Running task 1-5 failed because of: MUTEXES
7/12/2019 3:40:00 AM: 00001E60 Runner wait for 4294967295 ms
7/12/2019 3:40:00 AM: 00001EF8 API Entry: OP=WAIT_CHANGES_EX3 Ver=4 Misc=0 Id=0 IntUser=0 LogonSid=S-1-5-5-0-428939 User="xxx (S-1-5-21-717439316-576668354-443253472-1000)
7/12/2019 3:40:00 AM: 00001EF8 WaitId=220 Product=0 (NONE)
7/12/2019 3:40:00 AM: 00001EF8 API Reply: OP=WAIT_CHANGES_EX3 Ver=4 Status=0 Task=1-8 Result=6(RUN_PENDING) Extra=4(MUTEXES)
7/12/2019 3:40:00 AM: 00001EF8 API Entry: OP=WAIT_CHANGES_EX3 Ver=4 Misc=0 Id=0 IntUser=0 LogonSid=S-1-5-5-0-428939 User="xxx" (S-1-5-21-717439316-576668354-443253472-1000)
7/12/2019 3:40:00 AM: 00001EF8 WaitId=220 Product=0 (NONE)
7/12/2019 3:40:00 AM: 00001EF8 API Reply: OP=WAIT_CHANGES_EX3 Ver=4 Status=0 Task=1-5 Result=5(RUN_FAILED) Extra=4(MUTEXES)
7/12/2019 3:40:00 AM: 00001EF8 API Entry: OP=WAIT_CHANGES_EX3 Ver=4 Misc=0 Id=0 IntUser=0 LogonSid=S-1-5-5-0-428939 User="xxx" (S-1-5-21-717439316-576668354-443253472-1000)
The log that should hold information about why the E: task does not run is the Schedul2 log which should have entries related to that task, but these are referenced by a different notation than used in the GUI.
12/07/2019 20:59:20 :851 00001AC4 Trying task 1-2 as LOGON_NORMAL
12/07/2019 20:59:20 :851 00001AC4 Preferred WTS id=1
12/07/2019 20:59:20 :851 00001AC4 Stored token 00000000 replaced with 00000000
12/07/2019 20:59:20 :976 00001AA8 Running task 1-2
The above is an example from my computer for the Schedul2 log showing task 1-2
To identify the correct task number, you need to download the Acronis Scheduler Manager tool (link in my signature), run this as Administrator then issue the command: get list in the command window that is shown. This gets a list of all scheduled tasks along with the long name of the associated script file for the task.
inst=yes start=yes loc task=0-0 > get list
Id ExecApp ExecCmd
--- ---------------
CurUser 1 (DELLSTUDIO\smiths):
1-2 ~*TrueImageHomeNotify* /dummy /script:"0AEAD7F2-8576-46BF-BDB7-02AE8B69215D" /uuid: "0AEAD7F2-8576-46BF-BDB7-02AE8B69215D" /task_type:2 /run_mode:?RunMode?
1-3 ~*TrueImageHomeNotify* /dummy /script:"25AA2C55-0576-4E20-B5D5-4410A6B59910" /uuid: "25AA2C55-0576-4E20-B5D5-4410A6B59910" /task_type:2 /run_mode:?RunMode?
1-4 ~*TrueImageHomeNotify* /dummy /script:"29F90B9C-F74D-4E4B-9ADE-D8D31D2F17F2" /uuid: "29F90B9C-F74D-4E4B-9ADE-D8D31D2F17F2" /task_type:2 /run_mode:?RunMode?
Next, you need to find the task identifier for your E task, which you do by opening Explorer to C:\ProgramData\Acronis\TrueImageHome\Scripts and looking at the .tib.tis files shown there by opening them one by one in a text editor such as Notepad.
You are looking for the text <display> E </display> near the top of the file for the task name, and above this, the UUID for this task, to match this against the list from get list.
<?xml version="1.0" encoding="UTF-8" ?>
<batch>
<version>1.0</version>
<uuid>0AEAD7F2-8576-46BF-BDB7-02AE8B69215D</uuid>
<display>WINPE</display>
<priority>low</priority>
So putting this all together, my WINPE task has an UUID of 0AEAD7F2-8576-46BF-BDB7-02AE8B69215D which in the Scheduler Manager get list, equates to task 1-2.
Once you know the correct task identifier, you can use the Find feature of the MVP Log Viewer to see the various entries where the task is mentioned.
Thank you for the info. Did you see my post above where I pasted in part of the Schedul2 log? task 1-5 is the E job.
What does "Running task 1-5 failed because of: MUTEXES" mean?
MUTEX = Mutually Exclusive
This suggests that there was something else happening on your computer at that time which is preventing the task from running successfully.
Thanks for your help, anyway. I can't find anything in the Windows logs that looks suspicious, but I'll keep looking. I marked the thread solved because I doubt you can help much further.
Are there any other backups running (Windows backup or another tool) at the scheduled time. I wonder if VSS is already in use and unavailable at times.
I'll agree though, this one is a bit odd, and probably hard for us to decipher in the forums. If possible, I would open a support case for this and submit feedback from the app and attach a system report with it for the developers.
I dug through Windows logs and services, etc., yesterday and found that there was another service using VSS running at that time. It's an old service, and should be scheduled to do anything. But I've stopped it from running in the future.
I also moved E's schedule to last in line. (C-D-F-X-E). These are all backing up to a local drive. There's a cloud update that runs after the last local update. I've changed its schedule so that it runs first, instead of last.
Everything ran OK last night. But, then, sometimes it does. I'm keeping an eye on it.
Even the other VSS service does not really explain why it's always E that fails, and never any of the other jobs. They all can have their schedules pushed when C runs long. The only thing I can think of is if, perhaps, the old VSS service was trying to do something with E. That's a possibility, I guess, although it never fails.
It's not a huge deal, even if it keeps failing now and then. But if it starts to happen more frequently I'll certainly open a ticket.
Thanks for your help.
JABecker - good find. I hope that does the trick, but look forward to any findings on the status as well. You might also want to check your scheduled tasks to see if there are any leftovers there that could have been (or still may be) trying to trigger that old VSS job.
Can't say why only E: was impacted here. It could be however the job for E: was created with the old tool (maybe by disk signature or something that is still tied to the drive). Yeah, we'll never get over the overlap of jobs that eat into the time of other scheduled backups. Usually though, they just startup as soon as the opportunity arises if the original schedule has already started. So, you may not always get the exact start time, but definitely better than missing the backup entirely.
Update:
The E backup continued to inconsistently just not run. It was always the E backup, and never C, D, F, or X.
A couple of days after my last reply above, the external drive that I'd been using for backup suddenly temporarily disconnected for no reason that I could see. It was in the middle of a backup at the time, and the backup failed. (It was not the E backup.) I restarted the failed backup and it completed.
This got me wondering if perhaps the drive was doing something funky that somehow caused the E backup to be removed from the queue. I'm not sure what it could be that wouldn't also throw an error. But it uses a USB-C connection. On my Windows box this might be a little flaky. I've never used the USB-C port on my motherboard, which is a couple of years old, for anything but this drive.
I'd been thinking of replacing the single backup drive with a NAS using RAID because I'm tired of replacing backup disks that fail. This seemed like just the time to bite the bullet. I installed a NAS, created completely new backup jobs to use it as destination (just in case the E job was somehow "bad"), and retired the old backup drive.
Since then all of the backup jobs have run flawlessly, including the E job.
I'm still not sure what was going on, but I think the evidence points to something being weird with either the external disk itself or with the USB-C interface, the latter possibly the cable, the drive enclosure, or the motherboard. Since it's all working now, I don't feel inclined to investigate further.
Good to hear that you have a resolution for this issue plus have invested in the new NAS backup solution along the way too. Thanks for sharing your feedback.