Skip to main content

"Back up now" fails

Thread needs solution
Forum Star
Posts: 147
Comments: 978

An FTP backup failed today. My attempt to restart it via "Back up now" filed with "Failed to run the scheduled task: The task is already waiting."

I checked the error recovery setting in the backup task and it was the default 5 retries 30 seconds apart. I tried the manual backup way after that retry period had passed. (And there was no sign in the logs that retries had been attempted.)

Eventually (while I was writing this) the backup restarted - 5 minutes after the prior failure. I have no idea what scheduled that restart. It certainly wasn't the error recovery option.

The backup is scheduled to start at 1:00 AM - when the computer is always powered off - but has a "Run missed operations at the system start" up with a delay of 10 minutes. But that delay had expired: that's what kicked off the filed backup.

I know I asked about this many months ago - during or shortly after the Beta test - but I had not seen it since then.

I don't think it matters much, but here's the log from the failed run. I suspect the FTP server took too long to wake up and the backup timed out.

1/19/2020 11:56:58 AM: -----
1/19/2020 11:56:58 AM: ATI Demon started. Version: 24.5.1.22510.
1/19/2020 11:56:58 AM: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
1/19/2020 11:56:58 AM: Operation Users - FTP backup started by schedule.
1/19/2020 11:56:58 AM: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
1/19/2020 11:56:58 AM: Operation: Backup
1/19/2020 11:56:58 AM: Priority changed to Low.
1/19/2020 11:56:58 AM: Child process has exited with code '0'.
1/19/2020 11:56:58 AM: Execution of user command succeeded: C:/Validation/Integrity_check.bat
1/19/2020 11:57:00 AM: Error 0xb007f: The initial full backup version is not accessible at the moment.
1/19/2020 11:57:05 AM: Error 0x13c0005: Operation has completed with errors.

0 Users found this helpful
Forum Hero
Posts: 36
Comments: 7592

#1

Can you post a backup _worker log for this event?  It should be much more detailed.

With a whole 7 seconds transpiring in the log you posted it would appear that your network was not available for some reason.  Possibly the backup_worker log will give a clue as to the root cause.

Forum Star
Posts: 147
Comments: 978

#2

I think I wasn't very clear.  I'm not asking about the failure - I'm never surprised when an FTP backup fails.  I'll look in the backup_worker log, but that's beside the point.

I'm puzzled by the missing recovery action (which might show in the backup_worker log), and by whatever kicked off a new instance of the backup 5 minutes after the failure.

