"A task was canceled" error Duplicati - 2.0.3.9_canary_2018-06-30

11 de Jul de 2018 às 16:12: The operation Backup has failed with error: A task was canceled.

{"ClassName":"System.Threading.Tasks.TaskCanceledException",
"Message":"A task was canceled.",
"Data":null,
"InnerException":null,
"HelpURL":null,
"StackTraceString":"  at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <8f2c484307284b51944a1a13a14c0266>:0 
  at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) [0x00050] in <6973ce2780de4b28aaa2c5ffc59993b1>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter) [0x00008] in <0ce58d578b8642d49036dc15fbad38f1>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass13_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x00035] in <0ce58d578b8642d49036dc15fbad38f1>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0011d] in <0ce58d578b8642d49036dc15fbad38f1>:0 ","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":null,"HResult":-21
MainOperation: Repair
RecreateDatabaseResults: null
ParsedResult: Success
Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
EndTime: 11/07/2018 16:00:27 (1531335627)
BeginTime: 11/07/2018 15:58:48 (1531335528)
Duration: 00:01:39.2260210
Messages: [
    2018-07-11 15:58:48 -03 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
    2018-07-11 16:00:21 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2018-07-11 16:00:21 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (4,10 KB),
    2018-07-11 16:00:22 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-bb91f3c41d1504aa18e8d80b17c3aa8e5.dblock.zip.aes (206,04 KB),
    2018-07-11 16:00:22 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-bb91f3c41d1504aa18e8d80b17c3aa8e5.dblock.zip.aes (206,04 KB)
]
Warnings: []
Errors: []
TaskReader:
    ProgressAsync:
        Result: True
        Factory:
            CancellationToken:
                IsCancellationRequested: False
                CanBeCanceled: False
                WaitHandle:
                    Handle: 1245
                    SafeWaitHandle:
                        IsInvalid: False
                        IsClosed: False
            Scheduler: null
            CreationOptions: None
            ContinuationOptions: None
        Id: 5
        Exception: null
        Status: RanToCompletion
        IsCanceled: False
        IsCompleted: True
        CreationOptions: None
        AsyncState: null
        IsFaulted: False
    TransferProgressAsync:
        Result: True
        Id: 6
        Exception: null
        Status: RanToCompletion
        IsCanceled: False
        IsCompleted: True
        CreationOptions: None
        AsyncState: null
        IsFaulted: False
BackendStatistics:
    RemoteCalls: 2
    BytesUploaded: 0
    BytesDownloaded: 0
    FilesUploaded: 0
    FilesDownloaded: 0
    FilesDeleted: 1
    FoldersCreated: 0
    RetryAttempts: 0
    UnknownFileSize: 0
    UnknownFileCount: 4
    KnownFileCount: 4198
    KnownFileSize: 109855828318
    LastBackupDate: 07/07/2018 17:24:20 (1530995060)
    BackupListCount: 3
    TotalQuotaSpace: 1968872767488
    FreeQuotaSpace: 1488242651136
    AssignedQuotaSpace: -1
    ReportedQuotaError: False
    ReportedQuotaWarning: False
    ParsedResult: Success
    Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
    Messages: [
        2018-07-11 15:58:48 -03 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started,
        2018-07-11 16:00:21 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-11 16:00:21 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (4,10 KB),
        2018-07-11 16:00:22 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-bb91f3c41d1504aa18e8d80b17c3aa8e5.dblock.zip.aes (206,04 KB),
        2018-07-11 16:00:22 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-bb91f3c41d1504aa18e8d80b17c3aa8e5.dblock.zip.aes (206,04 KB)
    ]
    Warnings: []
    Errors: []
    TaskReader: null

That message implies the job was manually cancelled, do you recall trying to abort a running backup?

It looks to me like the “canceled” message you showed is from 2018-07-11 @ 16:12 but the job details seem to be for a Repair that ended at 16:00:27 so the two may not be related…

