Post-command stopped working?
I'm running ATI 2020 build 22510 on Windows 10 Enterprise v1909 (build 18363.752).
I have scheduled backup every night. I have pre-command to wake up NAS and post-command to put NAS back to sleep. This has been working fine for more than a year. Since last week, I noticed that post-command didn't put the NAS into sleep in scheduled backup. However, if I "Test command" within ATI, it works perfectly. I also review the logs and everything seems to be in order. How shall I troubleshoot this problem? Thank you!
QNAP_Off.cmd:
@echo off
plink qnap -ssh -l admin -pw pass123 /root/suspend.sh
TI_daemon log:
4/5/2020 12:01:07 AM: -----
4/5/2020 12:01:07 AM: ATI Demon started. Version: 24.5.1.22510.
4/5/2020 12:01:07 AM: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
4/5/2020 12:01:07 AM: Operation Micron started by schedule.
4/5/2020 12:01:07 AM: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
4/5/2020 12:01:07 AM: Operation: Backup
4/5/2020 12:01:07 AM: Priority changed to Low.
4/5/2020 12:01:07 AM: Starting user command: C:/Windows/QNAP_On.cmd
4/5/2020 12:01:15 AM: Create Backup Archive From: Disk 3 To file: nas://QNAP/Backup/Micron.tib Compression: Normal Exclude: Files matching mask Match criterion: hiberfil.sys, pagefile.sys, $Recycle.Bin, swapfile.sys, System Volume Information, *.tib, *.tib.metadata, *.~, *.tmp, D:\Users\User\AppData\Local\Mozilla\Firefox\Profiles\*\cache2, D:\Users\User\AppData\Local\Mozilla\Firefox\Profiles\*\OfflineCache, D:\Users\User\AppData\Local\Opera Software\Opera Stable\Cache, D:\Users\User\AppData\Local\Opera Software\Opera Stable\Media Cache, D:\Users\User\AppData\Local\Google\Chrome\User Data\Default\Cache, C:\WINDOWS\CSC, D:\VirtualMachines\Lab\, *.vdf, E:\
4/5/2020 12:01:18 AM: Pending operation 174 started: 'Creating partition image'.
4/5/2020 12:01:18 AM: Pending operation 174 started: 'Creating partition image'.
4/5/2020 12:01:18 AM: Pending operation 174 started: 'Creating partition image'.
4/5/2020 12:02:28 AM: Writing incremental version to file: Micron_inc_b8_s4_v1.tib
4/5/2020 12:02:34 AM: Pending operation 174 started: 'Creating partition image'.
4/5/2020 12:02:37 AM: Pending operation 174 started: 'Creating partition image'.
4/5/2020 12:04:54 AM: Volume '\\?\Volume{d4f3aed8-b62d-474c-9aa1-a176d7bb3e8f}\' has been backed up using the Express Backup method.
4/5/2020 12:04:54 AM: Volume '\\?\Volume{7c5ad9e4-a0cb-4f1a-9b59-ba42c5b95700}\' has been backed up using the Express Backup method.
4/5/2020 12:04:54 AM: Volume 'C:' has been backed up using the Express Backup method.
4/5/2020 12:04:54 AM: Volume '\\?\Volume{24b49f86-96f7-49cb-b5f6-09be255d048c}\' has been backed up using the Express Backup method.
4/5/2020 12:04:54 AM: Volume 'D:' has been backed up using the Express Backup method.
4/5/2020 12:04:54 AM: The following backups have been successfully created: nas://QNAP/Backup/Micron_inc_b8_s4_v1.tib
4/5/2020 12:04:54 AM: Starting user command: C:/Windows/QNAP_Off.cmd
4/5/2020 12:04:54 AM: Operation has succeeded.
Start: 4/5/2020 12:01:07 AM
Stop: 4/5/2020 12:04:54 AM
Total Time: 00:03:47
Michael, if your Pre/Post Commands have been working fine for a long time, and there have been no changes to ATI 2020 since build 22510 came out last November, then this issue must have its cause for some other reason. The log does not show any error for the commands but looks to be different to what I see in my own log when using Pre & Post commands.
05/04/2020 07:34:00:099 PM -----
05/04/2020 07:34:00:099 PM ATI Demon started. Version: 24.5.1.22510.
05/04/2020 07:34:00:210 PM Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
05/04/2020 07:34:00:211 PM Operation Downloads started manually.
05/04/2020 07:34:03:318 PM Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
05/04/2020 07:34:03:319 PM Operation: Backup
05/04/2020 07:34:03:322 PM Priority changed to Low.
05/04/2020 07:34:05:560 PM Child process has exited with code '0'.
05/04/2020 07:34:05:560 PM Execution of user command succeeded: C:/temp/backupactive.bat
05/04/2020 07:34:16:245 PM Create Backup Archive
05/04/2020 07:34:16:661 PM Writing incremental version to file: Downloads_inc_b1_s2_v1.tib
05/04/2020 07:34:35:734 PM The following backups have been successfully created:
05/04/2020 07:34:43:719 PM Child process has exited with code '0'.
05/04/2020 07:34:43:719 PM Execution of user command succeeded: C:/temp/backupended.bat
05/04/2020 07:34:43:797 PM Operation has succeeded.
The difference may be because you are using a backup task from an earlier version of ATI so still producing a .tib file for a disk backup.
With my backup tasks, I see confirmation that the Pre/Post command was successful with the lines:
05/04/2020 07:34:05:560 PM Child process has exited with code '0'.
05/04/2020 07:34:05:560 PM Execution of user command succeeded: C:/temp/backupactive.bat
05/04/2020 07:34:43:719 PM Child process has exited with code '0'.
05/04/2020 07:34:43:719 PM Execution of user command succeeded: C:/temp/backupended.bat
Just a guess... since there is no significant delay between the end of the backup and executing the post-command, could there still be some write activity going on in the NAS after ATI is done, and could that prevent the NAS from sleeping. What happens if you build a delay into the post command?
BrunoC wrote:Just a guess... since there is no significant delay between the end of the backup and executing the post-command, could there still be some write activity going on in the NAS after ATI is done, and could that prevent the NAS from sleeping. What happens if you build a delay into the post command?
I think I found the problem.
I do have delay in my pre-command script. For pre-command, I used to have the option "Do not perform operations until the command's execution is complete" enabled. That option was unchecked for some reasons. As BrunoC pointed out, it takes time for NAS to wake up. So the first attempt of backup failed (because NAS was not ready yet).
Fortunately, I have "Repeat attempt if a backup fails" option enabled. The backup was successful on the 2nd attempt. This was expected.
As a test, I re-enabled "Do not perform operations until the command's execution is complete" for pre-command. Then I ran the backup job. This time, the post-command executed successfully. NAS went to sleep.
But it seems to be a bug IMHO. Even if the first backup attempt failed, shouldn't the post-command be executed if the subsequent attempt was succeeded? Thank you!
Michael, glad you got it working.
As to your last point, yes I would think the command should be executed on a retry. It might be worth sending a Feedback to Acronis about this.