I also wanted to grumble about not being able to manually run the backup when the rerun is already scheduled, and not be able to inquire when that rerun is scheduled to run.  (I submitted feedback about that many months ago, but I'm still irritated every time I run into it.)

Forum Hero
Posts: 36
Comments: 7592

#3

I'm puzzled by the missing recovery action (which might show in the backup_worker log), and by whatever kicked off a new instance of the backup 5 minutes after the failure.

Are you talking about the retry attempts not showing in the logs?   I am certain there are times when Explorer will not show recent logs for a bit after a process has completed.  Not sure why that happens.

 

Forum Star
Posts: 147
Comments: 978

#4
Enchantech wrote:

I'm puzzled by the missing recovery action (which might show in the backup_worker log), and by whatever kicked off a new instance of the backup 5 minutes after the failure.

Are you talking about the retry attempts not showing in the logs?   I am certain there are times when Explorer will not show recent logs for a bit after a process has completed.  Not sure why that happens.

 

Well, my ignorance is showing in that question.  I don't know if retries based on the "Error handling" option for a task occur in a single execution of a task or if they result in a rescheduling of the task.  I would expect that the retry attempts would either all show in a single Ti_demon log entry or would result in multiple log entries.  I see neither ... even a day later.

After searching in vain for backup_worker logs related to this problem I finally woke up!  FTP backup:  .tib, not .tibx.  There won't be a backup_worker log entry for it.  All the data available would have been in my first posting if I have remembered to do a "regular view" rather than a "short view".  The full log entry is:

1/19/2020 11:56:58 AM: -08:00 5924 I00000000: -----
1/19/2020 11:56:58 AM: -08:00 5924 I00000000: ATI Demon started. Version: 24.5.1.22510.
1/19/2020 11:56:58 AM: -08:00 5924 I00640000: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
1/19/2020 11:56:58 AM: -08:00 5924 I00640002: Operation Users - FTP backup started by schedule.
1/19/2020 11:56:58 AM: -08:00 5924 I00640000: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
1/19/2020 11:56:58 AM: -08:00 5924 I013C0000: Operation: Backup
1/19/2020 11:56:58 AM: -08:00 5924 I0064000B: Priority changed to Low.
1/19/2020 11:56:58 AM: -08:00 5924 I00010400: Child process has exited with code '0'.
1/19/2020 11:56:58 AM: -08:00 5924 I00640086: Execution of user command succeeded: C:/Validation/Integrity_check.bat
1/19/2020 11:57:00 AM: -08:00 5924 W000B007F: Error 0xb007f: The initial full backup version is not accessible at the moment.
| trace level: warning
| line: 0x65e40aa0b4871b8
| file: c:\bs_hudson\workspace\23\products\imager\archive\impl\operations\archive_operation_backup.cpp:807
| function: TrueImage::Archive::BackupArchiveOperationImpl::TraceFirstVolumeExistance
| line: 0x65e40aa0b4871b8, c:\bs_hudson\workspace\23\products\imager\archive\impl\operations\archive_operation_backup.cpp:807, TrueImage::Archive::BackupArchiveOperationImpl::TraceFirstVolumeExistance
| $module: ti_demon_vs_22510
|
| error 0xb00eb: Failed to open the backup location.
| line: 0xd460020904af2928
| file: c:\bs_hudson\workspace\23\products\imager\archive\impl\volume_location.cpp:143
| function: TrueImage::Archive::VolumeLocation::OpenDir
| line: 0xd460020904af2928, c:\bs_hudson\workspace\23\products\imager\archive\impl\volume_location.cpp:143, TrueImage::Archive::VolumeLocation::OpenDir
| $module: ti_demon_vs_22510
|
| error 0x40000e: Failed to open the backup location.
| line: 0xbdf3287805c62c2a
| file: c:\bs_hudson\workspace\23\products\imager\archive\impl\uridir.cpp:845
| function: TrueImage::Archive::UriDir::OpenUriDir::FtpPlace::Open
| line: 0xbdf3287805c62c2a, c:\bs_hudson\workspace\23\products\imager\archive\impl\uridir.cpp:845, TrueImage::Archive::UriDir::OpenUriDir::FtpPlace::Open
| path: ftp://ds218_2:21/Private/LAPTOP-5QRI33E8/Users/
| $module: ti_demon_vs_22510
|
| error 0x40022: FTP connection has failed.
| line: 0x31813f5926d10e37
| file: c:\bs_hudson\workspace\23\core\network\ftp\ftp_api.cpp:299
| function: OpenFTP
| line: 0x31813f5926d10e37, c:\bs_hudson\workspace\23\core\network\ftp\ftp_api.cpp:299, OpenFTP
| $module: ti_demon_vs_22510
1/19/2020 11:57:05 AM: -08:00 5924 E013C0005: Error 0x13c0005: Operation has completed with errors.
| trace level: error
| line: 0x9f2c53c72e8bced8
| file: c:\bs_hudson\workspace\23\products\imager\demon\main.cpp:738
| function: main
| line: 0x9f2c53c72e8bced8, c:\bs_hudson\workspace\23\products\imager\demon\main.cpp:738, main
| $module: ti_demon_vs_22510

Start: 1/19/2020 11:56:58 AM
Stop: 1/19/2020 11:57:05 AM
Total Time: 00:00:07

I could have had a network problem just then, but I don't think I did.

Forum Star
Posts: 147
Comments: 978

#5

For what it's worth this backup - a daily backup - failed again today 4 times.  This is on a laptop that is usually powered down.  The backup, scheduled for 1:00 AM starter and failed at 9:15, around 10 minutes after I powered on.  It failed again in another 10 minutes.  I probably did have network connectivity problems at that time since the only reason I powered up was to (successfully) try a VPN connection.   I shut down shortly after that and restarted about 6:20 PM.

The FTP backup failed again at 6:30 and 6:40.  This time I know there was no network problem because I was downloading Windows maintenance.  And I know the NAS with the FTP server was available at least during the second try because I got on it's dashboard right after the 630 failure.  There was no 6:50 retry because I was rebooting after the maintenance.  At 7:00 the backup was successful.

Earlier I reported that the backup was retried after 5 minutes.  That was incorrect; it retries every 10 minutes.  As far as I know, the only 10 minute period I've specified anywhere is the 10 minute delay after system startup for missed operations.  (I wouldn't think that would apply in this case.)  And during that 10 minute delay I am not allowed to manually start a backup.

Forum Hero
Posts: 36
Comments: 7592

#6

Very strange Patrick.  Have you opened a support case?  I think I would.

Forum Star
Posts: 147
Comments: 978

#7

Yes, I know I should open a case.  I'm always reluctant to report intermittent problems because diagnosis is so long and frustrating.  (Get Acronis support to get a remote connection to my laptop within 10 minutes of my booting it.  Then watch everything run without incident.)

I'm also not sure which problem to report.  My biggest irritation is being told I cannot manually start the backup because a backup is already scheduled.  That's the problem I would like fixed.  But I suspect the backup failure is the more serious problem. 

Forum Hero
Posts: 36
Comments: 7592

#8

You should put in a feature request to Que backup now tasks behind any currently running tasks.

Forum Star
Posts: 147
Comments: 978

#9

The problem I'm running into is not that a task is already running, but that an execution of the task is already queued (with a delay).   What I should (and will) request is that a "backup now" for a task will cancel a "queued with delay" request for that same task.

I think I should also request clarification of how the "missed operation" delay actually works.  My impression is that if task is scheduled by the "missed operation" option, and execution of that task fails, that is is rescheduled using the "missed operation" delay rather than being handled by the "error retry" option.  If that is documented, I've missed it.