(By the way, I edited your post by adding “```json” before and after the messages to make them easier to read.)

12 de Jul de 2018 às 10:09: The operation Backup has failed with error: A task was canceled.
{"ClassName":"System.Threading.Tasks.TaskCanceledException",
"Message":"A task was canceled.",
"Data":null,
"InnerException":null,
"HelpURL":null,
"StackTraceString":"  at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <8f2c484307284b51944a1a13a14c0266>:0 
  at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) [0x00050] in <6973ce2780de4b28aaa2c5ffc59993b1>:0 
  at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter) [0x00008] in <0ce58d578b8642d49036dc15fbad38f1>:0 
  at Duplicati.Library.Main.Controller+<>c__DisplayClass13_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x00035] in <0ce58d578b8642d49036dc15fbad38f1>:0 
  at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x0011d] in <0ce58d578b8642d49036dc15fbad38f1>:0 ",
"RemoteStackTraceString":null,
"RemoteStackIndex":0,
"ExceptionMethod":null,
"HResult":-2

I did not cancel manually, this error happens after a Backup that I do, the second never works, it cancels, I gave permission in the directory and it still gives the error. And I do not cancel the operation.

I really t run into this error before so I’m probably going to have to ask some generic sounding questions to try and narrow down what’s going on.

This is likely an issue with something specific to your setup - hopefully we can narrow down the cause.

Has this error always happened or did it only start recently (like after updating to 2.0.3.9)?

Before, I was not having problems, after I upgraded to 2.0.3.9, I can only do the first backup, then start presenting the error that I reported, my backup is done by linux, I have already given permission on the folders and continues the same thing.

I did the test and it again gave error, the first backup works, then the second is presenting this error, can anyone help me? this is in linux!

DeletedFiles: 0
DeletedFolders: 0
ModifiedFiles: 0
ExaminedFiles: 300185
OpenedFiles: 300185
AddedFiles: 300185
SizeOfModifiedFiles: 0
SizeOfAddedFiles: 195629208975
SizeOfExaminedFiles: 195629208975
SizeOfOpenedFiles: 195629208975
NotProcessedFiles: 0
AddedFolders: 57866
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults: null
DeleteResults:
    DeletedSets: []
    Dryrun: False
    MainOperation: Delete
    CompactResults: null
    ParsedResult: Success
    Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
    EndTime: 18/07/2018 17:48:46 (1531946926)
    BeginTime: 18/07/2018 17:44:35 (1531946675)
    Duration: 00:04:10.8184190
    Messages: [
        2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (),
        2018-07-18 08:47:31 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b593a98cd3c5946dd8bf0fdff97bceae2.dblock.zip.aes (49,96 MB),
        2018-07-18 08:47:32 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b593a98cd3c5946dd8bf0fdff97bceae2.dblock.zip.aes (49,96 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
    BackendStatistics:
        RemoteCalls: 4198
        BytesUploaded: 109889425597
        BytesDownloaded: 74624087
        FilesUploaded: 4193
        FilesDownloaded: 3
        FilesDeleted: 0
        FoldersCreated: 0
        RetryAttempts: 0
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 4193
        KnownFileSize: 109889425597
        LastBackupDate: 18/07/2018 08:47:23 (1531914443)
        BackupListCount: 1
        TotalQuotaSpace: 1968872767488
        FreeQuotaSpace: 1284421967872
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Success
        Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
        Messages: [
            2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
            2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (),
            2018-07-18 08:47:31 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b593a98cd3c5946dd8bf0fdff97bceae2.dblock.zip.aes (49,96 MB),
            2018-07-18 08:47:32 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b593a98cd3c5946dd8bf0fdff97bceae2.dblock.zip.aes (49,96 MB),
...
        ]
        Warnings: []
        Errors: []
        TaskReader: null
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-20180718T114723Z.dlist.zip.aes
        Value: [],
        Key: duplicati-i98a3eb4e8d9249338e1ed491e97d0ad7.dindex.zip.aes
        Value: [],
        Key: duplicati-b7da639273e7f4637944c444dd6382e45.dblock.zip.aes
        Value: []
    ]
    ParsedResult: Success
    Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
    EndTime: 18/07/2018 17:49:37 (1531946977)
    BeginTime: 18/07/2018 17:49:36 (1531946976)
    Duration: 00:00:01.2058860
    Messages: [
        2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (),
        2018-07-18 08:47:31 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b593a98cd3c5946dd8bf0fdff97bceae2.dblock.zip.aes (49,96 MB),
        2018-07-18 08:47:32 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b593a98cd3c5946dd8bf0fdff97bceae2.dblock.zip.aes (49,96 MB),
...
    ]
    Warnings: []
    Errors: []
    TaskReader: null
ParsedResult: Success
Version: 2.0.3.9 (2.0.3.9_canary_2018-06-30)
EndTime: 18/07/2018 17:49:37 (1531946977)
BeginTime: 18/07/2018 08:47:23 (1531914443)
Duration: 09:02:14.8185910
Messages: [
    2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2018-07-18 08:47:23 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (),
    2018-07-18 08:47:31 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b593a98cd3c5946dd8bf0fdff97bceae2.dblock.zip.aes (49,96 MB),
    2018-07-18 08:47:32 -03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b593a98cd3c5946dd8bf0fdff97bceae2.dblock.zip.aes (49,96 MB),
...
]
Warnings: []
Errors: []
TaskReader:
    ProgressAsync:
        Result: True
        Factory:
            CancellationToken:
                IsCancellationRequested: False
                CanBeCanceled: False
                WaitHandle:
                    Handle: 3402
                    SafeWaitHandle:
                        IsInvalid: False
                        IsClosed: False
            Scheduler: null
            CreationOptions: None
            ContinuationOptions: None
        Id: 1
        Exception: null
        Status: RanToCompletion
        IsCanceled: False
        IsCompleted: True
        CreationOptions: None
        AsyncState: null
        IsFaulted: False
    TransferProgressAsync:
        Result: True
        Id: 2
        Exception: null
        Status: RanToCompletion
        IsCanceled: False
        IsCompleted: True
        CreationOptions: None
        AsyncState: null
        IsFaulted: False

Is the log you included above from the “cancelled” job?

Because it looks to me like it’s working as expected - added 300,185 files in 9 hours with a “Success” result.

Is it possible the backup is running but a --run-script-after process is what’s being cancelled?

If you look at the Restore page for the backup job, do you see the expected versions listed?

Hi,

The operation Backup has failed with error: A task was canceled.

I suspect “That message implies the job was manually cancelled” is true but accidental, and above shows the Message from the low-level .NET System.Threading.Tasks.TaskCanceledException seen in the post. There’s maybe a very indirect mapping of low-level .NET Tasks to high-level Duplicati operations.

The posted CoCoL.ChannelExtensions.WaitForTaskOrThrow reference is probably from
https://github.com/kenkendk/cocol/blob/master/src/CoCoL/ChannelExtensions.cs#L98

I’ve gotten a few “A task was canceled” in my 4 months of server logs. The first one was:

2018-07-19 14:39:59 -04 - [Error-Duplicati.Library.Main.Controller-FailedOperation]: The operation Backup has failed with error: A task was canceled.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task)
   at Duplicati.Library.Main.Controller.<>c__DisplayClass13_0.<Backup>b__0(BackupResults result)
   at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action`1 method)

