Scheduled backups are failing to start when coming out of sleep mode.
I've been struggling with this for a while and cannot figure out what is going on. I have a scheduled backup task which will not start when coming out of sleep mode. I've been through the schedul2 logs and find that the scheduler seems to be running fine and doing everything is is supposed to be doing... except starting the task.
The task in question is a daily backup to start at 19:00. It is Task 1-9. I'm posting the logs around the time in question for the past three days. On the 18th, the system was not in sleep mode and the task started as expected. On the 19, the system was awoken by a Windows scheduled task that I set up to start a minute before the backup is scheduled. (I set this up because in ATI2014, the system was not waking up for scheduled backups.) Today, the 20th, I disabled the Windows scheduled task to let Acronis wake up the system to run the backup.
What I find is that in all logs, the scheduler is saying that the system is waking up. It shows in a number of places that the "next time" is set for 19:00, when the scheduled backup is to be run. But if the system is sleeping shortly before 19:00, although the Acronis scheduler is doing something at the appointed time -- 19:00 -- it is NOT actually starting the task. There is no error condition I can find anywhere to indicate why Acronis will not start the task. But it will set the "next time" for the scheduler to 19:00 on the next day.
The attached logs have some notes inserted to indicate what is going on and I've highlighted some things of interest.
Is anyone else seeing this behavior? Any suggestions for further tests? It's frustrating because I cannot depend on the task to run unless I am here to start it. BTW, I only have the backup NAS on for a couple hours in the evenings to do backups, so I cannot set the option to retry on system startup.
Could the system actually be in hybrid sleep or even hibernation and not really sleep? I believe that it takes physical interaction to take a system out of hybrid sleep or hibernation. Check advanced peer settings and try disabling hybrid sleep, just to see if it helps. I guess this theory is debunked since Windows can wake it up, but let's see anyway.
Also see what option you have for allowed wake timers. There are multiple settings for mobile devices that need to be configured for AC and battery modes too.
Bobbo, my system has hibernation disabled so no hybrid sleep either. I'm not sure what wake timers you are referring to. Regardless, if you look at my log snippets, you can see that the Acronis scheduler is being activated exactly as it should at the time to start the task... it just isn't starting the task. In other words, with the backup scheduled for 19:00 hours, the scheduler is logging at precisely 19:00 hours and then saying it should go again at 19:00 hours the next day.
I submitted a support case to Acronis today so we will see what they have to say. Meanwhile, I'm trying to think of something I can do to make it work regardless... even if it's a hack for now.
Bruno - it should be an advanced power management setting...
https://www.howtogeek.com/122954/how-to-prevent-your-computer-from-waki…
The article explains how to disable them so your machine doesn't wake - check to make sure they are enabled. Try "enabled" and also res try "important wake timers only" if that doesn't help.
Personally, I would take the option to set your power setting back to default and see if that helps. I've had to do that on a few systems as that was the only way I could get some of my machines (non Acronis) to sleep like they were supposed to. Perhaps setting power scheme to default may be all you need, but then you can look at the wake timers a bit more if it still seems to be an issue.
Bobbo, there is no problem with the PC sleeping or waking, it is doing that just as it should. Also, the Acronis Scheduler2 task is being informed when the system awakes from sleep and it is also being informed at the time it should be informed to start the backup task. The logs show it running at exactly the time it should be. The problem is that the Acronis Scheduler2 is not going the final step and actually starting the backup task.
Here you can see in the Schedule2 log exactly what happens when it is correctly starting the backup task within the first two seconds after 19:00.
18.03.2017 19:00:01.684 0000000000000A40 OnServiceMainWake: begin
18.03.2017 19:00:01.685 0000000000000A40 Trying task 1-9 as TIME_NORMAL
18.03.2017 19:00:01.685 0000000000000A40 Stored token 0000000000000000 replaced with 0000000000000000
18.03.2017 19:00:01.685 0000000000000A40 Windows fast startup state to disable: ENABLED PRESENCE
18.03.2017 19:00:01.685 0000000000000A40 Windows fast startup state disabled: BACKUP PRESENCE
18.03.2017 19:00:01.699 0000000000000A40 SetWaitableTimer(-863390000000): error=0
18.03.2017 19:00:01.699 0000000000000A40 OnServiceMainWake: next time = 19.03.2017 10:54:42
18.03.2017 19:00:01.706 0000000000000A4C Running task 1-9
And here is a failing Schedule2 log. It correctly wakes at 19:00, but does not start the scheduled task. I can find no explanation in any of the logs and I've also been through the Windows Event Viewer looking for anything. There is no evidence of any sort of problem. It simply looks like Schedule2 is not doing its job.
19.03.2017 19:00:01.702 0000000000000A7C OnServiceMainWake: begin
19.03.2017 19:00:01.702 0000000000000A7C SetWaitableTimer(-863390000000): error=0
19.03.2017 19:00:01.702 0000000000000A7C OnServiceMainWake: next time = 20.03.2017 10:54:44
19.03.2017 19:09:19.977 000000000000088C OnServiceTimeChange: 0, 0, -78936
Have you tried a new backup task to see if the behavior is the same in it too?
No idea if it's running scheduled tasks while awake but not completing when waking up, other than a service is not fully started that it relies on.
try a new test backup script to see if the behavior is still there or not. You can try running the current version installer with right click and "run as administrator" even if logged in as admin already and try a repair too to see if it helps or not. I can't repeat the behavior you're seeing.
I descheduled the task 1-9 in question, then rescheduled it. I compared the script files and Acronis Scheduler Manager task descriptions from before and after the reschedule. The bad task has an added clear_later_mutexes flag in the FlagsEx and mutex flag missing in the FlagsLater. It also has an ExecApp(Subst) and ExecCmd(Subst) added in the description. They are gone in the changed task.
I then created a new identical task and compared it with the original task. Basically it matches the changed version of the bad task.
Tomorrow we'll see if it's working again.
Looking forward to the outcome. Keep us posted.
It is still failing. And, the script file and the Acronis Scheduler Manager views of the task have changed back to the way they were before I rescheduled. In other words, the mysterious problem is what is changing those files.
Also, in the old script file, I saw two entry lines per backup increment instead of 1 in the <volumes_locations>. When I rescheduled the script was fixed with only one line per increment, but today I am seeing two entries for today's increment only. I didn't check it before manually running the backup so I don't know when the second entry (or the first, for that matter) was created.
I did see tonight that the PC woke up at 18:59... one minute before the scheduled backup. I had disabled the external task in the Task Scheduler so at least I know that Acronis is correctly waking up the computer to run the backup task. This was a problem in ATI 2014 but seems OK here.
In summary, what I thought might have been the cause of the problem was merely another symptom. So now I am moving this backup to a new location on the NAS and I will create a whole new backup scheme from scratch to see where that leads me. Also, I filed a support case with Acronis but have yet to hear back from them.
Good thing I'm retired... and have bourbon.
Bruno,
I'm not retired (still have a ways to go), but I drink plenty of bourbon too - helps to ease the tension when troubleshooting problems like this :), plus it's a pretty fun hobby. Been on a bourbon quest for about 2 years now and working to expand my whiskey (and whisky) knowledge.
I recently started in on Japanese Whisky and am pretty suprised by the quality, but disappoinated in the price gauging now that it seeems to be catching on mainstream. Local Costco has been a blessing for some of these (better than B-Mo and Total-W) it and even Booker's is still $50 here, so plan to get some in stock now that Beam price gouge is for Booker's is upon us.
Feel free to shoot me a PM if you want ot talk more about bourbon or whiskey - it's another passion of mine that I'm tapped into. As for the NAS scheduled backup - curious to see how startign a new task will pan out. Very odd that it's waking, but not kicking in - I think there are some bugs that need to be worked out for the major version "upgrades" that may be playing a part in some of these oddities so am routing that a new task with the current version will serve you well moving forward.
I descheduled the original task and created a whole new one for my daily backup. I decided not to push my luck tonight so I didn't put the computer to sleep. The backup started as expected and completed without incident. Because it was a new task, it did a full backup. Maybe tomorrow I'll put the system to sleep before.
I got a response from Acronis on the support case. They suggested...
1. Restart the Scheduler service. This is pointless since the service is restarted every time I boot windows, which is at least once a day.
2. Reinstall ATI2017. I'm holding off on this option as long as possible.
3. Send 'em a whole lot of stuff. This is the standard request.
Going back to my post #7 on this thread... I discovered today that in Acronis Scheduler Manager, if you run "get report", the result is slightly different from the "get task" command and the difference is what I mentioned in that post. Which means there may not have been a difference. (Does that make sense?)
I'll let it ride for now and see how this new task fares.
Another bourbon, please.
Still failing and I'm getting really frustrated with this. Even the bourbon isn't helping.
I created a new task which ran fine last night when the system was not sleeping. Tonight I put the system to sleep about 5 minutes before the scheduled backup. As can be seen in this part of the log, it woke up fine a minute before the scheduled backup and then the scheduler got control at the time of the backup... and did nothing!
24.03.2017 18:58:59.634 0000000000000870 OnServiceTimeChange: suspend
24.03.2017 18:58:59.634 0000000000000870 Time zone: UTC-7.00 (Pacific Daylight Time)
24.03.2017 18:58:59.685 0000000000001B80 PowerRegisterSuspendResumeNotification callback: Type = 0x12 (PBT_APMRESUMEAUTOMATIC)
24.03.2017 18:58:59.685 0000000000000A48 OnServiceMainWake: begin
-->> right here... it knows that it needs to do something in one minute!
24.03.2017 18:58:59.687 0000000000000A48 OnServiceMainWake: next time = 24.03.2017 19:00:00
24.03.2017 18:58:59.693 00000000000012F0 OnServiceEvent(SE_POWER)
24.03.2017 18:58:59.693 00000000000012F0 power event 0x12 (PBT_APMRESUMEAUTOMATIC) received
24.03.2017 18:59:00.632 0000000000001B80 PowerRegisterSuspendResumeNotification callback: Type = 0x7 (PBT_APMRESUMESUSPEND)
24.03.2017 18:59:00.632 0000000000001B80 Fast startup processing
24.03.2017 18:59:01.920 00000000000012F0 OnServiceEvent(SE_POWER)
24.03.2017 18:59:01.920 00000000000012F0 power event 0x7 (PBT_APMRESUMESUSPEND) received
24.03.2017 19:00:01.687 0000000000000A48 OnServiceMainWake: begin
24.03.2017 19:00:01.687 0000000000000A48 SetWaitableTimer(-863390000000): error=0
-->> right here... it should have started the task! Instead, it just sets the next important time for tomorrow at 19:00!
24.03.2017 19:00:01.687 0000000000000A48 OnServiceMainWake: next time = 25.03.2017 19:00:00
ARGGHH!
So these are the scheduler2 logs, right? What do the TI_Demon logs show as well. This may only be showing that the schedule was enabled and when it is set to run agian. I'm going to run a couple of my own sleep tests, in conjunction with a cloud password test on a new task and see if we can compare notes. My scheduled task didn't even wake up just now so I have to play around with that- my other local scheduled tasks and cloud backups wake up fine.
Bobbo, yes, these are from the scheduler2 logs. The ti_demon log is only created when there is a backup, so no log is generated when the backup does not start.
I'm trying a new experiment for tonight's test. I created a .bat file to restart the scheduler service and through Task Scheduler will wake up the system to run it 2 minutes before the scheduled backup. The file includes:
net stop AcrSch2Svc
net start AcrSch2Svc
Keep me posted on your tests.
Oh the rush... when I saw that beautiful Acronis backup icon in the notification tray at just a couple seconds past 7:00 tonight!
My experiment in the previous post worked. I could see the scheduler2 log for two minutes before my backup where the system was awoken from sleep. And then, the service was stopped. A new instance started with a new log file and lo and behold my backup started!
As a former software developer, I was deeply involved in debugging. This tells me that something in the state of the scheduler2 service was being messed up. And there seems to be no logging information that could tell what it was. But restarting the service in between system wake and backup was what was needed to get things back in order.
I will now reply to the support case and hopefully someone at Acronis can do some experimenting to see if it can be reproduced there.
Now, a happy bourbon...
Bruno, well done for delving deeper into the root cause of this issue, please keep us informed on the outcome of the support case you have open.
Excellent work. You think it would make any differerence to change the scheduler services to autodelayed in lieu of stopping and starting them? Maybe it just isn't ready in time from the wakeup so the stop and restart forces it to kick into gear. Curious if setting from automatic to automatic-delayed would help at all. You've got your temp solution though so may not be worth persuing, but if you do, would be curious.
Bobbo, I don't this changing this would matter because that should only affect when it starts after a Windows boot, not during the wake from sleep scenario. And anyway, the log showed that the scheduler was actually running at the time it should have, it just was not firing off the backup task.
Only way way to find out though. Remember the scheduler service is running when the system is not sleeping so why still need to stop and start it when waking up from sleep? If the scheduler service was completly FUBAR then it would make more sense to me if this had to be done whether it was sleeping or awake, but since it only seems to happen right after waking - it's still a little weird. Probably won't help, but maybe it would. Understand if you're not up for it, but since it's occuring on your system, you're really the only one who can test it for us to verify if it does help or not.
Bobbo, not sure what you are saying to test. The delayed start would not even come into play.
My suspicion is that when the scheduler is either set to sleep or awoken, that process leaves it in a bad state. But then something else may happen that gets it all resynchronized if it is allowed to run a while before the backup happens. One of the things I thought about is that when the system is asleep, the clock is not being updated. But it gets immediately resynchronized on awake. The timestamps on the logs leaves me to believe it is being done OK, but there may be something that is not showing up in the logs that is still left incorrect for awhile.
In doing some further analysis, I came upon a thread from last summer: https://forum.acronis.com/forum/119704?page=1.
It looks like this might be the same issue, which apparently was fixed but maybe it got broken again. Steve and Bobbo, do you remember this one?
Bruno, I do remember the old topic you reminded us of and as you saw, the OP of that topic confirmed that the issue was resolved in ATIH 2017 for him.
I would suggest adding a reference to the old topic to your support case and asking Support to confirm that this is or is not the same issue come back again?