One Backup skipped after midnight
If this is a bug, it's a bit of a strange one.....
I have a backup configured to backup a single small file once an hour. I have automatic clean up set for 15 days. Right now, this series of backups runs at hh:37 during the hour. This all works well except that the 12:37am backup never runs; indeed, it doesn't even get scheduled. For example, at this very moment, the 11:37pm has run, but the next backup is scheduled for 1:37am rather than the expected 12:37am. It does this every day. (BTW, the 12:37pm runs fine mid-day.)
P.S. I've uploaded a screen shot of the folder where these backups are stored.
Sandy, so far my backup is running at hourly intervals similar time to yours with no problem but have another 3 hours (UK time) to go past the midnight scheduled task, so will be checking again in the morning to verify whether I am able to see the same issue as you have described or not?
I didn't do an exact test.
However, I setup an hourly backup and then manually started adjusting the local system time on my machine in Windows settings while Acronis was open to see what would happen. Every time I moved the time forward (manually) in Windows (I didn't do every hour, but skipped a few to speed things up), the Acronis backup kicked off as expected. It even ran the next backup after the midnight change to the next day forward. Perhaps, you could try the same at some point or test on another file in similar fashion as well?
I wonder if there is something else occurring at that same time that could be preventing it from running then? Another backup, or perhaps, the file itself is not there at midnight for some reason (locked by the application creating it because it's currently in use like from a SQL database that is doing it's own backup at that time?)
Ditto to Rob's results. My own hourly task ran all through the night with no missed slots! So does not look to be an issue directly with ATI or the Scheduler but the Scheduler 2 log should be able to give more information as to what happened at the missed run time?
Thanks guys for jumping on this. I appreciate it.
Steve, I d/l'd the tool and ran it (see discussion of results below); but first, allow me to describe the problem in a bit more detail given your and Bobbo's posts.
1. I do have other backups running near the time of this backup. OTOH, that is true for other times of the day also, but none of those other backups fail to get scheduled.
2. I doubt it has anything to do with the file itself because ATI doesn't even attempt to schedule the backup (see log below), so I don't see that ATI would know anything about the characteristics of the file at that first after midnight run.
3. I will stop all other backups for a day to see if that impacts what I am seeing at all.
4. BTW, I am on W10 Pro on a recent ASUS mobo with an AMD 4 x core CPU.
Steve, you mention a "Scheduler 2 log". I don't know what that means. I ran the "ReadLogFileNewGen.exe" tools as is, and it produced the log info I have attached. I assume that is what you are looking for. I don't see in the log any entry for the 00:37am run. It is as if that run doesn't exist.
I have attached 5 files in a zip archive.
- "activity log.jpg" screen shot from last night showing that the 00:37 run is non-existent
- "file backup options1.jpg" and "file backup options2.jpg" screen shots showing how I've configured the backup
- "Log file index.jpg" screen shot of the index to the logs produced by the ReadLogFileNewGen.exe tool for the 1/7/19 to 1/8/19 midnight transition.
- "log data.txt" which is a compilation of the log text entries of the logs shown in the index just before and after midnight. The logs are of the 11:37pm run; a blank log at midnight whose purpose I don't know; another backup that runs at 00:30am; then missing, of course, is the expected 00:37am run; then the regular 1:37am run
Later edit......I just discovered a bit of additional info. While disabling other backups, I noted that I do have a differential scheme backup that is scheduled to run twice a day: once at 12pm and again at 12am. It takes ~5 minutes when doing the full version, and ~1 minute when doing a differential. I assume this backup is the source of the midnight log entry; however, I can see no reason why that log entry is always blank. This 12am backup does run and the backup files are valid; also the 12pm runs *do* have valid data in their log files. Perhaps this blank midnight log entry is a clue.
P.S. Sorry about the extra postings below. I was attempting to edit this msg to clean up typos, and thought I was deleting the msg, when actually I was quoting it and posting it again. I can't figure out how to delete msgs on this board. I will research and clean up if I can.
Sandy,
Strange stuff, really hard to say in this case. Not sure what the file is created/modified with, or how, but it is odd it is missing that one backup at that same time.
Only other suggestions...
Change the backup time to something else - let's say daily and apply. Then change it back to hourly and see how it goes the next time. Maybe it just needs a kick in the pants :)
If that doesn't do the trick, could try creating an entirely new backup task that is hourly and see if it makes any difference or not (maybe something clooge-y in the existing backup task we can try to rule out, or not).
If it's still not working after that... well, I'd be curious if the program making/modifying the log file is deleting it at the end of the day and recreating it at 1AM? Probably not, but I've see a few oddball programs work like that. If the file didn't exist at all, you'd think that Acronis would still try to backup and then fail, but maybe it just detects it's not there and doesn't run until it's created again.
I had a SQL database that would back itself up automatically at a set time in the early morning and it relied on VSS to make that backup. While it was using VSS, the third party backup tools on the machine couldn't call on it so that was what lead me to this thought before. Not sure if something similar could be happening or not at the exact same time on this system.
-------------------------------------
Oops just noticed your comment about the other differential backup that runs twice a day... Still odd the other one wouldn't run. Usually, if one job is in progress when another is set to kick off, it will just go into the queue and then run as soon as it's available. I wonder if the hourly scheme just skips until the next hour, or something like that, but have not seen that behavior before. I'll dig through the .zip file you provided to see if anything stands out.
Sandy, thanks for the zip file, I am not seeing anything there that would explain why the midnight backup task is not running. As Rob says above, if another task is running, then the alarm task should get queued behind it to run.
In the MVP Log Viewer tool, please change the Log Type setting to the Scheduler 2 logs and save a copy of that log (ideally keeping the original name for the log file(s) or zipping up the C:\ProgramData\Acronis\Schedule2 folder contents) then uploading that zip file to this topic.
Here is the "Schedul2" log. I did several tests attempting to eliminate potential conflicts and/or confusion
First, I turned off the the program that uses this file. This program produces reminders (called "alarms"). It has an HTML file in which it keeps data on these alarms. The program is normally running at all times on my system, and its HTML data file can be written to or read from at any time......at any hour or any minute. ATI seems to backup this HTML data file just fine while the file is open; however, to eliminate any conflicts during these tests, I am NOT running this alarm program; so this HTML data file is NOT open during any of these tests.
Second, I disabled (not scheduled) all backups that are normally scheduled between 11pm and 1am daily. I implemented this in various stages over 3 days of transitions at midnight. The log file I am suppling contains each of these transitions:
1/9 to 1/10 transition
all backups enabled (including those within an hour of midnight)
1/10 to 1/11 transition
another backup that is scheduled to run at 12am and 12pm is set to "not scheduled" in order to eliminate possible conflicts
1/11 to 1/12 transition
all backups after 11pm and before 1am are set to "not scheduled"
BTW, The reason I backup this HTML file every hour is due to a problem I experience with the alarm program. Occasionally, this program must be closed and re-started; when this is done, and under certain circumstances, the HTML alarm data file does not get updated before closing; this results in lost alarm data that can't be recovered. So I backup this file frequently. In this manner, if I lose this alarm file, I can restore the file as it was no more than an hour ago. This ATI 'midnight" problem is not really a hassle for me since I have backups for the other 23 hours of the day. Missing this 00:37 backup is not a true concern of mine. However, I am interacting with you all simply because I am very impressed with the ATI backup system and appreciate what appears to me to be a commitment to quality. I figured that if there is a bug in the programming (and it sure looks like it to me), you'd want to know about it.
P.S. The file name for the attached log file below was: C:\ProgramData\Acronis\Schedule2\2019.01.06-21.25.52.190-schedul2.exe-EA3C3C83-FCAC-4FEE-ADDC-28400F9FBAF2.log
Sandy, thank you for the Scheduler 2 log data. This definitely shows that there is no attempt at all to run your missing task in the midnight slot!
See the attached abbreviated log data showing only the entries for Task 1-42 which runs hourly at all other times throughout the log.
Example of the extracted log data:
06/01/2019 22:37:00 :001 Trying task 1-42 as TIME_NORMAL 06/01/2019 22:37:00 :113 Running task 1-42 06/01/2019 22:37:47 :372 Task 1-42 completed with exit code=0 06/01/2019 23:37:00 :002 Trying task 1-42 as TIME_NORMAL 06/01/2019 23:37:00 :045 Running task 1-42 06/01/2019 23:37:35 :353 Task 1-42 completed with exit code=0 07/01/2019 01:37:00 :001 Trying task 1-42 as TIME_NORMAL 07/01/2019 01:37:00 :033 Running task 1-42 07/01/2019 01:37:36 :079 Task 1-42 completed with exit code=0 07/01/2019 02:37:00 :001 Trying task 1-42 as TIME_NORMAL 07/01/2019 02:37:00 :042 Running task 1-42 07/01/2019 02:37:36 :375 Task 1-42 completed with exit code=0 07/01/2019 03:37:00 :001 Trying task 1-42 as TIME_NORMAL 07/01/2019 03:37:00 :043 Running task 1-42 07/01/2019 03:37:34 :670 Task 1-42 completed with exit code=0
The options at this point would be as follows:
1. Open a Support Ticket with Acronis for this issue and reference this forum topic.
2. Try doing a Repair Install of ATI 2019 (re-install without uninstalling) and if that doesn't help then
3. Do a Clean Install of ATI 2019 - uninstall normally, run the Acronis Cleanup tool (link below) then reinstall. Note: save your backup task configuration data to a zip file using the option in the GUI Settings page.
I finally deleted the backup task and re-created it. That fixed the problem, but only for a few days. Eventually, it always comes back. This is why those of you who tested the problem didn't see it. The backup task has to run for a few days.
So today I submitted a trouble ticket to Acronis.
Bummer. Yeah, no idea why this behavior would return and only for this file. Hopefully technical support can find the root cause.
Another possibility, would be to run task zap and delete it from the database that way. Once deleted, clone the existing backup task and then re-pick the source and destination. Save the new backup, but use a unique name (modify it enough so it's not exactly the same as the original - just in case). Then delete the original backup task and run the new one and see if the problem comes back or not.
Bobbo_3C0X1,
I'm not sure I understand your suggestions here.
First, the reason that only this file in involved is that the ATI backup task only backs up this one file. There are no other files being backed up by this task (reasons etc were explained above).
Second, I deleted the task, and subsequently re-created it from scratch including re-picking the source and destination and all other aspect of the task. I did not clone the task, I re-created it after I deleted the original task. OTOH, when I re-created it, I did use the same task name. If you think deleting a task does not remove something, I could try re-creating it again, and this time use a different task name.
P.S. Note I assumed that when I deleted the original task, that did remove it from the database.
I understand what you're saying. Just meant that I don't understand why this one file is problematic. Never seen this behavior on any of my systems or in the forum in general.
Well, you would think that deleting the script and recreating would delete all traces of it, but every now and then something hangs on. That's why they have the taskzap tool. There have been other forum threads of "ghost" entries in taskscheduler after they were deleted from the console.
So, it probably wouldn't hurt to delete the task in the console again, then check with task scheduler and/or run taskzap to delete all of script entries scheduled tasks. Then recreate and use a slightly different name. Worse case, the behavior comes back again, but hopefully this will fix it for good. If not, I'm out of ideas and hopefully technical support can figure out what's going on . Again, this seems really unique and can't think of any other threads like this.
One other thought - just based on another thread from today. Maybe go into your system admin tools >>> services an set the Acronis Scheduler 2 service to automatic (delayed) instead of just the default of automatic. Perhaps the service is failing to fully start in the allotted time and this will give it a few more seconds to startup before Windows decides to stop it, if there is any issue like this happening.
Bobbo, just for the fun of it, I will do some additional testing to address some of the issues you raise.
I can't believe this behavior has anything to do with the specific file, but since another program always has this file open, perhaps. None the less, I would think that ATI would at least throw a error message when it is not able to run a scheduled task. Also, I will recreate the task with a new name etc and see if that makes a difference.
I've set the scheduler2 service for delayed. I'll report back here if that makes any difference. (BTW, it seems on my system that the Schedule2 task is always running, so it would seem the delay in starting couldn't affect this behavior.)
Yeah, all just possibilities. No idea why it behaves this way on this file and just in that hourly backup at times. It could very well be a bug with the time at 0000. I could see it being an issue on a time change day, but not on a regular basis.
I could see it being an issue on a time change day, but not on a regular basis.
Exactly, that's what made me think in the first place that it might be a bug. It only happens on the 1st hourly backup after the change to 00:00 hours......a classic situation for a bug to sneak in there.