and that followed a flood of per-file CoCoL exceptions like:

2018-07-19 14:39:52 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.FileEntry-ProcessingMetadataFailed]: Failed to process entry, path: C:\Users\Ted\Documents\size test\short.txt
CoCoL.RetiredException: The channel is retired
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoCoL.Channel`1.<WriteAsync>d__30.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.Backup.MetadataPreProcess.<>c__DisplayClass2_0.<<Run>b__0>d.MoveNext()

It’s not clear exactly what these are telling me, but Duplicati emailed me the fatal error. I too wasn’t doing any manual cancellations, but this began when I was investigating to help look into Skip-files-larger-than ignored.

Thanks for catching that @ts678!

So it looks like some underlying .NET/mono (or CoCoL) call is the task that was canceled, NOT the Duplicati backup task - that makes sense!

So for both your and @Elton_pereira_leite’s example errors it was whatever CoCoL called with the WaitForTaskOrThrow method reporting the issue. I’m GUESSING the call included some sort of a “try to do this but if not done within X seconds, abort and throw an error” parameter.

When the “within X seconds” limit is reached, the task is “cancelled” causing the error we’re seeing.

In your case specifically, it appears it was a “MetadataPreProcess” related call that timed out (or itself crashed so never returned a result thus appearing to time out).

Of course I’m not really sure how to go about resolving this, but I’m guessing it’s related to the multi-threading processes added in 2.0.3.6 so I’d suggest rolling back to 2.0.3.5 to see if that stops the error from appearing.