SFTP backup fatal error: Value does not fall within the expected range

[osnwt]

I started two backup jobs which were last time backed up in July 2019 using SFTP destination. In the end of backup I got for both a fatal error: Value does not fall within the expected range. After restarting them, one completed successfully, but another gave the same error again.

I had both local LAN FTP backups and remote SFTP ones. Local jobs for the same source data finished ok, remote ended with errors. It might be unrelated (FTP/SFTP), just FYI.

I am using MacOS Mojave 10.14.6. Duplicati version 2.0.5.104_canary_2020-03-25 which was updated from old one just before backups. Update was performed via self-update (not dmg, I use Mojave).

Error occurs in the end of backup with such log messages:

* Apr 27, 2020 1:34 PM: The operation Backup has failed with error: Value does not fall within the expected range.
* Apr 27, 2020 1:34 PM: Running Backup took 0:00:41:50.494
* Apr 27, 2020 1:34 PM: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.001
* Apr 27, 2020 1:34 PM: Starting - ExecuteNonQuery: PRAGMA optimize
* Apr 27, 2020 1:34 PM: Fatal error
* Apr 27, 2020 1:34 PM: ExecuteNonQuery: DELETE FROM "RemoteOperation" WHERE "Timestamp" < 1585391648 took 0:00:00:00.012
* Apr 27, 2020 1:34 PM: Starting - ExecuteNonQuery: DELETE FROM "RemoteOperation" WHERE "Timestamp" < 1585391648
* Apr 27, 2020 1:34 PM: ExecuteNonQuery: DELETE FROM "LogData" WHERE "Timestamp" < 1585391648 took 0:00:00:00.000
* Apr 27, 2020 1:34 PM: Starting - ExecuteNonQuery: DELETE FROM "LogData" WHERE "Timestamp" < 1585391648

Any ideas why this error happens, and how to fix it (except creating a new backup job).

The only similar report I found is this, but doesn’t look like it is related to my case:

SFTP based put fails on first retry but backup succeeds?

I’ve been getting this “Value does not fall within the expected range” error on and off lately (since updating to 2.0.3.3 beta). The error seems to happen during a put retry loop (see Retry @ 10:42) which then succeeds and the backup seems to have a ParsedResult: Success (see Result @ 10:42) however after the a Fatal error is left (see Message @ 10:44) and the job is NOT considered successful (at least according to the job menu Last successful run:Last Saturday at 11:00 AM (took 00:33:28)). I …

Detailed log from the “Fata error” line is below.

