Aller au contenu principal

Scheduled backups do not run

Thread needs solution

My scheduled backups ran for the first 3 days, then stopped occuring. I can do manual backups. I get no error messages, the scheduled backup just always shows one scheduled for tomorrow. I still have 468G available on a 1TB external hard drive (WD Passport brand).

 

Any suggestions on what to look for or how to solve? I've been searching the forums for several hours, but don't see this problem listed. 

0 Users found this helpful

Hi Michael,

Grab FTRPilot's log viewer and check some of the service.logs.  You can attach a couple of them here for additional eyes too.  They may help shed some light on the problem.

Scheduled backups may be missed if the system is sleeping during the scheduled time, or if the drive has changed (for instance, if Windows assigned a different drive letter than what was originally assigned when the backup was configured - this could be the case since you're using a USB as the external).  

Windows 10 FAST Startup/Fastboot can also be an issue because the system goes into hibrernation when you shutdown instead of actually shutting down so it does not trigger a missed backup to run when it wakes up.  If you reboot and the missed backup starts running, chances are fastboot is the problem.  You can either disable hibernation completely which will turn off fastboot, or you will have to reboot (a reboot triggers a full shutdown) from time to time.  Acronis 2017 handles fastboot correctly now, but 2016 was coded differently and doesn't play as nice with fastboot.  

Personally, I disable fastboot on all of my systems.  With a decent SSD, I can't tell the difference with fastboot on or off (save maybe 1 or 2 seconds in some rare instances) and prefer backups to run correctly than save 2 seconds (in some cases).  If you have a spinning hard drive, fastboot may save much more time so it's a trade-off with ATI 2016 where you'll have to reboot (not shutdown or wake from sleep)  more frequently.  

 

OK, more information that will hopefully help. 

 

System info:

Windows 7 Home Premium, 64-bit, SP1

Acronis True Image 2016, Build 6581

I leave my system on continuously, 24 hours a day, 7 day a week. I don't use hibernate, sleep, suspend, or fast boot.

I DO use GRUB-2 as my boot loader, not UETF.

 

Symptoms: 

There is no log for the days when the scheduled backup is missed. It's as if Acronis never even tried. The only logging occurs when I click "Back up Now".

 

 

Here is the log file: 

log uuid=259DE63A-935B-4160-BFF0-219DCAF1CA25;  product=True Image;  version=19.0;  build=6581;  task=6A8EE620-C498-4FC4-A9D6-3488B9704C1E;  task_name=Entire PC (EAGLE)
Start= 11/2/2016 7:12:41 AM
id=1;  level=2;  module=100;  code=0;  date/time=11/2/2016 7:12:41 AM
          message=Backup reserve copy attributes: format tib; need_reserve_backup_copy false
id=2;  level=2;  module=100;  code=2;  date/time=11/2/2016 7:12:41 AM
          message=Operation Entire PC (EAGLE) started manually.
id=3;  level=2;  module=100;  code=0;  date/time=11/2/2016 7:12:43 AM
          message=Backup reserve copy attributes: format tib; need_reserve_backup_copy false
id=4;  level=2;  module=316;  code=0;  date/time=11/2/2016 7:12:43 AM
          message=Operation: Backup
id=5;  level=2;  module=100;  code=11;  date/time=11/2/2016 7:12:43 AM
          message=Priority changed to Low.
id=6;  level=2;  module=11;  code=1008;  date/time=11/2/2016 7:12:43 AM
          message=Create Backup Archive From:  To file: F:\Entire PC (EAGLE).tib Compression: Normal Exclude: Files matching mask Match criterion:
          hiberfil.sys
          pagefile.sys
          $Recycle.Bin
          swapfile.sys
          System Volume Information
          *.tib
          *.tib.metadata
          *.~
          *.tmp
          C:\Users\Blakely\AppData\Local\Temp
          C:\Users\UpdatusUser\AppData\Local\Temp
          C:\Users\Steven\AppData\Local\Temp
          C:\Users\UpdatusUser\AppData\Local\Temp
          C:\Users\UpdatusUser\AppData\Local\Temp
          C:\Users\Blakely\AppData\Local\Microsoft\Windows\Temporary Internet Files
          C:\Users\UpdatusUser\AppData\Local\Microsoft\Windows\Temporary Internet Files
          C:\Users\Steven\AppData\Local\Microsoft\Windows\Temporary Internet Files
          C:\Users\UpdatusUser\AppData\Local\Microsoft\Windows\Temporary Internet Files
          C:\Users\UpdatusUser\AppData\Local\Microsoft\Windows\Temporary Internet Files
          C:\Users\Blakely\AppData\Local\Google\Chrome\User Data\Default\Cache
          C:\Users\Blakely\AppData\Local\Opera Software
          C:\Users\Blakely\AppData\Local\Mozilla\Firefox\Profiles
          C:\Users\Blakely\AppData\Local\Google\Chrome\User Data\Default\Cache
          C:\Users\Blakely\AppData\Local\Opera Software
          C:\Users\Blakely\AppData\Local\Mozilla\Firefox\Profiles
          C:\Users\Blakely\AppData\Local\Google\Chrome\User Data\Default\Cache
          C:\Users\Blakely\AppData\Local\Opera Software
          C:\Users\Blakely\AppData\Local\Mozilla\Firefox\Profiles
          C:\Users\Blakely\AppData\Local\Google\Chrome\User Data\Default\Cache
          C:\Users\Blakely\AppData\Local\Opera Software
          C:\Users\Blakely\AppData\Local\Mozilla\Firefox\Profiles
          C:\Users\Blakely\AppData\Local\Google\Chrome\User Data\Default\Cache
          C:\Users\Blakely\AppData\Local\Opera Software
          C:\Users\Blakely\AppData\Local\Mozilla\Firefox\Profiles
          C:\Windows\CSC

id=7;  level=2;  module=1;  code=504;  date/time=11/2/2016 7:12:45 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=8;  level=2;  module=1;  code=504;  date/time=11/2/2016 7:13:09 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=9;  level=2;  module=100;  code=0;  date/time=11/2/2016 7:20:59 AM
          message=Writing incremental version to file: Entire PC (EAGLE)_inc_b1_s3_v1.tib
id=10;  level=2;  module=1;  code=504;  date/time=11/2/2016 7:22:37 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=11;  level=3;  module=7;  code=46;  date/time=11/2/2016 7:22:37 AM
          message=Forced sector-by-sector mode.;  line_tag=0xA5695862AAF8E7B0
Error_Code=AS4ABwCw5/iqYlhppUZvcmNlZCBzZWN0b3ItYnktc2VjdG9yIG1vZGUuAFBhcnRpdGlvbklkAE7fAAAAAAAAACRtb2R1bGUAQXRpX2RlbW9uX3ZzXzY1ODEAJGZpbGUAQWs6XDY1ODFccmVzaXplclxiYWNrdXBcYmFja3VwLmNwcAAkZnVuYwBBcmVzaXplcjo6QmFja3VwSW1hZ2VCdWlsZGVySW1wOjpDcmVhdGVPdXRwdXRTdHJlYW0AJGxpbmUATlMEAAAAAAAAABYABwBME6f828pBgkJsb2NrIGJpdG1hcCBjb3JydXB0ZWQAJG1vZHVsZQBBdGlfZGVtb25fdnNfNjU4MQAkZmlsZQBBazpcNjU4MVxyZXNpemVyXGV4dDJmc1xmc19leHQyLmNwcAAkZnVuYwBBcmVzaXplcjo6RXh0MmZzUHJvY2Vzc29yOjpGcmVlTGVhZnNJbm9kZVByb2Nlc3Nvcjo6UHJvY2Vzc0Jsb2NrACRsaW5lAE7QEAAAAAAAAAA=
id=12;  level=3;  module=7;  code=22;  date/time=11/2/2016 7:22:37 AM
          message=Block bitmap corrupted;  line_tag=0x8241CADBFCA7134C;  hide=1
id=13;  level=2;  module=1;  code=504;  date/time=11/2/2016 7:22:40 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=14;  level=3;  module=7;  code=46;  date/time=11/2/2016 7:22:40 AM
          message=Forced sector-by-sector mode.;  line_tag=0xA5695862AAF8E7B0
Error_Code=AS4ABwCw5/iqYlhppUZvcmNlZCBzZWN0b3ItYnktc2VjdG9yIG1vZGUuAFBhcnRpdGlvbklkAE7hAAAAAAAAACRtb2R1bGUAQXRpX2RlbW9uX3ZzXzY1ODEAJGZpbGUAQWs6XDY1ODFccmVzaXplclxiYWNrdXBcYmFja3VwLmNwcAAkZnVuYwBBcmVzaXplcjo6QmFja3VwSW1hZ2VCdWlsZGVySW1wOjpDcmVhdGVPdXRwdXRTdHJlYW0AJGxpbmUATlMEAAAAAAAAABYABwBME6f828pBgkJsb2NrIGJpdG1hcCBjb3JydXB0ZWQAJG1vZHVsZQBBdGlfZGVtb25fdnNfNjU4MQAkZmlsZQBBazpcNjU4MVxyZXNpemVyXGV4dDJmc1xmc19leHQyLmNwcAAkZnVuYwBBcmVzaXplcjo6RXh0MmZzUHJvY2Vzc29yOjpGcmVlTGVhZnNJbm9kZVByb2Nlc3Nvcjo6UHJvY2Vzc0Jsb2NrACRsaW5lAE7QEAAAAAAAAAA=
id=15;  level=3;  module=7;  code=22;  date/time=11/2/2016 7:22:40 AM
          message=Block bitmap corrupted;  line_tag=0x8241CADBFCA7134C;  hide=1
id=16;  level=2;  module=1;  code=504;  date/time=11/2/2016 7:24:27 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=17;  level=3;  module=7;  code=46;  date/time=11/2/2016 7:24:29 AM
          message=Forced sector-by-sector mode.;  line_tag=0xA5695862AAF8E7B0
Error_Code=AS4ABwCw5/iqYlhppUZvcmNlZCBzZWN0b3ItYnktc2VjdG9yIG1vZGUuAFBhcnRpdGlvbklkAE7jAAAAAAAAACRtb2R1bGUAQXRpX2RlbW9uX3ZzXzY1ODEAJGZpbGUAQWs6XDY1ODFccmVzaXplclxiYWNrdXBcYmFja3VwLmNwcAAkZnVuYwBBcmVzaXplcjo6QmFja3VwSW1hZ2VCdWlsZGVySW1wOjpDcmVhdGVPdXRwdXRTdHJlYW0AJGxpbmUATlMEAAAAAAAAABYABwBME6f828pBgkJsb2NrIGJpdG1hcCBjb3JydXB0ZWQAJG1vZHVsZQBBdGlfZGVtb25fdnNfNjU4MQAkZmlsZQBBazpcNjU4MVxyZXNpemVyXGV4dDJmc1xmc19leHQyLmNwcAAkZnVuYwBBcmVzaXplcjo6RXh0MmZzUHJvY2Vzc29yOjpGcmVlTGVhZnNJbm9kZVByb2Nlc3Nvcjo6UHJvY2Vzc0Jsb2NrACRsaW5lAE7QEAAAAAAAAAA=
id=18;  level=3;  module=7;  code=22;  date/time=11/2/2016 7:24:29 AM
          message=Block bitmap corrupted;  line_tag=0x8241CADBFCA7134C;  hide=1
id=19;  level=2;  module=1;  code=504;  date/time=11/2/2016 8:07:07 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=20;  level=2;  module=1;  code=504;  date/time=11/2/2016 8:07:07 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=21;  level=2;  module=1;  code=504;  date/time=11/2/2016 8:07:07 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=22;  level=2;  module=100;  code=0;  date/time=11/2/2016 8:07:07 AM
          message=The following backups have been successfully created: F:\Entire PC (EAGLE)_inc_b1_s3_v1.tib
id=23;  level=2;  module=316;  code=6;  date/time=11/2/2016 8:07:07 AM
          message=Operation has succeeded.
Start= 11/2/2016 7:12:41 AM
Finish= 11/2/2016 8:07:07 AM
Total Time= 00:54:26

 

 

Michael, your log file shows that you have got a problem with your disk drive:

message=Forced sector-by-sector mode - this occurs when bad sectors or drive information is encountered.

message=Block bitmap corrupted - again this is a serious issue.  You need to run CHKDSK /F /R to check the drive(s) involved.

If you check the size of the F:\Entire PC (EAGLE)_inc_b1_s3_v1.tib backup image file, you may find that this is significantly larger than you expect as sector-by-sector mode will backup the whole partition, not just the data you selected - this will include unused sectors from the drive.

I ran chkdsk on both the C: drive (backup source) and the F: drive (backup destination). chkdsk didn't report any errors. Re-ran a full backup and the log is identical with the same 3 pairs of forced sector-by-sector mode/block bitmap corrupted errors. 

 

Would these errors prevent the nightly backup from running, or even being attempted? 

 

Any other suggestions for how to isloate the root cause of the errors? 

Michael, the problem with the bad sector or corrupted bitmap may be on one of the hidden / system partition that are being included in your backup source.

I would suggest taking an alternative approach to isolating where the problem is.  Make an individual backup of each partition in turn, one by one, until you find the one that is causing the problem.

Same exact problem, except my "service" logs show no errors, ex:

log uuid=D91B7130-2927-48FF-AB51-30E98CC05FC4;  product=True Image;  version=19.0;  build=6581;  task=631BD304-B71D-486D-ABDF-6A550F17F276;  task_name=Sys Image (INGRID)-1
Start= 11/9/2016 1:50:54 AM
id=1;  level=2;  module=100;  code=0;  date/time=11/9/2016 1:50:54 AM
          message=Backup reserve copy attributes: format tib; need_reserve_backup_copy false
id=2;  level=2;  module=100;  code=2;  date/time=11/9/2016 1:50:54 AM
          message=Operation Sys Image (INGRID)-1 started manually.
id=3;  level=2;  module=100;  code=0;  date/time=11/9/2016 1:50:55 AM
          message=Backup reserve copy attributes: format tib; need_reserve_backup_copy false
id=4;  level=2;  module=316;  code=0;  date/time=11/9/2016 1:50:56 AM
          message=Operation: Backup
id=5;  level=2;  module=11;  code=1008;  date/time=11/9/2016 1:50:56 AM
          message=Create Backup Archive From: Disk 2 To file: F:\Acronis Backups\Ingrid\Sys Image (INGRID)-1.tib Compression: High Exclude: Files matching mask Match criterion:
          hiberfil.sys
          pagefile.sys
          $Recycle.Bin
          swapfile.sys
          System Volume Information
          *.tib
          *.tib.metadata
          *.~
          *.tmp
          C:\Users\defaultuser0\AppData\Local\Temp
          C:\Users\GregK\AppData\Local\Temp
          C:\Users\defaultuser0\AppData\Local\Microsoft\Windows\INetCache
          C:\Users\GregK\AppData\Local\Microsoft\Windows\INetCache
          C:\Users\GregK\AppData\Local\Google\Chrome\User Data\Default\Cache
          C:\Users\GregK\AppData\Local\Opera Software
          C:\Users\GregK\AppData\Local\Mozilla\Firefox\Profiles
          C:\Windows\CSC
          C:\Windows.OLD
          C:\Users\GregTNL\AppData\Local\Temp
          C:\Users\GregTNL\AppData\Local\Microsoft\Windows\INetCache
          C:\Users\GregTNL\AppData\Local\Google\Chrome\User Data\Default\Cache
          C:\Users\GregTNL\AppData\Local\Mozilla\Firefox\Profiles

id=6;  level=2;  module=1;  code=504;  date/time=11/9/2016 1:50:56 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=7;  level=2;  module=1;  code=504;  date/time=11/9/2016 1:50:57 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=8;  level=2;  module=100;  code=0;  date/time=11/9/2016 1:50:58 AM
          message=Writing incremental version to file: Sys Image (INGRID)-1_inc_b3_s27_v1.tib
id=9;  level=2;  module=1;  code=504;  date/time=11/9/2016 1:50:58 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=10;  level=2;  module=1;  code=504;  date/time=11/9/2016 1:52:09 AM
          message=Pending operation 172 started: 'Creating partition image'.
id=11;  level=2;  module=100;  code=0;  date/time=11/9/2016 1:52:09 AM
          message=The following backups have been successfully created: F:\Acronis Backups\Ingrid\Sys Image (INGRID)-1_inc_b3_s27_v1.tib
id=12;  level=2;  module=11;  code=1026;  date/time=11/9/2016 1:52:10 AM
          message=Validate Backup Archive Location: F:\Acronis Backups\Ingrid\Sys Image (INGRID)-1_inc_b3_s27_v1.tib  
id=13;  level=2;  module=1;  code=504;  date/time=11/9/2016 1:52:10 AM
          message=Pending operation 4 started: 'Validate Backup Archive'.
id=14;  level=2;  module=316;  code=6;  date/time=11/9/2016 2:24:09 AM
          message=Operation has succeeded.
id=15;  level=2;  module=103;  code=0;  date/time=11/9/2016 2:24:13 AM
          message=The e-mail notification has been successfully sent.
id=16;  level=2;  module=103;  code=0;  date/time=11/9/2016 2:24:13 AM
          message=Batch operation has completed successfully.
Start= 11/9/2016 1:50:54 AM
Finish= 11/9/2016 2:24:13 AM
Total Time= 00:33:19

As described above, when a backup is missed, the "Next Backup" time in the True Image applicaition advances to the next scheduled time, but there's no evidence the backup task tried to start and no errors in the Windows event logs. After a missing scheduled backup I checked the scheduler2 service and it was running as usual.

My PC usually has to wake from sleep to run a backup, since they happen in the middle of the night. I have it set to keep the PC awake, and not to restart missed backups.

Sometimes restarting the PC gets backups going again for a day or three, sometimes not.

I am seeing this both on my home desktop (running Win 10 Pro v1607) and a work laptop (running Win 10 Enterprise v1607 and a few applications in common including MS Office 2016.)

Fast startup and hibernation are disabled, as I have SSD system drives in both systems.

Last night I was awake when the backup was scheduled, and the PC woke up on time. I had to get through the lock screen to see what was going on and nothing was running. I started the TIH main app and the "next backup" had already advanced to the next day. The destination disk was available and on the drive letter it always is.

I can't tell what makes Schedule2 drop a log. (Updating wake timers?) I'm attaching a ZIP file of before&after logs bracketing the time of the missed backup (1:45 AM PDT 11/9/16)

Hope there's a fix or workaround for this. It's pretty annoying. I'd revert but the constant "new version" popups are even more annoying.

Fichier attaché Taille
397912-135115.zip 9.79 Ko

Greg, thank you for the schedule2 logs data, this, to me, looks to be showing a possible issue related to Windows Fast Start even though you say that this is disabled on your system?  From the logs I see the following:

06.11.2016 07:55:52.614 0000000000001614 Trying task 1-2 as MANUAL
06.11.2016 07:55:52.614 0000000000001614 Preferred WTS id=1
06.11.2016 07:55:52.628 0000000000000FF8 Running task 1-2
..
06.11.2016 08:28:15.175 0000000000000FF8 Task 1-2 completed with exit code=0
..
06.11.2016 08:43:14.180 0000000000000FE0 OnServiceMainWake: next time = 7.11.2016 01:45:00
..
07.11.2016 01:42:44.527 00000000000021C8 Fast startup processing
07.11.2016 01:42:44.527 0000000000000FE0 OnServiceMainWake: begin
07.11.2016 01:42:44.528 0000000000004374 OnServiceEvent(SE_POWER)
07.11.2016 01:42:44.528 0000000000000FE0 OnServiceMainWake: next time = 7.11.2016 01:45:00
07.11.2016 01:42:44.528 0000000000004374 power event 0x7 (PBT_APMRESUMESUSPEND) received
07.11.2016 01:45:01.532 0000000000000FE0 OnServiceMainWake: begin
07.11.2016 01:45:01.532 0000000000000FE0 Trying task 1-2 as TIME_NORMAL
07.11.2016 01:45:01.532 0000000000000FE0 SetWaitableTimer(-863390000000): error=0
07.11.2016 01:45:01.532 0000000000000FE0 OnServiceMainWake: next time = 8.11.2016 01:45:00
..
07.11.2016 01:45:01.532 0000000000000FF8 Running task 1-2
..
07.11.2016 02:20:04.584 0000000000000FF8 Task 1-2 completed with exit code=0
..
07.11.2016 07:08:45.543 0000000000000FE0 OnServiceMainWake: next time = 8.11.2016 01:45:00
..
08.11.2016 01:45:01.145 0000000000000FE0 OnServiceMainWake: begin
08.11.2016 01:45:01.145 0000000000000FE0 Trying task 1-2 as TIME_NORMAL
..
08.11.2016 01:45:01.161 0000000000000FF8 Running task 1-2
..
08.11.2016 02:20:36.299 0000000000000FF8 Task 1-2 completed with exit code=0
..
08.11.2016 06:57:52.654 0000000000000FE0 OnServiceMainWake: next time = 9.11.2016 01:45:00
..

09.11.2016 01:42:33.399 0000000000000B0C Fast startup processing
09.11.2016 01:42:45.749 0000000000001814 OnServiceEvent(SE_POWER)
09.11.2016 01:42:45.749 0000000000001814 power event 0x7 (PBT_APMRESUMESUSPEND) received
09.11.2016 01:45:01.515 0000000000001084 OnServiceMainWake: begin
09.11.2016 01:45:01.515 0000000000001084 SetWaitableTimer(-863390000000): error=0
09.11.2016 01:45:01.515 0000000000001084 OnServiceMainWake: next time = 10.11.2016 01:45:00
..
09.11.2016 01:50:54.017 00000000000045F8 API Entry: OP=SET_TASK_FAILED_MAX_RETRIES Ver=4 Misc=0 Id=2 IntUser=1 LogonSid=S-1-5-5-0-2771133 User=INGRID\GregK
09.11.2016 01:50:54.017 00000000000045F8 API Reply: OP=SET_TASK_FAILED_MAX_RETRIES Ver=4 Status=0 Misc=0 Id=2
09.11.2016 01:50:54.017 00000000000045F8 API Entry: OP=SET_TASK_FAILED_INTERVAL Ver=4 Misc=0 Id=2 IntUser=1 LogonSid=S-1-5-5-0-2771133 User=INGRID\GregK
09.11.2016 01:50:54.019 00000000000045F8 API Reply: OP=SET_TASK_FAILED_INTERVAL Ver=4 Status=0 Misc=0 Id=2
09.11.2016 01:50:54.019 00000000000045F8 API Entry: OP=SET_MAX_DELAY_FOR_TRIGGER_SECONDS_INTERVAL Ver=4 Misc=0 Id=2 IntUser=1 LogonSid=S-1-5-5-0-2771133 User=INGRID\GregK
09.11.2016 01:50:54.021 00000000000045F8 API Reply: OP=SET_MAX_DELAY_FOR_TRIGGER_SECONDS_INTERVAL Ver=4 Status=0 Misc=0 Id=2
..
09.11.2016 01:50:54.030 0000000000001814 Trying task 1-2 as MANUAL
09.11.2016 01:50:54.030 0000000000001814 Preferred WTS id=1
09.11.2016 01:50:54.043 000000000000108C Running task 1-2
..
09.11.2016 02:24:13.220 000000000000108C Task 1-2 completed with exit code=0
..
09.11.2016 06:50:24.485 0000000000001084 ExecuteShutdownTasks begin
09.11.2016 06:50:24.485 0000000000001084 Sent wait result SHUTDOWN_STARTED notification: WaitID = 219

From the above, it shows that you ran the scheduled task manually on 6/11 then it ran to schedule on 7/11 & 8/11 and then was run again manually on 9/11 after the scheduler didn't show any indication of recognising a task to be run.

I would suggest downloading and running the Acronis Scheduler Manager program (link below in my signature) and using this to clean out all current scheduler entries, then go into your backup task and check that this still shows your daily schedule configuration for 01:45am - reset this if needed then click on Backup Later to save the settings and reestablish the schedule.

Run the schedmgr.exe program as administrator, this will open a command prompt type windows, enter the command get list to show how many entries are known by the schedule manager, then the command task zap to clear that list of scheduled tasks.
 

OK, I cleared out the task list, reset the schedule from the main UI (it was cleared) and for good measure turned on support logging. We'll see what happens. Might take a few days if it is going to start missing backups again.

Also attached screen cap of Fast Start turned off.

Thanks for the help!

inst=yes start=yes loc task=0-0 > get list
Id ExecApp ExecCmd
--- ---------------
CurUser 1 (INGRID\GregK):
  1-2  ~*TrueImageHomeNotify* /dummy /script:"631BD304-B71D-486D-ABDF-6A550F17F276" /uuid:"631BD304-B71D-486D-ABDF-6A550F17F276" /run_mode:?RunMode?
  1-3   C:\Program Files (x86)\Acronis\TrueImageHome\TrueImageMonitor.exe /shutup
User 2 (NT AUTHORITY\SYSTEM):
  2-1   C:\Program Files (x86)\Acronis\TrueImageHome\prl_stat.exe for_scheduler
User 3 (INGRID\GregTNL):
  3-1   C:\Program Files (x86)\Acronis\TrueImageHome\TrueImageMonitor.exe /shutup
inst=yes start=yes loc task=0-0 > task zap
inst=yes start=yes loc task=0-0 > get list
Id ExecApp ExecCmd
--- ---------------

​(Schedule restored)

inst=yes start=yes loc task=0-0 > get list
Id ExecApp ExecCmd
--- ---------------
CurUser 1 (INGRID\GregK):
  1-1  ~*TrueImageHomeNotify* /dummy /script:"631BD304-B71D-486D-ABDF-6A550F17F276" /uuid:"631BD304-B71D-486D-ABDF-6A550F17F276" /run_mode:?RunMode?
inst=yes start=yes loc task=0-0 > set logflags support
Fichier attaché Taille
397953-135124.png 26.68 Ko

I'm back. That didn't take long. Scheduled backup at 1:45 AM on 2016-11-11 missed, ran manually at about 2:34 am. New logs (with "Support" level logging) attached.

I'm going to try enabling Fast Startup, as most people will have that enabled by default, and most people aren't complaining about missed backups.

Fichier attaché Taille
397971-135133.zip 20.81 Ko

New logs show:

10.11.2016 01:42:44.044 00000000000010C4 OnServiceMainWake: next time = 10.11.2016 01:45:00
10.11.2016 01:42:44.076 0000000000001A24 OnServiceEvent(SE_POWER)
10.11.2016 01:42:44.076 0000000000001A24 power event 0x12 (PBT_APMRESUMEAUTOMATIC) received
10.11.2016 01:45:01.045 00000000000010C4 OnServiceMainWake: begin
10.11.2016 01:45:01.045 00000000000010C4 Trying task 1-2 as TIME_NORMAL
10.11.2016 01:45:01.061 00000000000010C4 SetWaitableTimer(-863390000000): error=0
10.11.2016 01:45:01.061 00000000000010C4 OnServiceMainWake: next time = 11.11.2016 01:45:00
10.11.2016 01:45:01.061 00000000000014B4 API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Task=1-2 Result=3(RUN_WAITED) Extra=8(TIME_NORMAL)
10.11.2016 01:45:01.061 0000000000000C04 API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Task=1-2 Result=3(RUN_WAITED) Extra=8(TIME_NORMAL)
10.11.2016 01:45:01.061 0000000000001100 Running task 1-2
..
10.11.2016 02:21:16.736 0000000000001100 Task 1-2 completed with exit code=0
..
10.11.2016 19:12:00.265 0000000000003920 API Entry: OP=DELETE_TASK Ver=4 Misc=4 Id=2 IntUser=1 ..
10.11.2016 19:12:00.266 0000000000003920 API Reply: OP=DELETE_TASK Ver=4 Status=0 Misc=4 Id=2
10.11.2016 19:12:00.266 0000000000000C04 API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Task=1-2 Result=2(DELETED) Extra=0
..
10.11.2016 19:12:00.266 0000000000003920 API Entry: OP=DELETE_TASK Ver=4 Misc=4 Id=3 IntUser=1 
..
10.11.2016 19:12:00.267 0000000000003920 API Reply: OP=DELETE_TASK Ver=4 Status=0 Misc=4 Id=3
10.11.2016 19:12:00.267 0000000000000C04 API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Task=1-3 Result=2(DELETED) Extra=0
..
10.11.2016 19:12:00.267 0000000000003920 API Entry: OP=DELETE_TASK Ver=4 Misc=4 Id=1 IntUser=2 
..
10.11.2016 19:12:00.267 0000000000000C04 API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Task=2-1 Result=2(DELETED) Extra=0
10.11.2016 19:12:00.267 0000000000003920 API Reply: OP=DELETE_TASK Ver=4 Status=0 Misc=41 Id=1
..
10.11.2016 19:12:00.268 0000000000003920 API Entry: OP=DELETE_TASK Ver=4 Misc=4 Id=1 IntUser=3 
..
10.11.2016 19:12:00.268 0000000000000C04 API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Task=3-1 Result=2(DELETED) Extra=0
10.11.2016 19:12:00.268 0000000000003920 API Reply: OP=DELETE_TASK Ver=4 Status=0 Misc=4 Id=1
..
10.11.2016 19:13:18.009 0000000000003920 API Reply: OP=WAIT_CHANGES_EX Ver=4 Status=0 Task=1-1 Result=1(CREATED) Extra=0
..
10.11.2016 19:13:18.014 0000000000000C04 API Entry: OP=CREATE_TASK Ver=4 Misc=4 Id=1 IntUser=1 LogonSid=S-1-5-5-0-108228074 User=INGRID\GregK
10.11.2016 19:13:18.014 00000000000010C4 OnServiceMainWake: next time = 11.11.2016 01:45:00
..
10.11.2016 19:15:12.369 00000000000010C4 OnServiceMainWake: begin
10.11.2016 19:15:12.369 00000000000010C4 Processing task 1-1
..
11.11.2016 01:42:33.539 00000000000010C4 OnServiceMainWake: begin
11.11.2016 01:42:33.539 00000000000010C4 Processing task 1-1
..
11.11.2016 01:45:01.541 00000000000010C4 OnServiceMainWake: begin
11.11.2016 01:45:01.541 00000000000010C4 Processing task 1-1
11.11.2016 01:45:01.541 00000000000010C4 RepStartFlag : 0
11.11.2016 01:45:01.541 00000000000010C4 SetWaitableTimer(-863390000000): error=0
11.11.2016 01:45:01.542 00000000000010C4 OnServiceMainWake: next time = 12.11.2016 01:45:00
..
11.11.2016 02:33:14.530 00000000000010C4 OnServiceMainWake: begin
11.11.2016 02:33:14.530 00000000000010C4 Processing task 1-1
11.11.2016 02:33:14.530 00000000000010C4 RepStartFlag : 1
11.11.2016 02:33:14.530 00000000000010C4 Conditions: isNextRepeated: 0, onTaskFinished: 0, checkedPast: 0, checkedFuture: 1, repeatedOrNotChecked: 1, doRun: 0
11.11.2016 02:33:14.530 00000000000010C4 SetWaitableTimer: not necessary to call with not changed time
11.11.2016 02:33:14.531 00000000000010C4 OnServiceMainWake: next time = 12.11.2016 01:45:00
..
11.11.2016 02:34:42.630 0000000000004D84 API Entry: OP=SET_TASK_FAILED_MAX_RETRIES Ver=4 Misc=199494272 Id=1 IntUser=1 LogonSid=S-1-5-5-0-108228074 User=INGRID\GregK
11.11.2016 02:34:42.630 0000000000004D84 API Reply: OP=SET_TASK_FAILED_MAX_RETRIES Ver=4 Status=0 Misc=199494272 Id=1
11.11.2016 02:34:42.630 0000000000004D84 API Entry: OP=SET_TASK_FAILED_INTERVAL Ver=4 Misc=0 Id=1 IntUser=1 LogonSid=S-1-5-5-0-108228074 User=INGRID\GregK
11.11.2016 02:34:42.632 0000000000004D84 API Reply: OP=SET_TASK_FAILED_INTERVAL Ver=4 Status=0 Misc=0 Id=1
11.11.2016 02:34:42.632 0000000000004D84 API Entry: OP=SET_MAX_DELAY_FOR_TRIGGER_SECONDS_INTERVAL Ver=4 Misc=199494272 Id=1 IntUser=1 LogonSid=S-1-5-5-0-108228074 User=INGRID\GregK
11.11.2016 02:34:42.633 0000000000004D84 API Reply: OP=SET_MAX_DELAY_FOR_TRIGGER_SECONDS_INTERVAL Ver=4 Status=0 Misc=199494272 Id=1
11.11.2016 02:34:42.633 0000000000004D84 API Entry: OP=CREATE_TASK Ver=4 Misc=4 Id=1 IntUser=1 LogonSid=S-1-5-5-0-108228074 User=INGRID\GregK
11.11.2016 02:34:42.634 0000000000004D84 API Reply: OP=CREATE_TASK Ver=4 Status=0 Misc=4 Id=1
11.11.2016 02:34:42.634 0000000000004D84 API Entry: OP=CREATE_TASK Ver=4 Misc=4 Id=1 IntUser=1 LogonSid=S-1-5-5-0-108228074 User=INGRID\GregK
11.11.2016 02:34:42.635 00000000000010C4 OnServiceMainWake: begin
11.11.2016 02:34:42.635 00000000000010C4 Processing task 1-1
11.11.2016 02:34:42.635 00000000000010C4 RepStartFlag : 0
11.11.2016 02:34:42.635 00000000000010C4 SetWaitableTimer: not necessary to call with not changed time
11.11.2016 02:34:42.636 00000000000010C4 OnServiceMainWake: next time = 12.11.2016 01:45:00
..
11.11.2016 02:34:42.637 00000000000051D8 API Entry: OP=CANCEL_WAITING_TASK Ver=4 Misc=4 Id=1 IntUser=1 LogonSid=S-1-5-5-0-108228074 User=INGRID\GregK
11.11.2016 02:34:42.637 00000000000051D8 API Reply: OP=CANCEL_WAITING_TASK Ver=4 Status=0 Misc=4 Id=1
11.11.2016 02:34:42.639 0000000000004D84 API Entry: OP=RUN_TASK_NO_RELOGON Ver=4 Misc=4 Id=1 IntUser=1 LogonSid=S-1-5-5-0-108228074 User=INGRID\GregK
11.11.2016 02:34:42.639 0000000000004D84 WtsId=4 TimeOut=40000
11.11.2016 02:34:42.639 0000000000004D84 For user 1 stored token 0000000000000000 replaced with 0000000000000344
11.11.2016 02:34:42.639 0000000000004D84 Trying task 1-1 as MANUAL
11.11.2016 02:34:42.639 0000000000004D84 Preferred WTS id=4
11.11.2016 02:34:42.651 0000000000001100 Running task 1-1
..
11.11.2016 03:08:31.318 0000000000001100 Task 1-1 completed with exit code=0
..
11.11.2016 06:58:05.535 00000000000010C4 OnServiceMainWake: begin
11.11.2016 06:58:05.535 00000000000010C4 Processing task 1-1
11.11.2016 06:58:05.536 00000000000010C4 RepStartFlag : 1
11.11.2016 06:58:05.536 00000000000010C4 Conditions: isNextRepeated: 0, onTaskFinished: 0, checkedPast: 0, checkedFuture: 1, repeatedOrNotChecked: 1, doRun: 0
11.11.2016 06:58:05.536 00000000000010C4 SetWaitableTimer: not necessary to call with not changed time
11.11.2016 06:58:05.536 00000000000010C4 OnServiceMainWake: next time = 12.11.2016 01:45:00

From the above, the log shows the task running as 1-2 on schedule prior to doing the schedmgr task zap which is reflected in the series of DELETE_TASK instructions recorded.  After this we see the task being rescheduled as 1-1 and this task being attempted to be processed at 19:15 on 10/11 then again at 01:45 and 02:33 where the log then shows entries for SET_TASK_FAILED_MAX_RETRIES and SET_TASK_FAILED_INTERVAL suggesting that a problem was encountered and the Error Handing options had been exhausted.  

At 02:34 the log shows CANCEL_WAITING_TASK and RUN_TASK_NO_RELOGON followed by Trying task 1-1 as MANUAL for the manual execution of the task which succeeded at 03:08.  Further, the task was attempted again at 06:58 but the log ends before further results are shown.

Please look at the service logs for this task for the attempts at 01:45 and 02:34 / 34 to see what messages are posted for the failure that triggered the error handling retries.

I don't have access to my home machine at the moment - I am at work - but I am assuming for now that, as before, the service log for 1:45 AM shows absolutely nothing, as if the service never started, let alone quit with errors. (But I will check later to make sure this is the case.) The PC would have gone back to sleep at 2:15, then I happened to be up at about 2:33, woke the PC up, saw that no backup occurred and ran it manually.

Since I don't have access to the machine I can't look at the service log but I do have the emailed "full log" status indicating success for the 2:34 manual backup:

1    True Image    11/11/2016 2:34:42 AM    Backup reserve copy attributes: format tib; need_reserve_backup_copy false; 
2    True Image    11/11/2016 2:34:42 AM    Operation Sys Image (INGRID)-1 started manually.
3    True Image    11/11/2016 2:34:44 AM    Backup reserve copy attributes: format tib; need_reserve_backup_copy false; 
4    True Image    11/11/2016 2:34:44 AM    Operation: Backup
5    True Image    11/11/2016 2:34:44 AM    Create Backup Archive From:    Disk 2 To file:    "F:\Acronis Backups\Ingrid\Sys Image (INGRID)-1.tib" Compression:    High Exclude:    Files matching mask Match criterion:    hiberfil.sys, pagefile.sys, $Recycle.Bin, swapfile.sys, System Volume Information, *.tib, *.tib.metadata, *.~, *.tmp, C:\Users\defaultuser0\AppData\Local\Temp, C:\Users\GregK\AppData\Local\Temp, C:\Users\defaultuser0\AppData\Local\Microsoft\Windows\INetCache, C:\Users\GregK\AppData\Local\Microsoft\Windows\INetCache, C:\Users\GregK\AppData\Local\Google\Chrome\User Data\Default\Cache, C:\Users\GregK\AppData\Local\Opera Software, C:\Users\GregK\AppData\Local\Mozilla\Firefox\Profiles, C:\Windows\CSC, C:\Windows.OLD, C:\Users\GregTNL\AppData\Local\Temp, C:\Users\GregTNL\AppData\Local\Microsoft\Windows\INetCache, C:\Users\GregTNL\AppData\Local\Google\Chrome\User Data\Default\Cache, C:\Users\GregTNL\AppData\Local\Mozilla\Firefox\Profiles  
6    True Image    11/11/2016 2:34:45 AM    Pending operation 172 started: 'Creating partition image'.
7    True Image    11/11/2016 2:34:45 AM    Pending operation 172 started: 'Creating partition image'.
8    True Image    11/11/2016 2:34:46 AM    Pending operation 172 started: 'Creating partition image'.
9    True Image    11/11/2016 2:35:14 AM    Writing incremental version to file: Sys Image (INGRID)-1_inc_b3_s29_v1.tib
10    True Image    11/11/2016 2:35:40 AM    Pending operation 172 started: 'Creating partition image'.
11    True Image    11/11/2016 2:35:40 AM    The following backups have been successfully created: "F:\Acronis Backups\Ingrid\Sys Image (INGRID)-1_inc_b3_s29_v1.tib"
12    True Image    11/11/2016 2:35:40 AM    Validate Backup Archive Location:    "F:\Acronis Backups\Ingrid\Sys Image (INGRID)-1_inc_b3_s29_v1.tib"  
13    True Image    11/11/2016 2:35:40 AM    Pending operation 4 started: 'Validate Backup Archive'.
14    True Image    11/11/2016 3:08:27 AM    Operation has succeeded.

Meanwhile, on my work laptop, I've noticed that if I leave the main TIH UI open overnight, the backups are running as scheduled (4 for 4, at the moment). To me, this suggests some kind of "DLL not loaded" problem that results in the scheduler not successfully launching the backup service unless something else (the TIH UI, maybe?) which loads the requisite DLL or component is also running . And that suggests maybe I should try a full uninstall / reinstall, since the problem started with the downloaded update to build 6581.

By the way, I've got the "sideloaded" TIB mounter build 2637 installed, since the previous TIH build before 6581 still had the problem where it couldn't mount certain .TIB files. I've also got DiskDirecter v12 installed at home (but not at work, so that doesn't seem to be a factor).

So unless anyone has more suggestions at the moment, I will try an uninstall - scraped clean - reinstall.