{"ClassName":"System.ArgumentException","Message":"Value does not fall within the expected range.","Data":null,"InnerException":null,"HelpURL":null,"StackTraceString":" at Renci.SshNet.Session.WaitOnHandle (System.Threading.WaitHandle waitHandle, System.TimeSpan timeout) [0x00041] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.Session.Renci.SshNet.ISession.WaitOnHandle (System.Threading.WaitHandle waitHandle) [0x0000d] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.Channels.Channel.WaitOnHandle (System.Threading.WaitHandle waitHandle) [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.Channels.Channel.Close () [0x00080] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.Channels.ChannelSession.Close () [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.Channels.Channel.Dispose (System.Boolean disposing) [0x0000f] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.Channels.ClientChannel.Dispose (System.Boolean disposing) [0x0000c] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.Channels.ChannelSession.Dispose (System.Boolean disposing) [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.Channels.Channel.Dispose () [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.SubsystemSession.Disconnect () [0x00053] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.SubsystemSession.Dispose (System.Boolean disposing) [0x0000c] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.Sftp.SftpSession.Dispose (System.Boolean disposing) [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.SubsystemSession.Dispose () [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.SftpClient.OnDisconnecting () [0x00017] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.BaseClient.Disconnect () [0x00006] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.BaseClient.Dispose (System.Boolean disposing) [0x0000c] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.SftpClient.Dispose (System.Boolean disposing) [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n at Renci.SshNet.BaseClient.Dispose () [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n at Duplicati.Library.Backend.SSHv2.Dispose () [0x00008] in <dfc308e761d54fe0b1800e3f5930bdf4>:0 \n at Duplicati.Library.Main.BackendManager.Dispose () [0x00077] in <d35eee4c56ca4ec6b30033967e3dac7d>:0 \n at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x01042] in <d35eee4c56ca4ec6b30033967e3dac7d>:0 \n at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) [0x00050] in <9a758ff4db6c48d6b3d4d0e5c2adf6d1>:0 \n at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00009] in <d35eee4c56ca4ec6b30033967e3dac7d>:0 \n at Duplicati.Library.Main.Controller+<>c__DisplayClass14_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x0004b] in <d35eee4c56ca4ec6b30033967e3dac7d>:0 \n at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action1[T] method) [0x0026f] in :0 \n at Duplicati.Library.Main.Controller.Backup (System.String inputsources, Duplicati.Library.Utility.IFilter filter) [0x00074] in :0 \n at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00349] in <46c5953990b348c78a387f111e07fba5>:0 ",“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:null,“HResult”:-2147024809,“Source”:“mscorlib”,“ParamName”:null}`

[ts678]

Changing newline into actual line break to improve readability in case the right expert stops by.
Chance may be that this will require an SSH.NET expert. It does seem some fixes are coming.
Some involve close, so might be related, but I’m not expert enough to say (or file a new issue).

{"ClassName":"System.ArgumentException","Message":"Value does not fall within the expected range.","Data":null,"InnerException":null,"HelpURL":null,"StackTraceString":"
 at Renci.SshNet.Session.WaitOnHandle (System.Threading.WaitHandle waitHandle, System.TimeSpan timeout) [0x00041] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.Session.Renci.SshNet.ISession.WaitOnHandle (System.Threading.WaitHandle waitHandle) [0x0000d] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.Channels.Channel.WaitOnHandle (System.Threading.WaitHandle waitHandle) [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.Channels.Channel.Close () [0x00080] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.Channels.ChannelSession.Close () [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.Channels.Channel.Dispose (System.Boolean disposing) [0x0000f] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.Channels.ClientChannel.Dispose (System.Boolean disposing) [0x0000c] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.Channels.ChannelSession.Dispose (System.Boolean disposing) [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.Channels.Channel.Dispose () [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.SubsystemSession.Disconnect () [0x00053] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.SubsystemSession.Dispose (System.Boolean disposing) [0x0000c] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.Sftp.SftpSession.Dispose (System.Boolean disposing) [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.SubsystemSession.Dispose () [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.SftpClient.OnDisconnecting () [0x00017] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.BaseClient.Disconnect () [0x00006] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.BaseClient.Dispose (System.Boolean disposing) [0x0000c] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.SftpClient.Dispose (System.Boolean disposing) [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Renci.SshNet.BaseClient.Dispose () [0x00000] in <c60291af03764e69b153abec058a6ec5>:0 \n
 at Duplicati.Library.Backend.SSHv2.Dispose () [0x00008] in <dfc308e761d54fe0b1800e3f5930bdf4>:0 \n
 at Duplicati.Library.Main.BackendManager.Dispose () [0x00077] in <d35eee4c56ca4ec6b30033967e3dac7d>:0 \n
 at Duplicati.Library.Main.Operation.BackupHandler.RunAsync (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x01042] in <d35eee4c56ca4ec6b30033967e3dac7d>:0 \n
 at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) [0x00050] in <9a758ff4db6c48d6b3d4d0e5c2adf6d1>:0 \n
 at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter, System.Threading.CancellationToken token) [0x00009] in <d35eee4c56ca4ec6b30033967e3dac7d>:0 \n
 at Duplicati.Library.Main.Controller+<>c__DisplayClass14_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x0004b] in <d35eee4c56ca4ec6b30033967e3dac7d>:0 \n
 at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action1[T] method) [0x0026f] in :0 \n
 at Duplicati.Library.Main.Controller.Backup (System.String inputsources, Duplicati.Library.Utility.IFilter filter) [0x00074] in :0 \n
 at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00349] in <46c5953990b348c78a387f111e07fba5>:0 ",“RemoteStackTraceString”:null,“RemoteStackIndex”:0,“ExceptionMethod”:null,“HResult”:-2147024809,“Source”:“mscorlib”,“ParamName”:null}`

At a Duplicati level, you should be able to view some of the usage of SFTP. The easiest way for small amounts is About → Show log → Live → Retry, but if long recording is needed, you can use options –log-file and –log-file-log-level=retry (good first level, but adjustable as needed either higher or lower).

@osnwt

last time backed up in July 2019

That would be before 2.0.5.1, so a just-to-be-sure check is to run mono --version. Needs at least v5.
Without that, symptoms vary (though this particular failure mode seems very rare over all of history…).

[osnwt]

My mono version is good:

Mono JIT compiler version 6.8.0.123 (2019-10/1d0d939dc30 Thu Mar 12 23:19:08 EDT 2020)

Thanks for response, I will keep an eye on this. I just thought that it may be already known issue. If not, I am ok to do more testing/logging being instructed what to log. It’s not a critical backup job for me (since I have few others). But would be good to ensure it is finally fixed.